Hi,
When performing post-mortem analysis of some short latency spikes on a heavily loaded database, I found that the reason for (less than 10 second latency spike) wasn't on the EXECUTE stage but on the BIND stage.
At the same time graphical monitoring shows that during this few second period there were some queries waiting in the BIND stage.
Logging setup:
log_min_duration_statement=200ms
log_lock_waits=on
deadlock_timeout=100ms
So I expected that every lock waiting over 100ms (>deadlock_timeout) should be in the log.
But in the log I see only spikes on slow BIND but not lock waits logged.
(
grep BIND /var/log/postgresql/postgresql-2022-12-29.log | grep 'duration' | perl -pe 's/^(2022-12-29 \d\d:\d\d:\d).*$/$1/' | sort | uniq -c | less
...
9 2022-12-29 00:12:5
2 2022-12-29 00:13:1
3 2022-12-29 00:13:5
2 2022-12-29 00:13:1
3 2022-12-29 00:13:5
!!! 68 2022-12-29 00:14:0
5 2022-12-29 00:14:1
3 2022-12-29 00:14:2
2 2022-12-29 00:14:3
5 2022-12-29 00:14:1
3 2022-12-29 00:14:2
2 2022-12-29 00:14:3
).
But no lock waits on the BIND stage logged during the problem period (and no lock waits in general).
Similar issues happen a few times per day without any visible pattern (but on the same tables usually).
No CPU or IO load/latency spikes found during problem periods.
No EXECUTE slowdown found in the log during that time.
So currently I have two hypotheses in research:
1)during BIND stage not every lock waits logged
2)there are some not a lock related intermittent slowdown of BIND
I ask for any ideas how to debug this issue (duration of such spike usually under 1s but given how many TPS database serving - 1s is too much and affect end users).
Maxim Boguk
Senior Postgresql DBA
https://dataegret.com/
Phone UA: +380 99 143 0000
Phone AU: +61 45 218 5678
Senior Postgresql DBA
https://dataegret.com/
Phone UA: +380 99 143 0000
Phone AU: +61 45 218 5678
