VU1 Fails to Take AWR Snapshot at the end of TPCC Test for Oracle

[enhaocui]

Hi, I am running hammerdbcli v4.6 in a container for TPCC test on Oracle. The monitor VU fails to take the end AWR snapshot. This happens quite consistently. I thought it was some problem with the DB, however the VU has always been able to take the start AWR snapshot. I also tried taking snapshot on the DB with sqlplus during the test, and it always succeeds. So this problem does not seem to be DB issue.

The HammerDB image is built from v4.6-docker

From the logs I cannot find any useful info. It just shows "VU1 finished FAILED". It appears VU1 was somehow "killed" silently. The transaction counter is working as expected, though.

print dict: 
tpcc       {
 count_ware       = 306
 num_vu           = 32
 tpcc_user        = tpcc
 tpcc_pass        = xxx
 tpcc_def_tab     = xxx
 tpcc_ol_tab      = xxx
 tpcc_def_temp    = temp
 partition        = false
 hash_clusters    = false
 tpcc_tt_compat   = false
 total_iterations = 10000000
 raiseerror       = false
 keyandthink      = false
 checkpoint       = false
 ora_driver       = timed
 rampup           = 3
 duration         = 15
 allwarehouse     = true
 ora_timeprofile  = true
 async_scale      = false
 async_client     = 10
 async_verbose    = false
 async_delay      = 1000
 connect_pool     = false
}

Start snapshot taken successfully:

^M7506 Oracle tpm
^M29982 Oracle tpm
^M25626 Oracle tpm
^M34140 Oracle tpm
^M40998 Oracle tpm
^M22596 Oracle tpm
^MVuser 1:Rampup 3 minutes complete ...
^MVuser 1:Rampup complete, Taking start AWR snapshot.
^M32478 Oracle tpm
^M34686 Oracle tpm
^MVuser 1:Start Snapshot 1 taken at 07 JUN 2023 04:01 of instance xxx (1) of database xxx (2300961451)
^MVuser 1:Timing test period of 15 in minutes
^M26298 Oracle tpm
^M35040 Oracle tpm
^M36498 Oracle tpm
^M35688 Oracle tpm

End snapshot cannot be taken, VU1 failed:

^MVuser 1:14 ...,
^M41016 Oracle tpm
^M47316 Oracle tpm
^M53262 Oracle tpm
^M34992 Oracle tpm
^M44712 Oracle tpm
^M46488 Oracle tpm
^MVuser 1:15 ...,
^MVuser 1:Test complete, Taking end AWR snapshot.
^M43116 Oracle tpm
^MVuser 2:FINISHED SUCCESS
^MVuser 23:FINISHED SUCCESS
^MVuser 33:FINISHED SUCCESS
^MVuser 4:FINISHED SUCCESS
^MVuser 15:FINISHED SUCCESS
^MVuser 3:FINISHED SUCCESS
^MVuser 10:FINISHED SUCCESS
^MVuser 31:FINISHED SUCCESS
^MVuser 22:FINISHED SUCCESS
^MVuser 16:FINISHED SUCCESS
^MVuser 25:FINISHED SUCCESS
^MVuser 14:FINISHED SUCCESS
^MVuser 9:FINISHED SUCCESS
^MVuser 21:FINISHED SUCCESS
^MVuser 27:FINISHED SUCCESS
^MVuser 20:FINISHED SUCCESS
^MVuser 6:FINISHED SUCCESS
^MVuser 26:FINISHED SUCCESS
^MVuser 13:FINISHED SUCCESS
^M46674 Oracle tpm
^MVuser 18:FINISHED SUCCESS
^MVuser 5:FINISHED SUCCESS
^MVuser 12:FINISHED SUCCESS
^MVuser 30:FINISHED SUCCESS
^MVuser 32:FINISHED SUCCESS
^MVuser 1:FINISHED FAILED  <------------------------ VU1 FAILED
^MVuser 24:FINISHED SUCCESS
^MVuser 17:FINISHED SUCCESS
^MVuser 8:FINISHED SUCCESS
^MVuser 7:FINISHED SUCCESS
^MVuser 28:FINISHED SUCCESS
^MVuser 19:FINISHED SUCCESS
^MVuser 29:FINISHED SUCCESS
^MVuser 11:FINISHED SUCCESS
^MALL VIRTUAL USERS COMPLETE
^Mvudestroy success
^MTransaction Counter thread running with threadid:tid0x7f93b2ffd700
^MStopping Transaction Counter
^MClosed Transaction Counter Log
^MTPCC test finished.
Jobid written to file

[enhaocui]

Also attaching the part of the log that shows start snapshot taken successfully:

^M7506 Oracle tpm
^M29982 Oracle tpm
^M25626 Oracle tpm
^M34140 Oracle tpm
^M40998 Oracle tpm
^M22596 Oracle tpm
^MVuser 1:Rampup 3 minutes complete ...
^MVuser 1:Rampup complete, Taking start AWR snapshot.
^M32478 Oracle tpm
^M34686 Oracle tpm
^MVuser 1:Start Snapshot 1 taken at 07 JUN 2023 04:01 of instance xxx (1) of database xxx (2300961451)
^MVuser 1:Timing test period of 15 in minutes
^M26298 Oracle tpm
^M35040 Oracle tpm
^M36498 Oracle tpm
^M35688 Oracle tpm

[sm-shaw]

The first thing to try is to increase the keepalive_margin https://www.hammerdb.com/docs/ch09s03.html
This is set in the generic.xml config file and by default is set to 10 seconds.

 <commandline>
	<sqlite_db>TMP</sqlite_db> 
        <keepalive_margin>10</keepalive_margin>
        <jobsoutput>JSON</jobsoutput>
        <jobs_disable>0</jobs_disable>
    </commandline>

Note that if you have already loaded the XML and have the dynamic config stored in SQLite you will either need to reset by deleting the SQLite files, so the XML is re-read, or you can do this dynamically as below (example extends keepalive to a minute):

hammerdb>dict set genericdict commandline keepalive_margin 60
theme {scaling auto scaletheme auto pixelsperpoint auto} sqlitedb {sqlitedb_dir TMP} code_highlight {highlight true} benchmark {rdbms Oracle bm TPC-C first_result NOPM} virtual_user_options {virtual_users 1 user_delay 500 repeat_delay 500 iterations 1 show_output 1 log_to_temp 0 unique_log_name 0 no_log_buffer 0 log_timestamps 0} autopilot {apmode disabled autopilot_duration 10 autopilot_sequence {1 2 4 8 12 16 20 24}} mode {hostname localhost id 0} transaction_counter {tc_refresh_rate 10 tc_log_to_temp 0 tc_unique_log_name 0 tc_log_timestamps 0 tc_graph_ribbon false} metrics {agent_hostname localhost agent_id 0} datageneration {gen_count_ware 1 gen_scale_fact 1 gen_num_vu 1} commandline {sqlite_db TMP keepalive_margin 60 jobsoutput JSON jobs_disable 0} timeprofile {profiler xtprof xt_unique_log_name 0 xt_gather_timeout 10 xt_job_storage 1} hdb_version {version v4.7} webservice {ws_port 8080}

If the AWR report generation is taking longer than 10 seconds after the rampup + duration time then this could be the cause.
I couldn't reproduce here even with keepalive set to 1 which is the minimum, however this does seem to be the first thing to try.

[enhaocui]

Thanks! This seems to be the issue. After increasing the timeout, it's able to take end snapshot now.

[sm-shaw]

👍