Postgres-15 response time jumps up from 0.5 ms to 100-200 ms once in a while (~ 0.5% of requests are affected)

Question

I have a simple database with one table of ~5 millions rows, another table with ~10 millions rows, couple of other tables have 10th of thousands of rows.

There is a constant load without any spikes at around 10-50 inserts per second and around 100 selects. All queries either use Index or Index Only scans. All queries end up in 0-10 ms ranges.

However, once in a while (i.e. 250 slow queries last 30 min with ~30k new records created) in my application logs I can see those same queries take 100-200ms. If I try to execute those same queries found in logs - I get fraction of millisecond time in results.

DB server is running on a separate CPU optimized digital-ocean server. I haven't yet tried to separate storages for WAL and data but I don't see how it could completely fix things.

I was trying to fix indexes (either adjust or delete), manually VACUUM ANALYZE, REINDEX, set auto vacuum to be more aggressive, nothing changes. Then I've noticed something I'm completely clueless how to read.

Some of those slows queries are SET standard_conforming_strings = on or SET SESSION timezone TO 'UTC'

As far as I was able to understand, it's not IO bound because workload is not that big and NVMe disks are used. I also can't see any spikes at CPU usage and memory usage is always low. Given that even "internal" postgres queries are affected means it's not my schema or indexes are root cause.

I'm not attaching any detailed info like EXPLAINs or schemas because it seems to be unrelated. Let me know what details are worth sharing.

It seems to be not a big deal when 0.5% of queries run 100ms instead of 1ms but I'd like to understand the root cause and how it affects scaling. Have no ideas what exactly to optimize in this case. (I even start thinking its something wrong with how Rails reports slow queries for some edge-cases but maybe I'm just missing something on postgres management side)

UPDATE I loaded up auto_explain and now one of the queries I want to understand the difference in is the following:

2023-08-02 12:55:12.040 UTC [16638] LOG:  duration: 256.053 ms  plan:
  Query Text: SELECT "events"."id" FROM "events" INNER JOIN "authors" ON "authors"."id" = "events"."author_id" WHERE (LOWER(authors.pubkey) = '0d1dd56ae3204328e45f78b1a64ac8f06d227129f775493ebe84cf28250d1ec6') AND "events"."kind" = $1 AND (events.created_at < '2023-08-02 03:47:03')
  Nested Loop  (cost=0.85..767.62 rows=1 width=8) (actual time=256.049..256.050 rows=0 loops=1)
    Buffers: shared hit=624 read=2158
    ->  Index Scan using index_authors_on_lower_pubkey_varchar_pattern_ops on authors  (cost=0.42..2.64 rows=1 width=8) (actual time=0.011..0.013 rows=1 loops=1)
          Index Cond: (lower(pubkey) = '0d1dd56ae3204328e45f78b1a64ac8f06d227129f775493ebe84cf28250d1ec6'::text)
          Buffers: shared hit=4
    ->  Index Scan using index_events_on_author_id on events  (cost=0.43..764.79 rows=19 width=16) (actual time=256.034..256.034 rows=0 loops=1)
          Index Cond: (author_id = authors.id)
          Filter: ((created_at < '2023-08-02 03:47:03'::timestamp without time zone) AND (kind = 3))
          Rows Removed by Filter: 2938
          Buffers: shared hit=620 read=2158

If I run this query manually, I get the following:

                                                                           QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------------
 Nested Loop  (cost=0.85..776.34 rows=1 width=8) (actual time=3.995..3.996 rows=0 loops=1)
   Buffers: shared hit=2783
   ->  Index Scan using index_authors_on_lower_pubkey_varchar_pattern_ops on authors  (cost=0.42..2.64 rows=1 width=8) (actual time=0.013..0.014 rows=1 loops=1)
         Index Cond: (lower(pubkey) = '0d1dd56ae3204328e45f78b1a64ac8f06d227129f775493ebe84cf28250d1ec6'::text)
         Buffers: shared hit=4
   ->  Index Scan using index_events_on_author_id on events  (cost=0.43..773.51 rows=19 width=16) (actual time=3.979..3.979 rows=0 loops=1)
         Index Cond: (author_id = authors.id)
         Filter: ((created_at < '2023-08-02 03:47:03'::timestamp without time zone) AND (kind = 3))
         Rows Removed by Filter: 2939
         Buffers: shared hit=2779
 Planning:
   Buffers: shared hit=22
 Planning Time: 0.304 ms
 Execution Time: 4.016 ms
(14 rows)

I understand that index on events(author_id, kind) would solve this but in current scenario it doesn't make much sense to have it. I want to understand what is the bottleneck that same query has so much different response times and how could I fix it without changing it: more RAM/CPU/Disks? Checkpoint configuration? etc

FINAL UPDATE So those logs showing 100-300 ms for SET SESSION timezone TO 'UTC' were actually incorrect application logs that were affected by high CPU usage and did not reflect real SQL numbers.

Auto Explain helped to find it out.

Answer 1

If even SET SESSION timezone... is randomly slow, that seems more like a system issue than specifically a PostgreSQL issue. Maybe network glitches, or a CPU seize-up (which I've seen on virtual machines sometimes).

(I even start thinking its something wrong with how Rails reports slow queries for some edge-cases but maybe I'm just missing something on postgres management side)

That could be. Set log_min_duration_statement to (for example) 50ms to get an independent opinion on what statements are being slow. Or better yet set up auto_explain and use auto_explain.log_min_duration instead, but that won't log SET statements even if they are slow, so use log_min_duration_statement which will log slow SET.

For the query plan you showed us, it is pretty clearly an IO issue. The slow one had to read 2158 pages, presumably randomly scattered ones, while the fast one found all the data already in the cache. I don't know why you think the index wouldn't make sense. It would solve the problem you showed us. If it wouldn't solve some other unseen problem, well, what can we do about that? If there are other real problems besides this one, you should show us a few of them. If you only show us one thing, we are going to focus on that one thing.

You could also wonder why the data wasn't already in cache. We can't address that with the info at hand. If shared_buffers and RAM in general is too small compared to the size of your database, then not everything will fit in cache. Less recently used data will age out. Or if you recently restarted the server, it will start out with a cold cache, even if you have enough memory to cache everything.