Performance issues with async clients on linux

[alfer-aws]

I realized that when keyandthink is flagged and async_clients are used, there is a huge difference in performance between MSSQL and Oracle database. (same VU and driver settings)

For MSSQL, when the benchmark starts running all the async_clients get into the database respecting the async_delay given in the script while for Oracle it seems like there is a delay and so the clients take much much longer to connect. (approx 2 connections per second)

Being more specific it looks like the 'promise' package withing the 'switch' code section behaves differently when Oracle is selected as a target introducing a delay which results in a not-consistent test as the clients connect to the DB not following the async_delay setting.

I troubleshooted this issue and figured out it is not related to network latency, oracle client version or database parameters.

However, I created a custom script where the 'switch' section was left out so only the promise package was making the async connections and in this scenario i haven't noticed any delay. The clients connect to the database following the async delay setting as expected.

I also tried to move out from the switch section all the procedures and leave just the TPC-C code execution but it didn't make any difference.

I have attached the scripts to reproduce the issue.

Hammerdb_keyandthink_ora.txt
HammerDB_noswitch_ora.txt

[sm-shaw]

Many thanks for the question. So I have done some verification/troubleshooting comparing Oracle and SQL Server below for the asynchronous connections with the findings as below.

At the outset as TPROC-C is derived from TPC-C when running with asynchronous clients the expected performance should be similar to what is defined in the TPC-C specification as this uses keying and thinking time with TPROC-C set to the same key and think values. So from the specification, we have 10 virtual users per warehouse (For each active warehouse in the database, the SUT must accept requests for transactions from a population of 10 terminals.) and per warehouse 9-12.86 tpmC - so as a rough guideline for TPROC-C we should be expecting 'around' 1 NOPM per asynchronous connection.

So as a first test I configured both Oracle and SQL Server on the same PC (using Virtual Box for Oracle) and ran 1 Virtual User with 10 asynchronous clients - this should give 'around' 1 NOPM per client (or more accurate in the 9-13 range). as below this is what I saw.

Hammerdb Log @ Fri Oct 08 05:17:09 EDT 2021
+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-
Vuser 1:Beginning rampup time of 1 minutes
Vuser 2:Delaying login of vuser2:ac1 for 1000 ms
Vuser 2:Delaying login of vuser2:ac2 for 2000 ms
Vuser 2:Delaying login of vuser2:ac3 for 3000 ms
Vuser 2:Delaying login of vuser2:ac4 for 4000 ms
Vuser 2:Delaying login of vuser2:ac5 for 5000 ms
Vuser 2:Delaying login of vuser2:ac6 for 6000 ms
Vuser 2:Delaying login of vuser2:ac7 for 7000 ms
Vuser 2:Delaying login of vuser2:ac8 for 8000 ms
Vuser 2:Delaying login of vuser2:ac9 for 9000 ms
Vuser 2:Delaying login of vuser2:ac10 for 10000 ms
Vuser 2:Started asynchronous clients:vuser2:ac1 vuser2:ac2 vuser2:ac3 vuser2:ac4 vuser2:ac5 vuser2:ac6 vuser2:ac7 vuser2:ac8 vuser2:ac9 vuser2:ac10
...
Vuser 1:1 VU * 10 AC = 10 Active Sessions configured
Vuser 1:TEST RESULT : System achieved 13 NOPM from 32 Oracle TPM


Hammerdb Log @ Fri Oct 08 10:56:51 BST 2021
+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-
Vuser 1:Beginning rampup time of 1 minutes
Vuser 2:Delaying login of vuser2:ac1 for 1000 ms
Vuser 2:Delaying login of vuser2:ac2 for 2000 ms
Vuser 2:Delaying login of vuser2:ac3 for 3000 ms
Vuser 2:Delaying login of vuser2:ac4 for 4000 ms
Vuser 2:Delaying login of vuser2:ac5 for 5000 ms
Vuser 2:Delaying login of vuser2:ac6 for 6000 ms
Vuser 2:Delaying login of vuser2:ac7 for 7000 ms
Vuser 2:Delaying login of vuser2:ac8 for 8000 ms
Vuser 2:Delaying login of vuser2:ac9 for 9000 ms
Vuser 2:Delaying login of vuser2:ac10 for 10000 ms
Vuser 2:Started asynchronous clients:vuser2:ac1 vuser2:ac2 vuser2:ac3 vuser2:ac4 vuser2:ac5 vuser2:ac6 vuser2:ac7 vuser2:ac8 vuser2:ac9 vuser2:ac10
...
Vuser 1:1 VU * 10 AC = 10 Active Sessions configured
Vuser 1:TEST RESULT : System achieved 12 NOPM from 33 SQL Server TPM

Doubling the number of asynchronous clients also gives us consistent results within expectations as follows

Hammerdb Log @ Fri Oct 08 05:32:23 EDT 2021
+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-
Vuser 1:Beginning rampup time of 1 minutes
Vuser 2:Delaying login of vuser2:ac1 for 1000 ms
Vuser 2:Delaying login of vuser2:ac2 for 2000 ms
Vuser 2:Delaying login of vuser2:ac3 for 3000 ms
Vuser 2:Delaying login of vuser2:ac4 for 4000 ms
Vuser 2:Delaying login of vuser2:ac5 for 5000 ms
Vuser 2:Delaying login of vuser2:ac6 for 6000 ms
Vuser 2:Delaying login of vuser2:ac7 for 7000 ms
Vuser 2:Delaying login of vuser2:ac8 for 8000 ms
Vuser 2:Delaying login of vuser2:ac9 for 9000 ms
Vuser 2:Delaying login of vuser2:ac10 for 10000 ms
Vuser 2:Delaying login of vuser2:ac11 for 11000 ms
Vuser 2:Delaying login of vuser2:ac12 for 12000 ms
Vuser 2:Delaying login of vuser2:ac13 for 13000 ms
Vuser 2:Delaying login of vuser2:ac14 for 14000 ms
Vuser 2:Delaying login of vuser2:ac15 for 15000 ms
Vuser 2:Delaying login of vuser2:ac16 for 16000 ms
Vuser 2:Delaying login of vuser2:ac17 for 17000 ms
Vuser 2:Delaying login of vuser2:ac18 for 18000 ms
Vuser 2:Delaying login of vuser2:ac19 for 19000 ms
Vuser 2:Delaying login of vuser2:ac20 for 20000 ms
Vuser 2:Started asynchronous clients:vuser2:ac1 vuser2:ac2 vuser2:ac3 vuser2:ac4 vuser2:ac5 vuser2:ac6 vuser2:ac7 vuser2:ac8 vuser2:ac9 vuser2:ac10 vuser2:ac11 vuser2:ac12 vuser2:ac13 vuser2:ac14 vuser2:ac15 vuser2:ac16 vuser2:ac17 vuser2:ac18 vuser2:ac19 vuser2:ac20
...
Vuser 1:1 VU * 20 AC = 20 Active Sessions configured
Vuser 1:TEST RESULT : System achieved 25 NOPM from 59 Oracle TPM

Hammerdb Log @ Fri Oct 08 11:03:03 BST 2021
+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-
Vuser 1:Beginning rampup time of 1 minutes
Vuser 2:Delaying login of vuser2:ac1 for 1000 ms
Vuser 2:Delaying login of vuser2:ac2 for 2000 ms
Vuser 2:Delaying login of vuser2:ac3 for 3000 ms
Vuser 2:Delaying login of vuser2:ac4 for 4000 ms
Vuser 2:Delaying login of vuser2:ac5 for 5000 ms
Vuser 2:Delaying login of vuser2:ac6 for 6000 ms
Vuser 2:Delaying login of vuser2:ac7 for 7000 ms
Vuser 2:Delaying login of vuser2:ac8 for 8000 ms
Vuser 2:Delaying login of vuser2:ac9 for 9000 ms
Vuser 2:Delaying login of vuser2:ac10 for 10000 ms
Vuser 2:Delaying login of vuser2:ac11 for 11000 ms
Vuser 2:Delaying login of vuser2:ac12 for 12000 ms
Vuser 2:Delaying login of vuser2:ac13 for 13000 ms
Vuser 2:Delaying login of vuser2:ac14 for 14000 ms
Vuser 2:Delaying login of vuser2:ac15 for 15000 ms
Vuser 2:Delaying login of vuser2:ac16 for 16000 ms
Vuser 2:Delaying login of vuser2:ac17 for 17000 ms
Vuser 2:Delaying login of vuser2:ac18 for 18000 ms
Vuser 2:Delaying login of vuser2:ac19 for 19000 ms
Vuser 2:Delaying login of vuser2:ac20 for 20000 ms
Vuser 2:Started asynchronous clients:vuser2:ac1 vuser2:ac2 vuser2:ac3 vuser2:ac4 vuser2:ac5 vuser2:ac6 vuser2:ac7 vuser2:ac8 vuser2:ac9 vuser2:ac10 vuser2:ac11 vuser2:ac12 vuser2:ac13 vuser2:ac14 vuser2:ac15 vuser2:ac16 vuser2:ac17 vuser2:ac18 vuser2:ac19 vuser2:ac20

Vuser 1:1 VU * 20 AC = 20 Active Sessions configured
Vuser 1:TEST RESULT : System achieved 27 NOPM from 63 SQL Server TPM

I've seen results with 10,000 connections delivering around 10,000 NOPM, so the results are also consistent in a server environment.

Doing a diff on the attached files the async delay is different and is set to 1 and 30 - note that this is in milliseconds, so 1 second would be 1000 and 30 seconds 30000. It could therefore be possible that there is a login storm taking place and somewhere in the Oracle configuration it is throttling the connections. By default, as above in the logs each asynchronous client will wait for a second before attempting to login after the previous one.

For the diff between the files removes the switch statement, the first part that has been removed is for the monitor virtual user so this one does the timing, however this is the only one that uses the system connection so it could be possible that there is an error using higher privileges.

To troubleshoot further I would suggest using the steps as above (Its the same in the GUI and/or CLI) to see if the throughput is expected for 1 virtual users with 10 then 20 asynchronous clients with a minimum of 1000 async delay (this is not fixed just in case you want to test a login storm) and logging the output. If this is not as expected we can investigate further. In particular the scripts are edited inline when selecting options such as use all warehouses and asynchronous so we can't rule out a clash between some of these options but firstly if you follow the steps above we can take it from there.

[alfer-aws]

Thanks for the detailed reply Steve.

The effect i was experiencing was more related to the login phase, my initial question was incorrect as i should have specified the "wrong" behavior was on a linux driver connected to an Oracle database while a driver on windows was doing just fine.

Diving deep into the issue i observed there was a refresh delay, eg. adding a puts just printing out the current timestamp i was getting timestamps with 1 second delay which pointed me to the runtimer procedure which has a 1 second update time:

set x 0
set timerstop 0
while {!$timerstop} {
 incr x
 after 1000
  if { ![ expr {$x % 60} ] } {
  set y [ expr $x / 60 ]
  puts "Timer: $y minutes elapsed"
  }
 update
 if {  [ vucomplete ] || $x eq $seconds } { set timerstop 1 }
    }
return
}

This procedure used to be inside our framework for linux driver and looking at the more recent code i found out the proc above is out of date, the new one is:

upvar elapsed elapsed
upvar timevar timevar
proc runtimer_loop { seconds } {
upvar elapsed elapsed
incr elapsed
upvar timevar timevar
set rcomplete [vucomplete]
  if { ![ expr {$elapsed % 60} ] } {
  set y [ expr $elapsed / 60 ]
  putscli "Timer: $y minutes elapsed"
  }
if {!$rcomplete && $elapsed < $seconds } {
;#Neither vucomplete or time reached, reschedule loop
catch {after 1000 runtimer_loop $seconds }} else {
putscli "runtimer returned after $elapsed seconds"
set elapsed 0
set timevar 1
        }
}
set elapsed 0
set timevar 0
runtimer_loop $seconds
vwait timevar
return
}

The first piece of code was the root cause of the issue, basically it was keeping control of the flow so the script was constantly making context switches and few connections were able to get into the database between each interrupt.

The most up to date version of that procedure doesn't block the flow control and connections are getting into the database consistently with the async_delay parameter.

Thanks for the effort checking on this
Alessandro

[sm-shaw]

Alessandro,

Great, I am glad it is resolved. Yes, runtimer is now built in. I realised it was being used in most scripts to keep the main thread alive and therefore it made sense to add it and this was the Issue to make it asynchronous.

Improve CLI runtimer by making asynchronous #179.

the key difference are these 2 lines:

this blocks after 1000
and this does doesn't after 1000 runtimer_loop $seconds

Therefore it makes sense the issue you saw, when there is a lot of output the first one will block the main loop for writing it out and the second doesn't.

Steve