我有一个简单的数据库,其中一个表约有 5 百万行,另一个表约有 1000 万行,其他几个表有十分之一的行。
每秒大约有 10-50 次插入和大约 100 次选择,负载恒定,没有任何尖峰。所有查询都使用索引或仅索引扫描。所有查询最终都在 0-10 毫秒范围内。
然而,偶尔(即过去 30 分钟内有 250 个慢速查询,创建了约 30k 个新记录)在我的应用程序日志中,我可以看到这些相同的查询需要 100-200 毫秒。如果我尝试执行在日志中找到的相同查询 - 我会在结果中得到毫秒时间的一小部分。
数据库服务器运行在单独的CPU优化的数字海洋服务器上。我还没有尝试分离 WAL 和数据的存储,但我不知道它如何能够完全解决问题。
我试图手动修复索引(调整或删除),VACUUM ANALYZE
将REINDEX
自动真空设置得更积极,没有任何变化。然后我注意到一些我完全不知道如何阅读的东西。
其中一些减慢查询速度的是SET standard_conforming_strings = on
或SET SESSION timezone TO 'UTC'
据我了解,它不受 IO 限制,因为工作负载不是很大并且使用了 NVMe 磁盘。我也看不到 CPU 使用率出现任何峰值,并且内存使用率始终很低。鉴于即使是“内部”postgres 查询也会受到影响,这意味着它不是我的架构或索引是根本原因。
我没有附加任何详细信息,例如解释或模式,因为它似乎不相关。让我知道哪些细节值得分享。
当 0.5% 的查询运行 100 毫秒而不是 1 毫秒时,这似乎不是什么大问题,但我想了解根本原因以及它如何影响扩展。不知道在这种情况下到底要优化什么。(我什至开始认为 Rails 报告某些边缘情况的缓慢查询的方式有问题,但也许我只是在 postgres 管理方面遗漏了一些东西)
我加载了更新auto_explain
,现在我想了解其中差异的查询之一如下:
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
如果我手动运行此查询,我会得到以下结果:
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)
我知道事件索引(author_id,kind)可以解决这个问题,但在当前情况下,拥有它没有多大意义。我想了解同一查询具有如此不同的响应时间的瓶颈是什么,以及如何在不更改它的情况下修复它:更多 RAM/CPU/磁盘?检查点配置?ETC
最终更新
因此,那些显示 100-300 毫秒的日志SET SESSION timezone TO 'UTC'
实际上是不正确的应用程序日志,它们受到高 CPU 使用率的影响,并且没有反映真实的 SQL 数字。
自动解释帮助找到了答案。