PostgreSQL慢查询日志的开启与慢SQL排查这个话题看起来基础实际里面坑不少。我最早接触PostgreSQL是从MySQL转过来的当时最直观的感受就是日志配置的命名完全不讲道理。MySQL里慢查询日志开关叫slow_query_log参数直观开起来就完事。PostgreSQL里跟慢查询相关的一大堆参数log_min_duration_statement、log_statement、auto_explain还有一堆log_line_prefix、log_destination的格式参数第一次配置的时候很容易被绕晕。更让人头疼的是就算你费劲把日志开起来了打开日志文件一看满屏的duration: 1234.567 ms也只知道哪条SQL慢但为什么慢、瓶颈在哪日志根本不会直接告诉你。最后还是得靠EXPLAIN ANALYZE手动去分析。这篇文章我不打算讲那种教科书式的内容就结合我自己在实际项目里从零配置、到日志采集、再到慢SQL排查的全过程把那些文档里不会明说、但实际一定会踩的坑和技巧整理出来。1. 慢查询日志开启前先想清楚你究竟要解决什么问题很多人在配置PostgreSQL日志时犯的第一个错误就是一上来就改参数改完重启完事。但慢查询日志不是一个孤立的开关它牵涉到你后面整套的监控、告警、分析方案。你希望日志回答什么样的问题决定了你的配置思路所以第一步其实是明确需求。如果你只是想回答今天有没有特别慢的SQL那最简单的log_min_duration_statement1000就足够了超过1秒的SQL记下来就行。这个粒度很粗能帮你发现最严重的性能事故但你会发现大量问题根本抓不到。如果你的问题是某条特定SQL的执行计划为什么变了那单纯靠慢日志根本不够。你需要的其实是auto_explain它能把慢SQL当时的执行计划连同实际执行时间一起打出来这是排查执行计划劣化类问题的利器。如果你的问题是某个时间段数据库为什么CPU飙升那你甚至可能不需要慢日志而是要开pg_stat_statements做全量SQL的统计聚合配合系统指标去看哪类SQL在某个时段集中变慢。慢日志是抽样pg_stat_statements是全景两者解决的问题完全不同。我在一个实际项目中就经历过这种转变。最初只开了log_min_duration_statement某天线上出现CPU 100%的告警打开日志发现确实有大量慢SQL但都是同一条UPDATE。这条SQL平时执行只要50毫秒突然变成5秒日志里却完全看不出原因。后来才发现是某次大批量导入数据导致表膨胀执行计划从索引扫描退化成了顺序扫描。这种问题用慢日志加auto_explain才能定位如果只有duration日志你只能看到现象抓不到根因。所以配置之前先想清楚你的核心诉求。最合理的做法通常是组合拳log_min_duration_statement抓慢SQL明细auto_explain抓慢SQL的执行计划细节pg_stat_statements做总量和趋势分析。三者互补覆盖不同的排查场景。1.1 配置参数前必须理解的几个日志开关PostgreSQL里跟查询日志相关的参数主要有这么几个很多人容易混log_statement控制的是什么样的SQL语句被记录可选值是none、ddl、mod、all。这个参数只管记录SQL文本跟执行时间没有关系。也就是说即使一条SQL执行了10分钟只要log_statementall没开它也不会被记录反过来即使一条SQL只执行了1毫秒只要log_statementall开了它也会被记下来。这个参数更多用于审计场景排查慢SQL时一般不开all否则日志量会非常恐怖。log_min_duration_statement才是真正的慢查询阈值。设置为1000表示执行时间超过1000毫秒的语句会被记录同时还会带上执行时间。设置为0时记录所有语句负数则禁用。这个参数是排查慢SQL的核心开关但它只记录执行时间超过了阈值的语句超过这个判断发生在语句执行完毕之后。所以它抓不到仍在执行中的长事务也抓不到被锁阻塞而卡住的语句——这一点后面会详细讲。auto_explain是PostgreSQL内置的一个模块需要在postgresql.conf中通过shared_preload_libraries加载然后配置auto_explain.log_min_duration来设置阈值的毫秒数。它会在SQL执行完成后自动输出EXPLAIN结果把你手工执行EXPLAIN ANALYZE的环节自动化了。排查执行计划劣化类问题这个模块几乎是杀手锏。这三个参数关系是log_statement控制记不记SQL文本log_min_duration_statement控制记不记慢SQL并显示耗时auto_explain控制慢SQL附带的执行计划。实践中我通常是log_statement保持默认的nonelog_min_duration_statement给一个合理的阈值auto_explain的阈值跟慢日志保持一致或略低让所有慢SQL都自动带上执行计划。1.2 日志参数的最佳实践组合我目前比较推荐的参数组合是下面这一套兼顾了排查能力和日志量控制。当然具体数值要根据业务情况调整但思路可以参考log_destination csvlog logging_collector on log_min_duration_statement 1000 log_line_prefix %m [%p] %q%u%d log_checkpoints on log_connections on log_disconnections on log_lock_waits on log_temp_files 0shared_preload_libraries auto_explain auto_explain.log_min_duration 1000 auto_explain.log_analyze on auto_explain.log_buffers on auto_explain.log_verbose on auto_explain.log_format text这套配置最大的好处是超过1秒的SQL会连执行计划一起打出来锁等待超过deadlock_timeout的会话也会被标记临时文件超过0字节会记录连接和断开也会记录。配合log_line_prefix里带上时间、进程号、用户和数据库名日志的可读性和可追溯性会好很多。 有一个参数容易忽略log_lock_waits。默认是off开启后如果会话等待锁超过了deadlock_timeout默认1秒日志里会输出一条PROCESS 1234 still waiting for AccessShareLock after 1000.123 ms这样的记录。线上很多慢SQL其实不是SQL本身慢而是被别的会话持有的锁堵住了。有了这个参数一眼就能看出是锁等待而不是语句本身性能差。 log_temp_files0也很实用。SQL执行过程中产生了临时文件比如排序内存不够落盘了如果超过这个大小就会被记录。这条日志的价值在于它提示你work_mem可能设置得太小了——很多SQL变慢不是CPU问题而是因为排序、哈希操作被迫写磁盘。 ## 2. 慢SQL排查的核心手段从日志文本到执行计划 日志开启只是第一步。接下来要处理的问题就是日志有了怎么把它变现为可执行的优化动作。这才是我认为整个慢查询排查流程里最核心的部分。 先说结论PostgreSQL日志本身能告诉你的信息非常有限。它只能告诉你这条SQL超过了阈值耗时多少如果开了auto_explain还能多告诉你当时的执行计划长什么样。但为什么慢的答案往往还需要你主动去EXPLAIN ANALYZE验证甚至需要结合表结构、索引情况、数据分布来综合判断。 慢SQL排查的标准工作流我一般拆成四步第一步从日志中找出目标慢SQL第二步提取SQL并查看执行计划第三步分析执行计划的瓶颈点确认是什么操作导致慢第四步针对瓶颈做优化通常是加索引、改SQL写法、调整参数或改表结构优化后再用EXPLAIN ANALYZE验证效果。 ### 2.1 从日志中提取慢SQL的几种方式 日志文件如果量不大直接用grep就能把慢SQL捞出来 bash grep duration: /var/log/postgresql/postgresql.csv | grep ms | sort -t: -k2 -rn | head -20这条命令会把所有带duration的行找出来按时间倒序排取出最慢的20条。但这是最原始的做法日志量大之后基本没法用。为什么我上面推荐csvlog因为csv格式的日志可以用工具直接解析字段是固定的方便后续处理。important一点是csvlog默认文件命名是postgresql-YYYY-MM-DD_HHMMSS.csv如果你配了logging_collectoron一定要设置log_rotation_age和log_rotation_size否则日志文件会无限增长。一般建议log_rotation_age 1d每天一个文件log_rotation_size 100MB超过100MB也轮转。这两个参数配合起来日志管理会省心很多。如果你有日志采集系统比如ELK或者Loki直接把csvlog日志filebeat采集进去用kibana按duration字段排序就行。这一段我暂时跳过工具细节回到SQL本身。执行时间超过2秒的SQL才是需要重点关注的对象如果一条SQL慢日志里出现频率特别高即使单次执行时间不算太长也是需要关注的——积少成多QPS高的时候单条200毫秒的SQL也能拖垮数据库。捞出来之后仔细观察执行时间分布和SQL规律比如是不是某个时间段集中出现是不是某几条SQL反复出现是不是跟某些业务操作有关联。这些规律是定位问题的线索来源。2.2 从EXPLAIN看懂执行计划快速锁死瓶颈点拿到慢SQL之后我几乎无条件地做这样一件事拿这条SQL到数据库里跑一遍EXPLAIN ANALYZE把执行计划打出来。注意这里的一个关键细节不要直接在生产库上执行EXPLAIN ANALYZE。 ANALYZE关键字会真实执行SQL如果是UPDATE、DELETE或复杂的SELECT可能造成锁、写放大甚至临时表空间膨胀。我会先确认SQL类型如果只是SELECT同时数据量可控那直接在测试环境执行更好。如果必须验证生产建议用EXPLAIN ANALYZE放到事务里包一层再回滚至少能规避数据被改动的问题BEGIN; EXPLAIN ANALYZE SELECT ...; ROLLBACK;然后怎么读执行计划两个维度执行时间和行数估算。拿下面这段执行计划举例Seq Scan on orders (cost0.00..687.61 rows15361 width42) (actual time0.015..12.546 rows15000 loops1) Filter: (status PENDING::text) Rows Removed by Filter: 985000 Planning time: 0.053 ms Execution time: 12.600 msrows15361是优化器基于统计信息估算的行数actual rows15000是真实返回的行数。这里估算和实际接近没什么问题。但如果估算和实际差了一个数量级那大概率是统计信息过期了需要跑一次ANALYZE或者调整统计信息相关参数。这就是为什么很多玄学变慢其实是统计信息不准导致的不是SQL本身的问题。再看时间Seq Scan阶段actual time是0.015..12.546毫秒总执行时间12.6毫秒。对于一个扫了100万行的查询来说这个速度已经算可以了。但如果这条SQL在慢日志里出现说明什么说明这条SQL平时可能只要5毫秒某段时间数据量增长或者统计信息变化后优化器放弃了原本可以用的索引选择了顺序扫描导致执行计划劣化。继续往下看关键的瓶颈标记。执行计划里最值得关注的是这些迹象Seq Scan出现在大表上说明没有有效索引可用或者优化器认为索引不如顺序扫描。如果表很大而且这个SQL频繁执行这基本就是慢的根源。Index Scan / Bitmap Index Scan后跟大量rows如果索引扫描了10万行但最终只返回100行说明索引选择性太差索引本身没有有效过滤。rows估算和actual差了数量级统计信息不准。此时VACUUM ANALYZE表通常能解决问题。Sort节点挂在后面且用了大量内存或落盘说明ORDER BY字段没有走索引或者work_mem太小导致排序落盘。Nested Loop循环次数巨大说明连接条件没走索引驱动表和被驱动表的关系有问题。Hash Join时的Hash条件行数估算严重不准同样指向统计信息问题。这些迹象在慢日志里看不到在auto_explain的执行计划输出里能看到这就是为什么我前面不建议只开log_min_duration_statement一个参数。3. 完整排查流程从日志告警到SQL优化落地这一部分我拿一个实际案例完整走一遍方便你理解整个流程是怎么串起来的。这个案例来自一个真实的线上系统业务是电商订单系统所以里面的表名、字段名我做了脱敏处理但排查思路和操作步骤是完整的。3.1 从一条慢日志开始某天监控告警提示订单库的CPU使用率持续在90%以上打开慢日志发现这样一条记录2025-11-08 14:23:45.678 CST [12345] userorderdb LOG: duration: 5821.234 ms statement: SELECT o.id, o.order_no, o.amount, u.username, u.phone FROM orders o LEFT JOIN users u ON o.user_id u.id WHERE o.status PENDING ORDER BY o.created_at DESC LIMIT 20;执行时间5.8秒这显然不正常。通常这种查询在几百毫秒以内。接下来不要直接去改SQL先明确几个问题这条SQL平时多久执行一次它在慢日志里出现了几次是偶发还是持续出现数据量和表结构是什么情况查看慢日志中同一条SQL的出现频率发现这个SQL在过去两个小时内出现次数并不多一共三次时间点比较分散。这说明它不是高频SQL但是每次执行都很慢属于偶发性能问题。再看表的基本情况。3.2 通过EXPLAIN定位瓶颈我先在测试环境复现这条SQL得到执行计划。测试环境的数据量结构和线上一致但数据量可能少一些结果Limit (cost0.00..1.27 rows20 width78) (actual time5123.456..5123.478 rows20 loops1) - Nested Loop Left Join (cost0.00..98123.45 rows15361 width78) (actual time5123.445..5123.468 rows20 loops1) Join Filter: (o.user_id u.id) - Seq Scan on orders o (cost0.00..687.61 rows15361 width42) (actual time12.546..12.546 rows15000 loops1) Filter: (status PENDING::text) Rows Removed by Filter: 985000 - Materialize (cost0.00..44.12 rows2412 width36) (actual time0.001..4.234 rows20 loops15000) - Seq Scan on users u (cost0.00..32.12 rows2412 width36) (actual time0.002..0.834 rows2412 loops1) Planning time: 0.053 ms Execution time: 5124.110 ms从执行计划可以看出几个问题orders表上有一个status PENDING的过滤条件但执行计划选择了Seq Scan说明这个表上(status)列没有索引或者优化器认为rows15361的行数不值得走索引。问题的关键在于这个表有100万行数据而满足status PENDING的有15000行占比约1.5%。对PostgreSQL来说这个比例完全应该走索引。再看users表执行计划里Materialize出现是一个非常糟糕的信号。这意味着对于orders表的每一行15000行都要去users表里扫描一次2412行总共扫描了15000次。虽然users表只有2412行但扫描15000次累计耗时也远超预期。这里索引缺失或者连接条件没走索引都是可能的。综合看下来核心瓶颈就是orders表上的全表扫描和users表上的反复扫描。我的判断是orders表需要加一个status created_at的复合索引因为查询里既用了status过滤又用了created_at排序。users表的user_id主键已经存在理论上LEFT JOIN应当走索引但从执行计划看确实没有走。检查users表的主键定义发现user_id确实有主键索引但执行计划里选择的是Seq Scan这说明优化器基于成本比较认为与其走索引再回表不如直接扫描这张小表更划算。这是PostgreSQL典型的小表扫描策略有一点无奈但也不是错关键优化方向还是想办法让orders表这一侧少输出行数。3.3 优化操作与效果验证优化动作分两步第一步在orders表上创建复合索引CREATE INDEX idx_orders_status_created_at ON orders(status, created_at DESC);这里选择(status, created_at)的组合既满足WHERE过滤又满足ORDER BY排序可以避免sort。DESC关键字是因为查询里是ORDER BY created_at DESC如果只写created_atPostgreSQL也能用但带上DESC能在排序方向上省一点开销。第二步重新执行EXPLAIN ANALYZE验证效果Limit (cost0.28..3.56 rows20 width78) (actual time0.234..0.318 rows20 loops1) - Index Scan using idx_orders_status_created_at on orders o (cost0.28..3.56 rows20 width42) (actual time0.231..0.312 rows20 loops1) Index Cond: (status PENDING::text) - Nested Loop Left Join (cost0.28..3.56 rows20 width78) (actual time0.228..0.308 rows20 loops1) - Index Scan using idx_orders_status_created_at on orders o (cost0.28..3.56 rows20 width42) (actual time0.228..0.294 rows20 loops1) Index Cond: (status PENDING::text) - Memoize (cost0.44..8.89 rows1 width36) (actual time0.001..0.001 rows1 loops20) Cache Key: u.id Cache Mode: logical - Index Scan using users_pkey on users u (cost0.44..8.89 rows1 width36) (actual time0.002..0.009 rows1 loops20) Index Cond: (id o.user_id)执行时间从5124毫秒降到0.3毫秒效果立竿见影。这里有个细节执行计划里出现了Memoize节点这是PostgreSQL 14及以上版本的一个缓存机制它会对users表的查询结果做哈希缓存。因为orders表输出20行后LIMIT 20就停止了所以users表只被查询了20次每次都是走主键索引性能自然就上来了。这再次说明优化orders表的过滤和排序才是根本users表侧的问题会随着驱动行数的减少自动消失。这个案例的核心思路就是先用索引消除大表上的顺序扫描让驱动行数降到很小的数量级后半段的连接问题自然就解决了。这也是排查大多数慢SQL的基本思路。4. 常见问题与排查避坑经验这部分我整理了一下这几年做PostgreSQL慢查询排查过程中遇到的高频问题和一些经常被忽略的坑希望对你有帮助。4.1 日志配置常见踩坑点第一个坑是log_min_duration_statement设置了但一直没生效。如果改的是postgresql.conf需要reload配置不是重启。可以执行SELECT pg_reload_conf()或者用pg_ctl reload。这里有个隐藏点如果配置的是用户级参数ALTER USER ... SET log_min_duration_statement 1000那只有该用户的会话才生效。排查问题时会发现日志里有些SQL不够慢但被记了有些SQL慢但没被记一脸懵。所以配置要分清数据库级、用户级和会话级优先在postgresql.conf里配全局的。第二个坑是log_destination选了stderr但不知道日志去哪了。如果你没开logging_collector日志会写到stderr通常是系统日志或者postgres进程的启动终端。要想统一管理必须开logging_collector并配合log_directory和log_filename。第三个非常容易踩的坑开启了auto_explain但没把它加进shared_preload_libraries。auto_explain跟log_min_duration_statement不一样它必须预加载才能生效。如果你只在postgresql.conf里写了auto_explain.log_min_duration但没有shared_preload_librariesauto_explain那模块根本没被加载参数会提示不存在或者直接忽略。我见过不止一次这种配置看似开了实际没开的情况。检查是否生效的办法很简单SHOW shared_preload_libraries; 看有没有auto_explainSHOW auto_explain.log_min_duration; 看阈值有没有成功设置。另外提醒一个细节auto_explain记录的执行计划文本会作为一条单独的日志输出里面带了duration字样但它的格式跟普通慢日志不一样。在采集时要注意区分避免日志解析错误。4.2 SQL执行慢但没进慢日志的几种情况这个现象很反直觉但实际发生概率还不低。第一种情况是SQL执行时间没超过log_min_duration_statement但它占用的CPU或者IO已经很高了。比如一条SQL执行了900毫秒阈值设置的是1000毫秒它就不会被记录。但因为QPS高900毫秒的SQL反复执行累积效应也会拖垮数据库。所以阈值的设定需要结合业务情况不要一味求大。第二种情况是语句被阻塞在锁等待上。log_min_duration_statement统计的是语句执行的总时间包括锁等待时间。但默认情况下锁等待本身是不会单独记录的。如果你没开log_lock_waits你只会在慢日志里看到一条SQL执行了很久却不知道它其实是在等锁。开了log_lock_waits之后日志里会明确告诉我们waiting for lock并且这个等待有可能是死锁检测的一部分或者是简单的行级锁竞争。第三种情况是事务特别长里面包含大量小语句。每条小语句都不超过阈值但整个事务执行时间很长这种情况慢日志是抓不到的。解决思路是用pg_stat_activity实时监控长事务或者加大log_min_duration_statement再配合log_statementmod来记录修改语句。4.3 排查过程中的几条实操心得第一是关于统计信息的。PostgreSQL的优化器是基于成本的而成本估算依赖表的统计信息。如果统计信息过期即便索引正确优化器也可能选错执行计划。所以我发现执行计划异常的时候第一件事会检查统计信息是否更新而不是急着加索引。可以查pg_stats里最后一行的last_analyze或者直接跑ANALYZE。实际工作中定期维护VACUUM ANALYZE是很有必要的特别是那些频繁UPDATE的表。第二是关于work_mem和排序落盘的。排序、哈希这些操作如果内存不够PostgreSQL会把中间结果写到磁盘临时文件。临时文件的IO开销非常大经常是SQL变慢的隐形杀手。log_temp_files0开启之后任何临时文件都会记录下来。如果发现慢SQL总是伴随temp file日志出现那就说明work_mem不够可以适当调大。但work_mem是每个会话每次排序操作允许使用的内存上限调太大也可能导致内存耗尽所以一般建议256MB到1GB之间根据实际情况调整不要追求极端。第三是执行计划里的估算行数跟实际行数差异巨大的情况很多时候不是索引问题而是统计信息或关联列相关性导致优化器判断偏差。这种情况加索引没用反而应该检查是否需要更新统计信息或者考虑使用扩展统计信息CREATE STATISTICS来让优化器更好地估算多列相关性。最后再分享一个容易被忽略的小技巧当你定位到一条SQL因为全表扫描变慢时不要急着加索引。先确认这个表的数据量是不是膨胀了也就是大量UPDATE和DELETE之后留下的死元组。因为查询的时候PostgreSQL扫描的顺序扫描也会读死元组数据膨胀严重的话即使逻辑行数没变物理IO会大幅增加。这个检查可以用一个简单的查询SELECT relname, n_live_tup, n_dead_tup FROM pg_stat_user_tables WHERE relname orders;如果n_dead_tup很大VACUUM一下可能比加索引更有效。根据我个人经验慢查询排查从来不是一个一次性的工作。数据库在变数据量在涨业务查询模式在迭代今天不改的SQL三个月后可能就成了新的瓶颈。所以慢查询日志的开启和排查不只是为了解决当下的问题更是为后续的数据库健康度监测打基础。建议每个项目上线之初就按照前面的配置把日志基础打好并且隔一段时间就回头看一眼慢日志的变化趋势不要等出了告警才去接日志。等到线上出问题再开日志往往会错过第一现场。
