https://www.hammerdb.com/blog/uncategorized/why-tcl-is-700-faster-than-python-for-database-benchmarking/

Skip to content
[cropped-network]
HammerDB Blog

HammerDB Blog

Making Database Performance Open Source

Posted on July 5, 2022 by HammerDB

Why Tcl is 700% faster than Python for database benchmarking

Python is a popular programming language, especially for beginners,
and consequently we see it occurring in places where it just
shouldn't be used, such as database benchmarking.  In contrast, a
frequent question when it comes to HammerDB is why is it written in
Tcl? Surely any language will do?

This post addresses both questions to illustrate exactly why HammerDB
is written in Tcl and why using Python to benchmark a database can
result in poor performance and misleading results.  To do this, we
are going to rewrite HammerDB in Python and run a series of tests on
a 2 socket Intel(R) Xeon(R) Platinum 8280L server to see how and why
Tcl is 700% faster than Python for database benchmarking*

Background and Concepts

To begin with, you should be familiar with the concepts of
parallelism vs concurrency and why it is vital that your benchmark
should run in parallel so that you are testing the concurrency of the
database. An introduction to these concepts is given in the following
post.

    What programming languages does HammerDB use and why does it
    matter?

You should also be familiar with the concepts of ACID compliance and
locking versus multiversioning as well as database transaction
isolation levels, as it is essential to ensure that the database
benchmark itself is not serialized.

Rewriting HammerDB in Python

So we are not actually going to rewrite HammerDB in Python, however
it is trivial to write a command line driver script in Python as all
the hard work in creating the schema and writing the stored
procedures has already been done. (We use stored procedures because,
as the introductory post shows, using single SQL statements turns our
database benchmark into a network test).  So instead we are going to
take a cut down version of the HammerDB TPROC-C driver script and do
the same in Python and use the HammerDB infrastructure to measure
performance. For this example, we are going to use PostgreSQL stored
procedures in PostgreSQL 14.1.

So firstly we have the Tcl based driver script called
pgtest_thread.tcl

Copy Code Copied Use a different Browser

#!/usr/local/bin/tclsh8.6
package require Thread
set maxvuser 64
for { set vuser 0 } {$vuser < $maxvuser } {incr vuser} {
        set threadID [thread::create {
#EDITABLE OPTIONS##################################################
set library Pgtcl ;# PostgreSQL Library
set total_iterations 10000000 ;# Number of transactions before logging off
set host "localhost" ;# Address of the server hosting PostgreSQL
set port "5432" ;# Port of the PostgreSQL Server
set sslmode "disable" ;# SSLMode of the PostgreSQL Server
set user "tpcc" ;# PostgreSQL user
set password "tpcc" ;# Password for the PostgreSQL user
set db "tpcc" ;# Database containing the TPC Schema
#EDITABLE OPTIONS##################################################
#RANDOM NUMBER
  proc RandomNumber {m M} {return [expr {int($m+rand()*($M+1-$m))}]}
  proc NURand { iConst x y C } {return [ expr {((([RandomNumber 0 $iConst] | [RandomNumber $x $y]) + $C) % ($y - $x + 1)) + $x }]}
   #RANDOM NAME
  proc randname { num } {
    array set namearr { 0 BAR 1 OUGHT 2 ABLE 3 PRI 4 PRES 5 ESE 6 ANTI 7 CALLY 8 ATION 9 EING }
    set name [ concat $namearr([ expr {( $num / 100 ) % 10 }])$namearr([ expr {( $num / 10 ) % 10 }])$namearr([ expr {( $num / 1 ) % 10 }]) ]
    return $name
  }

#LOAD LIBRARIES AND MODULES
if [catch {package require $library} message] { error "Failed to load $library - $message" }

#TIMESTAMP
proc gettimestamp { } {
    set tstamp [ clock format [ clock seconds ] -format %Y%m%d%H%M%S ]
    return $tstamp
}
#POSTGRES CONNECTION
proc ConnectToPostgres { host port sslmode user password dbname } {
    global tcl_platform
    if {[catch {set lda [pg_connect -conninfo [list host = $host port = $port sslmode = $sslmode user = $user password = $password dbname = $dbname ]]} message]} {
        set lda "Failed" ; puts $message
        error $message
    } else {
        if {$tcl_platform(platform) == "windows"} {
            #Workaround for Bug #95 where first connection fails on Windows
            catch {pg_disconnect $lda}
            set lda [pg_connect -conninfo [list host = $host port = $port sslmode = $sslmode user = $user password = $password dbname = $dbname ]]
        }
        pg_notice_handler $lda puts
        set result [ pg_exec $lda "set CLIENT_MIN_MESSAGES TO 'ERROR'" ]
        pg_result $result -clear
    }
    return $lda
}
#NEW ORDER
proc neword { lda no_w_id w_id_input } {
    #2.4.1.2 select district id randomly from home warehouse where d_w_id = d_id
    set no_d_id [ RandomNumber 1 10 ]
    #2.4.1.2 Customer id randomly selected where c_d_id = d_id and c_w_id = w_id
    set no_c_id [ RandomNumber 1 3000 ]
    #2.4.1.3 Items in the order randomly selected from 5 to 15
    set ol_cnt [ RandomNumber 5 15 ]
    #2.4.1.6 order entry date O_ENTRY_D generated by SUT
    set date [ gettimestamp ]
    set result [pg_exec $lda "call neword($no_w_id,$w_id_input,$no_d_id,$no_c_id,$ol_cnt,0.0,'','',0.0,0.0,0,TO_TIMESTAMP('$date','YYYYMMDDHH24MISS')::timestamp without time zone)" ]
    if {[pg_result $result -status] != "PGRES_TUPLES_OK"} {
            error "[pg_result $result -error]"
        pg_result $result -clear
    } else {
        #puts "New Order: $no_w_id $w_id_input $no_d_id $no_c_id $ol_cnt 0 [ pg_result $result -list ]"
        pg_result $result -clear
    }
}
#PAYMENT
proc payment { lda p_w_id w_id_input } {
    #2.5.1.1 The home warehouse id remains the same for each terminal
    #2.5.1.1 select district id randomly from home warehouse where d_w_id = d_id
    set p_d_id [ RandomNumber 1 10 ]
    #2.5.1.2 customer selected 60% of time by name and 40% of time by number
    set x [ RandomNumber 1 100 ]
    set y [ RandomNumber 1 100 ]
    if { $x <= 85 } {
        set p_c_d_id $p_d_id
        set p_c_w_id $p_w_id
    } else {
        #use a remote warehouse
        set p_c_d_id [ RandomNumber 1 10 ]
        set p_c_w_id [ RandomNumber 1 $w_id_input ]
        while { ($p_c_w_id == $p_w_id) && ($w_id_input != 1) } {
            set p_c_w_id [ RandomNumber 1  $w_id_input ]
        }
    }
    set nrnd [ NURand 255 0 999 123 ]
    set name [ randname $nrnd ]
    set p_c_id [ RandomNumber 1 3000 ]
    if { $y <= 60 } {
        #use customer name
        #C_LAST is generated
        set byname 1
    } else {
        #use customer number
        set byname 0
        set name {}
    }
    #2.5.1.3 random amount from 1 to 5000
    set p_h_amount [ RandomNumber 1 5000 ]
    #2.5.1.4 date selected from SUT
    set h_date [ gettimestamp ]
    #2.5.2.1 Payment Transaction
    #change following to correct values
    set result [pg_exec $lda "call payment($p_w_id,$p_d_id,$p_c_w_id,$p_c_d_id,$byname,$p_h_amount,'0','$name',$p_c_id,'','','','','','','','','','','','','','','','','','',TO_TIMESTAMP('$h_date','YYYYMMDDHH24MISS')::timestamp without time zone,0.0,0.0,0.0,'',TO_TIMESTAMP('$h_date','YYYYMMDDHH24MISS')::timestamp without time zone)" ]
    if {[pg_result $result -status] != "PGRES_TUPLES_OK"} {
            error "[pg_result $result -error]"
        pg_result $result -clear
    } else {
        #puts "Payment: $p_w_id $p_d_id $p_c_w_id $p_c_d_id $p_c_id $byname $p_h_amount $name 0 0 [ pg_result $result -list ]"
        pg_result $result -clear
    }
}
#ORDER_STATUS
proc ostat { lda w_id } {
    #2.5.1.1 select district id randomly from home warehouse where d_w_id = d_id
    set d_id [ RandomNumber 1 10 ]
    set nrnd [ NURand 255 0 999 123 ]
    set name [ randname $nrnd ]
    set c_id [ RandomNumber 1 3000 ]
    set y [ RandomNumber 1 100 ]
    if { $y <= 60 } {
        set byname 1
    } else {
        set byname 0
        set name {}
    }
            set date [ gettimestamp ]
            set result [pg_exec $lda "call ostat($w_id,$d_id,$c_id,$byname,'$name','','',0.0,0,TO_TIMESTAMP('$date','YYYYMMDDHH24MISS')::timestamp without time zone,0,'')" ]
    if {[pg_result $result -status] != "PGRES_TUPLES_OK"} {
            error "[pg_result $result -error]"
        pg_result $result -clear
    } else {
        #puts "Order Status: $w_id $d_id $c_id $byname $name [ pg_result $result -list ]"
        pg_result $result -clear
    }
}
#DELIVERY
proc delivery { lda w_id } {
    set carrier_id [ RandomNumber 1 10 ]
    set date [ gettimestamp ]
            set result [pg_exec $lda "call delivery($w_id,$carrier_id,TO_TIMESTAMP('$date','YYYYMMDDHH24MISS')::timestamp without time zone)" ]
    if {[pg_result $result -status] ni {"PGRES_TUPLES_OK" "PGRES_COMMAND_OK"}} {
            error "[pg_result $result -error]"
        pg_result $result -clear
    } else {
        #puts "Delivery: $w_id $carrier_id [ pg_result $result -list ]"
        pg_result $result -clear
    }
}
#STOCK LEVEL
proc slev { lda w_id stock_level_d_id } {
    set threshold [ RandomNumber 10 20 ]
            set result [pg_exec $lda "call slev($w_id,$stock_level_d_id,$threshold,0)"]
    if {[pg_result $result -status] ni {"PGRES_TUPLES_OK" "PGRES_COMMAND_OK"}} {
            error "[pg_result $result -error]"
        pg_result $result -clear
    } else {
        #puts "Stock Level: $w_id $stock_level_d_id $threshold [ pg_result $result -list ]"
        pg_result $result -clear
    }
}

#RUN TPC-C
set lda [ ConnectToPostgres $host $port $sslmode $user $password $db ]
if { $lda eq "Failed" } {
    error "error, the database connection to $host could not be established"
}
pg_select $lda "select max(w_id) from warehouse" w_id_input_arr {
    set w_id_input $w_id_input_arr(max)
}
#2.4.1.1 set warehouse_id stays constant for a given terminal
set w_id  [ RandomNumber 1 $w_id_input ]
pg_select $lda "select max(d_id) from district" d_id_input_arr {
    set d_id_input $d_id_input_arr(max)
}
set stock_level_d_id  [ RandomNumber 1 $d_id_input ]
puts "Processing $total_iterations transactions without output suppressed..."
for {set it 0} {$it < $total_iterations} {incr it} {
    set choice [ RandomNumber 1 23 ]
    if {$choice <= 10} {
        neword $lda $w_id $w_id_input
    } elseif {$choice <= 20} {
        payment $lda $w_id $w_id_input
    } elseif {$choice <= 21} {
        delivery $lda $w_id
    } elseif {$choice <= 22} {
        slev $lda $w_id $stock_level_d_id
    } elseif {$choice <= 23} {
        ostat $lda $w_id
    }
}
pg_disconnect $lda
thread::wait }]
}
vwait forever

and the same in Python called pgtest_thread.py

Copy Code Copied Use a different Browser

#!/usr/bin/python
import psycopg2
import sys
import random
import math
from datetime import datetime
import threading

def gettimestamp():
    tstamp = datetime.now().strftime("%Y%m%d%H%M%S")
    return tstamp

def nurand(iConst,x,y,C):
    nrnd = ((((random.randint(0,iConst) | random.randint(x,y)) + C) % (y - x + 1 )) + x)
    return nrnd

def randname(num):
    namearr = [ "BAR", "OUGHT", "ABLE", "PRI", "PRES", "ESE", "ANTI", "CALLY", "ATION", "EING" ]
    pt1 = namearr[math.floor((num / 100) % 10)]
    pt2 = namearr[math.floor((num / 10) % 10)]
    pt3 = namearr[math.floor((num / 1) % 10)]
    name = pt1 + pt2 + pt3
    return name

def neword(cur, no_w_id, w_id_input):
    #print("neword")
    no_d_id = random.randint(1,10)
    no_c_id = random.randint(1,3000)
    ol_cnt = random.randint(5,15)
    date = gettimestamp()
    cur.execute('call neword(%s,%s,%s,%s,%s,0.0,\'\',\'\',0.0,0.0,0,TO_TIMESTAMP(%s,\'YYYYMMDDHH24MISS\')::timestamp without time zone)',(no_w_id,w_id_input,no_d_id,no_c_id,ol_cnt,date))
    rows = cur.fetchall()
    #print(rows)

def payment(cur, p_w_id, w_id_input):
    #print("payment")
    p_d_id = random.randint(1,10)
    x = random.randint(1,100)
    y = random.randint(1,100)
    if (x <= 85):
            p_c_d_id = p_d_id
            p_c_w_id = p_w_id
    else:
            p_c_d_id = random.randint(1,10)
            p_c_w_id = random.randint(1,w_id_input)
            while (p_c_w_id == p_w_id) and (w_id_input != 1):
                p_c_w_id = random.randint(1,w_id_input)

    nrnd = nurand(255,0,999,123)
    name = randname(nrnd)
    p_c_id = random.randint(1,3000)
    if (y <= 85):
            byname = 1
    else:
            byname = 0
            name = ""

    p_h_amount = random.randint(1,5000)
    h_date = gettimestamp()
    p_c_since = gettimestamp()
    cur.execute('call payment(%s,%s,%s,%s,%s,%s,\'0\',%s,%s,\'\',\'\',\'\',\'\',\'\',\'\',\'\',\'\',\'\',\'\',\'\',\'\',\'\',\'\',\'\',\'\',\'\',\'\',TO_TIMESTAMP(%s,\'YYYYMMDDHH24MISS\')::timestamp without time zone,0.0,0.0,0.0,\'\',TO_TIMESTAMP(%s,\'YYYYMMDDHH24MISS\')::timestamp without time zone)',(p_w_id,p_d_id,p_c_w_id,p_c_d_id,byname,p_h_amount,name,p_c_id,p_c_since,h_date))
    rows = cur.fetchall()
    #print(rows)

def delivery(cur, w_id):
    #print("delivery")
    carrier_id = random.randint(1,10)
    date = gettimestamp()
    cur.execute('call delivery(%s,%s,TO_TIMESTAMP(%s,\'YYYYMMDDHH24MISS\')::timestamp without time zone)',(w_id,carrier_id,date))
    #rows = cur.fetchall()
    #print(rows)

def slev(cur, w_id, stock_level_d_id):
    #print("slev" )
    threshold = random.randint(10, 20)
    cur.execute('call slev(%s,%s,%s,0)',(w_id,stock_level_d_id,threshold))
    rows = cur.fetchall()
    #print(rows)

def ostat(cur, w_id):
    #print("ostat")
    d_id = random.randint(1, 10)
    nrnd = nurand(255,0,999,123)
    name = randname(nrnd)
    c_id = random.randint(1, 3000)
    y = random.randint(1, 100)
    if (y <= 60):
        byname = 1
    else:
        byname = 0
        name = ""

    date = gettimestamp()
    cur.execute('call ostat(%s,%s,%s,%s,%s,\'\',\'\',0.0,0,TO_TIMESTAMP(%s,\'YYYYMMDDHH24MISS\')::timestamp without time zone,0,\'\')',(w_id,d_id,c_id,byname,name,date))
    rows = cur.fetchall()
    #print(rows)

def runtpcc():
    total_iterations = 1000000
    conn = psycopg2.connect(host="localhost",port="5432",database="tpcc",user="tpcc",password="tpcc")
    conn.set_session(autocommit=True)
    cur = conn.cursor()
    cur.execute("select max(w_id) from warehouse")
    w_id_input = cur.fetchone()[0]
    w_id = random.randint(1, w_id_input)
    cur.execute("select max(d_id) from district")
    d_id_input = cur.fetchone()[0]
    stock_level_d_id = random.randint(1, d_id_input)
    print ("Processing", total_iterations, "transactions without output suppressed...")
    for x in range(total_iterations):
        choice = random.randint(1, 23)
        if (choice <= 10):
            neword (cur, w_id, w_id_input)
        elif (choice <= 20):
            payment (cur,w_id, w_id_input)
        elif (choice <= 21):
            delivery (cur, w_id)
        elif (choice <= 22):
            slev (cur, w_id, stock_level_d_id)
        elif (choice <= 23):
            ostat (cur, w_id)

        if (x == total_iterations):
            conn.close()

def main():
    threads = []
    for n in range(64):
        t = threading.Thread(target=runtpcc)
        threads.append(t)
        t.start()

    for t in threads:
        t.join()

if __name__ == '__main__':
    main()

It should be clear that  these driver scripts do exactly the same
thing, they create multiple threads and loop calling the 5 TPROC-C
stored procedures meaning that on the PostgreSQL database the
workload itself is identical only the language calling the stored
procedures is different.

Building the Test Schema and Timing Script

Next we are going to build a PostgreSQL test schema using the
HammerDB CLI as follows:

Copy Code Copied Use a different Browser

dbset db pg
dbset bm TPC-C
vuset logtotemp 0
diset tpcc pg_superuser postgres
diset tpcc pg_superuserpass postgres
diset tpcc pg_storedprocs true
diset tpcc pg_count_ware 1000
diset tpcc pg_num_vu 64
buildschema
waittocomplete
quit

Finally we are going to build a HammerDB timing script. The key thing
to note is that we are going to set pg_total_iterations to 1, this
means that we have a special form of driver script that will time the
transactions on the database but will not run any transactions itself
to impact the load. This way we can run our external Tcl and Python
test scripts and capture the results.

Copy Code Copied Use a different Browser

dbset db pg
dbset bm TPC-C
diset tpcc pg_superuser steve
diset tpcc pg_defaultdbase postgres
diset tpcc pg_storedprocs true
diset tpcc pg_total_iterations 1
diset tpcc pg_driver timed
diset tpcc pg_rampup 0
diset tpcc pg_duration 2
vuset logtotemp 1
loadscript
vuset vu 1
tcstart
vucreate
vurun
runtimer 130
vudestroy
tcstop

If all is configured correctly when running either our Tcl or Python
driver script we will see output such as follows, note that Vuser 2
shows FINISHED SUCCESS just after it starts so the only activity that
this script is doing on the database is capturing the NOPM and TPM
over a time period, in this example 2 minutes.

$ ./hammerdbcli auto pgtime.tcl
HammerDB CLI v4.4
Copyright (C) 2003-2022 Steve Shaw
Type "help" for a list of commands
The xml is well-formed, applying configuration
Database set to PostgreSQL
Benchmark set to TPC-C for PostgreSQL
Changed tpcc:pg_superuser from postgres to steve for PostgreSQL
Value postgres for tpcc:pg_defaultdbase is the same as existing value postgres, no change made
Changed tpcc:pg_storedprocs from false to true for PostgreSQL
Changed tpcc:pg_total_iterations from 10000000 to 1 for PostgreSQL
Clearing Script, reload script to activate new setting
Script cleared
Changed tpcc:pg_driver from test to timed for PostgreSQL
Changed tpcc:pg_rampup from 2 to 0 for PostgreSQL
Changed tpcc:pg_duration from 5 to 2 for PostgreSQL
Script loaded, Type "print script" to view
Transaction Counter Started
Vuser 1 created MONITOR - WAIT IDLE
Vuser 2 created - WAIT IDLE
Logging activated
to /tmp/hammerdb.log
2 Virtual Users Created with Monitor VU
Vuser 1:RUNNING
Vuser 1:Beginning rampup time of 0 minutes
Vuser 1:Rampup complete, Taking start Transaction Count.
0 PostgreSQL tpm
Vuser 1:Timing test period of 2 in minutes
Vuser 2:RUNNING
Vuser 2:Processing 1 transactions with output suppressed...
Vuser 2:FINISHED SUCCESS
3650220 PostgreSQL tpm
4245132 PostgreSQL tpm
4203948 PostgreSQL tpm
4211748 PostgreSQL tpm
4203648 PostgreSQL tpm
Timer: 1 minutes elapsed
Vuser 1:1 ...,
4367244 PostgreSQL tpm
4265898 PostgreSQL tpm
4320510 PostgreSQL tpm
4258518 PostgreSQL tpm
4426578 PostgreSQL tpm
4413780 PostgreSQL tpm
Timer: 2 minutes elapsed
Vuser 1:2 ...,
Vuser 1:Test complete, Taking end Transaction Count.
Vuser 1:1 Active Virtual Users configured
Vuser 1:TEST RESULT : System achieved 1844256 NOPM from 4232155 PostgreSQL TPM
Vuser 1:FINISHED SUCCESS
ALL VIRTUAL USERS COMPLETE

Running a single process pre-test

Before we test the multithreading capabilities it is important to
callibrate how our respective scripts. For this we will use a
slightly modified version for both that removes the threading. We
start these running as follows for Python

python3 pgtest_proc.py

and as follows from the HammerDB directory (export the HammerDB ./lib
directory into the LD_LIBRARY_PATH first)

./bin/tclsh8.6 pgtest_proc.tcl

Once the workload is started we then run the timing script in another
command window and once we get the result we Ctrl-C the driver script
to stop the test.

In our single process test we see 62257 NOPM for Python and 64142
NOPM for Tcl giving confidence that the test scripts and methodology
are correct (remember that the workload is running in PostgreSQL
stored procedures and the test is calling those stored procedures, so
we expect the single process result to be very close).

[pytcl1proc]

We can also use VizTracer to run the same workload under Python this
time in a single thread to understand a little about what the
workload should look like. For each stored procedure we calculate the
parameters with a number of random operations and then call
psycopg2.extensions.cursor.execute, during this we sleep while we
wait for the PostgreSQL database to execute the stored procedure and
then we run psycopg2.extensions.cursor.fetchall to fetch the results.
In total the Wall duration to run the neword stored procedure was
1.8ms.

[pyviz1]

Running the Mulithreaded Test

Now lets run a the multithreaded tests shown above. For each test we
are going to edit the script to change the number of threads testing
at 1,2,4,8,16,32 and 64 threads with the following results.

[pyvstcl]

At 1, 2 or 4 threads we barely notice a difference, however at 64
threads Python gives us 247976 NOPM and Tcl 1844256 NOPM meaning Tcl
is more than 700% faster for an identical workload once we start
running multiple threads.

So why is there such a marked contrast between an identical workload
in Python and Tcl? As an early indication we can take a look at the
output from top when running 64 threads. Firstly with Python observe
that we have 9 running tasks, 5.8% user CPU utilisation and all of
the top postgres processes show as idle.

Tasks: 1144 total, 9 running, 1135 sleeping, 0 stopped, 0 zombie
%Cpu(s): 5.8 us, 1.0 sy, 0.0 ni, 93.0 id, 0.0 wa, 0.0 hi, 0.2 si, 0.0 st
MiB Mem : 772719.8 total, 581155.8 free, 6252.7 used, 185311.2 buff/cache
MiB Swap: 2048.0 total, 2048.0 free, 0.0 used. 711977.4 avail Mem

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
52656 postgres 20 0 5347252 25784 13644 S 178.8 0.0 0:44.94 python3 pgtest_thread.py
52794 postgres 20 0 49.3g 2.4g 2.4g S 10.9 0.3 0:02.83 postgres: tpcc tpcc ::1(45366) idle
52663 postgres 20 0 49.3g 2.2g 2.2g S 10.3 0.3 0:02.88 postgres: tpcc tpcc ::1(45234) idle
52721 postgres 20 0 49.3g 2.3g 2.3g S 10.3 0.3 0:02.75 postgres: tpcc tpcc ::1(45292) idle
52778 postgres 20 0 49.3g 2.4g 2.4g S 10.3 0.3 0:02.82 postgres: tpcc tpcc ::1(45350) idle
52784 postgres 20 0 49.3g 2.3g 2.3g S 10.3 0.3 0:02.81 postgres: tpcc tpcc ::1(45356) idle

in contrast the same workload in Tcl shows that we have 64 running
tasks (for 64 threads) 53.1% CPU and the postgres processes are all
busy running stored procedures.

Tasks: 1143 total, 64 running, 1079 sleeping, 0 stopped, 0 zombie
%Cpu(s): 53.1 us, 6.0 sy, 0.0 ni, 40.0 id, 0.1 wa, 0.0 hi, 0.8 si, 0.0 st
MiB Mem : 772719.8 total, 578477.9 free, 9582.1 used, 184659.7 buff/cache
MiB Swap: 2048.0 total, 2048.0 free, 0.0 used. 708649.4 avail Mem

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
52329 postgres 20 0 5351472 222896 10216 S 441.3 0.0 1:33.25 ./bin/tclsh8.6 pgtest_thread.tcl
52362 postgres 20 0 49.3g 5.5g 5.5g R 87.1 0.7 0:17.59 postgres: tpcc tpcc ::1(45114) CALL
52408 postgres 20 0 49.3g 6.0g 6.0g R 87.1 0.8 0:17.49 postgres: tpcc tpcc ::1(45160) CALL
52338 postgres 20 0 49.3g 6.0g 6.0g R 86.8 0.8 0:17.63 postgres: tpcc tpcc ::1(45086) CALL
52344 postgres 20 0 49.3g 6.2g 6.2g R 86.8 0.8 0:17.63 postgres: tpcc tpcc ::1(45096) CALL
52348 postgres 20 0 49.3g 4.5g 4.5g S 86.8 0.6 0:17.42 postgres: tpcc tpcc ::1(45100) CALL

Analyzing the Python GIL

So, if you have read this far you won't be surprised that we suspect
that the roadblock we have encountered with Python is a major one
called the Global Interpreter Lock or GIL that means only one thread
can run at any one time. But lets confirm this using the GIL load
tool to time the amount of time that the GIL is held for our 64
thread workload. The tool is installed and run as follows:

pip install gil_load
python3 -m gil_load pgtest_thread_gil.py

and we add gil_load.start and gil_load.stop to the Python script and
run a smaller number of transactions without timing the test. The
following is the result.  The GIL is held for 77% of the time and the
threads wait for the GIL 99.9% of the time. For Tcl this is 0% and 0%
respectively because there is no GIL meaning Tcl threads execute in
parallel and the workload continues to scale.

[gilohead]

The difference between the two also shows that there is time when we
are synchronizing between the threads and not running any workload at
all.  As our results show the more threads we add the worse the
performance gets due to this GIL synchronization.

held: 0.771 (0.774, 0.771, 0.771)
wait: 0.999 (0.998, 0.999, 0.999)
<140263890196288>
held: 0.0 (0.0, 0.0, 0.0)
wait: 0.0 (0.0, 0.0, 0.0)
<140263853995776>
held: 0.008 (0.008, 0.008, 0.008)
wait: 0.903 (0.887, 0.902, 0.903)
<140263845603072>
held: 0.01 (0.01, 0.01, 0.01)
wait: 0.904 (0.888, 0.903, 0.904)
...
<140257727084288>
held: 0.01 (0.01, 0.01, 0.01)
wait: 0.904 (0.892, 0.904, 0.904)

If we now return to VizTracer and perf using the method described
here to trace Python with 16 threads we can now see that the Wall
Duration time for the neword stored procedure has increased by 300%
and we are spending a lot longer sleeping with only one thread
allowed to execute at any one time. PostgreSQL can sustain higher
throughput but our Python client cannot.

[pyviz2-1024x614]

Python GIL PostgreSQL wait events

So if the bottleneck is in the client what wait event would we expect
to see on our PostgreSQL database? To do this we can use the
pg_stat_statements and pg_sentinel packages to query the active
session history with the SQL as follows:

Copy Code Copied Use a different Browser

with ash as (
         select *,ceil(extract(epoch from max(ash_time)over()-min(ash_time)over()))::numeric samples
         from pg_active_session_history where ash_time>=current_timestamp - interval '10 minutes'
) select  round(100 * count(*)/sum(count(*)) over(),0) as "%", round(count(*)/samples,2) as "AAS",
   datname,wait_event_type,wait_event
 from ash
 group by samples,
  datname,wait_event_type,wait_event
 order by 1 desc
;

with the results as follows on Python:

 % | AAS | datname | wait_event_type | wait_event
----+------+---------+-----------------+--------------------
62 | 4.10 | tpcc | Client | ClientRead
33 | 2.19 | tpcc | CPU | CPU
3 | 0.18 | tpcc | LWLock | pg_stat_statements
1 | 0.06 | tpcc | IO | DataFileRead
1 | 0.03 | tpcc | LWLock | WALInsert
0 | 0.01 | tpcc | IO | SLRURead
0 | 0.01 | tpcc | IO | DataFileExtend
0 | 0.01 | tpcc | Timeout | VacuumDelay
0 | 0.00 | tpcc | IO | DataFileWrite
(9 rows)

and as follows on Tcl.

% | AAS | datname | wait_event_type | wait_event
----+-------+---------+-----------------+----------------------
60 | 34.76 | tpcc | CPU | CPU
26 | 15.12 | tpcc | LWLock | pg_stat_statements
7 | 3.88 | tpcc | LWLock | WALInsert
4 | 2.48 | tpcc | Client | ClientRead
1 | 0.52 | tpcc | IO | DataFileRead
1 | 0.32 | tpcc | Lock | extend
0 | 0.02 | tpcc | IO | SLRURead
0 | 0.03 | tpcc | LWLock | XidGen
0 | 0.26 | tpcc | Lock | transactionid
0 | 0.23 | tpcc | IPC | ProcArrayGroupUpdate
0 | 0.03 | tpcc | LWLock | LockManager
0 | 0.02 | tpcc | LWLock | BufferContent
0 | 0.12 | tpcc | LWLock | WALWrite
0 | 0.08 | tpcc | LWLock | XactSLRU
0 | 0.02 | tpcc | IO | DataFileExtend
0 | 0.26 | tpcc | LWLock | ProcArray
(16 rows)

So when using Python we are spending 62% of our time on a Client wait
event called ClientRead or in other words PostgreSQL is telling us it
is spending most of its time waiting for the Python client to
respond, either the transaction has finished and it is waiting for
Python to fetch the results or it has already fetched the results and
is waiting for the next query to be sent.  Either way high waits on
ClientRead means we are waiting for the client and not the database. 
Also note that with the Tcl workload we now start to see some of the
LWLock wait events that a database engineer working on scalability
would focus on and we can use the HammerDB PostgreSQL statistics
viewer to drill down on some of these wait events.

[sent5-1024x900]

Summary

What we have observed is that the Python GIL makes it impossible to
run anything but a single threaded benchmark against a database
because the GIL means that only one thread can ever run at one time. 
For decades databases have been designed to scale to process millions
of transactions a minute whilst maintaining database consistency, a
serialized benchmark client compromises the ability to compare
databases.

HammerDB and its predecessor Hammerora were written in the Tcl
language because they were written by database engineers looking to
write scalable database benchmarks rather than by application
engineers looking to use a particular language. At the time Tcl was
the only multi-threaded GIL free scripting language for database
access and this still holds true today. (And although the Python test
script could run in multiple processes HammerDB is an application
simulating multiple virtual users in a GUI and CLI environment
requiring the close interaction and control of using multiple
threads).

*700% Faster

Although we have seen that Tcl is 700% faster than Python for our
example PostgreSQL benchmark we observed that even with Tcl we were
only at approximately 50% CPU Utilization. With commerical databases
HammerDB can scale to full CPU utilization and 2-3X the transaction
rate seen here meaning that in reality the gap between Tcl and Python
running against a commericial database is more than 700%.

Post navigation

Previous PostPrevious HammerDB for Managers

Recent Posts

  * Why Tcl is 700% faster than Python for database benchmarking July
    5, 2022
  * HammerDB for Managers June 27, 2022
  * How to build HammerDB from source May 26, 2022
  * HammerDB v4.3 New Features Pt2: Enhanced Webservice with SQLite
    repository November 23, 2021
  * HammerDB v4.3 New Features Pt1: Graphical Metrics for PostgreSQL 
    November 22, 2021
  * HammerDB: Using MySQL 5.7 vs 8.0 to understand performance
    profiles July 16, 2021
  * HammerDB v4.2 New Features Pt2: Increase of TPROC-C Schema Size
    Limits July 15, 2021
  * HammerDB v4.2 New Features Pt1: MariaDB Build and Test Example
    with the CLI July 14, 2021
  * HammerDB at Percona Live ONLINE May 13th 2021 May 10, 2021
  * HammerDB v4.1 New Features Pt3: Step Workloads May 10, 2021
  * HammerDB v4.1 New Features Pt2: CLI Transaction Counter and Count
    Logging May 7, 2021
  * HammerDB v4.1 New Features Pt1: Extended Time Profiling May 6,
    2021
  * Interacting with Open Source for HammerDB Code and Documentation 
    April 30, 2021
  * HammerDB CLI 101 April 27, 2021
  * What programming languages does HammerDB use and why does it
    matter? February 25, 2021
  * HammerDB v4.0 Signed Installer for Windows December 21, 2020
  * HammerDB v4.0 New Features Pt4: Connect Pooling for Clusters 
    December 9, 2020
  * HammerDB v4.0 New Features Pt3: Refactored Stored Procedures 
    December 9, 2020
  * HammerDB v4.0 New Features Pt2: Scalable UHD Graphics December 8,
    2020
  * HammerDB v4.0 New Features Pt1: TPROC-C & TPROC-H December 5,
    2020
  * Automating CLI Tests on Windows November 28, 2019
  * How to Graph HammerDB Response Times November 22, 2019
  * HammerDB v3.3 event driven scaling November 14, 2019
  * How to maximize CPU performance for PostgreSQL 12.0 benchmarks on
    Linux October 18, 2019
  * How to add your database to HammerDB - Pt4 Commit changes and
    pull request July 18, 2019
  * How to add your database to HammerDB - Pt3 Adding to and
    modifying the source July 17, 2019
  * How to add you database to HammerDB - Pt2 Fork, clone and binary
    downloads July 17, 2019
  * How to add your database to HammerDB - Pt1 Opening an issue July
    17, 2019
  * Using HammerDB as a Web Service July 8, 2019
  * Running hammerdbcli from a bash or batch script updated for v3.2 
    July 8, 2019
  * HammerDB Source Code moved to the TPC Council May 24, 2019
  * Testing MySQL 8.0.16 on Skylake with
    innodb_spin_wait_pause_multiplier May 5, 2019
  * The top 5 reasons to run your own database benchmarks January 5,
    2019
  * Why both TPM and NOPM Performance Metrics? December 20, 2018
  * HammerDB Concepts and Architecture November 30, 2018
  * How to improve Redo, Transaction Log and WAL throughput for
    HammerDB benchmarks November 5, 2018
  * Driving hammerdbcli from a bash script October 27, 2018
  * Real Time Oracle Performance Monitoring for Benchmarks October
    18, 2018
  * How Many Warehouses for the HammerDB TPC-C Test? October 17, 2018
  * HammerDB MySQL and MariaDB Best Practice for Performance and
    Scalability October 12, 2018
  * HammerDB Best Practice for PostgreSQL Performance and Scalability
    October 8, 2018
  * HammerDB command line build and test examples October 5, 2018
  * HammerDB Best Practice for SQL Server Performance and Scalability
    October 5, 2018
  * HammerDB Best Practice for Oracle Performance and Scalability 
    October 4, 2018
  * How to use Python with HammerDB October 3, 2018

Archives

  * July 2022
  * June 2022
  * May 2022
  * November 2021
  * July 2021
  * May 2021
  * April 2021
  * February 2021
  * December 2020
  * November 2019
  * October 2019
  * July 2019
  * May 2019
  * January 2019
  * December 2018
  * November 2018
  * October 2018

Proudly powered by WordPress