Extended Time Profiling #224

sm-shaw · 2021-04-01T14:33:33Z

HammerDB currently uses the etprof package for time profiling. Due to the profiling overhead this package is restricted to running in the first active virtual user only. This does not give a full picture on all of the timings across the workload.
The requirement is to build an alternative time profiling package that can be loaded to measure the time profiles for all virtual users more efficiently and generate the output to a separate logfile. It will be optional whether to use extended time profiling or to use etprof to record percentiles at 10 second intervals for the first active virtual user.

sm-shaw · 2021-04-02T09:44:10Z

Solution adds a new time profile section to generic.xml.

<timeprofile>
           <profiler>xtprof</profiler>
           <xt_unique_log_name>0</xt_unique_log_name>
    </timeprofile>

User continues to choose a time profile option or checkbox as before, behaviour is determined by xml options.
If profiler is set to etprof time profiling works as before measuring timings in Virtual User 2 only.
If profiler is set to xtprof it will capture timings for all virtual users and report them at the end including a summary of all timings. Output is to file hdbxtprofile.log, the only current option is to create a unique log file name. All timing data is collated by the monitor virtual user.

Timing Data Written is:

CALLS: Number of calls to the stored procedure through the timing period
MIN: Minimum response time
AVG: Average response time
MAX: Max response time
TOTAL: Total response (for the summary this will be more than elapsed time as a sum of all virtual users)
P99: 99th percentile
P95: 95th percentile
P50:50th percentile
SD:Standard Deviation
RATIO: Percentage of calls by that Virtual User - output is ordered by ratio from high to low

Timing profile overhead measured on a latest generation server was 4%

Example below for SQL Server on test PC

MSSQLServer Hammerdb Time Profile Report @ Fri Apr 02 10:23:56 BST 2021
+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+
>>>>> VIRTUAL USER 2 : ELAPSED TIME : 421062ms
>>>>> PROC: NEWORD
CALLS: 169244	MIN: 0.430ms	AVG: 0.994ms	MAX: 1042.998ms	TOTAL: 168189.754ms
P99: 2.465ms	P95: 1.383ms	P50: 0.857ms	SD: 41300.051	RATIO: 39.944%
>>>>> PROC: PAYMENT
CALLS: 169863	MIN: 0.342ms	AVG: 0.854ms	MAX: 1726.371ms	TOTAL: 145028.480ms
P99: 2.353ms	P95: 1.390ms	P50: 0.685ms	SD: 64474.647	RATIO: 34.443%
>>>>> PROC: DELIVERY
CALLS: 17027	MIN: 1.298ms	AVG: 2.709ms	MAX: 163.655ms	TOTAL: 46129.940ms
P99: 5.360ms	P95: 3.647ms	P50: 2.541ms	SD: 25810.720	RATIO: 10.956%
>>>>> PROC: SLEV
CALLS: 16822	MIN: 0.617ms	AVG: 1.903ms	MAX: 764.873ms	TOTAL: 32006.646ms
P99: 2.308ms	P95: 1.821ms	P50: 1.343ms	SD: 156601.733	RATIO: 7.601%
>>>>> PROC: OSTAT
CALLS: 17188	MIN: 0.213ms	AVG: 1.035ms	MAX: 468.477ms	TOTAL: 17790.442ms
P99: 2.047ms	P95: 1.483ms	P50: 0.774ms	SD: 77601.204	RATIO: 4.225%
+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+
>>>>> VIRTUAL USER 3 : ELAPSED TIME : 420313ms
>>>>> PROC: NEWORD
CALLS: 159980	MIN: 0.444ms	AVG: 1.022ms	MAX: 1643.138ms	TOTAL: 163441.841ms
P99: 2.567ms	P95: 1.492ms	P50: 0.862ms	SD: 58276.974	RATIO: 38.886%
>>>>> PROC: PAYMENT
CALLS: 160285	MIN: 0.346ms	AVG: 0.881ms	MAX: 2023.197ms	TOTAL: 141213.427ms
P99: 2.503ms	P95: 1.473ms	P50: 0.705ms	SD: 65938.596	RATIO: 33.597%
>>>>> PROC: DELIVERY
CALLS: 16069	MIN: 1.272ms	AVG: 3.417ms	MAX: 206.193ms	TOTAL: 54904.266ms
P99: 7.418ms	P95: 5.324ms	P50: 3.192ms	SD: 32127.714	RATIO: 13.063%
>>>>> PROC: SLEV
CALLS: 16050	MIN: 0.678ms	AVG: 2.006ms	MAX: 626.750ms	TOTAL: 32200.179ms
P99: 2.643ms	P95: 1.910ms	P50: 1.343ms	SD: 168030.717	RATIO: 7.661%
>>>>> PROC: OSTAT
CALLS: 16000	MIN: 0.222ms	AVG: 1.072ms	MAX: 578.273ms	TOTAL: 17157.497ms
P99: 2.063ms	P95: 1.489ms	P50: 0.782ms	SD: 90527.786	RATIO: 4.082%
+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+
>>>>> VIRTUAL USER 4 : ELAPSED TIME : 419788ms
>>>>> PROC: NEWORD
CALLS: 171907	MIN: 0.439ms	AVG: 0.970ms	MAX: 1013.525ms	TOTAL: 166696.636ms
P99: 2.488ms	P95: 1.342ms	P50: 0.833ms	SD: 40049.741	RATIO: 39.710%
>>>>> PROC: PAYMENT
CALLS: 171395	MIN: 0.348ms	AVG: 0.825ms	MAX: 2027.276ms	TOTAL: 141448.137ms
P99: 2.309ms	P95: 1.353ms	P50: 0.669ms	SD: 59576.289	RATIO: 33.695%
>>>>> PROC: DELIVERY
CALLS: 17242	MIN: 1.292ms	AVG: 2.783ms	MAX: 1662.594ms	TOTAL: 47976.469ms
P99: 5.314ms	P95: 3.614ms	P50: 2.487ms	SD: 145408.189	RATIO: 11.429%
>>>>> PROC: SLEV
CALLS: 17149	MIN: 0.637ms	AVG: 1.911ms	MAX: 1053.436ms	TOTAL: 32775.092ms
P99: 2.231ms	P95: 1.805ms	P50: 1.319ms	SD: 169897.509	RATIO: 7.808%
>>>>> PROC: OSTAT
CALLS: 17379	MIN: 0.221ms	AVG: 1.076ms	MAX: 385.704ms	TOTAL: 18699.482ms
P99: 2.059ms	P95: 1.463ms	P50: 0.754ms	SD: 82806.139	RATIO: 4.455%
+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+
>>>>> VIRTUAL USER 5 : ELAPSED TIME : 419663ms
>>>>> PROC: NEWORD
CALLS: 171092	MIN: 0.424ms	AVG: 0.967ms	MAX: 1229.934ms	TOTAL: 165440.937ms
P99: 2.408ms	P95: 1.356ms	P50: 0.839ms	SD: 43716.072	RATIO: 39.422%
>>>>> PROC: PAYMENT
CALLS: 171379	MIN: 0.331ms	AVG: 0.829ms	MAX: 1731.137ms	TOTAL: 142134.192ms
P99: 2.240ms	P95: 1.372ms	P50: 0.676ms	SD: 66909.786	RATIO: 33.869%
>>>>> PROC: DELIVERY
CALLS: 17376	MIN: 1.333ms	AVG: 2.711ms	MAX: 522.322ms	TOTAL: 47110.423ms
P99: 5.066ms	P95: 3.665ms	P50: 2.502ms	SD: 55115.193	RATIO: 11.226%
>>>>> PROC: SLEV
CALLS: 17000	MIN: 0.677ms	AVG: 2.060ms	MAX: 638.143ms	TOTAL: 35019.365ms
P99: 2.227ms	P95: 1.820ms	P50: 1.324ms	SD: 181337.117	RATIO: 8.345%
>>>>> PROC: OSTAT
CALLS: 17393	MIN: 0.230ms	AVG: 1.028ms	MAX: 416.741ms	TOTAL: 17880.809ms
P99: 2.069ms	P95: 1.485ms	P50: 0.765ms	SD: 78776.046	RATIO: 4.261%
+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+
>>>>> VIRTUAL USER 6 : ELAPSED TIME : 418748ms
>>>>> PROC: NEWORD
CALLS: 156981	MIN: 0.440ms	AVG: 1.046ms	MAX: 1612.589ms	TOTAL: 164162.970ms
P99: 2.758ms	P95: 1.525ms	P50: 0.882ms	SD: 63714.779	RATIO: 39.203%
>>>>> PROC: PAYMENT
CALLS: 157020	MIN: 0.351ms	AVG: 0.895ms	MAX: 2026.866ms	TOTAL: 140488.701ms
P99: 2.654ms	P95: 1.525ms	P50: 0.719ms	SD: 61228.592	RATIO: 33.550%
>>>>> PROC: DELIVERY
CALLS: 15770	MIN: 1.383ms	AVG: 3.498ms	MAX: 788.532ms	TOTAL: 55159.762ms
P99: 7.326ms	P95: 5.431ms	P50: 3.250ms	SD: 66690.551	RATIO: 13.173%
>>>>> PROC: SLEV
CALLS: 15797	MIN: 0.670ms	AVG: 1.947ms	MAX: 583.215ms	TOTAL: 30754.041ms
P99: 2.723ms	P95: 1.898ms	P50: 1.380ms	SD: 152847.699	RATIO: 7.344%
>>>>> PROC: OSTAT
CALLS: 15976	MIN: 0.238ms	AVG: 1.024ms	MAX: 343.665ms	TOTAL: 16364.749ms
P99: 2.089ms	P95: 1.527ms	P50: 0.790ms	SD: 63035.213	RATIO: 3.908%
+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+
>>>>> SUMMARY OF 5 ACTIVE VIRTUAL USERS : MEDIAN ELAPSED TIME : 419788ms
>>>>> PROC: NEWORD
CALLS: 829204	MIN: 0.424ms	AVG: 0.998ms	MAX: 1643.139ms	TOTAL: 827932.303ms
P99: 2.542ms	P95: 1.419ms	P50: 0.854ms	SD: 49988.460	RATIO: 39.445%
>>>>> PROC: PAYMENT
CALLS: 829942	MIN: 0.331ms	AVG: 0.856ms	MAX: 2027.278ms	TOTAL: 710313.076ms
P99: 2.412ms	P95: 1.424ms	P50: 0.690ms	SD: 63696.833	RATIO: 33.841%
>>>>> PROC: DELIVERY
CALLS: 83484	MIN: 1.272ms	AVG: 3.010ms	MAX: 1662.596ms	TOTAL: 251280.909ms
P99: 6.723ms	P95: 4.607ms	P50: 2.694ms	SD: 78650.494	RATIO: 11.972%
>>>>> PROC: SLEV
CALLS: 82818	MIN: 0.617ms	AVG: 1.965ms	MAX: 1053.437ms	TOTAL: 162755.356ms
P99: 2.419ms	P95: 1.851ms	P50: 1.341ms	SD: 166238.802	RATIO: 7.754%
>>>>> PROC: OSTAT
CALLS: 83936	MIN: 0.213ms	AVG: 1.047ms	MAX: 578.273ms	TOTAL: 87892.997ms
P99: 2.067ms	P95: 1.488ms	P50: 0.772ms	SD: 79101.309	RATIO: 4.187%
+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+

greenhal · 2021-04-02T17:41:36Z

Request.. option to output in json format.

sm-shaw · 2021-04-03T08:57:24Z

Json format won't make it into v4.1. However all the functionality to store output in a SQLite database and convert output to Json is already in the web service/hammerdbws interface, so SQLite and Json formatting is already implemented. Of course this feature is not enabled for the WS because it outputs to a separate log file for now. Similarly, there is also a new logfile for output of the transaction counter #215 this also is not enabled for the web service for the same reason.

The key question is how much usage is the existing Web Service interface seeing compared to the GUI/CLI? (It would be useful to get feedback from anyone using it).

The potential (and existing functionality) is there to enable the database for all interfaces, store all output there (including the time profiling) and allow retrieval by CLI or HTTP into text or Json format related to a JOBID (as the WS does now). There has also been a long term plan to implement storing the configuration in this database as well.

Issue #3 is the placeholder for this plan. More design/planning work is needed however this would be the way to enable Json output, for example deprecate the existing WS and enable the functionality in the CLI/GUI to start a web service for additional HTTP querying and Json output retrieval from a SQLite repository without adding additional complexity for GUI and CLI users.

sm-shaw · 2021-04-03T09:27:26Z

Issue #145 also related to this requested functionality

Extended Time Profiling as per Issue #224

sm-shaw · 2021-10-13T17:37:37Z

Functionality to output timing data as JSON has been added to the web service as detailed in #145. The key addition is adding the CLI functionality to the web service (rather than the other way around) so that the same scripts can be run in CLI with output as text to stdout or in the webservice with output to a SQLite repository than can then be queried with a jobs command to retrieve the output and data related to the job.

hammerws>job 616714C1663403E243430363&timing&vu=2

{
  "NEWORD": {
    "elapsed_ms": "179958.0",
    "calls": "98551",
    "min_ms": "0.426",
    "avg_ms": "0.712",
    "max_ms": "365.634",
    "total_ms": "70153.878",
    "p99_ms": "1.286",
    "p95_ms": "0.927",
    "p50_ms": "0.681",
    "sd": "14706.473",
    "ratio_pct": "38.983"
  },
  "PAYMENT": {
    "elapsed_ms": "179958.0",
    "calls": "99103",
    "min_ms": "0.338",
    "avg_ms": "0.608",
    "max_ms": "124.76",
    "total_ms": "60229.165",
    "p99_ms": "1.32",
    "p95_ms": "1.033",
    "p50_ms": "0.555",
    "sd": "9058.897",
    "ratio_pct": "33.468"
  },
  "DELIVERY": {
    "elapsed_ms": "179958.0",
    "calls": "9937",
    "min_ms": "1.277",
    "avg_ms": "2.385",
    "max_ms": "908.634",
    "total_ms": "23701.627",
    "p99_ms": "3.836",
    "p95_ms": "3.117",
    "p50_ms": "2.248",
    "sd": "91170.719",
    "ratio_pct": "13.171"
  },
  "SLEV": {
    "elapsed_ms": "179958.0",
    "calls": "9834",
    "min_ms": "0.659",
    "avg_ms": "1.283",
    "max_ms": "312.497",
    "total_ms": "12621.653",
    "p99_ms": "1.329",
    "p95_ms": "1.032",
    "p50_ms": "0.838",
    "sd": "83145.556",
    "ratio_pct": "7.014"
  },
  "OSTAT": {
    "elapsed_ms": "179958.0",
    "calls": "9903",
    "min_ms": "0.208",
    "avg_ms": "0.814",
    "max_ms": "166.088",
    "total_ms": "8056.104",
    "p99_ms": "1.546",
    "p95_ms": "1.231",
    "p50_ms": "0.647",
    "sd": "39393.981",
    "ratio_pct": "4.477"
  }
}

sm-shaw linked a pull request Apr 2, 2021 that will close this issue

Extended Time Profiling as per Issue #224 #225

Merged

abondvt89 closed this as completed in #225 Apr 6, 2021

abondvt89 added a commit that referenced this issue Apr 6, 2021

Merge pull request #225 from sm-shaw/224

d0b2633

Extended Time Profiling as per Issue #224

sm-shaw mentioned this issue Apr 14, 2021

Exclude ramp up duration for time profiling #233

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Extended Time Profiling #224

Extended Time Profiling #224

sm-shaw commented Apr 1, 2021

sm-shaw commented Apr 2, 2021

greenhal commented Apr 2, 2021

sm-shaw commented Apr 3, 2021

sm-shaw commented Apr 3, 2021

sm-shaw commented Oct 13, 2021

Extended Time Profiling #224

Extended Time Profiling #224

Comments

sm-shaw commented Apr 1, 2021

sm-shaw commented Apr 2, 2021

greenhal commented Apr 2, 2021

sm-shaw commented Apr 3, 2021

sm-shaw commented Apr 3, 2021

sm-shaw commented Oct 13, 2021