49
49
50
50
<screen>
51
51
transaction type: <builtin: TPC-B (sort of)>
52
+ default transaction isolation level: read committed
52
53
scaling factor: 10
53
54
query mode: simple
54
55
number of clients: 10
55
56
number of threads: 1
56
57
number of transactions per client: 1000
57
58
number of transactions actually processed: 10000/10000
59
+ number of transactions with serialization failures: 0 (0.000 %)
60
+ number of transactions with deadlock failures: 0 (0.000 %)
58
61
tps = 85.184871 (including connections establishing)
59
62
tps = 85.296346 (excluding connections establishing)
60
63
</screen>
61
64
62
- The firstsix lines report some of the most important parameter
65
+ The firstseven lines report some of the most important parameter
63
66
settings. The next line reports the number of transactions completed
64
67
and intended (the latter being just the product of number of clients
65
68
and number of transactions per client); these will be equal unless the run
66
69
failed before completion. (In <option>-T</> mode, only the actual
67
70
number of transactions is printed.)
68
- The last two lines report the number of transactions per second,
71
+ The next two lines report the number of
72
+ transactions with serialization and deadlock failures; unlike other errors
73
+ transactions with these ones don't fail and continue run normally, but
74
+ transaction result is rolled back.
75
+ And the last two lines report the number of transactions per second,
69
76
figured with and without counting the time to start database sessions.
70
77
</para>
71
78
@@ -337,6 +344,30 @@ pgbench <optional> <replaceable>options</> </optional> <replaceable>dbname</>
337
344
</listitem>
338
345
</varlistentry>
339
346
347
+ <varlistentry>
348
+ <term><option>-I</option> <replaceable>isolationlevel</></term>
349
+ <term><option>--default-isolation-level=</option><replaceable>isolationlevel</></term>
350
+ <listitem>
351
+ <para>
352
+ Set default transaction isolation level. Use next abbreviations for
353
+ <replaceable>isolationlevel</>:
354
+ <itemizedlist>
355
+ <listitem>
356
+ <para><literal>RC</>: set default transaction isolation level as Read Committed.</para>
357
+ </listitem>
358
+ <listitem>
359
+ <para><literal>RR</>: set default transaction isolation level as Repeatable Read.</para>
360
+ </listitem>
361
+ <listitem>
362
+ <para><literal>S</>: set default transaction isolation level as Serializable.</para>
363
+ </listitem>
364
+ </itemizedlist>
365
+ The default is Read Committed isolation level. (See
366
+ <xref linkend="transaction-iso"> for more information.)
367
+ </para>
368
+ </listitem>
369
+ </varlistentry>
370
+
340
371
<varlistentry>
341
372
<term><option>-j</option> <replaceable>threads</></term>
342
373
<term><option>--jobs=</option><replaceable>threads</></term>
@@ -434,12 +465,12 @@ pgbench <optional> <replaceable>options</> </optional> <replaceable>dbname</>
434
465
<listitem>
435
466
<para>
436
467
Show progress report every <replaceable>sec</> seconds. The report
437
- includes the time since the beginning of the run, the tps since the
438
- last report, and thetransaction latency average and standard
439
- deviation since the last report. Under throttling (<option>-R</>),
440
- the latencyis computed with respect to the transaction scheduled
441
- start time, not the actual transaction beginning time, thus it also
442
- includes the average schedule lag time.
468
+ includes the time since the beginning of the run and next
469
+ characteristics since the last report: thetps, the number of
470
+ transactions with serialization and deadlock failures, and the
471
+ transaction latencyaverage and standard deviation. Under throttling
472
+ (<option>-R</>), the latency is computed with respect to the transaction scheduled start time, not the actual transaction beginning time, thus it
473
+ also includes the average schedule lag time.
443
474
</para>
444
475
</listitem>
445
476
</varlistentry>
@@ -451,7 +482,9 @@ pgbench <optional> <replaceable>options</> </optional> <replaceable>dbname</>
451
482
<para>
452
483
Report the average per-statement latency (execution time from the
453
484
perspective of the client) of each command after the benchmark
454
- finishes. See below for details.
485
+ finishes (with the number of serialization and deadlock failures for
486
+ each command if it is used with <option>--report-failures</> option).
487
+ See below for details.
455
488
</para>
456
489
</listitem>
457
490
</varlistentry>
@@ -495,6 +528,15 @@ pgbench <optional> <replaceable>options</> </optional> <replaceable>dbname</>
495
528
separately.
496
529
</para>
497
530
531
+ <para>
532
+ Transactions with serialization or deadlock failures (or with both
533
+ of them if used script contains several transactions; see
534
+ <xref linkend="transactions-and-scripts"
535
+ endterm="transactions-and-scripts-title"> for more information) are
536
+ marked separately and their time is not reported as for skipped
537
+ transactions.
538
+ </para>
539
+
498
540
<para>
499
541
A high schedule lag time is an indication that the system cannot
500
542
process transactions at the specified rate, with the chosen number of
@@ -596,6 +638,18 @@ pgbench <optional> <replaceable>options</> </optional> <replaceable>dbname</>
596
638
</listitem>
597
639
</varlistentry>
598
640
641
+ <varlistentry>
642
+ <term><option>--report-failures</option></term>
643
+ <listitem>
644
+ <para>
645
+ Report the number of serialization and deadlock failures for each
646
+ command after the benchmark finishes (with the average per-statement
647
+ latencies of each command if it is used with <option>-r</> option). See
648
+ below for details.
649
+ </para>
650
+ </listitem>
651
+ </varlistentry>
652
+
599
653
<varlistentry>
600
654
<term><option>--sampling-rate=<replaceable>rate</></option></term>
601
655
<listitem>
@@ -697,8 +751,8 @@ pgbench <optional> <replaceable>options</> </optional> <replaceable>dbname</>
697
751
<refsect1>
698
752
<title>Notes</title>
699
753
700
- <refsect2>
701
- <title>What is the <quote>Transaction</> Actually Performed in <application>pgbench</application>?</title>
754
+ <refsect2 id="transactions-and-scripts" >
755
+ <title id="transactions-and-scripts-title" >What is the <quote>Transaction</> Actually Performed in <application>pgbench</application>?</title>
702
756
703
757
<para>
704
758
<application>pgbench</> executes test scripts chosen randomly
@@ -1163,6 +1217,13 @@ END;
1163
1217
When both <option>--rate</> and <option>--latency-limit</> are used,
1164
1218
the <replaceable>time</> for a skipped transaction will be reported as
1165
1219
<literal>skipped</>.
1220
+ If transaction has serialization / deadlock failure or them both (last thing
1221
+ is possible if used script contains several transactions; see
1222
+ <xref linkend="transactions-and-scripts"
1223
+ endterm="transactions-and-scripts-title"> for more information), its
1224
+ <replaceable>time</> will be reported as <literal>serialization failure</> /
1225
+ <literal>deadlock failure</> /
1226
+ <literal>serialization and deadlock failures</> appropriately.
1166
1227
</para>
1167
1228
1168
1229
<para>
@@ -1190,6 +1251,20 @@ END;
1190
1251
were already late before they were even started.
1191
1252
</para>
1192
1253
1254
+ <para>
1255
+ Example with serialization, deadlock and both these failures:
1256
+ <screen>
1257
+ 1 128 24968 0 1496759158 426984
1258
+ 0 129 serialization failure 0 1496759158 427023
1259
+ 3 129 serialization failure 0 1496759158 432662
1260
+ 2 128 serialization failure 0 1496759158 432765
1261
+ 0 130 deadlock failure 0 1496759159 460070
1262
+ 1 129 serialization failure 0 1496759160 485188
1263
+ 2 129 serialization and deadlock failures 0 1496759160 485339
1264
+ 4 130 serialization failure 0 1496759160 485465
1265
+ </screen>
1266
+ </para>
1267
+
1193
1268
<para>
1194
1269
When running a long test on hardware that can handle a lot of transactions,
1195
1270
the log files can become very large. The <option>--sampling-rate</> option
@@ -1204,16 +1279,19 @@ END;
1204
1279
With the <option>--aggregate-interval</option> option, the logs use a bit different format:
1205
1280
1206
1281
<synopsis>
1207
- <replaceable>interval_start</> <replaceable>num_of_transactions</> <replaceable>latency_sum</> <replaceable>latency_2_sum</> <replaceable>min_latency</> <replaceable>max_latency</> <optional><replaceable>lag_sum</> <replaceable>lag_2_sum</> <replaceable>min_lag</> <replaceable>max_lag</> <optional><replaceable>skipped_transactions</></optional></optional>
1282
+ <replaceable>interval_start</> <replaceable>num_of_transactions</> <replaceable>num_serialization_failures_transactions</> <replaceable>num_deadlock_failures_transactions</> <replaceable> latency_sum</> <replaceable>latency_2_sum</> <replaceable>min_latency</> <replaceable>max_latency</> <optional><replaceable>lag_sum</> <replaceable>lag_2_sum</> <replaceable>min_lag</> <replaceable>max_lag</> <optional><replaceable>skipped_transactions</></optional></optional>
1208
1283
</synopsis>
1209
1284
1210
1285
where <replaceable>interval_start</> is the start of the interval (Unix epoch
1211
1286
format time stamp), <replaceable>num_of_transactions</> is the number of transactions
1212
- within the interval, <replaceable>latency_sum</replaceable> is a sum of latencies
1213
- (so you can compute average latency easily). The following two fields are useful
1214
- for variance estimation - <replaceable>latency_sum</> is a sum of latencies and
1215
- <replaceable>latency_2_sum</> is a sum of 2nd powers of latencies. The next two
1216
- fields are <replaceable>min_latency</> - a minimum latency within the interval, and
1287
+ within the interval, <replaceable>num_serialization_failures_transactions</>
1288
+ and <replaceable>num_deadlock_failures_transactions</> are the numbers of
1289
+ transactions with appropriate failures within the interval, <replaceable>
1290
+ latency_sum</replaceable> is a sum of latencies (so you can compute average
1291
+ latency easily). The following two fields are useful for variance estimation
1292
+ - <replaceable>latency_sum</> is a sum of latencies and <replaceable>
1293
+ latency_2_sum</> is a sum of 2nd powers of latencies. The next two fields are
1294
+ <replaceable>min_latency</> - a minimum latency within the interval, and
1217
1295
<replaceable>max_latency</> - maximum latency within the interval. A transaction is
1218
1296
counted into the interval when it was committed. The fields in the end,
1219
1297
<replaceable>lag_sum</>, <replaceable>lag_2_sum</>, <replaceable>min_lag</>,
@@ -1228,11 +1306,11 @@ END;
1228
1306
<para>
1229
1307
Here is example output:
1230
1308
<screen>
1231
- 1345828501 5601 1542744 483552416 61 2573
1232
- 1345828503 7884 1979812 565806736 60 1479
1233
- 1345828505 7208 1979422 567277552 59 1391
1234
- 1345828507 7685 1980268 569784714 60 1398
1235
- 1345828509 7073 1979779 573489941 236 1411
1309
+ 1345828501 56010 0 1542744 483552416 61 2573
1310
+ 1345828503 78840 0 1979812 565806736 60 1479
1311
+ 1345828505 72080 0 1979422 567277552 59 1391
1312
+ 1345828507 76850 0 1980268 569784714 60 1398
1313
+ 1345828509 70730 0 1979779 573489941 236 1411
1236
1314
</screen></para>
1237
1315
1238
1316
<para>
@@ -1244,31 +1322,45 @@ END;
1244
1322
</refsect2>
1245
1323
1246
1324
<refsect2>
1247
- <title>Per-Statement Latencies</title>
1325
+ <title>Per-Statement Latencies and Failures </title>
1248
1326
1249
1327
<para>
1250
- With the <option>-r</> option, <application>pgbench</> collects
1251
- the elapsed transaction time of each statement executed by every
1252
- client. It then reports an average of those values, referred to
1253
- as the latency for each statement, after the benchmark has finished.
1328
+ There're two options to get some per-statement characteristics: <option>-r</>
1329
+ and <option>--report-failures</> (they can be combined together). All values
1330
+ are computed for each statement executed by every client and are reported
1331
+ after the benchmark has finished. With the <option>-r</> option,
1332
+ <application>pgbench</> collects the elapsed transaction time of each
1333
+ statement. It then reports an average of those values, referred to as the
1334
+ latency for each statement. With the <option>--report-failures</> option,
1335
+ <application>pgbench</> collects the number of serialization and deadlock
1336
+ failures for each statement (notice that the total sum of per-command
1337
+ failures of each type can be greater than the number of "transactions" with
1338
+ these failures; see <xref linkend="transactions-and-scripts"
1339
+ endterm="transactions-and-scripts-title"> for more information).
1254
1340
</para>
1255
1341
1256
1342
<para>
1257
- For the default script, the output will look similar to this:
1343
+ For the default script if you use <option>-r</> option, the output will look
1344
+ similar to this:
1258
1345
<screen>
1259
1346
starting vacuum...end.
1260
1347
transaction type: <builtin: TPC-B (sort of)>
1348
+ default transaction isolation level: read committed
1261
1349
scaling factor: 1
1262
1350
query mode: simple
1263
1351
number of clients: 10
1264
1352
number of threads: 1
1265
1353
number of transactions per client: 1000
1266
1354
number of transactions actually processed: 10000/10000
1355
+ number of transactions with serialization failures: 0 (0.000 %)
1356
+ number of transactions with deadlock failures: 0 (0.000 %)
1267
1357
latency average = 15.844 ms
1268
1358
latency stddev = 2.715 ms
1269
1359
tps = 618.764555 (including connections establishing)
1270
1360
tps = 622.977698 (excluding connections establishing)
1271
1361
script statistics:
1362
+ - number of transactions with serialization failures: 0 (0.000%)
1363
+ - number of transactions with deadlock failures: 0 (0.000%)
1272
1364
- statement latencies in milliseconds:
1273
1365
0.002 \set aid random(1, 100000 * :scale)
1274
1366
0.005 \set bid random(1, 1 * :scale)
@@ -1282,11 +1374,45 @@ script statistics:
1282
1374
0.371 INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (:tid, :bid, :aid, :delta, CURRENT_TIMESTAMP);
1283
1375
1.212 END;
1284
1376
</screen>
1377
+
1378
+ Another example of output for the default script using serializable default
1379
+ transaction isolation level (-I S) and <option>--report-failures</> option:
1380
+ <screen>
1381
+ starting vacuum...end.
1382
+ transaction type: <builtin: TPC-B (sort of)>
1383
+ default transaction isolation level: serializable
1384
+ scaling factor: 1
1385
+ query mode: simple
1386
+ number of clients: 10
1387
+ number of threads: 1
1388
+ number of transactions per client: 1000
1389
+ number of transactions actually processed: 10000/10000
1390
+ number of transactions with serialization failures: 9284 (92.840 %)
1391
+ number of transactions with deadlock failures: 0 (0.000 %)
1392
+ latency average = 10.817 ms
1393
+ tps = 924.477920 (including connections establishing)
1394
+ tps = 928.159352 (excluding connections establishing)
1395
+ script statistics:
1396
+ - number of transactions with serialization failures: 9284 (92.840%)
1397
+ - number of transactions with deadlock failures: 0 (0.000%)
1398
+ - statement serialization and deadlock failures:
1399
+ 0 0 \set aid random(1, 100000 * :scale)
1400
+ 0 0 \set bid random(1, 1 * :scale)
1401
+ 0 0 \set tid random(1, 10 * :scale)
1402
+ 0 0 \set delta random(-5000, 5000)
1403
+ 0 0 BEGIN;
1404
+ 0 0 UPDATE pgbench_accounts SET abalance = abalance + :delta WHERE aid = :aid;
1405
+ 0 0 SELECT abalance FROM pgbench_accounts WHERE aid = :aid;
1406
+ 7975 0 UPDATE pgbench_tellers SET tbalance = tbalance + :delta WHERE tid = :tid;
1407
+ 1305 0 UPDATE pgbench_branches SET bbalance = bbalance + :delta WHERE bid = :bid;
1408
+ 0 0 INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (:tid, :bid, :aid, :delta, CURRENT_TIMESTAMP);
1409
+ 4 0 END;
1410
+ </screen>
1285
1411
</para>
1286
1412
1287
1413
<para>
1288
- If multiple script files are specified, the averagesare reported
1289
- separately for each script file.
1414
+ If multiple script files are specified, the averagesand the failures are
1415
+ reported separately for each script file.
1290
1416
</para>
1291
1417
1292
1418
<para>