postgres (v16) experiences lock contention with autovacuum and HammerDB TPROC

[gary-ntnx]

I wanted to share this in case others experience the same issues - as it took me a while to figure out what was going on.

I don't think this is a bug - more of a symptom of me deliberately loading the system to be CPU saturated, but it's interesting behavior nonetheless)

Background - I am deliberately trying to make my postgres DB CPU bound by having a small (300 WH) database that is fully read-cached, and using 100 vUsers on a 32 CPU Linux machine.

By default I observed that transactions occasionally drop from from ~21K to about ~2K all of a sudden - and the CPU spikes to near 100%. This is a much larger impact from vacuuming than I usually see (which is a 30-50% reduction, not 10X)

When I disable autovacuum in postgres.conf the issue goes away. Eventually I was able to capture what was going on in the postgres log.

• autovacuum starts to run analyzing the tables to see if it needs to do work
• Initially this has minumal impact... but then we start to see lines like this in the postgres log

2024-09-30 12:30:26.853 UTC [119844] tpcc@tpcc300 LOG:  process 119844 still waiting for ExclusiveLock on extension of relation 137553 of database 137529 after 1000.055 ms
2024-09-30 12:30:26.853 UTC [119844] tpcc@tpcc300 DETAIL:  Process holding the lock: 119867. Wait queue: 119844, 119850, 119813, 119866, 119894, 119819, 119889, 119827, 119849, 119852, 119890, 119891, 119853, 119807, 119847, 119893, 119882, 119869, 119878, 119879, 119835, 119839, 119859, 119799, 119905, 119829, 119823, 119814, 119830, 119901, 119812, 119892.
2024-09-30 12:30:26.853 UTC [119844] tpcc@tpcc300 CONTEXT:  SQL statement "INSERT INTO order_line (ol_o_id, ol_d_id, ol_w_id, ol_number, ol_i_id, ol_supply_w_id, ol_quantity, ol_amount, ol_dist_info)
                        SELECT no_d_next_o_id,
                        no_d_id,
                        no_w_id,
                        data.line_number,
                        data.item_id,
                        data.supply_wid,
                        data.quantity,
                        data.amount,
                        data.stock_dist
                        FROM UNNEST(order_line_array,
                        item_id_array,
                        supply_wid_array,
                        quantity_array,
                        amount_array,
                        stock_dist_array)
                        AS data( line_number, item_id, supply_wid, quantity, amount, stock_dist)"
        PL/pgSQL function neword(integer,integer,integer,integer,integer,integer) line 220 at SQL statement

and the analyze statements are taking between a few seconds to almost 1 minute to complete

2024-09-30 12:30:18.543 UTC [119940] LOG:  automatic analyze of table "tpcc300.public.order_line"
        avg read rate: 88.601 MB/s, avg write rate: 4.367 MB/s
        buffer usage: 4012 hits, 26175 misses, 1290 dirtied
        system usage: CPU: user: 0.51 s, system: 0.18 s, elapsed: 2.30 s

2024-09-30 12:31:15.897 UTC [119940] LOG:  automatic analyze of table "tpcc300.public.orders"
        avg read rate: 3.510 MB/s, avg write rate: 0.250 MB/s
        buffer usage: 4358 hits, 25768 misses, 1834 dirtied
        system usage: CPU: user: 0.53 s, system: 0.12 s, elapsed: 57.3

The work eventually completes, and the TPM rate goes back to normal - so there is no deadlock as such, but it is a very odd looking behavior.

FWIW - It is possible to force the transactions to fail after N milliseconds waiting for a lock in the postgres.conf file (lock_timeout = 100 give a 100msec timeout). In this scenario hammerDB will rightly issue errors and move on.

Vuser 19:New Order Procedure Error set RAISEERROR for Details
Vuser 46:Payment Procedure Error set RAISEERROR for Details
Vuser 32:Payment Procedure Error set RAISEERROR for Details
Vuser 99:Payment Procedure Error set RAISEERROR for Details
Vuser 97:Payment Procedure Error set RAISEERROR for Details
Vuser 87:Payment Procedure Error set RAISEERROR for Details

[sm-shaw]

As a proof of concept, below is the sequence of tests with autovacuuming set to off and no manual vacuum after tests

This is the individual transaction count at test 40 Virtual Users

So in general when running a sequence of tests against PostgreSQL you want to ensure that autovacuuming is enabled to consistently maintain higher levels of performance.

[gary-ntnx]

I agree that autovacuuming helps to maintain performance when retaining the same DB and executing multiple runs. My use-case is a bit different. I want consistency with a single run, when the DB is CPU bound. Specifically, I am measuring the impact of NUMA placement, hugepages, hyperthreading etc. So for me autovacuuming impacts those measurements quite a bit. Also since the DB grows during the run - I am restoring the DB each time. As ever, it all depends on what the goal of the measurement is. I am optimizing for consistency in a single CPU-bound run, my settings are probably not suitable for most production situations.