Category: Uncategorized

If you are new to running Oracle, SQL Server, MySQL and PostgreSQL TPC-C workloads with HammerDB and have needed to investigate I/O performance the chances are that you have experienced waits on writing to the Redo, Transaction Log or WAL depending on the database you are testing. This post at an entry-level discusses the options you have to improve log throughput in your benchmark environment. 

Note that the parameters in this article do have the potential to cause data loss if implemented on your production database without full understanding so ensure that you have read this post in its entirety before applying the settings to your environment. 

Logging Waits

Firstly we’ll take a look at why these log waits are so important to database performance in an OLTP environment. The diagram below shows a much simplified way how the I/O in a typical relational database operates.

Before  the database is started your data should  be in a consistent state on disk. When the database is started a component of the in-memory database instance is the data buffer. As data is requested (depending on the type of read), data blocks will be fetched and stored in-memory in this buffer, show in-blue.  Over time your workload will modify this data, shown in-red, however these changed data blocks or pages are not written back to the data disk immediately. In fact a single block or page may be modified in-memory multiple times before it is eventually at some point in-time written back to the data disk. In contrast to many people’s understanding of a traditional database against an “in-memory” database it is likely that if the buffer is large enough most of the data you are operating on remains in-memory for the duration of a HammerDB OLTP test. Therefore you are likely to see a spike of reads at the start of the test (this is why there is ramp-up time) and then potentially depending on your configuration the data disk can be relatively quiet for the duration of the test while periodically seeing write activities related to checkpoints (which will be discussed later). 

However it should be clear that in the case of a failure such as a crash of the database all of the data in-memory would be lost.  Therefore you have the redo, transaction or write-ahead log recording all of the changes to the database. Typically we will see a constant stream of write activity to this disk with no (or minimal) read activity.  If there is a failure of the database, subsequently on startup this log will be used to recover the data on the data disk up to the point of the most recent transaction (or the chosen recovery point) i.e. replaying all of those changes in-memory that we lost. To recover right up to the most recent point those writes to the log needed to be synchronous i.e. when a transaction is committed the session waits until the database has confirmed that the changes have been recorded to the log before continuing work.  Note that this does not mean that the log is only written at the time of a commit, changes will be streamed into an in-memory log buffer and written to the log disk constantly however once a transaction is committed the user sessions will wait until this log write is confirmed. This wait by the session is what is typically seen as a log wait.  Bear in mind that writing to the log takes CPU, it will be a log writing thread or process that needs CPU time to be scheduled to be active,  it also requires memory for the log buffer and finally disk for the log itself, therefore this log wait is more than just the disk component. Additionally for the log disk component it is latency for an individual write that is crucial rather than the total I/O bandwidth.

As HammerDB supports graphical metrics for Oracle, this provides the best illustration however the concepts apply in general terms to all databases.

Oracle Log File Sync

The following example takes a snapshot of Oracle metrics showing 3 spikes of activity on a consumer level PC running Oracle within a Virtual Box VM for illustration purposes.The database has been created with the default redo log configuration which is 2 redo logs of 200MB in size each.  The first example shows a data load, the second a TPC-C based workload with 5 virtual users and the 2nd example with 10 virtual users.

What can be seen fairly quickly is that the dominant colour is orange and the majority of database time is spent on “log file sync”, waiting for these synchronous writes to the redo log. As the activity is increased with the 2nd run performance is not improved, instead the database is spending more time waiting for the redo log.

To illustrate the data reads on Oracle we can flush the buffer cache.

SQL> alter system flush buffer_cache;

System altered.

SQL>

Re-running the same workload we can now see some blue read activity of “db file sequential read” from index reads at the start of the test, Once our data is buffered this read activity is then diminished as the data in memory is sufficient to sustain the workload that is being run by the rate that it is constrained by “log file sync”.

In this scenario the total throughput is considerably lower than the full potential of the system., so what are  your options?

Making Logging asynchronous

Clearly the most obvious option is to upgrade your log disk I/O capabilities to be able to sustain writes at the level that the test can produce and if running on a production system, this (and investigating your log size and configuration such as using the right disk sector size is the way to go). However what if in a test environment you cannot upgrade the log I/O but want to move beyond the log bottleneck to be able to test other system components more fully.  Fortunately all of the database supported by HammerDB include an option to make the logging asynchronous. In other words we will put our changes in the log buffer, issue a commit but not wait until this is confirmed. Instead we will continue under the assumption that the log write eventually made it to disk.  in this scenario it is possible that in the event of a failure data can be lost but for testing purposes it means we can potentially drive much higher levels of throughput than our log disk can typically sustain, showing the system potential if there were a better performing log configuration. Note however that this is not a solution that will make all log related waits disappear. As noted logging also involves CPU and memory and you will still need to make sure all writes reach the disk, the difference is that you are not flushing to disk synchronously on each commit and therefore are aiming to improve throughput by removing this dependency.

Oracle commit_wait and commit_logging

for Oracle the key parameter is commit_wait. By setting this parameter to NOWAIT the session will not wait for the write to be complete, instead continuing its work once the write has been issued.  This can be complemented by the parameter commit_logging being set to BATCH which groups the individual writes to be written in larger writes. 

These parameters can be set as follows:

SQL> alter system set commit_logging='BATCH' scope=spfile;

System altered.

SQL> alter system set commit_wait='NOWAIT' scope=spfile;

System altered.

Having set these parameters and re-run the previous test it can be seen that the wait events are now very different. In particular log file sync as intended has reduced considerably and been replaced by “db file sequential read” as the top event. Why is this the case? Because we have removed the log sync bottleneck we have now increased the throughput and put emphasis on the amount of data in the buffer that is being read-in and written-out at a much greater rate. Consequently we now need to increase the buffer cache in size if we are to see more CPU activity.  A good example of how tuning is an iterative process.

Checkpoint not complete

in the previous diagram we can also see the wait event log file switch (checkpoint incomplete). Returning to the first illustration it was shown that data will be periodically written to disk, at a checkpoint all of the data on disk is up to date with the same point in the log.  In this example with the default log configuration of 2 redo logs the database is attempting to switch from one log to the other however the checkpoint operation flushing the data from memory to the data disk has not yet caught up with the previous log and to begin writing to it would overwrite changes on the redo log that correspond to this not yet written yet, consequently the database will wait until this operation has been completed.

2018-11-02T15:38:27.662098+00:00
Thread 1 advanced to log sequence 1402 (LGWR switch)
  Current log# 1 seq# 1402 mem# 0: /home/oracle/app/oracle/oradata/VULCDB1/onlinelog/o1_mf_1_fjj87ghr_.log
2018-11-02T15:39:25.628040+00:00
Thread 1 cannot allocate new log, sequence 1403
Checkpoint not complete
  Current log# 1 seq# 1402 mem# 0: /home/oracle/app/oracle/oradata/VULCDB1/onlinelog/o1_mf_1_fjj87ghr_.log
2018-11-02T15:39:29.360911+00:00
Thread 1 advanced to log sequence 1403 (LGWR switch)
  Current log# 2 seq# 1403 mem# 0: /home/oracle/app/oracle/oradata/VULCDB1/onlinelog/o1_mf_2_fjj87gjj_.log

As can be seen this has happened on a consumer PC configuration with the default redo configuration, therefore for higher throughput also ensure that you resize the logs accordingly.

SQL Server DELAYED_DURABILITY

For SQL Server the equivalent parameter for asynchronous logging is set as follows for the parameter DELAYED_DURABILITY

ALTER DATABASE … SET DELAYED_DURABILITY = { DISABLED | ALLOWED | FORCED } 

On the same test system it can be seen that without setting this parameter, Logging is shown as the top resource wait. 

After setting ALTER DATABASE TPCC SET DELAYED_DURABILITY = FORCED  it can be seen that the waits on logging are reduced.

MySQL

For MySQL the dependency is at the storage engine level and in this case for the InnoDB storage engine the parameter is self-explanatory.

innodb_flush_log_at_trx_commit=0

PostgreSQL

Similarly for PostgreSQL logging can be set by setting synchronous_commit to off.

synchronous_commit = off                # synchronization

Summary

This post aims to address what is the most common scenario for someone running HammerDB TPC-C OLTP workloads for the first time when seeing waits on logging disks and what parameters can be set in a test based environment to achieve more throughput and observe what performance potentially could be achieved without a log disk bottleneck. 

Update: There is considerably more efficient method of running HammerDB through a bash script described in a more recent post here:  Running hammerdbcli from a bash or batch script updated for v3.2 It is strongly recommended to move to this method described for v3.2 rather than the method described in this post which can have a greater overhead and a potential impact on performance imposed by bash.

A current FAQ is how to drive the command line hammerdbcli from an external bash script. This post gives an example of one way which this can be done.

For an example we will run a bash script that prints output and then runs hammerdbcli to build an Oracle schema before wating for this to finish and printing more output.  Firstly we need the hammerdbcli script.  Note that as HammerDB is multithreaded, adding exit to the end of a script will cause that script to terminate before virtual users are complete. This is unlikely to be the desired outcome. Therefore you need a function that will wait for the script to complete before issuing the exit. The important command here is vucomplete and you need to wait until the condition of this is “true”. An example of this is as follows:

#!/bin/tclsh
puts "SETTING CONFIGURATION"
global complete
proc wait_to_complete {} {
global complete
set complete [vucomplete]
if {!$complete} {after 5000 wait_to_complete} else { exit }
}
dbset db ora
diset connection system_password oracle
diset connection instance vulpdb1 
diset tpcc count_ware 4
diset tpcc num_vu 4
diset tpcc tpcc_def_tab users
print dict
buildschema
wait_to_complete

This script has been saved as buildora.tcl.  Now we want the driving bash script that looks as follows:

#!/bin/bash
echo "BASH SCRIPT BEFORE BUILD.."
./hammerdbcli <<!
source buildora.tcl
!
echo "BASH SCRIPT AFTER BUILD.."

if you want to redirect your output to a file it can look like the following:

#!/bin/bash
echo "BASH SCRIPT BEFORE BUILD.."
./hammerdbcli <<!>> buildora.output 2>&1
source buildora.tcl
!
echo "BASH SCRIPT AFTER BUILD.."

If you run the bash script it will now call hammerdbcli that will run buildora.tcl, this will wait until complete to call exit before returning control back to the bash script. This is just one example of many ways in which hammerdbcli can be blended with Tcl, bash or even Python to automate HammerDB functionality.

If it is needed to strip the control characters from the output this can be done using sed. The stdbuf command can also be used to write the output line by line to the output file.

#!/bin/bash
echo "BASH SCRIPT BEFORE BUILD.."
./hammerdbcli <<! 2>&1 | stdbuf -oL -eL sed -e "s,\x1B\[[0-9;]*[a-zA-Z],,g" -e "s,\r,,g" -e "s,hammerdb>,,g" -e "s,after\#[0-9]*,,g" >> buildora.output
source buildora.tcl
!
echo "BASH SCRIPT AFTER BUILD.."

An essential part of database performance testing is viewing the statistics generated by the database during the test and in 2009 HammerDB introduced automatic AWR snapshot generation for Oracle for the TPC-C test. With this feature Oracle generates a wealth of performance data that can be reviewed once the test is complete. However what if you want to review performance data in real time as the test is running? With HammerDB 3.1 you can now do that with Oracle Metrics. 
Before introducing how this works it is important to acknowledge the ASHMON tool from which this functionality was adopted and more importantly its author Kyle Hailey for giving permission to add it as open source.

To get started with Oracle metrics use the previous option for CPU metrics that now shows the service name and system user and password.

With these filled out click the metrics button and once connected to the Oracle database the metrics window will appear embedded within HammerDB. 

you can either resize the window embedded using the grab bar or you can grab the tab at the top of the notebook that says Metrics (with the arrows indicator) and drag the window out to be standalone (closing the window embeds it again).

As this feature uses the Oracle Active Session History, use the mouse to highlight a timeframe of interest and the SQL, wait events and users will appear in the panes to the left. On the right you have the choice of displaying the sql text, explain plan, io or statistics. The CPU option allows you to view the original live CPU metrics window. It is clear from the window below that HammerDB was running a schema build and the top wait event was log file switch (checkpoint incomplete) – time to resize the redo logs or move them to faster disk!

Running a TPC-C performance test information can be viewed live (by not selecting an area) or by highlighting the area of interest. In this example a test with 2 minute rampup and 5 minute test time can be seen.  It is also clear that most significant wait event is “log file sync” and therefore tuning should focus on the redo log performance. The user CPU is highlighted in green and the aim for maximum performance is for the top event to be CPU. 

You can also drill down on particular SQL ID’s be double clicking on them that will highlight the related wait events and in this example the session showing the most “db file sequential read” is highlighted with the associated explain plan showing the index access that we would expect. 

All of this functionality is also available for the TPC-H workload as well so you can see the actual queries how they were run, the explain plans and the events. 

Finally like all HammerDB features everything that is available on Linux is equally available on Windows as well so if running an Oracle client on Windows you can access exactly the same features to monitor your benchmark performance in real time. 

/dev/nvme0n1p1                                /mnt/ssd        xfs     noatime

# ls
acpidbg  cpupower  perf  turbostat  usbip  usbipd  x86_energy_perf_policy

# ./cpupower frequency-set --governor=performance
Setting cpu: 0
Setting cpu: 1
Setting cpu: 2

# ./cpupower frequency-info
analyzing CPU 0:
  driver: intel_pstate
  CPUs which run at the same hardware frequency: 0
  CPUs which need to have their frequency coordinated by software: 0
  maximum transition latency:  Cannot determine or is not supported.
  hardware limits: 1000 MHz - 3.80 GHz
  available cpufreq governors: performance powersave
  current policy: frequency should be within 1000 MHz and 3.80 GHz.
                  The governor "performance" may decide which speed to use
                  within this range.
  current CPU frequency: Unable to call hardware
  current CPU frequency: 1.99 GHz (asserted by call to kernel)
  boost state support:
    Supported: yes
    Active: yes

# ./cpupower idle-set --enable-all
# ./cpupower idle-info
CPUidle driver: intel_idle
CPUidle governor: menu
analyzing CPU 0:
Number of idle states: 4
Available idle states: POLL C1 C1E C6
POLL:
Flags/Description: CPUIDLE CORE POLL IDLE
Latency: 0
Usage: 10736
Duration: 29182086

# ./x86_energy_perf_policy -rcpu0: EPB 6
cpu0: HWP_REQ: min 38 max 38 des 0 epp 0 window 0x0 (0*10^0us) use_pkg 0
cpu0: HWP_CAP: low 7 eff 10 guar 25 high 38
cpu1: EPB 6
# ./x86_energy_perf_policy performance

# ./x86_energy_perf_policy -rcpu0: EPB 0
cpu0: HWP_REQ: min 38 max 38 des 0 epp 0 window 0x0 (0*10^0us) use_pkg 0
cpu0: HWP_CAP: low 7 eff 10 guar 25 high 38
cpu1: EPB 0

For the memory we need to set Huge Pages – so as root add the following line to /etc/sysctl.conf we are going to create 64GB of buffers by adding the vm.nr_hugepages line (Huge Pages are 2MB in size). 

vm.swappiness = 0
kernel.sem = 250 32000 100 128
fs.file-max = 6815744
net.ipv4.ip_local_port_range = 9000 65500
net.core.rmem_default = 262144
net.core.rmem_max = 4194304
net.core.wmem_default = 262144
net.core.wmem_max = 1048576
fs.aio-max-nr = 1048576
vm.nr_hugepages = 35000

postgres soft memlock 100000000
postgres hard memlock 100000000

cat /proc/meminfo
HugePages_Total:   35000
HugePages_Free:     6588
HugePages_Rsvd:     4572

postgres:/mnt/ssd/postgresqlsrc$ ls
pgsql  postgresql-9.6.5  postgresql-9.6.5.tar

find . -name pg_config.h -print
./src/include/pg_config.h 

 So it looks like below, this will set the WAL file size to be 1GB instead of the default 16MB. 

/* XLOG_SEG_SIZE is the size of a single WAL file. This must be a power of 2
   and larger than XLOG_BLCKSZ (preferably, a great deal larger than
   XLOG_BLCKSZ). Changing XLOG_SEG_SIZE requires an initdb. */
#define XLOG_SEG_SIZE (1024 * 1024 * 1024)

pgsql -> /mnt/ssd/postgresqlsrc/pgsql
postgres:/mnt/ssd/postgresqlsrc$ ls -ltr /usr/local
total 32
lrwxrwxrwx 1 root root   28 Oct 11 03:41 pgsql -> /mnt/ssd/postgresqlsrc/pgsql

postgres:/usr/local/pgsql$ ls
bin  data  include  lib  share

./bin/initdb -D ./data

postgres:/mnt/ssd/postgresqlsrc/pgsql/data$ more postgresql.conf
listen_addresses ='192.168.1.1'              # what IP address(es) to listen on;
port = 5432                             # (change requires restart)
max_connections = 256                   # (change requires restart)
shared_buffers = 64000MB                        # min 128kB
huge_pages = on                 # on, off, or try
temp_buffers = 4000MB                   # min 800kB
work_mem = 4000MB                               # min 64kB
maintenance_work_mem = 512MB            # min 1MB
autovacuum_work_mem = -1                # min 1MB, or -1 to use maintenance_work_mem
max_stack_depth = 7MB                   # min 100kB
dynamic_shared_memory_type = posix      # the default is the first option
max_files_per_process = 4000            # min 25
effective_io_concurrency = 32           # 1-1000; 0 disables prefetching
wal_level = minimal                     # minimal, archive, hot_standby, or logical
synchronous_commit = off                # synchronization level;
wal_buffers = 512MB                     # min 32kB, -1 sets based on shared_buffers
#checkpoint_segments = 256              # in logfile segments, min 1, 16MB each
checkpoint_timeout = 1h         # range 30s-1h
checkpoint_completion_target = 1        # checkpoint target duration, 0.0 - 1.0
checkpoint_warning = 0          # 0 disables
log_min_messages = error                # values in order of decreasing detail:
log_min_error_statement = error # values in order of decreasing detail:
log_timezone = 'GB'
autovacuum = off                        # Enable autovacuum subprocess?  'on'
datestyle = 'iso, dmy'
timezone = 'GB'
lc_messages = 'en_GB.UTF-8'                     # locale for system error message
lc_monetary = 'en_GB.UTF-8'                     # locale for monetary formatting
lc_numeric = 'en_GB.UTF-8'                      # locale for number formatting
lc_time = 'en_GB.UTF-8'                         # locale for time formatting
default_text_search_config = 'pg_catalog.english'
max_locks_per_transaction = 64          # min 10
max_pred_locks_per_transaction = 64     # min 10

# TYPE  DATABASE        USER            ADDRESS                 METHOD
# "local" is for Unix domain socket connections only
local   all             all                                     trust
# IPv4 local connections:
host    all             all             127.0.0.1/32            trust
# IPv6 local connections:
host    all             all             ::1/128                 trust
host    all             all             192.168.1.1/32        trust
host    all             all             192.168.1.2/32        trust
# Allow replication connections from localhost, by a user with the
# replication privilege.
#local   replication     postgres                                trust
#host    replication     postgres        127.0.0.1/32            trust
#host    replication     postgres       ::1/128                 trust

Start the PostgreSQL Database

./bin/pg_ctl start -D ./data

postgres:/usr/local/pgsql$ ps -ef | grep post
postgres    201539      1  0 Sep19 ?        00:00:00 /mnt/ssd/postgresqlsrc/pgsql/bin/postgres -D ./data
postgres    201541 201539  0 Sep19 ?        00:00:57 postgres: checkpointer process
postgres    201542 201539  0 Sep19 ?        00:00:02 postgres: writer process
postgres    201543 201539  0 Sep19 ?        00:03:18 postgres: wal writer process
postgres   201544 201539  0 Sep19 ?        00:00:04 postgres: stats collector process

./bin/pg_ctl stop -D ./data

postgres:/usr/local/pgsql$ ./bin/psql -U postgres -d postgres
psql (9.6.5)
Type "help" for help.
postgres=# alter role postgres password 'postgres';
ALTER ROLE
postgres=#

postgres:/usr/local/pgsql$ ./bin/psql -U postgres -d postgres -W
Password for user postgres:
psql (9.6.5)
Type "help" for help.
postgres=#

postgres:~$ export LD_LIBRARY_PATH=/usr/local/pgsql/lib:$LD_LIBRARY_PATH

$ ./hammerdbcli
HammerDB CLI v3.1
Copyright (C) 2003-2018 Steve Shaw
Type "help" for a list of commands
The xml is well-formed, applying configuration
hammerdb>librarycheck
Checking database library for PostgreSQL
Success ... loaded library Pgtcl for PostgreSQL

With the HammerDB command line its very easy to script the schema build and automated test so that if you don’t have a GUI or don’t want to use one you can still access all of the HammerDB functionality. The following example is with MySQL on Linux but can easily apply to any database you choose.

Firstly if you don’t have MySQL installed copy the client library to your home directory

$ ls -l libmysqlclient.so.20
-rw-r--r-- 1 mysql mysql 4237408 Apr 23 09:21 libmysqlclient.so.20

$ export LD_LIBRARY_PATH=/home/intel:$LD_LIBRARY_PATH

$ ./hammerdbcli
HammerDB CLI v3.1
Copyright (C) 2003-2018 Steve Shaw
Type "help" for a list of commands
The xml is well-formed, applying configuration
hammerdb>librarycheck
...
Checking database library for MySQL
Success ... loaded library mysqltcl for MySQL
...

$ more schemabuild.tcl
#!/bin/tclsh
puts "SETTING CONFIGURATION"
dbset db mysql
diset connection mysql_host 127.0.0.1
diset connection mysql_port 3306
diset tpcc mysql_count_ware 800
diset tpcc mysql_partition true
diset tpcc mysql_num_vu 64
diset tpcc mysql_storage_engine innodb
print dict
buildschema

$ ./hammerdbcli
HammerDB CLI v3.1
Copyright (C) 2003-2018 Steve Shaw
Type "help" for a list of commands
The xml is well-formed, applying configuration
hammerdb>source schemabuild.tcl

$ more mysqlrun.tcl
#!/bin/tclsh
proc runtimer { seconds } {
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
}
puts "SETTING CONFIGURATION"
dbset db mysql
diset connection mysql_host 192.168.1.1
diset connection mysql_port 3306
diset tpcc mysql_driver timed
diset tpcc my_rampup 2
diset tpcc my_duration 5
vuset logtotemp 1
loadscript
puts "SEQUENCE STARTED"
foreach z { 1 2 4 8 12 16 20 24 28 32 36 40 44 48 52 56 60 64 68 72 76 80 84 88 92 96 100 104 } {
puts "$z VU TEST"
vuset vu $z
vucreate
vurun
runtimer 600
vudestroy
after 5000
        }
puts "TEST SEQUENCE COMPLETE"

$ ./hammerdbcli
HammerDB CLI v3.1
Copyright (C) 2003-2018 Steve Shaw
Type "help" for a list of commands
The xml is well-formed, applying configuration
hammerdb>source mysqlrun.tcl