Investigating which operation is causing high CPU usage on PostgreSQL - How?

Question

Today we had an incident in production which started as a 100% CPU usage on our RDS followed by a general performance degradation. It took us several hours of investigation on the PostgreSQL side to eventually find the cause by reviewing all application pull requests, file by file, from the last couple of days to find the winner - set enable_sort=off; - a performance optimization experiment gone wrong. There was a good intention to experiment with one particular query, which ended up not clearing the flag and eventually "poisoning" all connections and thus all queries from the app. Queries that normally take less than 1ms would now take up to a second burning the CPUs.

What we did:

• checked wait events - 90% CPU, a little buffer mapping here and there .. nothing too obvious
• checked all other monitoring available in AWS and Datadog, flagged a few queries that take longer than normally ... ended up blaming it as a symptom of the high CPU
• pg_stat_activity - no stuck session, no long running sessions, only up to about 10 to 50 short lived sessions (second or two tops) at any point in time, no real suspicions here
• pg_stat_statements - we found a few queries which we know normally take ~1ms to take 1s+ in average, so we were flagging those as suspects (later on confirmed that we were on the right track) however after trying to run those with EXPLAIN ANALYZE we found nothing (our test connection didn't have enable_sort=off so it was obviously quick as) and gave no further clues
• after pg_stat_statements we worked with a theory of stale statistics (perhaps caused by a recent minor version update 10.18-10.21) and went for ANALYZE VACUUM on the suspected tables, no effect - ended up blaming it as a symptom of the high CPU too

At this point we got stuck and didn't know what to do next and went for the pull request search.

And my question today is: Is there something else we could have checked on the database side to narrow down the investigation to sorts and this flag ideally? Did we miss something? What can we do differently next time around in such situation? Except for not blowing such experiments obviously .. but that's a different story.

Even if we were able to dump EXPLAIN ANALYZEs from the affected connections, I am not convinced we would have deduced something like this from it.

Answer 1

If you had used auto_explain to log the plans for slow queries, and the cutoff auto_explain.log_min_duration were low enough to catch these specific slow queries, and you had set auto_explain.log_settings TO on (The log_settings option was introduced in v12), that probably would have clued you in when you looked in the log file. You would have seen "Settings: enable_sort = 'off'" as part of the logs. Of course there is no guarantee you would have recognized the significance of that, especially not if there are a bunch of other non-default settings which would be listed there.

Even if we were able to dump EXPLAIN ANALYZEs from the affected connections,

That is what auto_explain does. I configure that with a suitable log_min_duration, as well as log_analyze and log_buffers, on every server I set up. I've never looked into changing log_settings before now; but taking your story as a cautionary tale I might start doing that as well.

I am not convinced we would have deduced something like this from it.

I would like to think I would have figured it out based on the "natural" connections not using sort, while the investigative connections were using sort (on the queries pulled from pg_stat_statements).