Re: log_duration and \timing times repeatably much higher - Mailing list pgsql-general

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.07rows=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)
(actualtime=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.07rows=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=1loops=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.16rows=1 loops=2) 
>                                                      ->  Index Scan using idx_bar_qux_bar on bar_qux
(cost=0.00..2.85rows=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)
(actualtime=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)
(actualtime=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)
(actualtime=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@candle.pha.pa.us               |  (610) 359-1001
  +  If your life is a hard drive,     |  13 Roberts Road
  +  Christ can be your backup.        |  Newtown Square, Pennsylvania 19073