7. Generating Time Profiles

In addition to performance profiles based on throughput you should also take note of transaction response times. Whereas performance profiles show the cumulative performance of all of the virtual users running on the system, response times show performance based on the experience of the individual user. When comparing systems both throughput and response time are important comparative measurements. HammerDB includes a time profiling package called etprof that enables you to select an individual user and measure the response times. This functionality is enabled by selecting Time Profile checkbox in the driver options. When enabled the time profile will report response time percentile values at 10 second intervals as well as cumulative values for all of the test at the end of the test run. The time profile values are recorded in microseconds.

Hammerdb Log @ Fri Jul 05 09:55:26 BST 2019
+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-
Vuser 1:Beginning rampup time of 1 minutes
Vuser 2:Processing 1000000 transactions with output suppressed...
Vuser 3:Processing 1000000 transactions with output suppressed...
Vuser 4:Processing 1000000 transactions with output suppressed...
Vuser 5:Processing 1000000 transactions with output suppressed...
Vuser 2:|PERCENTILES 2019-07-05 09:55:46 to 2019-07-05 09:55:56
Vuser 2:|neword|MIN-391|P50%-685|P95%-1286|P99%-3298|MAX-246555|SAMPLES-3603
Vuser 2:|payment|MIN-314|P50%-574|P95%-1211|P99%-2253|MAX-89367|SAMPLES-3564
Vuser 2:|delivery|MIN-1128|P50%-1784|P95%-2784|P99%-6960|MAX-267012|SAMPLES-356
Vuser 2:|slev|MIN-723|P50%-884|P95%-1363|P99%-3766|MAX-120687|SAMPLES-343
Vuser 2:|ostat|MIN-233|P50%-568|P95%-1325|P99%-2387|MAX-82538|SAMPLES-365
Vuser 2:|gettimestamp|MIN-2|P50%-4|P95%-7|P99%-14|MAX-39|SAMPLES-7521
Vuser 2:|prep_statement|MIN-188|P50%-209|P95%-1067|P99%-1067|MAX-1067|SAMPLES-6
Vuser 2:+-----------------+--------------+------+--------+--------------+--------------+
...
Vuser 2:+-----------------+--------------+------+--------+--------------+--------------+
Vuser 2:|PERCENTILES 2019-07-05 09:59:26 to 2019-07-05 09:59:36
Vuser 2:|neword|MIN-410|P50%-678|P95%-1314|P99%-4370|MAX-32030|SAMPLES-4084
Vuser 2:|payment|MIN-331|P50%-583|P95%-1271|P99%-3152|MAX-43996|SAMPLES-4142
Vuser 2:|delivery|MIN-1177|P50%-2132|P95%-3346|P99%-4040|MAX-8492|SAMPLES-416
Vuser 2:|slev|MIN-684|P50%-880|P95%-1375|P99%-1950|MAX-230733|SAMPLES-364
Vuser 2:|ostat|MIN-266|P50%-688.5|P95%-1292|P99%-1827|MAX-9790|SAMPLES-427
Vuser 2:|gettimestamp|MIN-3|P50%-4|P95%-7|P99%-14|MAX-22|SAMPLES-8639
Vuser 2:+-----------------+--------------+------+--------+--------------+--------------+
Vuser 2:|PERCENTILES 2019-07-05 09:59:36 to 2019-07-05 09:59:46
Vuser 2:|neword|MIN-404|P50%-702|P95%-1296|P99%-4318|MAX-71663|SAMPLES-3804
Vuser 2:|payment|MIN-331|P50%-597|P95%-1250|P99%-4190|MAX-47539|SAMPLES-3879
Vuser 2:|delivery|MIN-1306|P50%-2131|P95%-4013|P99%-8742|MAX-25095|SAMPLES-398
Vuser 2:|slev|MIN-713|P50%-913|P95%-1438|P99%-2043|MAX-7434|SAMPLES-386
Vuser 2:|ostat|MIN-268|P50%-703|P95%-1414|P99%-3381|MAX-249963|SAMPLES-416
Vuser 2:|gettimestamp|MIN-3|P50%-4|P95%-8|P99%-16|MAX-27|SAMPLES-8079
Vuser 2:+-----------------+--------------+------+--------+--------------+--------------+
Vuser 1:3 ...,
Vuser 1:Test complete, Taking end Transaction Count.
Vuser 1:4 Active Virtual Users configured
Vuser 1:TEST RESULT : System achieved 468610 SQL Server TPM at 101789 NOPM
Vuser 2:+-----------------+--------------+------+--------+--------------+--------------+
Vuser 2:|PROCNAME | EXCLUSIVETOT| %| CALLNUM| AVGPERCALL| CUMULTOT|
Vuser 2:+-----------------+--------------+------+--------+--------------+--------------+
Vuser 2:|neword | 82051665|39.96%| 93933| 873| 88760245|
Vuser 2:|payment | 73823956|35.95%| 93922| 786| 80531339|
Vuser 2:|delivery | 22725292|11.07%| 9577| 2372| 23418195|
Vuser 2:|slev | 14396765| 7.01%| 9340| 1541| 14402033|
Vuser 2:|ostat | 10202116| 4.97%| 9412| 1083| 10207260|
Vuser 2:|gettimestamp | 2149552| 1.05%| 197432| 10| 13436919|
Vuser 2:|TOPLEVEL | 2431| 0.00%| 1| 2431| NOT AVAILABLE|
Vuser 2:|prep_statement | 1935| 0.00%| 5| 387| 1936|
Vuser 2:+-----------------+--------------+------+--------+--------------+--------------+

The output from etprof taken from each system should be used in context with the overall performance profile to break down the overall system throughput to the timing of the individual transactions themselves and then graphed to show the comparison.

Figure 3.4. Response Times

Response Times