log_duration和\时间可重复地远高于“总运行时间”。从解释分析 [英] log_duration and \timing times repeatably much higher than "Total runtime" from explain analyze

问题描述

这个查询是奇怪的，根据我的

log_duration日志并根据psql的\timing数字似乎需要一秒钟。然而，解释

分析表明它在大约三分之一秒内运行。


会导致什么？是某种postgresql.conf配置

失败？我在同一台机器上运行正常的查询。

查询计划

-------------------- -------------------------------------------------- -------------------------------------------------- -------------------------------------------------- ------

限制（成本= 15.12..15.13行= 1宽度= 2315）（实际时间= 315.15..315.15行= 2个循环= 1）

- >排序（成本= 15.12..15.13行= 1宽度= 2315）（实际时间= 315.14..315.14行= 2循环= 1）

排序键：x_title_xform，baz_xform，xfrm_en（（qux_name） :: text）

- >子查询扫描x（成本= 0.00..15.11行= 1宽度= 2315）（实际时间= 314.20..314.99行= 2个循环= 1）

- >限制（成本= 0.00..15.11行= 1宽度= 2315）（实际时间= 283.95..284.64行= 2个循环= 1）

- >嵌套循环（成本= 0.00..15.11行= 1宽度= 2315）（实际时间= 283.95..284.64行= 2个循环= 1）

- >嵌套循环（成本= 0.00..11.92行= 1宽度= 1569）（实际时间= 0.16..0.22行= 2个循环= 1）

- >在foo上使用foo_pkey进行索引扫描（成本= 0.00..3.20行= 1宽度= 1561）（实际时间= 0.07..0.07行= 1个循环= 1）

索引条件：（foo_id = 815 ）

- >使用bar_foo上的idx_bar_foo_loc进行索引扫描（成本= 0.00..8.64行= 7宽度= 8）（实际时间= 0.06..0.09行= 2个循环= 1）

索引条件:(外部 ; .foo_id = bar_foo.foo_id）

- >使用条形图上的bar_pkey进行索引扫描（成本= 0.00..3.18行= 1宽度= 746）（实际时间= 0.07..0.07行= 1个循环= 2）

索引条件:(外部 ; .bar_id = bar.bar_id）

过滤：（bar_type_code<>''s'':: bpchar）

SubPlan

- >聚合（成本= 6.05..6.05行= 1宽度= 59）（实际时间= 30.26..30.27行= 1个循环= 2）

- >子查询扫描x（成本= 6.05..6.05行= 1宽度= 59）（实际时间= 30.25..30.25行= 1个循环= 2）

- >排序（成本= 6.05..6.05行= 1宽度= 59）（实际时间= 30.24..30.24行= 1个循环= 2）

排序键：xfrm_en（qux.short_name）

- >嵌套循环（成本= 0.00..6.04行= 1宽度= 59）（实际时间= 30.14..30.16行= 1个循环= 2）

- >在bar_qux上使用idx_bar_qux_bar进行索引扫描（成本= 0.00..2.85行= 1宽度= 4）（实际时间= 0.03..0.03行= 1个循环= 2）

索引条件：（bar_id = $ 0 ）

- >在qux上使用qux_pkey进行索引扫描（成本= 0.00..3.05行= 1宽度= 55）（实际时间= 0.02..0.03行= 1个循环= 2）

索引条件:(外部 ; .qux_id = qux.qux_id）

- >聚合（成本= 2.85..2.85行= 1宽度= 0）（实际时间= 0.03..0.03行= 1个循环= 2）

- >在bar_qux上使用idx_bar_qux_bar进行索引扫描（成本= 0.00..2.85行= 1宽度= 0）（实际时间= 0.02..0.02行= 1个循环= 2）

索引条件：（bar_id = $ 0 ）

- >限制（成本= 0.00..5.80行= 1宽度= 80）（实际时间= 0.05..0.06行= 1个循环= 2）

- >嵌套循环（成本= 0.00..6.04行= 1宽度= 80）（实际时间= 0.05..0.05行= 1个循环= 2）

- >在bar_qux上使用idx_bar_qux_bar进行索引扫描（成本= 0.00..2.85行= 1宽度= 4）（实际时间= 0.01..0.02行= 1个循环= 2）

索引条件：（bar_id = $ 0 ）

- >在qux上使用qux_pkey进行索引扫描（成本= 0.00..3.05行= 1宽度= 76）（实际时间= 0.02..0.02行= 1个循环= 2）

索引条件:(外部 ; .qux_id = qux.qux_id）

- >限制（成本= 0.00..2.74行= 1宽度= 4）（实际时间= 0.02..0.02行= 1个循环= 2）

- >在bar_qux上使用idx_bar_qux_bar进行索引扫描（成本= 0.00..2.85行= 1宽度= 4）（实际时间= 0.01..0.01行= 1个循环= 2）

索引条件：（bar_id = $ 0 ）

总运行时间：316.19毫秒

（37行）


时间：1333.72毫秒

-

greg

---------------------------（播出结束）---------------------------

提示5：您是否查看了我们广泛的常见问题解答？

http://www.postgresql.org/docs/ faqs / FAQ.html

解决方案

0）

- >在qux上使用qux_pkey进行索引扫描（成本= 0.00..3.05行= 1宽度= 55）（实际时间= 0.02..0.03行= 1个循环= 2）

索引条件:(外部 ; .qux_id = qux.qux_id）

- >聚合（成本= 2.85..2.85行= 1宽度= 0）（实际时间= 0.03..0.03行= 1个循环= 2）

- >在bar_qux上使用idx_bar_qux_bar进行索引扫描（成本= 0.00..2.85行= 1宽度= 0）（实际时间= 0.02..0.02行= 1个循环= 2）

索引条件：（bar_id =

0）

- >限制（成本= 0.00..5.80行= 1宽度= 80）（实际时间= 0.05..0.06行= 1个循环= 2）

- >嵌套循环（成本= 0.00..6.04行= 1宽度= 80）（实际时间= 0.05..0.05行= 1个循环= 2）

- >在bar_qux上使用idx_bar_qux_bar进行索引扫描（成本= 0.00..2.85行= 1宽度= 4）（实际时间= 0.01..0.02行= 1个循环= 2）

索引条件：（bar_id =

0）

- >在qux上使用qux_pkey进行索引扫描（成本= 0.00..3.05行= 1宽度= 76）（实际时间= 0.02..0.02行= 1个循环= 2）

索引条件:(外部 ; .qux_id = qux.qux_id）

- >限制（成本= 0.00..2.74行= 1宽度= 4）（实际时间= 0.02..0.02行= 1个循环= 2）

- >在bar_qux上使用idx_bar_qux_bar进行索引扫描（成本= 0.00..2.85行= 1宽度= 4）（实际时间= 0.01..0.01行= 1个循环= 2）

索引条件：（bar_id =

This query is odd, it seems to be taking over a second according to my
log_duration logs and according to psql''s \timing numbers. However explain
analyze says it''s running in about a third of a second.

What would cause this? Is it some kind of postgresql.conf configuration
failure? I have the same query running fine on a different machine.
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Limit (cost=15.12..15.13 rows=1 width=2315) (actual time=315.15..315.15 rows=2 loops=1)
-> Sort (cost=15.12..15.13 rows=1 width=2315) (actual time=315.14..315.14 rows=2 loops=1)
Sort Key: x_title_xform, baz_xform, xfrm_en((qux_name)::text)
-> Subquery Scan x (cost=0.00..15.11 rows=1 width=2315) (actual time=314.20..314.99 rows=2 loops=1)
-> Limit (cost=0.00..15.11 rows=1 width=2315) (actual time=283.95..284.64 rows=2 loops=1)
-> Nested Loop (cost=0.00..15.11 rows=1 width=2315) (actual time=283.95..284.64 rows=2 loops=1)
-> Nested Loop (cost=0.00..11.92 rows=1 width=1569) (actual time=0.16..0.22 rows=2 loops=1)
-> Index Scan using foo_pkey on foo (cost=0.00..3.20 rows=1 width=1561) (actual time=0.07..0.07 rows=1 loops=1)
Index Cond: (foo_id = 815)
-> Index Scan using idx_bar_foo_loc on bar_foo (cost=0.00..8.64 rows=7 width=8) (actual time=0.06..0.09 rows=2 loops=1)
Index Cond: ("outer".foo_id = bar_foo.foo_id)
-> Index Scan using bar_pkey on bar (cost=0.00..3.18 rows=1 width=746) (actual time=0.07..0.07 rows=1 loops=2)
Index Cond: ("outer".bar_id = bar.bar_id)
Filter: (bar_type_code <> ''S''::bpchar)
SubPlan
-> Aggregate (cost=6.05..6.05 rows=1 width=59) (actual time=30.26..30.27 rows=1 loops=2)
-> Subquery Scan x (cost=6.05..6.05 rows=1 width=59) (actual time=30.25..30.25 rows=1 loops=2)
-> Sort (cost=6.05..6.05 rows=1 width=59) (actual time=30.24..30.24 rows=1 loops=2)
Sort Key: xfrm_en(qux.short_name)
-> Nested Loop (cost=0.00..6.04 rows=1 width=59) (actual time=30.14..30.16 rows=1 loops=2)
-> Index Scan using idx_bar_qux_bar on bar_qux (cost=0.00..2.85 rows=1 width=4) (actual time=0.03..0.03 rows=1 loops=2)
Index Cond: (bar_id = $0)
-> Index Scan using qux_pkey on qux (cost=0.00..3.05 rows=1 width=55) (actual time=0.02..0.03 rows=1 loops=2)
Index Cond: ("outer".qux_id = qux.qux_id)
-> Aggregate (cost=2.85..2.85 rows=1 width=0) (actual time=0.03..0.03 rows=1 loops=2)
-> Index Scan using idx_bar_qux_bar on bar_qux (cost=0.00..2.85 rows=1 width=0) (actual time=0.02..0.02 rows=1 loops=2)
Index Cond: (bar_id = $0)
-> Limit (cost=0.00..5.80 rows=1 width=80) (actual time=0.05..0.06 rows=1 loops=2)
-> Nested Loop (cost=0.00..6.04 rows=1 width=80) (actual time=0.05..0.05 rows=1 loops=2)
-> Index Scan using idx_bar_qux_bar on bar_qux (cost=0.00..2.85 rows=1 width=4) (actual time=0.01..0.02 rows=1 loops=2)
Index Cond: (bar_id = $0)
-> Index Scan using qux_pkey on qux (cost=0.00..3.05 rows=1 width=76) (actual time=0.02..0.02 rows=1 loops=2)
Index Cond: ("outer".qux_id = qux.qux_id)
-> Limit (cost=0.00..2.74 rows=1 width=4) (actual time=0.02..0.02 rows=1 loops=2)
-> Index Scan using idx_bar_qux_bar on bar_qux (cost=0.00..2.85 rows=1 width=4) (actual time=0.01..0.01 rows=1 loops=2)
Index Cond: (bar_id = $0)
Total runtime: 316.19 msec
(37 rows)

Time: 1333.72 ms
--
greg
---------------------------(end of broadcast)---------------------------
TIP 5: Have you checked our extensive FAQ?

http://www.postgresql.org/docs/faqs/FAQ.html

解决方案

0)
-> Index Scan using qux_pkey on qux (cost=0.00..3.05 rows=1 width=55) (actual time=0.02..0.03 rows=1 loops=2)
Index Cond: ("outer".qux_id = qux.qux_id)
-> Aggregate (cost=2.85..2.85 rows=1 width=0) (actual time=0.03..0.03 rows=1 loops=2)
-> Index Scan using idx_bar_qux_bar on bar_qux (cost=0.00..2.85 rows=1 width=0) (actual time=0.02..0.02 rows=1 loops=2)
Index Cond: (bar_id =

0)
-> Limit (cost=0.00..5.80 rows=1 width=80) (actual time=0.05..0.06 rows=1 loops=2)
-> Nested Loop (cost=0.00..6.04 rows=1 width=80) (actual time=0.05..0.05 rows=1 loops=2)
-> Index Scan using idx_bar_qux_bar on bar_qux (cost=0.00..2.85 rows=1 width=4) (actual time=0.01..0.02 rows=1 loops=2)
Index Cond: (bar_id =

0)
-> Index Scan using qux_pkey on qux (cost=0.00..3.05 rows=1 width=76) (actual time=0.02..0.02 rows=1 loops=2)
Index Cond: ("outer".qux_id = qux.qux_id)
-> Limit (cost=0.00..2.74 rows=1 width=4) (actual time=0.02..0.02 rows=1 loops=2)
-> Index Scan using idx_bar_qux_bar on bar_qux (cost=0.00..2.85 rows=1 width=4) (actual time=0.01..0.01 rows=1 loops=2)
Index Cond: (bar_id =

这篇关于log_duration和\时间可重复地远高于“总运行时间”。从解释分析的文章就介绍到这了，希望我们推荐的答案对大家有所帮助，也希望大家多多支持IT屋！