@@ -2289,33 +2289,96 @@ END;
2289
2289
</para>
2290
2290
2291
2291
<para>
2292
- The format of the log is:
2293
-
2294
- <synopsis>
2295
- <replaceable>client_id</replaceable> <replaceable>transaction_no</replaceable> <replaceable>time</replaceable> <replaceable>script_no</replaceable> <replaceable>time_epoch</replaceable> <replaceable>time_us</replaceable> <optional> <replaceable>schedule_lag</replaceable> </optional> <optional> <replaceable>retries</replaceable> </optional>
2296
- </synopsis>
2297
-
2298
- where
2299
- <replaceable>client_id</replaceable> indicates which client session ran the transaction,
2300
- <replaceable>transaction_no</replaceable> counts how many transactions have been
2301
- run by that session,
2302
- <replaceable>time</replaceable> is the total elapsed transaction time in microseconds,
2303
- <replaceable>script_no</replaceable> identifies which script file was used (useful when
2304
- multiple scripts were specified with <option>-f</option> or <option>-b</option>),
2305
- and <replaceable>time_epoch</replaceable>/<replaceable>time_us</replaceable> are a
2306
- Unix-epoch time stamp and an offset
2307
- in microseconds (suitable for creating an ISO 8601
2308
- time stamp with fractional seconds) showing when
2309
- the transaction completed.
2310
- The <replaceable>schedule_lag</replaceable> field is the difference between the
2311
- transaction's scheduled start time, and the time it actually started, in
2312
- microseconds. It is only present when the <option>--rate</option> option is used.
2292
+ Each line in a log file describes one transaction.
2293
+ It contains the following space-separated fields:
2294
+
2295
+ <variablelist>
2296
+ <varlistentry>
2297
+ <term><replaceable>client_id</replaceable></term>
2298
+ <listitem>
2299
+ <para>
2300
+ identifies the client session that ran the transaction
2301
+ </para>
2302
+ </listitem>
2303
+ </varlistentry>
2304
+
2305
+ <varlistentry>
2306
+ <term><replaceable>transaction_no</replaceable></term>
2307
+ <listitem>
2308
+ <para>
2309
+ counts how many transactions have been run by that session
2310
+ </para>
2311
+ </listitem>
2312
+ </varlistentry>
2313
+
2314
+ <varlistentry>
2315
+ <term><replaceable>time</replaceable></term>
2316
+ <listitem>
2317
+ <para>
2318
+ transaction's elapsed time, in microseconds
2319
+ </para>
2320
+ </listitem>
2321
+ </varlistentry>
2322
+
2323
+ <varlistentry>
2324
+ <term><replaceable>script_no</replaceable></term>
2325
+ <listitem>
2326
+ <para>
2327
+ identifies the script file that was used for the transaction
2328
+ (useful when multiple scripts are specified
2329
+ with <option>-f</option> or <option>-b</option>)
2330
+ </para>
2331
+ </listitem>
2332
+ </varlistentry>
2333
+
2334
+ <varlistentry>
2335
+ <term><replaceable>time_epoch</replaceable></term>
2336
+ <listitem>
2337
+ <para>
2338
+ transaction's completion time, as a Unix-epoch time stamp
2339
+ </para>
2340
+ </listitem>
2341
+ </varlistentry>
2342
+
2343
+ <varlistentry>
2344
+ <term><replaceable>time_us</replaceable></term>
2345
+ <listitem>
2346
+ <para>
2347
+ fractional-second part of transaction's completion time, in
2348
+ microseconds
2349
+ </para>
2350
+ </listitem>
2351
+ </varlistentry>
2352
+
2353
+ <varlistentry>
2354
+ <term><replaceable>schedule_lag</replaceable></term>
2355
+ <listitem>
2356
+ <para>
2357
+ transaction start delay, that is the difference between the
2358
+ transaction's scheduled start time and the time it actually
2359
+ started, in microseconds
2360
+ (present only if <option>--rate</option> is specified)
2361
+ </para>
2362
+ </listitem>
2363
+ </varlistentry>
2364
+
2365
+ <varlistentry>
2366
+ <term><replaceable>retries</replaceable></term>
2367
+ <listitem>
2368
+ <para>
2369
+ count of retries after serialization or deadlock errors during the
2370
+ transaction
2371
+ (present only if <option>--max-tries</option> is not equal to one)
2372
+ </para>
2373
+ </listitem>
2374
+ </varlistentry>
2375
+ </variablelist>
2376
+ </para>
2377
+
2378
+ <para>
2313
2379
When both <option>--rate</option> and <option>--latency-limit</option> are used,
2314
2380
the <replaceable>time</replaceable> for a skipped transaction will be reported as
2315
2381
<literal>skipped</literal>.
2316
- <replaceable>retries</replaceable> is the sum of all retries after the
2317
- serialization or deadlock errors during the current script execution. It is
2318
- present only if the <option>--max-tries</option> option is not equal to 1.
2319
2382
If the transaction ends with a failure, its <replaceable>time</replaceable>
2320
2383
will be reported as <literal>failed</literal>. If you use the
2321
2384
<option>--failures-detailed</option> option, the
@@ -2398,78 +2461,182 @@ END;
2398
2461
2399
2462
<para>
2400
2463
With the <option>--aggregate-interval</option> option, a different
2401
- format is used for the log files:
2402
-
2403
- <synopsis>
2404
- <replaceable>interval_start</replaceable> <replaceable>num_transactions</replaceable> <replaceable>sum_latency</replaceable> <replaceable>sum_latency_2</replaceable> <replaceable>min_latency</replaceable> <replaceable>max_latency</replaceable>
2405
- <replaceable>sum_lag</replaceable> <replaceable>sum_lag_2</replaceable> <replaceable>min_lag</replaceable> <replaceable>max_lag</replaceable> <replaceable>skipped</replaceable>
2406
- <replaceable>retried</replaceable> <replaceable>retries</replaceable> <replaceable>failures</replaceable> <replaceable>serialization_failures</replaceable> <replaceable>deadlock_failures</replaceable>
2407
- </synopsis>
2408
-
2409
- where
2410
- <replaceable>interval_start</replaceable> is the start of the interval (as a Unix
2411
- epoch time stamp),
2412
- <replaceable>num_transactions</replaceable> is the number of transactions
2413
- within the interval,
2414
- <replaceable>sum_latency</replaceable> is the sum of the transaction
2415
- latencies within the interval,
2416
- <replaceable>sum_latency_2</replaceable> is the sum of squares of the
2417
- transaction latencies within the interval,
2418
- <replaceable>min_latency</replaceable> is the minimum latency within the interval,
2419
- and
2420
- <replaceable>max_latency</replaceable> is the maximum latency within the interval,
2421
- <replaceable>failures</replaceable> is the number of transactions that ended
2422
- with a failed SQL command within the interval.
2423
- </para>
2424
- <para>
2425
- The next fields,
2426
- <replaceable>sum_lag</replaceable>, <replaceable>sum_lag_2</replaceable>, <replaceable>min_lag</replaceable>,
2427
- and <replaceable>max_lag</replaceable>, only meaningful if the <option>--rate</option>
2428
- option is used. Otherwise, they are all 0.0.
2429
- They provide statistics about the time each transaction had to wait for the
2430
- previous one to finish, i.e., the difference between each transaction's
2431
- scheduled start time and the time it actually started.
2432
- The next field, <replaceable>skipped</replaceable>,
2433
- is only meaningful if the <option>--latency-limit</option> option is used, too. Otherwise it is 0.
2434
- It counts the number of transactions skipped because they would have
2435
- started too late.
2436
- </para>
2437
- <para>
2438
- The <replaceable>retried</replaceable>
2439
- and <replaceable>retries</replaceable> fields are only meaningful if
2440
- the <option>--max-tries</option> option is not equal to 1. Otherwise they
2441
- are 0. They report the number of retried transactions and the sum of all
2442
- retries after serialization or deadlock errors within the interval. Each
2443
- transaction is counted in the interval when it was committed.
2444
- </para>
2445
- <para>
2446
- <replaceable>failures</replaceable> is the sum of all failed transactions.
2447
- If <option>--failures-detailed</option> is specified, instead of the sum of
2448
- all failed transactions you will get more detailed statistics for the
2449
- failed transactions grouped by the following types:
2450
- <replaceable>serialization_failures</replaceable> is the number of
2451
- transactions that got a serialization error and were not retried after this,
2452
- <replaceable>deadlock_failures</replaceable> is the number of transactions
2453
- that got a deadlock error and were not retried after this.
2454
- If <option>--failures-detailed</option> is not
2455
- specified, <replaceable>serialization_failures</replaceable>
2456
- and <replaceable>deadlock_failures</replaceable> are always 0.
2464
+ format is used for the log files. Each log line describes one
2465
+ aggregation interval. It contains the following space-separated
2466
+ fields:
2467
+
2468
+ <variablelist>
2469
+ <varlistentry>
2470
+ <term><replaceable>interval_start</replaceable></term>
2471
+ <listitem>
2472
+ <para>
2473
+ start time of the interval, as a Unix-epoch time stamp
2474
+ </para>
2475
+ </listitem>
2476
+ </varlistentry>
2477
+
2478
+ <varlistentry>
2479
+ <term><replaceable>num_transactions</replaceable></term>
2480
+ <listitem>
2481
+ <para>
2482
+ number of transactions within the interval
2483
+ </para>
2484
+ </listitem>
2485
+ </varlistentry>
2486
+
2487
+ <varlistentry>
2488
+ <term><replaceable>sum_latency</replaceable></term>
2489
+ <listitem>
2490
+ <para>
2491
+ sum of transaction latencies
2492
+ </para>
2493
+ </listitem>
2494
+ </varlistentry>
2495
+
2496
+ <varlistentry>
2497
+ <term><replaceable>sum_latency_2</replaceable></term>
2498
+ <listitem>
2499
+ <para>
2500
+ sum of squares of transaction latencies
2501
+ </para>
2502
+ </listitem>
2503
+ </varlistentry>
2504
+
2505
+ <varlistentry>
2506
+ <term><replaceable>min_latency</replaceable></term>
2507
+ <listitem>
2508
+ <para>
2509
+ minimum transaction latency
2510
+ </para>
2511
+ </listitem>
2512
+ </varlistentry>
2513
+
2514
+ <varlistentry>
2515
+ <term><replaceable>max_latency</replaceable></term>
2516
+ <listitem>
2517
+ <para>
2518
+ maximum transaction latency
2519
+ </para>
2520
+ </listitem>
2521
+ </varlistentry>
2522
+
2523
+ <varlistentry>
2524
+ <term><replaceable>sum_lag</replaceable></term>
2525
+ <listitem>
2526
+ <para>
2527
+ sum of transaction start delays
2528
+ (zero unless <option>--rate</option> is specified)
2529
+ </para>
2530
+ </listitem>
2531
+ </varlistentry>
2532
+
2533
+ <varlistentry>
2534
+ <term><replaceable>sum_lag_2</replaceable></term>
2535
+ <listitem>
2536
+ <para>
2537
+ sum of squares of transaction start delays
2538
+ (zero unless <option>--rate</option> is specified)
2539
+ </para>
2540
+ </listitem>
2541
+ </varlistentry>
2542
+
2543
+ <varlistentry>
2544
+ <term><replaceable>min_lag</replaceable></term>
2545
+ <listitem>
2546
+ <para>
2547
+ minimum transaction start delay
2548
+ (zero unless <option>--rate</option> is specified)
2549
+ </para>
2550
+ </listitem>
2551
+ </varlistentry>
2552
+
2553
+ <varlistentry>
2554
+ <term><replaceable>max_lag</replaceable></term>
2555
+ <listitem>
2556
+ <para>
2557
+ maximum transaction start delay
2558
+ (zero unless <option>--rate</option> is specified)
2559
+ </para>
2560
+ </listitem>
2561
+ </varlistentry>
2562
+
2563
+ <varlistentry>
2564
+ <term><replaceable>skipped</replaceable></term>
2565
+ <listitem>
2566
+ <para>
2567
+ number of transactions skipped because they would have started too late
2568
+ (zero unless <option>--rate</option>
2569
+ and <option>--latency-limit</option> are specified)
2570
+ </para>
2571
+ </listitem>
2572
+ </varlistentry>
2573
+
2574
+ <varlistentry>
2575
+ <term><replaceable>retried</replaceable></term>
2576
+ <listitem>
2577
+ <para>
2578
+ number of retried transactions
2579
+ (zero unless <option>--max-tries</option> is not equal to one)
2580
+ </para>
2581
+ </listitem>
2582
+ </varlistentry>
2583
+
2584
+ <varlistentry>
2585
+ <term><replaceable>retries</replaceable></term>
2586
+ <listitem>
2587
+ <para>
2588
+ number of retries after serialization or deadlock errors
2589
+ (zero unless <option>--max-tries</option> is not equal to one)
2590
+ </para>
2591
+ </listitem>
2592
+ </varlistentry>
2593
+
2594
+ <varlistentry>
2595
+ <term><replaceable>failures</replaceable></term>
2596
+ <listitem>
2597
+ <para>
2598
+ number of transactions that ended with a failed SQL command
2599
+ </para>
2600
+ </listitem>
2601
+ </varlistentry>
2602
+
2603
+ <varlistentry>
2604
+ <term><replaceable>serialization_failures</replaceable></term>
2605
+ <listitem>
2606
+ <para>
2607
+ number of transactions that got a serialization error and were not
2608
+ retried afterwards
2609
+ (zero unless <option>--failures-detailed</option> is specified)
2610
+ </para>
2611
+ </listitem>
2612
+ </varlistentry>
2613
+
2614
+ <varlistentry>
2615
+ <term><replaceable>deadlock_failures</replaceable></term>
2616
+ <listitem>
2617
+ <para>
2618
+ number of transactions that got a deadlock error and were not
2619
+ retried afterwards
2620
+ (zero unless <option>--failures-detailed</option> is specified)
2621
+ </para>
2622
+ </listitem>
2623
+ </varlistentry>
2624
+ </variablelist>
2457
2625
</para>
2458
2626
2459
2627
<para>
2460
- Here is some example output with following options:
2628
+ Here is some example output generated with these options:
2461
2629
<screen>
2462
- <userinput>pgbench --aggregate-interval=10 --time=20 --client=10 --log --rate=1000
2463
- --latency-limit=10 --failures-detailed --max-tries=10 test</userinput>
2630
+ <userinput>pgbench --aggregate-interval=10 --time=20 --client=10 --log --rate=1000 --latency-limit=10 --failures-detailed --max-tries=10 test</userinput>
2464
2631
2465
2632
1649114136 5815 27552565 177846919143 1078 21716 2756787 7264696105 0 9661 0 7854 31472 4022 4022 0
2466
2633
1649114146 5958 28460110 182785513108 1083 20391 2539395 6411761497 0 7268 0 8127 32595 4101 4101 0
2467
2634
</screen>
2468
2635
</para>
2469
2636
2470
2637
<para>
2471
- Notice that while the plain (unaggregated) log file shows which script
2472
- was used for each transaction, the aggregated log does not. Therefore if
2638
+ Notice that while the plain (unaggregated) log format shows which script
2639
+ was used for each transaction, the aggregated format does not. Therefore if
2473
2640
you need per-script data, you need to aggregate the data on your own.
2474
2641
</para>
2475
2642
0 commit comments