Run the workload
We are finally ready to run our workload! In this section, we inspect a little bit more the output we saw in the previous section, explaining how to interpret it.
Do a test run
We now run a workload for 2 minutes (-d 120) and 4 connections (-c 4).
We also want read operations to make 70% of the overall traffic.
# targeting PostgreSQL Server
$ dbworkload run -w bank.py \
--uri 'postgres://fabio:postgres@localhost:5432/bank?sslmode=disable' \
--args '{"read_pct": 70}' -d 120 -c 4
2024-10-21 09:49:12,276 [INFO] (MainProcess MainThread) run:269: Starting workload Bank.20241021_134912
My thread ID is 0. The total count of threads is 4
My thread ID is 3. The total count of threads is 4
My thread ID is 1. The total count of threads is 4
My thread ID is 2. The total count of threads is 4
PostgreSQL 16.2 (Postgres.app) on aarch64-apple-darwin21.6.0, compiled by Apple clang version 14.0.0 (clang-1400.0.29.102), 64-bit
PostgreSQL 16.2 (Postgres.app) on aarch64-apple-darwin21.6.0, compiled by Apple clang version 14.0.0 (clang-1400.0.29.102), 64-bit
PostgreSQL 16.2 (Postgres.app) on aarch64-apple-darwin21.6.0, compiled by Apple clang version 14.0.0 (clang-1400.0.29.102), 64-bit
PostgreSQL 16.2 (Postgres.app) on aarch64-apple-darwin21.6.0, compiled by Apple clang version 14.0.0 (clang-1400.0.29.102), 64-bit
elapsed id threads tot_ops tot_ops/s period_ops period_ops/s mean(ms) p50(ms) p90(ms) p95(ms) p99(ms) max(ms)
--------- -------------- --------- --------- ----------- ------------ -------------- ---------- --------- --------- --------- --------- ---------
10 __cycle__ 4 4,792 479 4,792 0 7.22 0.27 24.55 25.46 26.57 72.60
10 txn_new_order 4 1,417 141 1,417 0 0.50 0.38 0.56 0.64 1.03 32.68
10 txn_order_exec 4 1,417 141 1,417 0 23.25 23.12 25.36 25.78 26.75 66.76
10 txn_read 4 3,375 337 3,375 0 0.27 0.23 0.36 0.41 0.52 31.26
elapsed id threads tot_ops tot_ops/s period_ops period_ops/s mean(ms) p50(ms) p90(ms) p95(ms) p99(ms) max(ms)
--------- -------------- --------- --------- ----------- ------------ -------------- ---------- --------- --------- --------- --------- ---------
20 __cycle__ 4 10,492 524 5,700 0 6.95 0.26 24.27 25.18 26.26 40.11
20 txn_new_order 4 3,065 153 1,648 0 0.40 0.36 0.53 0.61 0.80 7.34
20 txn_order_exec 4 3,065 153 1,648 0 23.01 22.91 25.21 25.62 26.27 39.71
20 txn_read 4 7,427 371 4,052 0 0.24 0.22 0.35 0.40 0.51 5.02
[...truncating...]
elapsed id threads tot_ops tot_ops/s period_ops period_ops/s mean(ms) p50(ms) p90(ms) p95(ms) p99(ms) max(ms)
--------- -------------- --------- --------- ----------- ------------ -------------- ---------- --------- --------- --------- --------- ---------
110 __cycle__ 4 59,242 538 5,602 0 7.08 0.26 24.88 25.54 26.35 41.93
110 txn_new_order 4 17,685 160 1,617 0 0.42 0.37 0.55 0.62 0.92 9.19
110 txn_order_exec 4 17,685 160 1,617 0 23.48 23.70 25.45 25.75 26.43 41.59
110 txn_read 4 41,557 377 3,985 0 0.25 0.22 0.35 0.40 0.51 15.43
2024-10-21 09:51:12,330 [INFO] (MainProcess MainThread) run:369: Requested iteration/duration limit reached
2024-10-21 09:51:12,331 [INFO] (MainProcess MainThread) run:176: Printing final stats
elapsed id threads tot_ops tot_ops/s period_ops period_ops/s mean(ms) p50(ms) p90(ms) p95(ms) p99(ms) max(ms)
--------- -------------- --------- --------- ----------- ------------ -------------- ---------- --------- --------- --------- --------- ---------
120 __cycle__ 4 64,652 538 5,410 0 7.39 0.27 24.87 25.57 26.39 55.03
120 txn_new_order 4 19,322 161 1,637 0 0.46 0.37 0.55 0.62 0.79 29.40
120 txn_order_exec 4 19,322 161 1,637 0 23.39 23.53 25.49 25.77 26.27 44.41
120 txn_read 4 45,330 377 3,773 0 0.25 0.23 0.35 0.40 0.49 5.49
2024-10-21 09:51:12,332 [INFO] (MainProcess MainThread) run:181: Printing summary for the full test run
------------- --------------------
run_name Bank.20241021_134912
start_time 2024-10-21 13:49:12
end_time 2024-10-21 13:51:12
test_duration 120
------------- --------------------
┌───────────┬────────────────┬───────────┬───────────┬─────────────┬────────────┬───────────┬───────────┬───────────┬───────────┬───────────┐
│ elapsed │ id │ threads │ tot_ops │ tot_ops/s │ mean(ms) │ p50(ms) │ p90(ms) │ p95(ms) │ p99(ms) │ max(ms) │
├───────────┼────────────────┼───────────┼───────────┼─────────────┼────────────┼───────────┼───────────┼───────────┼───────────┼───────────┤
│ 120 │ __cycle__ │ 4 │ 64,652 │ 538 │ 7.29 │ 0.30 │ 24.72 │ 25.51 │ 26.42 │ 98.36 │
│ 120 │ txn_new_order │ 4 │ 19,322 │ 161 │ 0.44 │ 0.37 │ 0.56 │ 0.64 │ 0.88 │ 33.19 │
│ 120 │ txn_order_exec │ 4 │ 19,322 │ 161 │ 23.34 │ 23.34 │ 25.45 │ 25.78 │ 26.39 │ 97.89 │
│ 120 │ txn_read │ 4 │ 45,330 │ 377 │ 0.26 │ 0.23 │ 0.36 │ 0.41 │ 0.52 │ 31.26 │
└───────────┴────────────────┴───────────┴───────────┴─────────────┴────────────┴───────────┴───────────┴───────────┴───────────┴───────────┘
Parameter Value
------------- -----------------------------------------------------------------------------------------------------------------------
workload_path /path/to/workloads/bank.py
conn_params {'conninfo': 'postgres://fabio:postgres@localhost:5432/bank?sslmode=disable&application_name=Bank', 'autocommit': True}
conn_extras {}
concurrency 4
duration 120
iterations
ramp 0
args {'read_pct': 70}
As we have created 4 connections, each connection will execute the setup() function and print its thread ID and server version.
dbworkload will then print out, every 10 seconds, a table with count and latency statistics for the functions it invoked.
It is importand to understand that the statistics are on a function basis, not SQL transaction basis:
as we saw while coding the bank.py workload class, certain functions do more than just executing a SQL statement.
Function txn_order_exec, for example, executes 1 SELECT statements, then pauses for 20ms, and last it executes the UPDATE statement.
dbworkload thus shows you the latency to execute business functions rather than individual database statements/transactions.
Finally, you have noticed there is a __cycle__ entry in the table.
This metric shows you the duration of the total execution of all functions returned in the loop().
This is helpful if the metric you use to benchmark your workload is neither at SQL transaction nor function level,
but for the overall time taken to perform a series of functions.
For example, you can measure the performance based on total execution time of an Order Transaction,
that is, the sum of executing the txn_new_order and txn_order_exec.
Save stats to CSV
dbworkload can save the statistics to a CSV file for later inspection.
There are 2 common uses of the CSV files:
- as an input to plot charts.
- if
dbworkloadis executed from multiple servers towards the same target, you can merge the CSV files to have a unified view of all the collected metrics.
For this second run, we add flags for saving to CSV (-s) and for omitting printing to stdout (-q).
$ dbworkload run -w bank.py \
--uri 'postgres://fabio:postgres@localhost:5432/bank?sslmode=disable' \
--args '{"read_pct": 70}' -d 120 -c 4 \
-s -q
After 2 minutes, check your directory for 2 new files:
- a
.csvfile - a
.txtfile
$ ls -lh1 Bank.*
Bank.20241021_145825.csv
Bank.20241021_145825.txt
The .txt file shows a summary of the test run, whose name you've noticed takes the form
of the workload name, Bank, followed by the timestamp.
In the next session, we will use the .csv file to plot some charts.