Re: Missing CFI in hlCover()?

Greetings,

* Tom Lane (tgl@sss.pgh.pa.us) wrote:
> Stephen Frost <sfrost@snowman.net> writes:
> > I'm looking into an issue that we're seeing on the PG archives server
> > with runaway queries that don't seem to ever want to end- and ignore
> > signals.
>
> > This is PG11, 11.8-1.pgdg100+1 specifically on Debian/buster and what
> > we're seeing is the loop in hlCover() (wparser_def.c:2071 to 2093) is
> > lasting an awful long time without any CFI call.  It's possible the CFI
> > call should actually go elsewhere, but the complete lack of any CFI in
> > wparser_def.c or tsvector_op.c seems a bit concerning.
>
> > I'm suspicious there's something else going on here that's causing this
> > to take a long time but I don't have any smoking gun as yet.
>
> Hm.  I'd vote for a CFI within the recursion in TS_execute(), if there's
> not one there yet.  Maybe hlFirstIndex needs one too --- if there are
> a lot of words in the query, maybe that could be slow?  Did you pin the
> blame down any more precisely than hlCover?

I've definitely seen hlFirstIndex take a few seconds to run (while
running this under gdb and stepping through), so that could be a good
choice to place one (perhaps even additionally to this...).  I have to
admit to wondering if we shouldn't consider having one in
check_stack_depth() to try and reduce the risk of us forgetting to have
one in sensible places, though I've not really looked at all the callers
and that might not be reasonable in some cases (though I wonder if maybe
we consider having a 'default' version that has a CFI, and an alternate
that doesn't...).

The depth of recursion for TS_execute_recurse() is actually not all that
bad either though (only 6 or so, as the query string here is:
"ERROR: The required file is not available"), so maybe that isn't really
the right thing to be thinking here.

Down in checkcondition_HL(), checkval->len is 213601, and it seems to
pretty much always end up with a result of TS_NO, but doesn't seem to
take all that long to arrive at that.

Over in hlFirstIndex():

hlFirstIndex (prs=0x7ffc2d4b16c0, prs=0x7ffc2d4b16c0, pos=219518, query=0x559619f81528) at
./build/../src/backend/tsearch/wparser_def.c:2013
2013    hlFirstIndex(HeadlineParsedText *prs, TSQuery query, int pos)
(gdb) n
2026                            if (item->type == QI_VAL &&
(gdb)
2029                            item++;
(gdb) p pos
$72 = 219518
(gdb) p prs->curwords
$73 = 583766
(gdb)

Here's a full backtrace down to the checkcondition_HL():

(gdb) i s
#0  checkcondition_HL (opaque=0x7ffc2d4b11f0, val=0x559619f815c0, data=0x0) at
./build/../src/backend/tsearch/wparser_def.c:1981
#1  0x0000559617eced2b in TS_execute_recurse (curitem=0x559619f815c0, arg=arg@entry=0x7ffc2d4b11f0,
flags=flags@entry=0,chkcond=chkcond@entry=0x559617df0120 <checkcondition_HL>) 
    at ./build/../src/backend/utils/adt/tsvector_op.c:1872
                                                                                          #2  0x0000559617ecedd1 in
TS_execute_recurse(curitem=0x559619f815a8, arg=arg@entry=0x7ffc2d4b11f0, flags=flags@entry=0,
chkcond=chkcond@entry=0x559617df0120<checkcondition_HL>) 
    at ./build/../src/backend/utils/adt/tsvector_op.c:1892
#3  0x0000559617ecedd1 in TS_execute_recurse (curitem=0x559619f81590, arg=arg@entry=0x7ffc2d4b11f0,
flags=flags@entry=0,chkcond=chkcond@entry=0x559617df0120 <checkcondition_HL>)                                     at
./build/../src/backend/utils/adt/tsvector_op.c:1892
#4  0x0000559617ecedd1 in TS_execute_recurse (curitem=0x559619f81578, arg=arg@entry=0x7ffc2d4b11f0,
flags=flags@entry=0,chkcond=chkcond@entry=0x559617df0120 <checkcondition_HL>) 
    at ./build/../src/backend/utils/adt/tsvector_op.c:1892
#5  0x0000559617ecedd1 in TS_execute_recurse (curitem=0x559619f81560, arg=arg@entry=0x7ffc2d4b11f0,
flags=flags@entry=0,chkcond=chkcond@entry=0x559617df0120 <checkcondition_HL>)                                     at
./build/../src/backend/utils/adt/tsvector_op.c:1892
#6  0x0000559617ecedd1 in TS_execute_recurse (curitem=0x559619f81548, arg=arg@entry=0x7ffc2d4b11f0,
flags=flags@entry=0,chkcond=chkcond@entry=0x559617df0120 <checkcondition_HL>) 
    at ./build/../src/backend/utils/adt/tsvector_op.c:1892
#7  0x0000559617ecedd1 in TS_execute_recurse (curitem=curitem@entry=0x559619f81530, arg=arg@entry=0x7ffc2d4b11f0,
flags=flags@entry=0,chkcond=chkcond@entry=0x559617df0120 <checkcondition_HL>) 
    at ./build/../src/backend/utils/adt/tsvector_op.c:1892
#8  0x0000559617ed26d9 in TS_execute (curitem=curitem@entry=0x559619f81530, arg=arg@entry=0x7ffc2d4b11f0,
flags=flags@entry=0,chkcond=chkcond@entry=0x559617df0120 <checkcondition_HL>) 
    at ./build/../src/backend/utils/adt/tsvector_op.c:1854
#9  0x0000559617df041e in hlCover (prs=prs@entry=0x7ffc2d4b16c0, query=query@entry=0x559619f81528,
p=p@entry=0x7ffc2d4b12a0,q=q@entry=0x7ffc2d4b12a4) at ./build/../src/backend/tsearch/wparser_def.c:2075        #10
0x0000559617df1a2din mark_hl_words (max_words=35, min_words=15, shortword=3, highlightall=<optimized out>,
query=<optimizedout>, prs=0x7ffc2d4b16c0) at ./build/../src/backend/tsearch/wparser_def.c:2393 
#11 prsd_headline (fcinfo=<optimized out>) at ./build/../src/backend/tsearch/wparser_def.c:2614
#12 0x0000559617f0cdab in FunctionCall3Coll (flinfo=flinfo@entry=0x559619fe1d90, collation=collation@entry=0,
arg1=arg1@entry=140721068381888,arg2=<optimized out>, arg3=arg3@entry=94103169144104) 
    at ./build/../src/backend/utils/fmgr/fmgr.c:1170
#13 0x0000559617def48b in ts_headline_byid_opt (fcinfo=fcinfo@entry=0x7ffc2d4b1740) at
./build/../src/backend/tsearch/wparser.c:336
#14 0x0000559617f0c484 in DirectFunctionCall4Coll (func=0x559617def380 <ts_headline_byid_opt>, collation=<optimized
out>,arg1=<optimized out>, arg2=<optimized out>, arg3=<optimized out>, arg4=<optimized out>) 
    at ./build/../src/backend/utils/fmgr/fmgr.c:877
#15 0x0000559617c8ad41 in ExecInterpExpr (state=0x559619f9b170, econtext=0x559619fd2ae0, isnull=<optimized out>) at
./build/../src/backend/executor/execExprInterp.c:678
#16 0x0000559617cb51da in ExecEvalExprSwitchContext (isNull=0x7ffc2d4b1b97, econtext=0x559619fd2ae0,
state=0x559619f9b170)at ./build/../src/include/executor/executor.h:313 
#17 ExecProject (projInfo=0x559619f9b168) at ./build/../src/include/executor/executor.h:347
#18 ExecResult (pstate=<optimized out>) at ./build/../src/backend/executor/nodeResult.c:136
#19 0x0000559617c955d9 in ExecProcNodeInstr (node=0x559619fd29d0) at ./build/../src/backend/executor/execProcnode.c:461
#20 0x0000559617cadc08 in ExecProcNode (node=0x559619fd29d0) at ./build/../src/include/executor/executor.h:247
#21 ExecLimit (pstate=0x559619fd27e0) at ./build/../src/backend/executor/nodeLimit.c:149
#22 0x0000559617c955d9 in ExecProcNodeInstr (node=0x559619fd27e0) at ./build/../src/backend/executor/execProcnode.c:461
#23 0x0000559617c8e37b in ExecProcNode (node=0x559619fd27e0) at ./build/../src/include/executor/executor.h:247
#24 ExecutePlan (execute_once=<optimized out>, dest=0x559618187460 <donothingDR>, direction=<optimized out>,
numberTuples=0,sendTuples=<optimized out>, operation=CMD_SELECT, use_parallel_mode=<optimized out>, 
    planstate=0x559619fd27e0, estate=0x559619fd25d0) at ./build/../src/backend/executor/execMain.c:1723
#25 standard_ExecutorRun (queryDesc=0x559619f92af8, direction=<optimized out>, count=0, execute_once=<optimized out>)
at./build/../src/backend/executor/execMain.c:364 
#26 0x00007f607e5e5045 in pgss_ExecutorRun (queryDesc=0x559619f92af8, direction=ForwardScanDirection, count=0,
execute_once=<optimizedout>) at ./build/../contrib/pg_stat_statements/pg_stat_statements.c:892 
#27 0x0000559617c251d6 in ExplainOnePlan (plannedstmt=plannedstmt@entry=0x559619f937e8, into=into@entry=0x0,
es=es@entry=0x559619fda528,
    queryString=queryString@entry=0x559619ea3e80 "explain (analyze, buffers) SELECT messageid, date, subject, _from,
ts_rank_cd(fti,plainto_tsquery('public.pg', 'ERROR: The required file is not available')), ts 
_headline(bodytxt, plainto_tsquery('pub"..., params=params@entry=0x0, queryEnv=<optimized out>,
planduration=0x7ffc2d4b1e70)at ./build/../src/backend/commands/explain.c:536 
#28 0x0000559617c254ee in ExplainOneQuery (queryEnv=<optimized out>, params=0x0,
    queryString=0x559619ea3e80 "explain (analyze, buffers) SELECT messageid, date, subject, _from, ts_rank_cd(fti,
plainto_tsquery('public.pg','ERROR: The required file is not available')), ts_headline(bodytxt, 
 plainto_tsquery('pub"..., es=0x559619fda528, into=0x0, cursorOptions=<optimized out>, query=<optimized out>) at
./build/../src/backend/commands/explain.c:372
#29 ExplainOneQuery (query=<optimized out>, cursorOptions=<optimized out>, into=0x0, es=0x559619fda528,
    queryString=0x559619ea3e80 "explain (analyze, buffers) SELECT messageid, date, subject, _from, ts_rank_cd(fti,
plainto_tsquery('public.pg','ERROR: The required file is not available')), ts_headline(bodytxt, 
 plainto_tsquery('pub"..., params=0x0, queryEnv=0x0) at ./build/../src/backend/commands/explain.c:340
#30 0x0000559617c25a2d in ExplainQuery (pstate=pstate@entry=0x559619f8c0e8, stmt=stmt@entry=0x55961a045650,
    queryString=queryString@entry=0x559619ea3e80 "explain (analyze, buffers) SELECT messageid, date, subject, _from,
ts_rank_cd(fti,plainto_tsquery('public.pg', 'ERROR: The required file is not available')), ts 
_headline(bodytxt, plainto_tsquery('pub"..., params=params@entry=0x0, queryEnv=queryEnv@entry=0x0,
dest=dest@entry=0x559619f8c058)at ./build/../src/backend/commands/explain.c:255 
#31 0x0000559617deb94b in standard_ProcessUtility (pstmt=pstmt@entry=0x55961a045700,
    queryString=queryString@entry=0x559619ea3e80 "explain (analyze, buffers) SELECT messageid, date, subject, _from,
ts_rank_cd(fti,plainto_tsquery('public.pg', 'ERROR: The required file is not available')), ts 
_headline(bodytxt, plainto_tsquery('pub"..., context=context@entry=PROCESS_UTILITY_TOPLEVEL, params=params@entry=0x0,
queryEnv=queryEnv@entry=0x0,dest=dest@entry=0x559619f8c058, 
    completionTag=0x7ffc2d4b22b0 "") at ./build/../src/backend/tcop/utility.c:675
#32 0x00007f607e5e7347 in pgss_ProcessUtility (pstmt=0x55961a045700,
    queryString=0x559619ea3e80 "explain (analyze, buffers) SELECT messageid, date, subject, _from, ts_rank_cd(fti,
plainto_tsquery('public.pg','ERROR: The required file is not available')), ts_headline(bodytxt, 
 plainto_tsquery('pub"..., context=PROCESS_UTILITY_TOPLEVEL, params=0x0, queryEnv=0x0, dest=0x559619f8c058,
completionTag=0x7ffc2d4b22b0"") at ./build/../contrib/pg_stat_statements/pg_stat_statements.c:1005 
#33 0x0000559617de83d9 in PortalRunUtility (portal=0x559619f33de0, pstmt=0x55961a045700, isTopLevel=<optimized out>,
setHoldSnapshot=<optimizedout>, dest=0x559619f8c058, completionTag=0x7ffc2d4b22b0 "") 
    at ./build/../src/backend/tcop/pquery.c:1178
#34 0x0000559617de91ea in FillPortalStore (portal=0x559619f33de0, isTopLevel=<optimized out>) at
./build/../src/include/nodes/pg_list.h:79
#35 0x0000559617de9dc7 in PortalRun (portal=portal@entry=0x559619f33de0, count=count@entry=9223372036854775807,
isTopLevel=isTopLevel@entry=true,run_once=run_once@entry=true, dest=dest@entry=0x559619fd7c08, 
    altdest=altdest@entry=0x559619fd7c08, completionTag=0x7ffc2d4b24f0 "") at ./build/../src/backend/tcop/pquery.c:768
#36 0x0000559617de5a3e in exec_simple_query (
    query_string=0x559619ea3e80 "explain (analyze, buffers) SELECT messageid, date, subject, _from, ts_rank_cd(fti,
plainto_tsquery('public.pg','ERROR: The required file is not available')), ts_headline(bodytxt 
, plainto_tsquery('pub"...) at ./build/../src/backend/tcop/postgres.c:1145
#37 0x0000559617de72a6 in PostgresMain (argc=<optimized out>, argv=argv@entry=0x559619efa418, dbname=<optimized out>,
username=<optimizedout>) at ./build/../src/backend/tcop/postgres.c:4193 
#38 0x0000559617d709e2 in BackendRun (port=0x559619eee4c0) at ./build/../src/backend/postmaster/postmaster.c:4364
#39 BackendStartup (port=0x559619eee4c0) at ./build/../src/backend/postmaster/postmaster.c:4036
#40 ServerLoop () at ./build/../src/backend/postmaster/postmaster.c:1707
#41 0x0000559617d71886 in PostmasterMain (argc=5, argv=0x559619e9e930) at
./build/../src/backend/postmaster/postmaster.c:1380
#42 0x0000559617aecdc9 in main (argc=5, argv=0x559619e9e930) at ./build/../src/backend/main/main.c:228

and down to the hlFirstIndex():

#0  hlFirstIndex (prs=0x7ffc2d4b16c0, prs=0x7ffc2d4b16c0, pos=219518, query=0x559619f81528) at
./build/../src/backend/tsearch/wparser_def.c:2029
#1  hlCover (prs=prs@entry=0x7ffc2d4b16c0, query=query@entry=0x559619f81528, p=p@entry=0x7ffc2d4b12a0,
q=q@entry=0x7ffc2d4b12a4)at ./build/../src/backend/tsearch/wparser_def.c:2083 
#2  0x0000559617df1a2d in mark_hl_words (max_words=35, min_words=15, shortword=3, highlightall=<optimized out>,
query=<optimizedout>, prs=0x7ffc2d4b16c0) at ./build/../src/backend/tsearch/wparser_def.c:2393 
#3  prsd_headline (fcinfo=<optimized out>) at ./build/../src/backend/tsearch/wparser_def.c:2614
#4  0x0000559617f0cdab in FunctionCall3Coll (flinfo=flinfo@entry=0x559619fe1d90, collation=collation@entry=0,
arg1=arg1@entry=140721068381888,arg2=<optimized out>, arg3=arg3@entry=94103169144104) 
    at ./build/../src/backend/utils/fmgr/fmgr.c:1170
#5  0x0000559617def48b in ts_headline_byid_opt (fcinfo=fcinfo@entry=0x7ffc2d4b1740) at
./build/../src/backend/tsearch/wparser.c:336
#6  0x0000559617f0c484 in DirectFunctionCall4Coll (func=0x559617def380 <ts_headline_byid_opt>, collation=<optimized
out>,arg1=<optimized out>, arg2=<optimized out>, arg3=<optimized out>, arg4=<optimized out>) 
    at ./build/../src/backend/utils/fmgr/fmgr.c:877
#7  0x0000559617c8ad41 in ExecInterpExpr (state=0x559619f9b170, econtext=0x559619fd2ae0, isnull=<optimized out>) at
./build/../src/backend/executor/execExprInterp.c:678
#8  0x0000559617cb51da in ExecEvalExprSwitchContext (isNull=0x7ffc2d4b1b97, econtext=0x559619fd2ae0,
state=0x559619f9b170)at ./build/../src/include/executor/executor.h:313 
#9  ExecProject (projInfo=0x559619f9b168) at ./build/../src/include/executor/executor.h:347
#10 ExecResult (pstate=<optimized out>) at ./build/../src/backend/executor/nodeResult.c:136
#11 0x0000559617c955d9 in ExecProcNodeInstr (node=0x559619fd29d0) at ./build/../src/backend/executor/execProcnode.c:461
#12 0x0000559617cadc08 in ExecProcNode (node=0x559619fd29d0) at ./build/../src/include/executor/executor.h:247
#13 ExecLimit (pstate=0x559619fd27e0) at ./build/../src/backend/executor/nodeLimit.c:149
#14 0x0000559617c955d9 in ExecProcNodeInstr (node=0x559619fd27e0) at ./build/../src/backend/executor/execProcnode.c:461
#15 0x0000559617c8e37b in ExecProcNode (node=0x559619fd27e0) at ./build/../src/include/executor/executor.h:247
#16 ExecutePlan (execute_once=<optimized out>, dest=0x559618187460 <donothingDR>, direction=<optimized out>,
numberTuples=0,sendTuples=<optimized out>, operation=CMD_SELECT, use_parallel_mode=<optimized out>, 
    planstate=0x559619fd27e0, estate=0x559619fd25d0) at ./build/../src/backend/executor/execMain.c:1723
#17 standard_ExecutorRun (queryDesc=0x559619f92af8, direction=<optimized out>, count=0, execute_once=<optimized out>)
at./build/../src/backend/executor/execMain.c:364 
#18 0x00007f607e5e5045 in pgss_ExecutorRun (queryDesc=0x559619f92af8, direction=ForwardScanDirection, count=0,
execute_once=<optimizedout>) at ./build/../contrib/pg_stat_statements/pg_stat_statements.c:892 
#19 0x0000559617c251d6 in ExplainOnePlan (plannedstmt=plannedstmt@entry=0x559619f937e8, into=into@entry=0x0,
es=es@entry=0x559619fda528,
    queryString=queryString@entry=0x559619ea3e80 "explain (analyze, buffers) SELECT messageid, date, subject, _from,
ts_rank_cd(fti,plainto_tsquery('public.pg', 'ERROR: The required file is not available')), ts 
_headline(bodytxt, plainto_tsquery('pub"..., params=params@entry=0x0, queryEnv=<optimized out>,
planduration=0x7ffc2d4b1e70)at ./build/../src/backend/commands/explain.c:536 
#20 0x0000559617c254ee in ExplainOneQuery (queryEnv=<optimized out>, params=0x0,
    queryString=0x559619ea3e80 "explain (analyze, buffers) SELECT messageid, date, subject, _from, ts_rank_cd(fti,
plainto_tsquery('public.pg','ERROR: The required file is not available')), ts_headline(bodytxt, 
 plainto_tsquery('pub"..., es=0x559619fda528, into=0x0, cursorOptions=<optimized out>, query=<optimized out>) at
./build/../src/backend/commands/explain.c:372
#21 ExplainOneQuery (query=<optimized out>, cursorOptions=<optimized out>, into=0x0, es=0x559619fda528,
    queryString=0x559619ea3e80 "explain (analyze, buffers) SELECT messageid, date, subject, _from, ts_rank_cd(fti,
plainto_tsquery('public.pg','ERROR: The required file is not available')), ts_headline(bodytxt, 
 plainto_tsquery('pub"..., params=0x0, queryEnv=0x0) at ./build/../src/backend/commands/explain.c:340
#22 0x0000559617c25a2d in ExplainQuery (pstate=pstate@entry=0x559619f8c0e8, stmt=stmt@entry=0x55961a045650,
    queryString=queryString@entry=0x559619ea3e80 "explain (analyze, buffers) SELECT messageid, date, subject, _from,
ts_rank_cd(fti,plainto_tsquery('public.pg', 'ERROR: The required file is not available')), ts 
_headline(bodytxt, plainto_tsquery('pub"..., params=params@entry=0x0, queryEnv=queryEnv@entry=0x0,
dest=dest@entry=0x559619f8c058)at ./build/../src/backend/commands/explain.c:255 
#23 0x0000559617deb94b in standard_ProcessUtility (pstmt=pstmt@entry=0x55961a045700,
    queryString=queryString@entry=0x559619ea3e80 "explain (analyze, buffers) SELECT messageid, date, subject, _from,
ts_rank_cd(fti,plainto_tsquery('public.pg', 'ERROR: The required file is not available')), ts 
_headline(bodytxt, plainto_tsquery('pub"..., context=context@entry=PROCESS_UTILITY_TOPLEVEL, params=params@entry=0x0,
queryEnv=queryEnv@entry=0x0,dest=dest@entry=0x559619f8c058, 
    completionTag=0x7ffc2d4b22b0 "") at ./build/../src/backend/tcop/utility.c:675
#24 0x00007f607e5e7347 in pgss_ProcessUtility (pstmt=0x55961a045700,
    queryString=0x559619ea3e80 "explain (analyze, buffers) SELECT messageid, date, subject, _from, ts_rank_cd(fti,
plainto_tsquery('public.pg','ERROR: The required file is not available')), ts_headline(bodytxt, 
 plainto_tsquery('pub"..., context=PROCESS_UTILITY_TOPLEVEL, params=0x0, queryEnv=0x0, dest=0x559619f8c058,
completionTag=0x7ffc2d4b22b0"") at ./build/../contrib/pg_stat_statements/pg_stat_statements.c:1005 
#25 0x0000559617de83d9 in PortalRunUtility (portal=0x559619f33de0, pstmt=0x55961a045700, isTopLevel=<optimized out>,
setHoldSnapshot=<optimizedout>, dest=0x559619f8c058, completionTag=0x7ffc2d4b22b0 "") 
    at ./build/../src/backend/tcop/pquery.c:1178
#26 0x0000559617de91ea in FillPortalStore (portal=0x559619f33de0, isTopLevel=<optimized out>) at
./build/../src/include/nodes/pg_list.h:79
#27 0x0000559617de9dc7 in PortalRun (portal=portal@entry=0x559619f33de0, count=count@entry=9223372036854775807,
isTopLevel=isTopLevel@entry=true,run_once=run_once@entry=true, dest=dest@entry=0x559619fd7c08, 
    altdest=altdest@entry=0x559619fd7c08, completionTag=0x7ffc2d4b24f0 "") at ./build/../src/backend/tcop/pquery.c:768
#28 0x0000559617de5a3e in exec_simple_query (
    query_string=0x559619ea3e80 "explain (analyze, buffers) SELECT messageid, date, subject, _from, ts_rank_cd(fti,
plainto_tsquery('public.pg','ERROR: The required file is not available')), ts_headline(bodytxt 
, plainto_tsquery('pub"...) at ./build/../src/backend/tcop/postgres.c:1145
#29 0x0000559617de72a6 in PostgresMain (argc=<optimized out>, argv=argv@entry=0x559619efa418, dbname=<optimized out>,
username=<optimizedout>) at ./build/../src/backend/tcop/postgres.c:4193 
#30 0x0000559617d709e2 in BackendRun (port=0x559619eee4c0) at ./build/../src/backend/postmaster/postmaster.c:4364
#31 BackendStartup (port=0x559619eee4c0) at ./build/../src/backend/postmaster/postmaster.c:4036
#32 ServerLoop () at ./build/../src/backend/postmaster/postmaster.c:1707
#33 0x0000559617d71886 in PostmasterMain (argc=5, argv=0x559619e9e930) at
./build/../src/backend/postmaster/postmaster.c:1380
#34 0x0000559617aecdc9 in main (argc=5, argv=0x559619e9e930) at ./build/../src/backend/main/main.c:228

Thanks!

Stephen