Mysterious spikes in Postgres query latency

Question

At work we've been running into a sort of mysterious problem. Every few hours, one of our tables (tasks) sees query latency grow (caused by CPU use) followed by a burst of LWLock:BufferContent, then it drops back down to normal. Here's a screenshot of RDS's performance insights:

We've done a ton of work to try to mitigate this, and the work has resulted in the incidents being (anecdotally) less frequent and less severe. However, the problem has not gone away.

First we noticed that there were some queries that were not hitting indexes. I've spent time making sure that all of our queries for this table perform index and index-only scans. Queries tend to look like this:

SELECT COUNT(1) FROM tasks WHERE status = 'PENDING' AND NOT deleted

and we have corresponding indexes on status with a condition status = 'PENDING' AND deleted = FALSE. EXPLAIN ANALYZE shows that the index is being used correctly.

We did discover that some queries which specify a condition on our userId column had a bad query plan when the user has a huge number of records. This was remedied with fixes to the query and index improvements. As best we can tell, there are no queries which have a bad query plan for any values (yet the problem persists).

During the spikes, there is no increase in incoming load. Before, during, and after the incident, the queries which are affected show the same number of "Calls/sec" in the RDS performance insights, and our client application shows a stable QPS, so this isn't caused by an increase in queries.

I did observe that the EXPLAIN ANALYZE results for these queries does show an increase in heap fetches during these spikes, even for index-only scans. I read that the heap is still hit during index scans because the visibility map might indicate that pages containing tuples referenced by the index might not be visible. This seemed to be a strong signal: PENDING tasks (as shown in the query above) are often "hot" rows that receive many updates, so it makes sense that the visibility map for pages containing those rows would require fetches.

To compensate, the autovacuum settings were adjusted to cause much more frequent vacuums. We now see autovacuums every few hours, but the problem has not gone away. I've seen these spikes only 20 minutes after an autovacuum for the table completes. Moreover, the number of heap fetches reported by EXPLAIN ANALYZE during the spike can be 1-2 orders of magnitude greater than the number of PENDING task records: the number rarely exceeds 200 total, and we can see many thousands of heap fetches on index-only scans for indexes that only contain PENDING records.

During debugging, I noticed that the query planner does tend to adjust which indexes it queries over time, even when load remains ~constant. It sometimes chooses indexes which allow for index scans, but not index-only scans. For example, it might choose an index on status alone and ignores an index on status that's conditional on status = 'PENDING' and not deleted, even when the latter perfectly satisfies the query. I adjusted the seq_page_cost and random_page_cost settings to both by 1.0 instead of the Postgres defaults (1 and 4, respectively), which should direct Postgres to prefer index scans. Unfortunately the issue has persisted (though perhaps with less frequency). The screenshot above is from after the settings adjustment.

Some additional information:

1. The issue only affects this one table (or I should say, the queries for this one table).
2. All queries on the table during the spike are affected, not a single query.

At this point, I'm almost out of ideas. For reference, we're on Postgres 14.10 running on db.m5.16xlarge with a GP2 SSD volume. My suspicion is that this our Postgres version just needs an update (planned work) but this isn't a satisfying solution.

Something I'm a bit stumped by is why the resource use causing the latency is CPU. You can see in the screenshot above the increase in green (CPU). In essentially every query, there should be very very few records scanned. All of the queries are count aggregations, and the conditions on the queries are all simple equality. Here's one of the affected query outputs when there is not a spike:

Aggregate  (cost=46.02..46.03 rows=1 width=8) (actual time=0.362..0.362 rows=1 loops=1)
"  ->  Index Only Scan using ""tasks_globalPending"" on tasks  (cost=0.25..37.54 rows=3393 width=0) (actual time=0.239..0.353 rows=128 loops=1)"
        Heap Fetches: 178
Planning Time: 0.161 ms
Execution Time: 0.377 ms

Very fast! Arguably extremely efficient (though I'd prefer zero heap fetches). And for a COUNT() that ~never returns a value greater than 300, it's mystifying how this can go from 0.4ms to 10-20ms per query and burn that time on CPU use. What is it doing?

Answer 1

The mystery has been solved!

The issue was long-running queries on a read replica with hot_standby_feedback enabled. Long-running queries on the replica for an ETL job were aligning perfectly with the spikes. I discovered this when I noticed that the top of the spike seemed to always happen right around 30 minutes past the hour. Looking for things that run at that cadence, I found our ETL job.

hot_standby_feedback tells the primary "hey, I'm doing a thing, I'll let you know when I'm done". This prevents replication lag.

Replication lag can happen during long-running queries on the replica because of the way Postgres replication works. Postgres replicates changes to tuples rather than sending queries and replaying the queries on the replica. The "feed" of updates to tuples comes in serially, and applied on the replica. Consider this scenario:

1. The replica starts executing running a long-running query
2. The primary runs a VACUUM operation that deletes some tuples that the query on the replica might be reading.
3. The replica receives the update to those tuples mid-query

At this point, the replica has to pause its application of those updates because it doesn't know whether those specific tuples affect the outcome of the query. This causes the replica to fall behind the primary.

hot_standby_feedback lets the primary know not to do that while the replica is in one of those queries, allowing concurrent queries on the replica to complete successfully with fresh data from the primary.

The downside is for very busy tables, this seems to cause a number of issues (at least on Postgres 14.10). The fix was to add indexes to the busy table such that the long running queries on the replica became relatively fast queries. Once this was done, the problem completely went away on the primary.