ClientRead statement_timeout

I have been observing a strange behaviour where PostgreSQL backends created by node-postgres are hanging in ClientRead state.

cinema_data_task_executor=> SHOW statement_timeout;
 statement_timeout
-------------------
 10s
(1 row)

cinema_data_task_executor=> SELECT
cinema_data_task_executor->   psa1.backend_start,
cinema_data_task_executor->   psa1.pid,
cinema_data_task_executor->   now() - psa1.query_start duration,
cinema_data_task_executor->   psa1.query,
cinema_data_task_executor->   psa1.state,
cinema_data_task_executor->   psa1.application_name,
cinema_data_task_executor->   psa1.wait_event_type,
cinema_data_task_executor->   psa1.wait_event,
cinema_data_task_executor->   psa1.usename
cinema_data_task_executor-> FROM pg_stat_activity psa1
cinema_data_task_executor-> WHERE
cinema_data_task_executor->   psa1.pid = 29342 AND
cinema_data_task_executor->   psa1.state = 'active'
cinema_data_task_executor-> ORDER BY psa1.query_start ASC;
         backend_start         |  pid  |    duration     |                                                query                                                 | state  |     application_name     | wait_event_type | wait_event |          usename
-------------------------------+-------+-----------------+------------------------------------------------------------------------------------------------------+--------+--------------------------+-----------------+------------+---------------------------
 2019-08-20 20:25:00.282386+00 | 29342 | 00:08:02.920093 | UPDATE event_seating_lookup SET last_seen_at = now() WHERE id = $1 AND ended_at IS NULL RETURNING id | active | do-event-seating-lookups | Client          | ClientRead | cinema_data_task_executor
(1 row)

In the above example you can see a backend with statement_timeout set to 10 seconds. Meanwhile, the particular query has been running for 8 minutes. From Node.js perspective, the program is just hanging after sending the query.

There appears to be a case where node-postgres is stuck in ClientRead state.

To those knowledgeable about PostgreSQL in general: is there a way to enforce statement_timeout or another timeout even when client is in ClientRead state?

I've just come across this issue as well. The code runs fine locally, but when I deploy it to AWS Lambda the statements all just hang. With the above query on pg_stat_activity I can see that they are also sitting in the ClientRead state. My timeouts are also 10 seconds but it hangs for many minutes.

The query does actually run (in my case it's an INSERT and the data does get inserted), just that the promise returned by query() never resolves.

However I have noticed that if I send another query to the database, that DOES cause the first one to complete. It will either return a timeout error if I've waited too long to send the second query, or it completes as normal if I send the second query shortly after the first.

It looks like there is definitely something causing the queries to stick, but in such a way that subsequent queries can "unstick" earlier ones.

Any ideas where to start looking to debug it?

@brianc

@brianc Any chance of getting a comment from you on this one?

I "worked around" this by adding a cron job that kills transactions above the limit assigned to them. Obviously, not optimal.

18:02:34 <RhodiumToad> ClientRead means that the database is waiting for something from the client.
18:05:18 <RhodiumToad> gajus: so here's the thing: the state is shown as "active"
18:05:46 <RhodiumToad> gajus: but what that means is that the server has seen a protocol message that begins a query, e.g. a Parse
18:06:34 <RhodiumToad> gajus: but it hasn't yet returned to the idle state, which happens when the server sends the ReadyForQuery response at the end of the query
18:07:59 <RhodiumToad> gajus: so, one possibility is that the client didn't send the Sync message
18:08:31 <RhodiumToad> if the client sent Parse/Bind/Execute but no Sync, then the statement timeout is disarmed at the end of the Execute (since the query is done),
18:10:04 <RhodiumToad> but the state in pg_stat_activity isn't reset to "idle" or "idle in transaction" until Sync is seen

From a discussion on IRC.

tl;dr; It appears that node-postgres does not send Sync message in some cases.

Any chance of getting a comment from you on this one?

If you can give me a self-contained piece of code that reproduces this problem I can look at it right away.

If you can give me a self-contained piece of code that reproduces this problem I can look at it right away.

Never managed to replicate it.

All I can say that it has nothing to do with the query itself or if it was within an explicit transaction. I have seen all sorts of queries get stuck in this way, ranging from simple SELECT to long multi-statement transactions.

Here is a bit of code that has a problem:

console.log('before query');
const r = await this.database.query('SELECT field FROM table');
console.log('after query');

When run, it shows before query but not after query. However the trick is that when run on my local machine it works, and when run on AWS Lambda it fails 100% of the time.

I tried adding some debug messages to the node-postgres code, and I get this:

parameterStatus
parameterStatus
parameterStatus
backendKeyData
readyForQuery
before query

If I wait 10 minutes and then run a second query, I get this: (following on from the messages above)

parseComplete
bindComplete
noData
commandComplete
Error: Query read timeout (node_modules/pg/lib/client.js:484)
readyForQuery
readyForQuery
authenticationMD5Password
[...]
parameterStatus
parameterStatus
parameterStatus
backendKeyData
readyForQuery
before query

So the second query pokes the first one into completion (albeit with a timeout) and the second query then becomes stuck. If the first query was an INSERT then the DB gets updated even though it returns a timeout error to the client.

This continues to happen, with each query unfreezing the one before. If I send the queries quickly enough then they return data apparently as normal, but if I wait too long between queries then the prior ones return with timeout errors after they are unfrozen. If they are never unfrozen then they never time out.

It's probably going to be difficult to give you something that will reproduce the error since it appears to be so environment-specific, however if you have any suggestions for debugging statements I can add that might be useful then I am happy to try them and report back.

@gajus

OK I've worked out what's causing my problem, but it may not be the same as the one @gajus is experiencing. Mine was due to a misunderstanding in how AWS Lambda interacts with async code like node-postgres.

Since I didn't care for the result of some of my queries, I wasn't using await when running them, expecting them to just finish in the background in their own time.

However AWS Lambda works by calling a function in your code, and as soon as you return from that function, it suspends the process even if there are outstanding timers, promises, etc. If you get it to quickly call your function again, it will unfreeze it and keep going, which is why the timers eventually triggered and reported a query timeout when I sent multiple requests (in order to run multiple queries).

The solution, for me, was to ensure I used await for all calls to the node-postgres library. This way I could be 100% sure that all database calls had completed (or timed out) before my main function returned.

Having done this I no longer see any of the buggy behaviour and everything is now working as expected.

The above described behaviour is unrelated to what is being reported here.

@gajus

To those knowledgeable about PostgreSQL in general: is there a way to enforce statement_timeout or another timeout even when client is in ClientRead state?

@gajus I saw that this is implemented with normal setTimeout() calls. So if your query timeout is not triggering, then it must be because setTimeout() is not functioning correctly. In my case it was because AWS was suspending the process, so can you think of any reasons why setTimeout() would not be working correctly in your environment?

(Also, I'm not quite sure whether your complaint is that the client-side code hangs, or that the server builds up too many idle connections which you have to clear out periodically. If your complaint is that the server accumulates more and more connections over time, then we've seen that happen when an unhandled exception occurs or the script otherwise terminates unexpectedly, and the call to client.end() gets skipped.)

Apologies if I'm misunderstanding the problem and it's neither of these situations.

@brianc

@brianc For what it is worth, I just discovered that switching to require('pg').native makes the issue go away.

@gajus

@gajus @brianc I am experiencing the same problem with node-postgres driver. To replicate, you can use the https://github.com/MagicStack/pgbench pointing to any postgres database.

This is how i ran mine after cloning the repo:

PGPASSWORD=** ./pgbench nodejs --concurrency-levels 50 --pghost <your hpst> --pguser <your user>

pointing the database to an AWS RDS instance. For some reason ts-postgres erred out, but pg and pg-native were able to run successfully.

This is the result from AWS enhanced monitoring which was capturing the AAS (Average Active Sessions) in a graph.

The red line is when the benchmark was using pg-native driver and you can see it does not spend any time on ClientRead for slightly better commits/second. While the performance is slightly better for pg-native, what's interesting is that javascript driver seems to spend a considerable time on ClientRead.

I have not seen any ClientRead delays when directly running Postgres own pgbench tool (c++ driver perhaps) and that provides much better latency/throughput (Almost 4x increase) and that's only when you get to see the database spinning CPU. With nodejs drivers, the database is not sweating a bit.

I did the benchmark after having performance issues and was not performing up to the standards reported by other AWS RDS users who were using different stacks.

This issue looks totally strange and perhaps is a bug that is avoidable.

hmmm yeah if the native driver doesn't exhibit the behavior it's almost certainly something we can solve on our end in the JS driver. I'm out of the country for a couple more days but as soon as I get back I'll take a look at this in detail and see if I can get a tight reproducible case I can work on.

…

On Sat, Nov 9, 2019 at 9:20 PM Murukesh Sadasivan ***@***.***> wrote: @gajus <https://github.com/gajus> @brianc <https://github.com/brianc> I am experiencing the same problem with node-postgres driver. To replicate, you can use the https://github.com/MagicStack/pgbench pointing to any postgres database. This is how i ran mine after cloning the repo: PGPASSWORD=** ./pgbench nodejs --concurrency-levels 50 --pghost <your hpst> --pguser <your user> pointing the database to an AWS RDS instance. For some reason ts-postgres erred out, but pg and pg-native were able to run successfully. This is the result from AWS enhanced monitoring which was capturing the AAS (Average Active Sessions) in a graph. [image: Screenshot 2019-11-10 at 5 37 56 AM] <https://user-images.githubusercontent.com/937228/68536700-f9343e00-037c-11ea-966b-73b9f171082e.png> The red line is when the benchmark was using pg-native driver and you can see it does not spend any time on clientRead. While the performance is slightly better for pg-native, what's interesting is that javascript driver seems to spend a considerable time on ClientRead. I have not seen any clientRead delays when directly running Postgres own pgbench tool (c++ driver perhaps) and that provides much better latency/throughput. I did the benchmark after having performance issues with our production system which was not performing up to the standards reported by other AWS RDS users who were using different stacks. This issue looks totally strange and perhaps is a bug that is avoidable. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#1952?email_source=notifications&email_token=AAAMHIJNZOAFSOKGBDYTXDDQS5HT7A5CNFSM4IN46UWKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEDUSH7Q#issuecomment-552150014>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAAMHINT2EIDTRMCJ426SQ3QS5HT7ANCNFSM4IN46UWA> .

Hey Brianc, any news on this ?

I've been looking at the protocol and various implementations and experimenting w/ something. Locally I'm seeing ~100 queries per second faster with a very rudimentary benchmark hitting a local postgres instance. Would you be interested in trying it out on a branch? I want to test some more stuff, but this might help...

@WNemencha

@WNemencha @murukesh @gajus I think I might have found something to help - would y'all be able to try the code on this branch & see if it makes things go away?

#2031 🙏

When it's in the ClientRead, is the query active?

Is this an instance of the bug?

-[ RECORD 1 ]----+------------------------------
datid            | 20492
datname          | rivet
pid              | 26427
usesysid         | 16408
usename          | rivet
application_name | 
client_addr      | 10.1.5.97
client_hostname  | 
client_port      | 43278
backend_start    | 2021-04-13 00:36:01.393611+00
xact_start       | 2021-04-13 00:36:05.083558+00
query_start      | 2021-04-13 00:36:05.163927+00
state_change     | 2021-04-13 00:36:05.163927+00
wait_event_type  | Client
wait_event       | ClientRead
state            | active
backend_xid      | 2387035679
backend_xmin     | 2387016150
query            |                              +
                 |           SELECT start_job(  +
                 |             $1,              +
                 |             $2,              +
                 |             $3,              +
                 |             $4               +
                 |           ) AS id            +
                 |         
backend_type     | client backend

We just experienced this in production, completely taking down two of our API servers. The servers' CPU immediately went to 100% CPU usage and stayed there despite getting no further requests.

Our PM2 logs show the following error. For convenience, here's the first code line in the stack trace for pg@8.7.1 (the version we use).

Error: Query read timeout
at Timeout._onTimeout (node_modules/pg/lib/client.js:526:21)
at listOnTimeout (internal/timers.js:554:17)
at processTimers (internal/timers.js:497:7)

We also experienced a similar production incident over the last few months that fits the symptoms described here.

On occasion, a subset of a normally performant (<1s) query would take upwards of 30 minutes and triggered our transaction duration monitors
The query was stuck in the ClientRead wait type
The DB experienced elevated CPU
The long running queries would eventually become unstuck and complete successfully

At the time we did not have a statement_timeout in place and thought it was a solution until coming across this thread. While we still plan to add one, we're also trying to understand and fix this type of stuck query error.

Did the test PR Some intial performance work #2031 yield any indication about the problem in the Node library?
Is using pg-native a solution to the stuck query problem, assuming we don't need the additional features offered in pg?

@brianc

Hey @brianc, in your opinion is this a reliability concern you or the team would consider investigating?

Hi! While diagnosing a similar problem the way I got the path to root cause was enabling verbose debugging at the postgresql service. We use docker compose for local dev stacks so it's something like:

services:
  # ...
  db:  # ...
    command: ["postgres", "-c", "log_statement=all", "-c", "log_destination=stderr"]

The reason behind our problem was a weird array parameter substitution.
At diagnose statement logging It was clear database was waiting for a parameter value to perform the substitution.
To over-simplify and explain, the js-side was something like

await client.query(`UPDATE some_table SET state = $1 WHERE state NOT IN ($2)`, [
  'busy',
  ['done', 'fail']  // This array wasn't being substituted neither thrown an error, producing the hang
])

I suggest attempting a log_statement=all diagnose, and see if it helps

@lorenzogrv

@lorenzogrv thanks for the data point. One follow-up question for your scenario is whether you were able to reproduce the error consistently with the improper array substitution? One reason this has been hard to debug on our side is due to the unpredictable nature of the error – reproducing definitely less than 1% of the time we run the query.

Unfortunately isn't enough stable to reproduce with 100% consistency, but wanted to share how useful may be that verbose logging with people here

Oh, I missed that it was a NOT IN. If state is of a type that allows '{"done","fail"}' to parse, like text, that query will update every row in the table. Maybe you were just seeing a slow query. Does “similar problem” still mean stuck in ClientRead, or…?

I oversimplified the query to retain only the "buggy thing" and reduce noise. That said, the real query isn't complex.

The client hangs waiting forever until killed (but I didn't dig through Client$ead specifically, as demonstrated here). I'll still give a try with native driver, because even after identifying this substitution and reworking it it's still flaky. Does not fail that often, but still hangs some times

Some more interesting data points that we have observed when this occurs:

the query was executed in a transaction (probably not important, but is certainly what made it more visible to us, and gives us more avenues to diagnose since there is defined behavior around transactions when protocol errors occur)
another query from the same machine encounters a protocol error (08P01 error) specifically with invalid message format link shortly after the stalled query begins (likely the next query executed on the machine).
the stalled query contains jsonb data from a user source (aka it had not been processed into pg yet)
However, the data itself passes through a graphql layer which we are reasonably confident already verifies no \0 characters are in the body.

That seems to point towards some type of length miscalculation, since that is the only way I can think of where the back end would be waiting on more data (since the message size header told it so) while the client is not doing sending any more data (because it already passed everything it had).

However, this doesn't really match expectations since:

the size of the message is computed from the serialized message, so there isn't really a way for a discrepancy to arise without some control character like \0 needing to be involved. If a \0 was involved, the behavior would be the opposite of a stall: the back end would think the message was completed but the message length was not at the current cursor. This is very interesting because the \0 does match the invalid message format, even if it does not match the stall.
even if there was a mismatch, the connection would never be handed back to the connection pool (we do not have query_timeout set)
and even if it did hand it back to the pool, any eventual protocol error on that connection would still trigger the transaction to be rolled back (pg raise, aborts transaction)

Not sure where that leaves this, and I unfortunately do not have a repro.

As an aside, is there any chance #1954 is revived? I think for this issue's context, any assumption of health on the connection side would generally be better served by statement_timeout. For cases where the protocol breaks down, the query_timeout seems best served to kill the TCP connection directly, instead of relying on the communication channel being healthy enough that we can issue a termination request to the backend. Then the backend will see the TCP connection terminated and be able to immediately roll back the transaction as expected.

Navigation Menu

Repository navigation

ClientRead statement_timeout #1952

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

ClientRead statement_timeout #1952

Description

Activity

gajus commented on Aug 20, 2019

adam-nielsen commented on Oct 11, 2019

gajus commented on Oct 13, 2019

gajus commented on Oct 13, 2019

brianc commented on Oct 14, 2019

gajus commented on Oct 14, 2019

adam-nielsen commented on Oct 15, 2019

adam-nielsen commented on Oct 15, 2019

gajus commented on Oct 15, 2019

adam-nielsen commented on Oct 15, 2019

gajus commented on Oct 15, 2019

murukesh commented on Nov 10, 2019

brianc commented on Nov 10, 2019

WNemencha commented on Dec 12, 2019

brianc commented on Dec 19, 2019

brianc commented on Dec 19, 2019

pauldraper commented on Apr 13, 2021

bfelbo commented on Jan 29, 2022

patxu commented on Jul 22, 2025

patxu commented on Jul 29, 2025

lorenzogrv commented on Dec 19, 2025

patxu commented on Dec 19, 2025

lorenzogrv commented on Dec 19, 2025

charmander commented on Dec 19, 2025

charmander commented on Dec 19, 2025

lorenzogrv commented on Dec 25, 2025

brandonw commented on Jan 20, 2026

Metadata

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

Issue actions