Re: log_duration and \timing times repeatably much higher

I know \timing counts the time to transfer the data to the client, and I
think log_duration also might have that timing added too. It does seem
like a long time to transfer data, though.

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

Greg Stark wrote:
>
> 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
>

--
Bruce Momjian | http://candle.pha.pa.us
pgman(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073