Skip to content

Commit b6b8824

Browse files
committed
Doc: reformat descriptions of pgbench output formats.
This is mostly driven by trying to get rid of line-too-wide warnings in PDF output; but I think converting to a <variablelist> makes it more readable anyway. Discussion: https://postgr.es/m/4183048.1649536705@sss.pgh.pa.us
1 parent c835dcd commit b6b8824

File tree

1 file changed

+252
-85
lines changed

1 file changed

+252
-85
lines changed

doc/src/sgml/ref/pgbench.sgml

Lines changed: 252 additions & 85 deletions
Original file line numberDiff line numberDiff line change
@@ -2289,33 +2289,96 @@ END;
22892289
</para>
22902290

22912291
<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>
23132379
When both <option>--rate</option> and <option>--latency-limit</option> are used,
23142380
the <replaceable>time</replaceable> for a skipped transaction will be reported as
23152381
<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.
23192382
If the transaction ends with a failure, its <replaceable>time</replaceable>
23202383
will be reported as <literal>failed</literal>. If you use the
23212384
<option>--failures-detailed</option> option, the
@@ -2398,78 +2461,182 @@ END;
23982461

23992462
<para>
24002463
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>
24572625
</para>
24582626

24592627
<para>
2460-
Here is some example output with following options:
2628+
Here is some example output generated with these options:
24612629
<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>
24642631

24652632
1649114136 5815 27552565 177846919143 1078 21716 2756787 7264696105 0 9661 0 7854 31472 4022 4022 0
24662633
1649114146 5958 28460110 182785513108 1083 20391 2539395 6411761497 0 7268 0 8127 32595 4101 4101 0
24672634
</screen>
24682635
</para>
24692636

24702637
<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
24732640
you need per-script data, you need to aggregate the data on your own.
24742641
</para>
24752642

0 commit comments

Comments
 (0)