当您试图找出 Postgres 查询缓慢的原因时，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 ms。
为了了解排序花费了多少时间，而不是一起扫描和排序，我们可以减去 0.054 - 0.018 = 0.036 ms。
注意循环
查询计划中的计时不直接的下一个最大原因是时间统计是每个循环的平均值（平均值）。所以当循环次数大于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
我们可以看到单个索引扫描 (loops=1) 需要0.019 ms。
索引扫描行报告 loops=9，因此我们需要乘以 0.028 * 9 = 0.252 ms。
这很重要，因为我们现在可以看到，它占其父操作（嵌套循环）报告的时间的很大一部分 (0.252 / 0.335 = 75%)。
我们可以通过减去它的孩子的总数来计算嵌套循环的额外开销，就像我们上面所做的一样：0.335 - 0.019 - 0.252 = 0.064 ms。
并行计时也有点棘手
当操作并行完成时，PostgreSQL 会将线程数报告为循环。这意味着上面的部分已经涵盖了计算 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 个线程（循环）：Worker 0，Worker 1，加上主线程。平均而言，他们花费了 7178.509 毫秒。
(7178.509 * 3) - 7160.961 - 7108.307 = 7266.259ms
通过将平均值乘以 3 并减去工作时间，我们可以看到主线程占用了三个中最长的时间，因此我们可以将其用作更准确的操作挂钟时间估计。
围绕 CTE 的一些微妙之处
如果 Postgres 选择实现 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
如果我们仔细观察，我们可以看到 ~ 300ms 被报告了两次，一次是在 CTE Scans and Limit 中，一次是在 Append 中（它是 children）。在这个简单的例子中，我们可以很容易地捕捉到这一点，但在更复杂的情况下，它可能会引起混淆，值得留心。
可以提供帮助的工具
有一些工具会尝试为您进行这些按操作的计时计算，较流行的是explain.depesz和explain.dalibo（基于亚历克斯Tatiyant的PEV），这两个工具的基础很好。
Felix 的Flame Explain着重于尝试获得准确的每次操作计时，即使在最复杂的情况下也是如此。使用pgMustard，我们付出了很多努力来很好地计算和显示这些，并添加关于可能加快查询速度的建议。
但是正如我们所看到的，可能会涉及一些微妙之处，准确度甚至可能取决于您使用的参数（例如 VERBOSE），因此即使是工具也很难做到这一点！如有疑问，我经常在第二个工具中检查时间。
我希望这能帮助您掌握一两个技巧，如果是这样，很高兴收到您的来信。
