Thread: How to analyze of short but heavy intermittent slowdown on BIND on production database (or BIND vs log_lock_waits)

On Sat, Dec 31, 2022 at 02:26:08PM +0200, Maxim Boguk wrote:
> 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.

What version postgres?  What settings have non-default values ?
What OS/version?  What environment/hardware?  VM/image/provider/...
What are the queries that are running BIND ?  What parameter types ?
Are the slow BINDs failing?  Are their paramters being logged ?
What else is running besides postgres ?  Are the DB clients local or
remote ?  It shouldn't matter, but what client library?

Howdy,

Few additional questions:

1. How many concurrent, active connections are running when these BIND problems occur?  select count(*) from pg_stat_activity where state in ('active','idle in transaction')
2. Are the queries using gigantic IN (<big list>) values?
3. Perhaps unrelated, but is log_temp_files turned on, and if so, do you have a lot of logs related to that?

Regards,
Michael Vitale, just another PG DBA

Hi Maxim,

10-20 active, concurrent connections is way below any CPU load problem you should have with 48 available vCPUs. 
You never explicitly said what the load is, so what is it in the context of the 1,5,15?

You said it's a dedicated server, but pgbouncer is running locally, right?  PGBouncer has a small footprint, but is the CPU high for it?

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

!!!  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

).

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.

What happens if you take pg_stat_statements out of the picture (remove from shared_preload_libraries)?  Does your BIND problem go away?