log_duration and \timing times repeatably much higher than "Total runtime" from explain analyze - Mailing list pgsql-general

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.85
rows=1width=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