Question 263758 in PostgreSQL Question posted in
The official documentation can be found here.

PostgreSQL slow COMMITs

I see lots of slow COMMITs in my logs :

2023-10-06 14:35:47 CEST Tx[0] cmd[COMMIT PREPARED] PID[16591] DB[db_XX] LOG: duration: 1049.941 ms execute <unnamed>: COMMIT PREPARED '131077_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTdiSzE=_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTdiWAAAAAQAAAAA'
2023-10-06 14:35:47 CEST Tx[0] cmd[COMMIT PREPARED] PID[24320] DB[db_XX] LOG: duration: 1049.209 ms execute <unnamed>: COMMIT PREPARED '131077_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTdjzzE=_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTdj1QAAAAQAAAAA'
2023-10-06 14:35:47 CEST Tx[0] cmd[COMMIT PREPARED] PID[27681] DB[db_XX] LOG: duration: 1048.986 ms execute <unnamed>: COMMIT PREPARED '131077_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTdjNDE=_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTdjOgAAAAQAAAAA'
2023-10-06 14:35:47 CEST Tx[0] cmd[COMMIT PREPARED] PID[18060] DB[db_XX] LOG: duration: 1188.703 ms execute <unnamed>: COMMIT PREPARED '131077_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTdiTTE=_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTdiVwAAAAQAAAAA'
2023-10-06 14:35:43 CEST Tx[0] cmd[COMMIT PREPARED] PID[28640] DB[db_XX] LOG: duration: 1033.370 ms execute <unnamed>: COMMIT PREPARED '131077_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTdgsjE=_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTdhHwAAAAQAAAAA'
2023-10-06 14:30:46 CEST Tx[0] cmd[COMMIT PREPARED] PID[16339] DB[db_XX] LOG: duration: 1478.801 ms execute <unnamed>: COMMIT PREPARED '131077_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTba9zE=_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTba/wAAAAQAAAAA'
2023-10-06 14:30:45 CEST Tx[0] cmd[COMMIT PREPARED] PID[27878] DB[db_XX] LOG: duration: 1233.219 ms execute <unnamed>: COMMIT PREPARED '131077_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTba1jE=_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTba3QAAAAQAAAAA'
2023-10-06 14:30:43 CEST Tx[0] cmd[COMMIT PREPARED] PID[27878] DB[db_XX] LOG: duration: 1012.639 ms execute <unnamed>: COMMIT PREPARED '131077_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTbatjE=_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTbavAAAAAQAAAAA'
2023-10-06 14:30:31 CEST Tx[0] cmd[COMMIT PREPARED] PID[28640] DB[db_XX] LOG: duration: 1228.278 ms execute <unnamed>: COMMIT PREPARED '131077_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTbYMjE=_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTbYOgAAAAQAAAAA'
2023-10-06 14:30:30 CEST Tx[0] cmd[COMMIT PREPARED] PID[16339] DB[db_XX] LOG: duration: 1268.856 ms execute <unnamed>: COMMIT PREPARED '131077_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTbYFDE=_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTbYGwAAAAQAAAAA'
2023-10-06 14:30:27 CEST Tx[0] cmd[COMMIT PREPARED] PID[16339] DB[db_XX] LOG: duration: 2105.008 ms execute <unnamed>: COMMIT PREPARED '131077_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTbXyzE=_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTbX0QAAAAQAAAAA'
2023-10-06 14:30:27 CEST Tx[0] cmd[COMMIT PREPARED] PID[28640] DB[db_XX] LOG: duration: 2127.526 ms execute <unnamed>: COMMIT PREPARED '131077_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTbXtDE=_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTbXwAAAAAQAAAAA'
2023-10-06 14:30:22 CEST Tx[0] cmd[COMMIT PREPARED] PID[16339] DB[db_XX] LOG: duration: 1535.906 ms execute <unnamed>: COMMIT PREPARED '131077_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTbWxTE=_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTbWzQAAAAQAAAAA'
2023-10-06 14:30:21 CEST Tx[0] cmd[COMMIT PREPARED] PID[28640] DB[db_XX] LOG: duration: 1242.736 ms execute <unnamed>: COMMIT PREPARED '131077_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTbWpzE=_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTbWrgAAAAQAAAAA'
2023-10-06 14:30:20 CEST Tx[0] cmd[COMMIT PREPARED] PID[28640] DB[db_XX] LOG: duration: 1455.468 ms execute <unnamed>: COMMIT PREPARED '131077_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTbWNjE=_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTbWPAAAAAQAAAAA'
2023-10-06 14:30:19 CEST Tx[0] cmd[COMMIT PREPARED] PID[16339] DB[db_XX] LOG: duration: 1986.581 ms execute <unnamed>: COMMIT PREPARED '131077_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTbWHzE=_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTbWJgAAAAQAAAAA'
2023-10-06 14:14:58 CEST Tx[0] cmd[COMMIT PREPARED] PID[28640] DB[db_XX] LOG: duration: 1637.472 ms execute <unnamed>: COMMIT PREPARED '131077_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTS3MzE=_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTS3PgAAAAQAAAAA'
2023-10-06 14:14:53 CEST Tx[0] cmd[COMMIT PREPARED] PID[28640] DB[db_XX] LOG: duration: 1040.691 ms execute <unnamed>: COMMIT PREPARED '131077_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTSzWTE=_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTSzYAAAAAQAAAAA'
2023-10-06 14:13:34 CEST Tx[0] cmd[COMMIT PREPARED] PID[28640] DB[db_XX] LOG: duration: 1178.765 ms execute <unnamed>: COMMIT PREPARED '131077_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTRwsjE=_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTRwtQAAAAQAAAAA'
2023-10-06 14:10:11 CEST Tx[0] cmd[COMMIT PREPARED] PID[16270] DB[db_XX] LOG: duration: 1156.853 ms execute <unnamed>: COMMIT PREPARED '131077_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTO+ETE=_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTO+FwAAAAQAAAAA'
2023-10-06 14:10:03 CEST Tx[0] cmd[COMMIT PREPARED] PID[18060] DB[db_XX] LOG: duration: 1835.203 ms execute <unnamed>: COMMIT PREPARED '131077_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTN3HDE=_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTN3KgAAAAQAAAAA'
2023-10-06 14:10:03 CEST Tx[0] cmd[COMMIT PREPARED] PID[19612] DB[db_XX] LOG: duration: 1835.187 ms execute <unnamed>: COMMIT PREPARED '131077_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTN3GDE=_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTN3LgAAAAQAAAAA'
2023-10-06 14:10:02 CEST Tx[0] cmd[COMMIT PREPARED] PID[26583] DB[db_XX] LOG: duration: 1725.870 ms execute <unnamed>: COMMIT PREPARED '131077_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTN3GjE=_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTN3LQAAAAQAAAAA'
2023-10-06 14:09:55 CEST Tx[0] cmd[COMMIT PREPARED] PID[18060] DB[db_XX] LOG: duration: 1594.778 ms execute <unnamed>: COMMIT PREPARED '131077_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTNxlTE=_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTNxnAAAAAQAAAAA'
2023-10-06 14:09:53 CEST Tx[0] cmd[COMMIT PREPARED] PID[18060] DB[db_XX] LOG: duration: 1023.697 ms execute <unnamed>: COMMIT PREPARED '131077_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTNtPTE=_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTNtQwAAAAQAAAAA'
2023-10-06 14:09:53 CEST Tx[0] cmd[COMMIT PREPARED] PID[24320] DB[db_XX] LOG: duration: 1023.716 ms execute <unnamed>: COMMIT PREPARED '131077_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTNsXDE=_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTNsagAAAAQAAAAA'
2023-10-06 14:09:53 CEST Tx[0] cmd[COMMIT PREPARED] PID[28640] DB[db_XX] LOG: duration: 1023.706 ms execute <unnamed>: COMMIT PREPARED '131077_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTNsWzE=_AAAAAAAAAAAAAP//ZGKVXjMhkrRlCESsBTNsZwAAAAQAAAAA'

Most of them are related to transactions doing ONLY SELECT queries.

I checked memory, disk/IO, everything is fine.
When I run pgbench I have good transaction/second rates.

How to debug what’s being slow on such COMMITs ?

How to tune that ?

This is my config :

  • PostgreSQL 12.6, Alpine based image
  • 12g memory, 1 to 8 cores
  • 8g shared_buffers
  • synchronous_commit = ‘off’
Tags:

2

Answers


  1. Chosen as BEST ANSWER
    0

    Answer to my own question : slow COMMITs were related to disks running out of IOPS at some times.


  2. 0

    COMMIT PREPARED does only two things that can potentially take a long time:

    • write a commit record to WAL and sync WAL to disk

    • if synchronous replication is used, wait for the OK from the synchronous standby server(s)

    Since you say that your disk is not overloaded, the first reason can be ruled out.

    Login or Signup to reply.
Please signup or login to give your own answer.

Back To Top
Search