Postgres Performance degradation

Question

I have a Postgres 9.6 database and after some time (15 h), database performance starts to decrease dramatically, to the point where we get client side timeouts due to a very slow response from the server.

Initially we tracked down the problem to the autovacuum process running in a very large table (77M records) and we tuned autovaccuum process to be extra conservative (for testing purposes):

vacuum_cost_delay = 30
vacuum_cost_page_hit = 1               
vacuum_cost_page_miss = 60              
vacuum_cost_page_dirty = 80             
vacuum_cost_limit = 150         
log_autovacuum_min_duration = 0 
autovacuum_max_workers = 6
autovacuum_naptime = 15s
autovacuum_vacuum_threshold = 25
autovacuum_analyze_threshold = 10
autovacuum_vacuum_scale_factor = 0.1
autovacuum_analyze_scale_factor = 0.05
autovacuum_vacuum_cost_delay = -1                                      
autovacuum_vacuum_cost_limit = -1
                                       

This configuration caused the disk I/O to be quite low during autovacuum processes, however after a while we started getting many COMMIT spikes (> 250ms):

2020-07-05 04:21:52.394 UTC [25950] user@xdb LOG:  duration: 382.169 ms  statement: COMMIT
2020-07-05 04:21:52.394 UTC [25952] user@xdb LOG:  duration: 381.811 ms  statement: COMMIT
2020-07-05 04:21:52.394 UTC [32297] user@xdb LOG:  duration: 416.967 ms  statement: COMMIT
2020-07-05 04:21:52.394 UTC [25958] user@xdb LOG:  duration: 378.262 ms  statement: COMMIT
2020-07-05 04:21:52.394 UTC [25953] user@xdb LOG:  duration: 381.613 ms  statement: COMMIT
2020-07-05 04:21:52.394 UTC [25948] user@xdb LOG:  duration: 382.491 ms  statement: COMMIT
2020-07-05 04:21:52.396 UTC [25954] user@xdb LOG:  duration: 381.689 ms  statement: COMMIT
2020-07-05 04:21:52.396 UTC [25957] user@xdb LOG:  duration: 380.337 ms  statement: COMMIT

Finally, few seconds later we got these incredibly slow statements which caused our test run to abort, because we have 5 second timeout per client:

2020-07-05 04:21:53.419 UTC [32292] user@xdb LOG:  duration: 8106.307 ms  plan:
        Query Text: INSERT INTO play (bet,creditsafter,creditsbefore,endtime,gameelementsmask,gamenumber,idterminalinstance,starttime,wins) VALUES ($1,$2,$3,$4,$5,$6,$7,$8,$9) RETURNING idplay
        Insert on "SystemServerLocal".play  (cost=0.00..0.01 rows=1 width=76) (actual time=0.121..0.124 rows=1 loops=1)
          Output: idplay
          Buffers: shared hit=8
          ->  Result  (cost=0.00..0.01 rows=1 width=76) (actual time=0.017..0.018 rows=1 loops=1)
                Output: nextval('play_idplay_seq'::regclass), $7, $6, $3, $2, $1, $9, $5, $8, $4
                Buffers: shared hit=1
2020-07-05 04:21:53.419 UTC [32292] user@xdb LOG:  duration: 8106.765 ms  execute __gencmd__44: INSERT INTO play (bet,creditsafter,creditsbefore,endtime,gameelementsmask,gamenumber,idterminalinstance,starttime,wins) VALUES ($1,$2,$3,$4,$5,$6,$7,$8,$9) RETURNING idplay
2020-07-05 04:21:53.419 UTC [32292] user@xdb DETAIL:  parameters: $1 = '200', $2 = '0', $3 = '159333', $4 = NULL, $5 = '0', $6 = '93266', $7 = '4039', $8 = '2020-07-05 04:21:45+00', $9 = '0'
2020-07-05 04:21:53.422 UTC [32295] user@xdb LOG:  duration: 8927.034 ms  plan:
        Query Text: UPDATE TerminalInstance SET currentCounters = $1, lastUpdate = NOW() WHERE idTerminalInstance = $2
        Update on "SystemServerLocal".terminalinstance  (cost=0.41..8.43 rows=1 width=551) (actual time=8924.499..8924.500 rows=0 loops=1)
          Buffers: shared hit=477
          ->  Index Scan using terminalinstance_pkey on "SystemServerLocal".terminalinstance  (cost=0.41..8.43 rows=1 width=551) (actual time=0.038..0.354 rows=1 loops=1)
                Output: idterminalinstance, machnum, idgame, idbundle, idsession, now(), eventcontrol, active, nvclear, initialcounters, $1, gameversion, gameminorversion, ctid
                Index Cond: (terminalinstance.idterminalinstance = $2)
                Buffers: shared hit=237
2020-07-05 04:21:53.422 UTC [32295] user@xdb LOG:  duration: 8927.422 ms  execute __gencmd__148: UPDATE TerminalInstance SET currentCounters = $1, lastUpdate = NOW() WHERE idTerminalInstance = $2

The table "SystemServerLocal".play has 11M records and we also know that a autovacuum analyze was being executed in this table when those statements were executed:

2020-07-05 04:23:15.681 UTC [16833] LOG:  automatic analyze of table "XServer.SystemServerLocal.play" system usage: CPU 1.75s/0.83u sec elapsed 462.17 sec

When we start the test with 30 concurrent clients everything seems to be quite stable with (100 ms or less response time), but after a while the response time reaches the point where our timeout condition is triggered due to performance degradation in the database side.

We also monitored the disk I/O and we know that at the time of the problem we did not had any I/O intensive processes running along with Postgres, i.e. the disk was being used exclusively by the Postgres processes.

Any ideas, why we are experiencing this behavior?

Kind regards,

Miguel Lopes

Answer 1

There are two possible explanations:

1. Your I/O system is hopelessly overloaded.

   That is the most likely explanation.

2. You are using WITH HOLD cursors, which are materialized during COMMIT.