Issue with Profiling Workloads in HammerDB Using xtprof Module

[Sheharyar570]

Hi HammerDB Team,
I'm working on a setup where I’m trying to distribute two workloads (one of which is standard tpcc workload) between virtual users (VUs). I'm using the xtprof module to profile each function that makes a database call.
I've added a new function e.g. that makes the database call for the new workload that I'm trying to run.
Here’s how my code is structured:
workloads: There are 2 workloads I'm trying to run in parrallel, one of which is standard TPCC workload.
workload1vus: The number of VUs that will handle execution of workload 1 (Could be standard TPCC workload).

if {$myposition eq 1} {
    # monitor thread
} elseif { $myposition <= $workload1vus } {
    # workload1
} else {
    # workload2
}

The issue I'm facing is that only the VUs assigned to the last code block (workload2) are reporting back to the monitor thread or are being profiled. VUs in the workload1 block do not seem to be getting profiled.
Below is a snippet of the relevant code:

set rema [ lassign [ findvuposition ] myposition totalvirtualusers ]
set workload1vu [expr 0.8 * [expr $totalvirtualusers - 1]]

if {$myposition == 1} {
    # Monitoring and ramp-up logic here
} elseif {$myposition <= $workload1vu} {
    # Logic for workload1 (One of which is standard TPCC workload)
} else {
    # Logic for workload2
}

Only the VUs that fall into the last block (i.e., workload2) are getting profiled, but not functions related to workload1.
Virtual user 1, the monitor thread, fails to complete while waiting for other virtual users to report the timings and the stats are not written in the log file.
Although, I've verified that both workloads are distributed according to the condition and queries related to both workloads are made to the DB. Only problem is one set of function is profiled and the other is not.
All other VUs successfully complete their run, except for VU 1.
Note: Only the else block is being profiled irrespective of the workload it handles.
Could you help me identify what might be causing this issue? Any insights would be greatly appreciated.

[sm-shaw]

Firstly note that there is another time profiler package called etprof that is a bit more generic. xtprof is specifically for the TPROC-C workload and captures timings for the 5 workload transactions. (etprof records everything in a proc).

Loading the xtprof package initialises the timing for all virtual users. However VU1 the monitor virtual user does the timing so is excluded. Instead VU1 gathers and calculates the timings from all virtual users when the workload has finished with the xttimeproflog command. The virtual users report their own timings with xtreport that are gathered by VU1. (To be clear VU1 does not do any timing as it does not run the workload).
so when you load time profiling, it adds the following 3 lines. The first line for all VUs, the 2nd for VU1 and the 3rd for all other VUs.

if [catch {package require xtprof} ] { error "Failed to load extended time profile functions" } else { namespace import xtprof::* }
xttimeproflog $totalvirtualusers $library
xtreport $myposition

So when we run the workload with timing available, you can see the additional timing steps in the output.

"0",
"Vuser 1:RUNNING",
"1",
"Initializing xtprof time profiler",
"1",
"Ssl_cipher {}",
"1",
"DBVersion:10.8.1",
"1",
"Beginning rampup time of 2 minutes",
"0",
"Vuser 2:RUNNING",
"2",
"Initializing xtprof time profiler",
"2",
"Ssl_cipher {}",
"2",
"Processing 10000000 transactions with output suppressed...",
"0",
"Vuser 3:RUNNING",
"3",
"Initializing xtprof time profiler",
"3",
"Ssl_cipher {}",
"3",
"Processing 10000000 transactions with output suppressed...",
"0",
"Vuser 4:RUNNING",
"4",
"Initializing xtprof time profiler",
"4",
"Ssl_cipher {}",
"4",
"Processing 10000000 transactions with output suppressed...",
"0",
"Vuser 5:RUNNING",
"5",
"Initializing xtprof time profiler",
"5",
"Ssl_cipher {}",
"5",
"Processing 10000000 transactions with output suppressed...",
"1",
"Rampup 1 minutes complete ...",
"1",
"Rampup 2 minutes complete ...",
"1",
"Rampup complete, Taking start Transaction Count.",
"1",
"Timing test period of 5 in minutes",
"1",
"1  ...,",
"1",
"2  ...,",
"1",
"3  ...,",
"1",
"4  ...,",
"1",
"5  ...,",
"1",
"Test complete, Taking end Transaction Count.",
"1",
"4 Active Virtual Users configured",
"1",
"TEST RESULT : System achieved 33510 NOPM from 77782 MariaDB TPM",
"1",
"Gathering timing data from Active Virtual Users...",
"0",
"Vuser 2:FINISHED SUCCESS",
"0",
"Vuser 3:FINISHED SUCCESS",
"0",
"Vuser 5:FINISHED SUCCESS",
"0",
"Vuser 4:FINISHED SUCCESS",
"1",
"Calculating timings...",
"1",
"Writing timing data to /tmp/hdbxtprofile.log",
"0",
"Vuser 1:FINISHED SUCCESS",
"0",
"ALL VIRTUAL USERS COMPLETE"

in the CLI you can drill down into the timings

hammerdb>job 66BF22C461FC03E243231393 timing
{
  "NEWORD": {
    "elapsed_ms": "418829.0",
    "calls": "62731",
    "min_ms": "1.189",
    "avg_ms": "3.663",
    "max_ms": "175.377",
    "total_ms": "229758.842",
    "p99_ms": "11.041",
    "p95_ms": "6.077",
    "p50_ms": "3.353",
    "sd": "2511.627",
    "ratio_pct": "54.857"
  },
  "PAYMENT": {
    "elapsed_ms": "418829.0",
    "calls": "62763",
    "min_ms": "0.591",
    "avg_ms": "1.575",
    "max_ms": "163.811",
    "total_ms": "98840.134",
    "p99_ms": "5.886",
    "p95_ms": "3.119",
    "p50_ms": "1.32",
    "sd": "1700.102",
    "ratio_pct": "23.599"
  },
  "DELIVERY": {
    "elapsed_ms": "418829.0",
    "calls": "6396",
    "min_ms": "4.125",
    "avg_ms": "9.606",
    "max_ms": "197.788",
    "total_ms": "61442.519",
    "p99_ms": "25.916",
    "p95_ms": "14.007",
    "p50_ms": "8.684",
    "sd": "5782.097",
    "ratio_pct": "14.67"
  },
  "SLEV": {
    "elapsed_ms": "418829.0",
    "calls": "6275",
    "min_ms": "0.862",
    "avg_ms": "1.879",
    "max_ms": "25.233",
    "total_ms": "11793.488",
    "p99_ms": "6.055",
    "p95_ms": "3.171",
    "p50_ms": "1.645",
    "sd": "1070.749",
    "ratio_pct": "2.816"
  },
  "OSTAT": {
    "elapsed_ms": "418829.0",
    "calls": "6219",
    "min_ms": "0.57",
    "avg_ms": "1.491",
    "max_ms": "82.048",
    "total_ms": "9271.712",
    "p99_ms": "6.18",
    "p95_ms": "2.813",
    "p50_ms": "1.214",
    "sd": "2145.64",
    "ratio_pct": "2.214"
  }
}

The web service will graph the timings.