我在我的日志中看到了很多缓慢的提交:
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'
它们中的大多数都与只执行SELECT查询的事务有关。
我检查了内存,磁盘/IO,一切正常。当我运行pgbench时,我有很好的交易/秒速。
如何调试在这样的COMMIT上慢的部分?
怎么调?
这是我的配置:
- PostgreSQL 12.6,基于Alpine的镜像
- 12 g内存,1至8核
- 8g shared_buffer
- synchronous_commit = 'off'
2条答案
按热度按时间lvjbypge1#
COMMIT PREPARED
只做两件可能需要很长时间的事情:既然你说你的磁盘没有过载,那么第一个原因就可以排除了。
zd287kbt2#
回答我自己的问题:缓慢的COMMIT与磁盘有时会超出IOPS有关。