log_duration and \timing times repeatably much higher than "Total runtime" from explain analyze

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