0

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

  • That an autovac worker was running while you had a problem doesn't mean it was causing the problem. Indeed the more you throttle it, the more time it will spend macroscopically "running", so the more likely it will be running at the time you notice a problem. – jjanes Jul 6 at 17:28
0

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.

| improve this answer | |

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.