八月 25, 2025
摘要：当你想弄清楚 PostgreSQL 查询为何执行缓慢时，EXPLAIN ANALYZE会提供极大帮助，但计算每个操作的耗时却可能会十分复杂。
目录
基础原理
首先需要明确的是，执行计划中父操作的耗时包含其所有子操作的耗时。因此，若要了解父操作本身的耗时，需用父操作的耗时减去所有子操作的耗时。
以一个小表的扫描与排序操作为例（为简洁起见，省略成本统计信息）：
Sort (actual time=0.049..0.054 rows=51 loops=1)
Sort Key: c DESC
Sort Method: quicksort Memory: 31kB
-> Seq Scan on t (actual time=0.012..0.018 rows=51 loops=1)
Planning time: 0.064 ms
Execution time: 0.077 ms
在查询计划的下方，我们可以看到顺序扫描操作的实际总耗时为 0.018 毫秒。
其上层父操作 “排序” 的实际总耗时为 0.054 毫秒。
若要单独计算 “排序” 操作本身的耗时（而非 “扫描 + 排序” 的总耗时），可通过减法得出：0.054 - 0.018 = 0.036 毫秒。
循环次数（loops）的影响
查询计划中耗时计算不直观的另一大原因是：时间统计数据均为每轮循环的平均值。因此，当循环次数（loops）大于 1 时，需将 “实际总耗时” 乘以 “循环次数”，才能得到该操作的真实总耗时。
下面是一个简单的嵌套循环示例：
Nested Loop (actual time=0.061..0.335 rows=86 loops=1)
-> Index Only Scan using i on t (actual time=0.014..0.019 rows=9 loops=1)
Index Cond: (id < 10)
Heap Fetches: 0
-> Index Scan using i2 on t2 (actual time=0.011..0.028 rows=10 loops=9)
Index Cond: (id = t.id)
Planning Time: 0.802 ms
Execution Time: 0.412 ms
从计划中可知 Index Only Scan 操作的循环次数为 1（loops=1），耗时 0.019 毫秒；
Index Scan 操作的循环次数为 9（loops=9），计算出的真实总耗时：0.028 × 9 = 0.252 毫秒。
这一计算非常重要。由此可见，Index Scan 操作的耗时占其父操作 “嵌套循环” 总耗时的比例高达 75%（0.252 / 0.335 = 75%）。
与前面方法类似，嵌套循环本身的额外开销（非子操作耗时）可通过这样计算得出：0.335 - 0.019 - 0.252 = 0.064 毫秒。
并行操作的耗时计算更复杂
当操作以并行方式执行时，PostgreSQL 会将进程数量记录为 “循环次数”（loops）。这意味着，前文介绍的方法可用于计算CPU 时间，但由于操作是并行执行的，该时间并非 “时钟上的时间”（即实际流逝时间）。
若要估算时钟上的时间，可先参考 “每轮循环平均值”；若需更精确的结果，可使用VERBOSE参数获取单个工作进程的耗时，取其中耗时最长的作为该操作的时钟总耗时（通常会是主导进程，若其参与执行的话）。需注意：主导进程不会直接上报自身的统计数据，需通过总耗时减去其他工作进程的耗时来推算，而这一步的计算更加复杂。
下面是使用EXPLAIN (ANALYZE, VERBOSE)（详细模式）得到的示例：
-> Parallel Seq Scan on s.t
(actual time=4.095..7178.509 rows=236170 loops=3)
Output: c1, c2, c3
Worker 0: actual time=0.118..7160.961 rows=247183 loops=1
Worker 1: actual time=0.151..7108.307 rows=227603 loops=1
从计划中可知，共有 3 个进程（loops=3）：Worker 0、Worker 1，以及主进程。各进程的平均耗时为 7178.509 毫秒。
(7178.509 * 3) - 7160.961 - 7108.307 = 7266.259 毫秒
结果显示，主进程是三个进程中耗时最长的，因此可将该值作为该并行操作更精确的时钟时间估算值。
关于公共表表达式（CTE）的一些细微问题
若 PostgreSQL 选择将 CTE “物化”（例如，因 CTE 在查询中被多次引用），则 “用父操作耗时减去子操作耗时” 的简单逻辑会不再适用。
下面是一个刻意简化的查询示例，该查询中 CTE 被引用了两次，便于跟踪耗时：
WITH init AS (
SELECT * FROM pg_sleep_for('100ms')
UNION ALL
SELECT * FROM pg_sleep_for('200ms')
)
(SELECT * FROM init LIMIT 1)
UNION ALL
(SELECT * FROM init);
使用EXPLAIN (ANALYZE, COSTS OFF)查看执行计划，简化输出：
Append (actual time=102.409..302.675 rows=3 loops=1)
CTE init
-> Append (actual time=102.397..302.649 rows=2 loops=1)
-> Function Scan on pg_sleep pg_sleep_for (actual time=102.396..102.398 rows=1 loops=1)
-> Function Scan on pg_sleep pg_sleep_for_1 (actual time=200.243..200.245 rows=1 loops=1)
-> Limit (actual time=102.407..102.409 rows=1 loops=1)
-> CTE Scan on init init_1 (actual time=102.402..102.402 rows=1 loops=1)
-> CTE Scan on init (actual time=0.001..200.256 rows=2 loops=1)
Planning Time: 47.003 ms
Execution Time: 303.905 ms
仔细观察可发现：约 300 毫秒的耗时被上报了两次：一次出现在 “CTE 扫描（CTE Scan）” 和 “限制（Limit）” 操作中，另一次出现在 “合并（Append）” 及其子操作中。在这个简单示例中，我们很容易发现问题，但在更复杂的场景中，这种重复统计可能引发混淆，需特别留意。