PgBouncer logging details for `query_wait_timeout` error

Question

Regarding this type of error in PgBouncer log:

2020-03-10 03:46:01.730 EDT [25305] LOG C-0xa5cf00: testdb/testdb_user@127.0.0.1:49214 closing because: query_wait_timeout (age=120s)
2020-03-10 03:46:01.730 EDT [25305] WARNING C-0xa5cf00: testdb/testdb_user@127.0.0.1:49214 pooler error: query_wait_timeout

Is there any possibility to see (or to log) the query that triggered the error? What are the most frequent causes for this error? a stopped server, a busy server?

UPDATE: the log file from PostgreSQL does not show any error at 2020-03-10 03:46:01

Answer 1

The log message you shared is not due to some error with a query. Rather, it is due to a pgbouncer client session that is waiting for a server connection, but that wait took more than 2 minutes. In other words, all real-connections in a pool have been used, and some session was waiting around for 2 minutes to get an opportunity to run a query on the database. There could be a number of factors causing this situation:

1. Session-level pooling -- you may have several pgbouncer sessions that get real connections to the database, but are idle and never releasing a connection back to the pool. Then, the newest session just waits around and never gets a chance to run its query (and query_wait_timeout happens, and the new pgbouncer session is booted)
2. Transaction-level pooling, pool size too small -- you may just have a lot of connections from applications and they spend a lot of time running a transaction, such that any new sessions are stuck waiting around for the transactions to finish, but 2 minutes was not enough time.
3. query_wait_timeout too small -- you might just have lots of long-running queries (check pg_stat_activity for any old queries that are still running, or for idle transactions)

There may be a few other possible reasons for what you're seeing, but these are just a few that came to mind.