☰
PostgreSQL慢查询日志配置与SQL性能排查实践
2026/10/10 17:01:38 网站建设 项目流程

做 PostgreSQL 运维和开发的人,基本都遇到过这么一幕:业务方跑来反馈“页面又卡了”,监控面板上数据库 CPU 飙到百分百,连接数打满,一查当前会话,全是同一条 SQL 在反复执行。这时候你最需要的,不是拍脑袋猜,而是一条带着具体耗时信息的慢查询日志。慢查询日志是 PostgreSQL 排查性能问题的第一入口,它能直接告诉你哪条 SQL 慢、慢多久、什么时候慢,配合执行计划分析就能定位到缺索引、统计信息不准还是锁等待。这篇文章写给第一次在 PostgreSQL 上开启慢查询日志、并且准备认真排查慢 SQL 的开发者或 DBA,从参数配置讲到日志解读,再到根因分析,是一条完整的排查链路。

1. 先搞清楚:慢查询日志到底在解决什么问题

1.1 一条慢 SQL 是怎么把整个库拖垮的

很多人觉得慢 SQL 只是“响应慢一点”,顶多影响几个请求。实际上在 PostgreSQL 里,一条慢 SQL 的杀伤力是连锁反应。先看 CPU:如果这条 SQL 走了全表扫描,要读几千万行,CPU 和 IO 同时被占满。再看锁:慢 SQL 持有行锁或者表锁的时间变长,后面针对同一行的更新、删除全部堵在锁等待上。最要命的是连接数——PostgreSQL 默认max_connections一般是 100,慢查询一条条堵着不释放,新请求拿不到连接就开始排队,最终表现为整个数据库“假死”。

以前排查过一个订单系统的案例:症状是每天上午十点的报表接口超时,监控里连接数满,数据库 CPU 90% 以上。顺着堆栈往下摸,发现罪魁祸首是一条对百万级订单表做LIKE '%xxx%'模糊匹配的查询,单次执行 30 秒以上,接口一被调用就占用住连接。这种问题如果不开慢查询日志,你根本不知道是哪条 SQL,排查全靠猜,效率极低。

1.2 日志是起点,不是终点

慢查询日志的价值在于它把“问题的入口”暴露给你:SQL 文本、执行耗时、开始时间、来自哪个应用。有了这些信息,你才能进入下一步——用执行计划分析为什么慢。所以慢查询日志更像一个探针,它不直接告诉你优化方案,但能帮你把怀疑范围从“整个数据库”缩小到“具体某几条 SQL”。

这也是我为什么建议每个 PostgreSQL 实例都开启它,哪怕暂时没遇到性能问题。日志开着,磁盘多占一点,换来的是一旦出问题你能立即找到入口。很多生产事故之所以要排查半天,就是因为没开日志,现场已经被覆盖了,只能靠猜。日志在手,至少你能回答“到底哪条 SQL 在作妖”这个问题。

2. 慢查询日志的开启配置:参数逐个拆解

2.1 总开关:logging_collector 必须重启生效

PostgreSQL 里日志相关参数分两类:一类决定日志写到哪,一类决定日志记什么。要开启慢查询日志文件,第一步是把logging_collector设为on。这个参数控制 postgres 是否开启日志收集进程,把日志重定向到文件。注意:它属于“需要重启才能生效”的参数,改完只 reload 是不够的。

# 编辑 postgresql.conf 后重启 pg_ctl restart -D /path/to/data

很多第一次配置的人在这步踩坑:改了参数、reload、查配置发现是on,但日志文件就是不产生。原因就是logging_collector没经过完整重启。想确认参数是否需要重启,可以查pg_settings:

SELECT name, setting, context FROM pg_settings WHERE name = 'logging_collector';

context列如果显示postmaster,就表示必须重启才能生效;如果显示sighup,reload 就行。这个细节能省你大量排查时间,先记住。

2.2 记录阈值:log_min_duration_statement 怎么定

慢查询日志的核心参数是log_min_duration_statement,单位是毫秒。它表示“执行时间超过这个值的 SQL 会被记录下来”。设置为0表示记录所有 SQL;设置为-1表示关闭慢查询记录。生产环境常见做法是1000(1秒),但这绝不是标准答案。

怎么定阈值?建议看你应用的性能基线。如果平时接口 P95 在 500ms,那阈值设 1000 就合理;如果业务整体偏慢,P95 已经到 3 秒,阈值设 1000 会刷出一堆“正常慢”的语句,日志瞬间爆炸。反过来如果业务对延迟极敏感,P95 只有 50ms,阈值设 1000 就会漏掉很多真实问题。我的经验是先设一个宽松值(比如 2000),跑一周看量级,再逐步收紧到 500 或 1000,让日志保持“有内容但不刷屏”的状态。

-- 查看当前值 SHOW log_min_duration_statement; -- 临时调整(生产建议直接改配置文件并 reload) ALTER SYSTEM SET log_min_duration_statement = 1000; SELECT pg_reload_conf();

这里有一个容易忽略的细节:ALTER SYSTEM会把参数写到postgresql.auto.conf里,需要执行pg_reload_conf()或 reload 才生效。改完立即查一下pg_settings的setting列,确认新值已经加载,别凭感觉。

2.3 配套参数和一份可以直接抄的模板

光有log_min_duration_statement不够,你最好把日志输出的位置、格式、轮转都配好。否则日志文件在默认路径下漂着,或者一个文件写到几个 GB,磁盘被打满,那才是雪上加霜。我常用的一套配置如下:

logging_collector = on log_destination = 'stderr' log_directory = 'log' log_filename = 'postgresql-%Y-%m-%d.log' log_rotation_age = 1d log_rotation_size = 100MB log_min_duration_statement = 1000 log_line_prefix = '%m [%p] %q%u@%d ' log_statement = 'none' track_io_timing = on

逐个说明一下为什么要这么配:

  • log_directory和log_filename:日志放哪、文件名格式。按天命名方便以后按日期查找,配合日志分析脚本的时候尤其舒服。
  • log_rotation_age = 1d:每天切一个新文件。log_rotation_size = 100MB:文件超过 100MB 也切。两个条件满足一个就切,防止单文件无限变大。
  • log_line_prefix:日志每行的前缀。%m是带毫秒和时区的时间,%p是进程号,%u是用户名,%d是数据库名。有了这几个信息,你才能把日志跟具体会话和应用对应上。如果省掉前缀,日志里只有 SQL 文本,排查时很难还原现场。
  • log_statement = 'none':不要记录所有 SQL,否则日志量爆炸,而且和慢查询日志功能重复。有些新手会把log_statement设成all来“监控”,代价是磁盘和 IO 双重开销,得不偿失。
  • track_io_timing = on:让执行计划里能显示实际 IO 耗时,后面分析慢 SQL 时非常有用。

需要提醒的是,track_io_timing开启有一点额外开销,但在排查性能问题的场景下这点开销完全值得。如果你比较谨慎,可以在需要分析时临时开启,排完再关掉。

另外还有一个重型武器值得顺手装上:auto_explain。它可以在日志里自动记录慢 SQL 的完整执行计划:

shared_preload_libraries = 'auto_explain' auto_explain.log_min_duration = 1000 auto_explain.log_analyze = on

注意shared_preload_libraries同样需要重启才能加载。auto_explain的价值在于:慢查询日志只告诉你“这条 SQL 慢”,它能把“当时是怎么执行的”(完整执行计划)也一并写进日志。这在事后复盘、尤其是问题发生时没能现场 EXPLAIN 的场景下,几乎是救命级别的数据。代价是日志体积会明显变大,你要评估一下磁盘余量。

3. 配置完成后的实操:确认生效到定位慢 SQL

3.1 怎么确认日志真的在写

配好参数、重启实例之后,第一步不是等业务来报障,而是主动验证。我习惯按下面顺序检查:

  1. 确认参数加载:SELECT * FROM pg_settings WHERE name LIKE 'log%';看log_min_duration_statement、log_directory的值。
  2. 制造一条慢查询:在某个会话里故意执行SELECT pg_sleep(2);,因为执行时间超过阈值,它会被记进日志。
  3. 检查日志文件:看看指定目录下有没有生成文件,文件里有没有刚才那条pg_sleep(2)。

这套验证流程 5 分钟内能完成。如果日志没出现,优先检查logging_collector是否真的生效(context是postmaster),其次是文件权限——PostgreSQL 进程对log_directory要有写权限。很多人把日志目录建在奇怪的地方导致写不进去,比如目录属主不对,或者挂在只读分区上。

3.2 日志行里都藏了什么信息

一条典型的慢查询日志长这样:

2025-01-15 10:23:45.678 CST [12345] user@appdb duration: 2048.123 ms statement: SELECT * FROM orders WHERE customer_id = 88 AND status = 'pending';

拆开看:开头的时间是 SQL 开始执行的时间(精确到毫秒),CST 是服务器时区,12345 是后端进程号,user@appdb 是执行这条 SQL 的用户和数据库,duration 是执行耗时,statement 是完整 SQL 文本。

这里有个经验:如果你发现日志里的时间比业务侧记录的时间慢了几小时,别慌,多半是时区问题。log_line_prefix里的%m默认带服务器本地时区,而业务日志可能是 UTC。遇到时间对不上,第一时间查timezone设置,别怀疑是时钟漂移或者日志延迟。曾经有一次我们对比日志发现差 8 小时,查了一圈最后发现是业务日志用 UTC、数据库日志用 CST,根本不是时间记录错。

拿到这些信息之后,下一步就是把慢 SQL 汇总统计。如果你只有几条慢查询,人工看就行;但生产环境一晚上可能产生几千条,这时候需要分类汇总。我习惯把日志导入本地分析工具,或者直接用命令统计耗时分布:

grep 'duration:' postgresql-2025-01-15.log | awk '{print $NF}' | sort -n > durations.txt

更实用的做法是:把每个 SQL 去掉具体参数值之后归并,统计归一化后的 TOP N。后文讲pg_stat_statements时会有更规范的做法,但日志侧的归一化同样重要,因为它是第一手数据。

3.3 用 pg_stat_statements 做高频慢语句归并

如果慢查询日志里的语句数量太多,人工一条条看效率太低。PostgreSQL 自带的pg_stat_statements扩展是慢查询日志之外最好的补充。它能把 SQL 按文本归一化(把常量替换成占位符),统计每类语句的总执行次数、总耗时、平均耗时、缓冲区命中情况。

shared_preload_libraries = 'pg_stat_statements'
CREATE EXTENSION IF NOT EXISTS pg_stat_statements; SELECT calls, total_exec_time, mean_exec_time, query FROM pg_stat_statements ORDER BY total_exec_time DESC LIMIT 20;

total_exec_time是这组 SQL 累计消耗的总毫秒数,calls是执行次数,mean_exec_time是单次平均耗时。注意,pg_stat_statements里的时间是累计到快照时刻的,不是实时单次。用排序出来的 TOP 20,再和慢查询日志交叉对比,基本能锁定真正值得优化的语句。

这里要提一个版本坑:不同版本 PostgreSQL 里pg_stat_statements的字段名不一样。老版本是total_time,新版本拆成了total_exec_time。如果你在某个版本上发现字段不存在,先执行SELECT * FROM pg_stat_statements LIMIT 1;看看列名,别照着旧文章硬写。还有,这个扩展默认只统计访问过的 SQL,且缓冲区不区分共享和本地,分析时主要看趋势和排行,不要过度解读绝对值。

4. 慢 SQL 根因分析:从日志到执行计划

4.1 EXPLAIN ANALYZE 的正确打开方式

日志只是入口。真正要找“为什么慢”,必须看执行计划。PostgreSQL 里最常用的工具是EXPLAIN ANALYZE,它会把 SQL 真正执行一遍,告诉你每一步的实际行数、耗时、存储访问情况。

EXPLAIN (ANALYZE, BUFFERS) SELECT * FROM orders WHERE customer_id = 88 AND status = 'pending';

参数说明:

  • ANALYZE:实际执行并报告运行时间。不加ANALYZE得到的只是估算计划,不是实际结果。
  • BUFFERS:显示每一步的缓冲区读写情况(shared hit/read、local hit/read),是判断索引是否被使用、数据是否从磁盘读出来的关键。

读执行计划有个顺序:从最里层、缩进最多的节点开始往外读,每个节点关注三样东西——actual time(实际耗时)、rows(实际返回行数)、rows与估算值(第一个rows)的差距。差距大通常意味着统计信息不准,后面细说。

4.2 场景一:缺索引,全表顺序扫描

最常见的问题形态是Seq Scan。执行计划里如果出现:

Seq Scan on orders (cost=0.00..18000.00 rows=9000 width=100) (actual time=0.050..800.000 rows=9000 loops=1) Filter: ((customer_id = 88) AND (status = 'pending'::text))

它意味着 PostgreSQL 把整张表从头到尾读了一遍,再逐个过滤。表有几百万行,就算每行读取很快,累加起来也是秒级。解决办法很直接——加索引:

CREATE INDEX idx_orders_customer_status ON orders(customer_id, status);

加完索引再跑一遍EXPLAIN ANALYZE,你会看到执行计划变成了Index Scan或Bitmap Heap Scan,耗时可能从几秒降到几毫秒。这里要提醒一个细节:不是所有查询都适合加索引。如果这条 SQL 要读超过表中大约 5% 到 10% 的行,优化器大概率还是会选择顺序扫描,因为索引查找的随机 IO 反而更慢。判断标准以EXPLAIN ANALYZE的实际结果为准,不要凭直觉拍板,也不要逢慢查就加索引。

4.3 场景二:统计信息过期,行数估算离谱

执行计划里最隐蔽的问题是估算行数(第一个rows)和实际行数(actual rows)差距巨大。比如优化器以为某张表只有 100 行,实际有 100 万行,它可能错误地选择了嵌套循环而不是哈希连接。这类问题的根因是统计信息陈旧,尤其是大表经过大量增删改之后,系统表里的信息没跟上。

解决办法是更新统计信息:

ANALYZE orders;

在数据变化频繁的表上,可以调高autovacuum和自动 ANALYZE 的频率,或者对大表做定时 ANALYZE。判断统计信息是否过期的经验标准:计划里第一个rows和actual rows如果差到 10 倍以上,基本可以怀疑统计信息问题。另外,查询里用到的条件如果是强相关的两个列(比如customer_id和status),单列统计有时候不够,可以建立扩展统计信息:

CREATE STATISTICS orders_stat ON customer_id, status FROM orders; ANALYZE orders;

这不是必须的,但当你遇到“索引也加了,统计信息也更新了,计划还是乱选”的情况时,它是一个很有效的进阶手段。实际排查中,这一类问题经常被误判成“加索引没用”,其实根子是统计信息,方向错了自然越查越迷糊。

4.4 场景三:慢不是因为 SQL,而是等锁和连接排队

还有一类慢 SQL,日志里duration很长,但执行计划本身非常快,单独看 SQL 文本也挑不出毛病。这时候要怀疑 SQL 根本没在“执行”,而是卡在等锁。PostgreSQL 里的锁等待是隐性的,EXPLAIN ANALYZE不一定能完全看出来(等锁时间有一部分会计入执行时间),更直接的做法是查当前活动会话:

SELECT pid, state, wait_event_type, wait_event, now() - query_start AS query_runtime, query FROM pg_stat_activity WHERE state = 'active' AND now() - query_start > interval '5 seconds' ORDER BY query_runtime DESC;

如果某条 SQL 的wait_event是Lock: tuple或者Lock: relation,说明它在等锁。等锁的典型场景是:长事务持有行锁不提交,导致后续对同一行的更新全部排队。顺着pid去找持有锁的会话,再去看那个会话在跑什么事务,问题就清楚了。锁等待排查的关键是链路:先找到等待者,再通过锁视图找到持有者,最后分析持有者为什么不提交。慢查询日志在这里的角色是提供第一现场的耗时依据,没有它你甚至不知道该查哪条会话。

还有一种“慢”是连接耗尽造成的排队。日志里看到一堆查询同时出现,每条duration都不算太长,但业务反馈很卡,多半是连接池被打满,新请求在池子里排队等连接。这个问题只看数据库 CPU 往往看不出来,要看连接数曲线。慢查询日志的辅助价值在于告诉你这些查询确实在某个时间段集中出现,配合连接数监控才能完整还原现场。

4.5 场景四:写放大和 IO 瓶颈造成的隐性慢

执行计划解读还有一个不可忽视的方向:即使执行计划本身选型没问题,如果底层 IO 延迟很高,实际执行时间也会很夸张。这时候track_io_timing = on的价值就体现出来了——EXPLAIN (ANALYZE, BUFFERS)里会显示每个节点消耗了多少 IO 时间。如果你发现shared read数量巨大、IO 耗时占据大头,问题就不在 SQL 本身,而在磁盘性能或者缓存命中率。

这种场景下,单纯加索引优化 SQL 作用有限,要考虑提升磁盘性能、扩大shared_buffers,或者调整热点表的访问模式。我遇到过不少把 SQL 优化了几轮还是慢的情况,最后定位到是磁盘 IO 延迟过高,换成更高性能磁盘后立竿见影。永远记住:执行计划只告诉你 PostgreSQL 打算怎么做,实际的耗时还得看它落地到硬件上是什么表现。

5. 常见问题速查与避坑实录

5.1 典型问题速查表

把我在实际配置和排查中遇到的高频问题整理成一张表,遇到类似症状可以直接对照:

现象可能原因处理思路
日志文件一直不生成logging_collector未重启生效检查pg_settings.context,完整重启实例
改参数后 reload 不生效参数context是postmaster完整重启;确认ALTER SYSTEM已写入
日志文件把磁盘打满轮转参数没配或日志量过大配置log_rotation_size/age,定期清理归档
日志里出现大量短查询阈值设置过低调高log_min_duration_statement
日志时间与业务时间对不上时区不一致检查timezone和log_line_prefix里的%m
同一 SQL 在日志里刷屏语句文本未归一化用pg_stat_statements归并统计
执行计划rows与实际差 10 倍以上统计信息过期执行ANALYZE,必要时建扩展统计信息
EXPLAIN 快但实际慢存在锁等待或连接排队查pg_stat_activity.wait_event和连接数曲线
加了索引计划还是Seq Scan返回行数占比过高或统计不准重新ANALYZE,评估查询选择性后再决定

这张表是每次排查都会过一遍的心智清单。顺序是:先确认日志没问题,再确认计划没问题,最后怀疑环境和锁。如果跳过前两步直接看锁,很容易被表象带偏。

5.2 四条实操心得

最后分享几条比较主观但很实用的经验。

第一条,慢查询日志的参数要纳入配置管理,不要手工一台台改。用统一的配置模板下发,再写一个简单的巡检脚本,每天检查每台实例是否开启了慢查询日志、日志目录是否有增长。很多事故发生在“以为加了配置,实际没生效”的情况,巡检能兜底。

第二条,阈值不要一成不变。业务在增长,SQL 在变化,去年 1000ms 的阈值可能今年就不合适了。我习惯每季度重新评估一次,看日志量级和 TOP 慢查询分布,必要时微调。调阈值这件事不需要太频繁,但也不能放任不管,环境变了日志策略不变,迟早会失灵。

第三条,慢查询日志负责“找入口”,pg_stat_statements负责“做归并”,EXPLAIN ANALYZE负责“定根因”,三者的配合比任何一个单独的指标都重要。曾经有段时间我只盯着慢查询日志,结果被刷屏的归一化 SQL 淹没,真正的问题反而沉底了。后来把pg_stat_statements的 TOP N 查询做成定时任务,每天上班先看报告,效率高很多。这三件套配合起来,才是完整的慢 SQL 处理流水线。

第四条,注意慢查询日志和auto_explain的磁盘占用。宽松阈值加上大业务量,一天几十 GB 日志并不夸张。我会给日志目录单独挂一个分区,并设定保留天数,超过 N 天的压缩归档。千万别等到磁盘写满数据库自动停摆才想起来处理,那是最尴尬的运维事故。顺带说一句,日志目录单独挂分区的另一个好处是,即使日志爆炸也不会拖垮数据目录所在的磁盘。

我自己在实际操作中的体会是,开慢查询日志这件事,真正的难点从来不是那两条配置,而是你有没有一套从日志到执行计划再到根因的完整排查习惯。工具都给你了,关键是要在问题发生前把链路建好,等线上真出问题的时候,你打开日志直接用就行,不用现场查文档。希望你配好之后,能顺手做一次主动验证,把这条排查链路完整跑一遍。后面再遇到性能问题,你就是那个最先定位到 SQL 的人。

需要专业的网站建设服务?

联系我们获取免费的网站建设咨询和方案报价,让我们帮助您实现业务目标

立即咨询