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

Tom Lane <tgl@sss.pgh.pa.us> writes:

> Greg Stark <gsstark@mit.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.85rows=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.85rows=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
:opretsetfalse } :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
:typeOid16  :opType op :oper { OPER :opno 96 :opid 65 :opresulttype 16 :opretset false } :args ({ VAR :varno 1
:varattno2 :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
:opretsetfalse } :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
:vartype23 :vartypmod -1  :varlevelsup 0 :varnoold 1 :varoattno 2} { CONST :consttype 23 :constlen 4 :constbyval true
:constisnullfalse :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
:constbyvaltrue :constisnull false :constvalue  4 [ 0 0 0 0 ] }"}



                              

                                                                          | {"{ CONST :consttype 16 :constlen 1
:constbyvaltrue :constisnull false :constvalue  1 [ 0 0 0 0 ] }","{ CONST :consttype 705 :constlen -1 :constbyval false
:constisnullfalse :constvalue  5 [ 5 0 0 0 32 ] }","{ EXPR :typeOid 20  :opType func :oper { FUNC :funcid 1574
:funcresulttype20 :funcretset false :funcformat 0 } :args ({ CONST :consttype 25 :constlen -1 :constbyval false
:constisnullfalse :constvalue  15 [ 15 0 0 0 100 101 112 116 95 105 100 95 115 101 113 ] })}","{ EXPR :typeOid 20
:opTypefunc :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
:constbyvalfalse :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
110101 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
:constisnullfalse :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
10095 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
11697 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
:constbyvalfalse :constisnull false :constvalue  34 [ 34 0 0 0 112 117 98 108 105 99 46 106 111 98 115 95 112 111 115
116105 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
:constisnullfalse :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
108101 114 116 95 105 100 95 115 101 113 ] })}","{ EXPR :typeOid 20  :opType func :oper { FUNC :funcid 1574
:funcresulttype20 :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
9946 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
115101 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