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

Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> writes:

> Greg Stark <gsstark(at)mit(dot)edu> writes:
> > What's really strange is that some other
> > queries perform fine but this one and a few others reliably takes this long
> > and behaves this way under explain analyze. It's as if there's something
> > specific about this query that triggers the delay.
>
> You haven't shown us the query (naughty naughty)

oops, I included the (mangled) plan but forgot the actual query.
I've included it below (mangled unfortunately. I just substituted
foo/bar/baz/quux for the entity names. The client insists.)

> but I'm wondering about extremely-expensive-to-evaluate immutable functions.

I don't see any functions applied to constants anywhere. There are some
functions, but they're applied to columns. And they should be fairly fast,
lang_en just expands to (($1)[1]) and xfrm_en just expands to
lower(lang_en($1)) until I implement the strxfrm stuff sometime.

> An immutable function applied to constant arguments will be evaluated in the
> planner. The difference between total time and run time has to be
> essentially all parse/rewrite/plan time, and the query doesn't look complex
> enough to be needing a full second to plan without some, um, outside help.

It seems you guys are right, a simple explain is taking nearly a full second
on this box. Explaining the same query on another machine with a more or less
identical database takes 50ms. Hell, an "explain analyze" takes less time on
the other box than the "explain" does on this one.

The configuration of the two machines aren't identical. The slow one is 7.3.2
and the other 7.3.3. But they both performed similarly not long ago. There's
no big performance problem with 7.3.2 is there? This is only development so
I'm not worried about reliability/integrity bugs.

I suspect some configuration change to this box relative to the other may have
done this, but I can't think of anything that could possibly cause this kind
of slowdown. I've done a pg_dump -s and compared schemas, I'm checking the
statistics and guc variables now.

I've run "vacuum full analyze" on both machines.

explain SELECT *,
xfrm_en(quux_name) as quux_xform
FROM (
SELECT
lang_en(title) as x_title,
xfrm_en(title) as x_title_xform,
lang_en(foo.description) as x_description,
lang_en(fine_print) as x_fine_print,
foo_start::timestamp::abstime::int4 as foo_start_time,
foo_end::timestamp::abstime::int4 as foo_end_time,
lang_en(foo_p_text) as x_foo_p_text,
lang_en(subtitle) as x_subtitle,
(SELECT concat_agg(quux_name)
FROM (
SELECT lang_en(quux.short_name) AS quux_name
FROM foo_quux
JOIN quux USING (quux_id)
WHERE foo_quux.foo_id = foo.foo_id
ORDER BY xfrm_en(quux.short_name)
) AS x
) as quux_name,
(SELECT count(*)
FROM foo_quux
WHERE foo_quux.foo_id = foo.foo_id
) as quux_count,
(SELECT lang_en(quux.small_logo) AS quux_logo
FROM foo_quux
JOIN quux USING (quux_id)
WHERE foo_quux.foo_id = foo.foo_id
LIMIT 1
) as quux_logo,
(SELECT quux_id from foo_quux where foo_quux.foo_id = foo.foo_id limit 1 ) as quux_id,
lang_en(baz.short_name) as bar_name,
xfrm_en(baz.short_name) as bar_xform,
lang_en(baz.small_logo) as bar_logo,
baz_id,
*
FROM baz
JOIN foo_baz USING (baz_id)
JOIN foo USING (foo_id)
WHERE baz_id = 815
AND foo_type_code<>'S'
AND (0=0 OR exists (select * from foo_dept where foo_id = foo.foo_id and 0 IN (dept_id, level_1_id, level_2_id)))
LIMIT 20000
) as x
ORDER BY x_title_xform asc, bar_xform asc, quux_xform asc
OFFSET 0
LIMIT 25

db-> ;
QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------
Limit (cost=15.07..15.07 rows=1 width=2315)
-> Sort (cost=15.07..15.07 rows=1 width=2315)
Sort Key: x_title_xform, bar_xform, xfrm_en((quux_name)::text)
-> Subquery Scan x (cost=0.00..15.06 rows=1 width=2315)
-> Limit (cost=0.00..15.06 rows=1 width=2315)
-> Nested Loop (cost=0.00..15.06 rows=1 width=2315)
-> Nested Loop (cost=0.00..11.87 rows=1 width=1542)
-> Index Scan using baz_pkey on baz (cost=0.00..3.20 rows=1 width=1534)
Index Cond: (baz_id = 815)
-> Index Scan using idx_foo_baz_loc on foo_baz (cost=0.00..8.58 rows=7 width=8)
Index Cond: ("outer".baz_id = foo_baz.baz_id)
-> Index Scan using foo_pkey on foo (cost=0.00..3.18 rows=1 width=773)
Index Cond: ("outer".foo_id = foo.foo_id)
Filter: (foo_type_code <> 'S'::bpchar)
SubPlan
-> Aggregate (cost=6.05..6.05 rows=1 width=59)
-> Subquery Scan x (cost=6.05..6.05 rows=1 width=59)
-> Sort (cost=6.05..6.05 rows=1 width=59)
Sort Key: xfrm_en(quux.short_name)
-> Nested Loop (cost=0.00..6.04 rows=1 width=59)
-> Index Scan using idx_foo_quux_foo on foo_quux (cost=0.00..2.85 rows=1 width=4)
Index Cond: (foo_id = $0)
-> Index Scan using quux_pkey on quux (cost=0.00..3.05 rows=1 width=55)
Index Cond: ("outer".quux_id = quux.quux_id)
-> Aggregate (cost=2.85..2.85 rows=1 width=0)
-> Index Scan using idx_foo_quux_foo on foo_quux (cost=0.00..2.85 rows=1 width=0)
Index Cond: (foo_id = $0)
-> Limit (cost=0.00..5.80 rows=1 width=80)
-> Nested Loop (cost=0.00..6.04 rows=1 width=80)
-> Index Scan using idx_foo_quux_foo on foo_quux (cost=0.00..2.85 rows=1 width=4)
Index Cond: (foo_id = $0)
-> Index Scan using quux_pkey on quux (cost=0.00..3.05 rows=1 width=76)
Index Cond: ("outer".quux_id = quux.quux_id)
-> Limit (cost=0.00..2.74 rows=1 width=4)
-> Index Scan using idx_foo_quux_foo on foo_quux (cost=0.00..2.85 rows=1 width=4)
Index Cond: (foo_id = $0)
(36 rows)

Time: 996.83 ms

On the machine that's working properly, the same plan with similar costs but in 50ms:

Limit (cost=15.56..15.56 rows=1 width=3274)
-> Sort (cost=15.56..15.56 rows=1 width=3274)
Sort Key: x_title_xform, bar_xform, xfrm_en((quux_name)::text)
-> Subquery Scan x (cost=0.00..15.55 rows=1 width=3274)
-> Limit (cost=0.00..15.55 rows=1 width=3274)
-> Nested Loop (cost=0.00..15.55 rows=1 width=3274)
-> Nested Loop (cost=0.00..12.33 rows=1 width=2486)
-> Index Scan using baz_pkey on baz (cost=0.00..3.17 rows=1 width=2478)
Index Cond: (baz_id = 815)
-> Index Scan using idx_foo_baz_loc on foo_baz (cost=0.00..9.07 rows=7 width=8)
Index Cond: ("outer".baz_id = foo_baz.baz_id)
-> Index Scan using foo_pkey on foo (cost=0.00..3.20 rows=1 width=788)
Index Cond: ("outer".foo_id = foo.foo_id)
Filter: (foo_type_code <> 'S'::bpchar)
SubPlan
-> Aggregate (cost=6.06..6.06 rows=1 width=76)
-> Subquery Scan x (cost=6.05..6.06 rows=1 width=76)
-> Sort (cost=6.05..6.06 rows=1 width=76)
Sort Key: xfrm_en(quux.short_name)
-> Nested Loop (cost=0.00..6.04 rows=1 width=76)
-> Index Scan using idx_foo_quux_foo on foo_quux (cost=0.00..2.85 rows=1 width=4)
Index Cond: (foo_id = $0)
-> Index Scan using quux_pkey on quux (cost=0.00..3.06 rows=1 width=72)
Index Cond: ("outer".quux_id = quux.quux_id)
-> Aggregate (cost=2.85..2.85 rows=1 width=0)
-> Index Scan using idx_foo_quux_foo on foo_quux (cost=0.00..2.85 rows=1 width=0)
Index Cond: (foo_id = $0)
-> Limit (cost=0.00..5.84 rows=1 width=80)
-> Nested Loop (cost=0.00..6.04 rows=1 width=80)
-> Index Scan using idx_foo_quux_foo on foo_quux (cost=0.00..2.85 rows=1 width=4)
Index Cond: (foo_id = $0)
-> Index Scan using quux_pkey on quux (cost=0.00..3.06 rows=1 width=76)
Index Cond: ("outer".quux_id = quux.quux_id)
-> Limit (cost=0.00..2.74 rows=1 width=4)
-> Index Scan using idx_foo_quux_foo on foo_quux (cost=0.00..2.85 rows=1 width=4)
Index Cond: (foo_id = $0)
(36 rows)

Time: 50.33 ms

There do seem to be some suspiciously long lines in pg_statistic for pg_index and pg_attrdef:

16390 | 10 | 0 | 14 | 6 | 1 | 2 | 3 | 0 | 98 | 664 | 664 | 0 | {0.965753} | | {0.985817} | | {""}
| {"({ EXPR :typeOid 16 :opType op :oper { OPER :opno 1054 :opid 1048 :opresulttype 16 :opretset false } :args ({ VAR :varno 1 :varattno 2 :vartype 1042 :vartypmod 5 :varlevelsup 0 :varnoold 1 :varoattno 2} { CONST :consttype 1042 :constlen -1 :constbyval false :constisnull false :constvalue 5 [ 5 0 0 0 80 ] })})","({ EXPR :typeOid 16 :opType op :oper { OPER :opno 1054 :opid 1048 :opresulttype 16 :opretset false } :args ({ VAR :varno 1 :varattno 2 :vartype 1042 :vartypmod 5 :varlevelsup 0 :varnoold 1 :varoattno 2} { CONST :consttype 1042 :constlen -1 :constbyval false :constisnull false :constvalue 5 [ 5 0 0 0 83 ] })})","({ EXPR :typeOid 16 :opType op :oper { OPER :opno 96 :opid 65 :opresulttype 16 :opretset false } :args ({ VAR :varno 1 :varattno 2 :vartype 23 :vartypmod -1
:varlevelsup 0 :varnoold 1 :varoattno 2} { CONST :consttype 23 :constlen 4 :constbyval true :constisnull false :constvalue 4 [ 1 0 0 0 ] })})","({ EXPR :typeOid 16 :opType op :oper { OPER :opno 96 :opid 65 :opresulttype 16 :opretset false } :args ({ VAR :varno 1 :varattno 2 :vartype 23 :vartypmod -1 :varlevelsup 0 :varnoold 1 :varoattno 2} { CONST :consttype 23 :constlen 4 :constbyval true :constisnull false :constvalue 4 [ 2 0 0 0 ] })})","({ EXPR :typeOid 16 :opType op :oper { OPER :opno 96 :opid 65 :opresulttype 16 :opretset false } :args ({ VAR :varno 1 :varattno 2 :vartype 23 :vartypmod -1 :varlevelsup 0 :varnoold 1 :varoattno 2} { CONST :consttype 23 :constlen 4 :constbyval true :constisnull false :constvalue 4 [ 3 0 0 0 ] })})"}

| |
16384 | 3 | 0 | 230 | -0.735294 | 1 | 2 | 3 | 0 | 98 | 664 | 664 | 0 | {0.205882,0.117647} | | {0.304813} | | {"{ EXPR :typeOid 1184 :opType func :oper { FUNC :funcid 1299 :funcresulttype 1184 :funcretset false :funcformat 0 } :args <>}","{ CONST :consttype 23 :constlen 4 :constbyval true :constisnull false :constvalue 4 [ 0 0 0 0 ] }"}
| {"{ CONST :consttype 16 :constlen 1 :constbyval true :constisnull false :constvalue 1 [ 0 0 0 0 ] }","{ CONST :consttype 705 :constlen -1 :constbyval false :constisnull false :constvalue 5 [ 5 0 0 0 32 ] }","{ EXPR :typeOid 20 :opType func :oper { FUNC :funcid 1574 :funcresulttype 20 :funcretset false :funcformat 0 } :args ({ CONST :consttype 25 :constlen -1 :constbyval false :constisnull false :constvalue 15 [ 15 0 0 0 100 101 112 116 95 105 100 95 115 101 113 ] })}","{ EXPR :typeOid 20 :opType func :oper { FUNC :funcid 1574 :funcresulttype 20 :funcretset false :funcformat 0 } :args ({ CONST :consttype 25 :constlen -1 :constbyval false :constisnull false :constvalue 16 [ 16 0 0 0 115 116 111 114 101 95 105 100 95 115 101 113 ] })}","{ EXPR :typeOid 20 :opType func :oper { FU
NC :funcid 1574 :funcresulttype 20 :funcretset false :funcformat 0 } :args ({ CONST :consttype 25 :constlen -1 :constbyval false :constisnull false :constvalue 18 [ 18 0 0 0 112 97 114 116 110 101 114 95 105 100 95 115 101 113 ] })}","{ EXPR :typeOid 20 :opType func :oper { FUNC :funcid 1574 :funcresulttype 20 :funcretset false :funcformat 0 } :args ({ CONST :consttype 25 :constlen -1 :constbyval false :constisnull false :constvalue 23 [ 23 0 0 0 112 97 114 116 110 101 114 95 117 115 101 114 95 105 100 95 115 101 113 ] })}","{ EXPR :typeOid 20 :opType func :oper { FUNC :funcid 1574 :funcresulttype 20 :funcretset false :funcformat 0 } :args ({ CONST :consttype 25 :constlen -1 :constbyval false :constisnull false :constvalue 29 [ 29 0 0 0 112 117 98 108 105 99 46 120 108 97 116 101 95 120 108 97 116 101 95 105 100 95 115 101 113 ] })}","{ EXPR :typeOid 20 :opType func :oper { FUNC :funcid 1574 :funcresulttype 20 :funcretset false :funcformat 0 } :args ({ CONST :consttype
25 :constlen -1 :constbyval false :constisnull false :constvalue 33 [ 33 0 0 0 112 117 98 108 105 99 46 99 111 110 116 97 99 116 95 99 111 110 116 97 99 116 95 105 100 95 115 101 113 ] })}","{ EXPR :typeOid 20 :opType func :oper { FUNC :funcid 1574 :funcresulttype 20 :funcretset false :funcformat 0 } :args ({ CONST :consttype 25 :constlen -1 :constbyval false :constisnull false :constvalue 34 [ 34 0 0 0 112 117 98 108 105 99 46 106 111 98 115 95 112 111 115 116 105 110 103 95 106 111 98 95 105 100 95 115 101 113 ] })}","{ EXPR :typeOid 20 :opType func :oper { FUNC :funcid 1574 :funcresulttype 20 :funcretset false :funcformat 0 } :args ({ CONST :consttype 25 :constlen -1 :constbyval false :constisnull false :constvalue 35 [ 35 0 0 0 112 117 98 108 105 99 46 115 97 108 101 115 95 97 108 101 114 116 95 97 108 101 114 116 95 105 100 95 115 101 113 ] })}","{ EXPR :typeOid 20 :opType func :oper { FUNC :funcid 1574 :funcresulttype 20 :funcretset false :funcformat 0 } :args (
{ CONST :consttype 25 :constlen -1 :constbyval false :constisnull false :constvalue 44 [ 44 0 0 0 112 117 98 108 105 99 46 115 116 111 114 101 95 108 111 99 97 116 105 111 110 95 112 104 111 110 101 95 112 104 111 110 101 95 105 100 95 115 101 113 ] })}"} | |

but they're present on the machine that's working properly too. None of the
statistics columns for my schema tables have more than 10 buckets or too
anywhere near as much data in them as these records.

--
greg