Re: Interesting case of IMMUTABLE significantly hurting performance - Mailing list pgsql-performance

On 08/14/2013 08:41 AM, Craig Ringer wrote:
> Hi folks
>
> I've run into an interesting Stack Overflow post where the user shows
> that marking a particular function as IMMUTABLE significantly hurts the
> performance of a query.

Here's `perf` report data for the two.

With IMMUTABLE:

Samples: 90K of event 'cycles', Event count (approx.): 78028435735
  7.74%  postgres  postgres           [.] base_yyparse
  6.54%  postgres  postgres           [.] SearchCatCache
  5.75%  postgres  postgres           [.] AllocSetAlloc
  3.14%  postgres  postgres           [.] core_yylex
  1.88%  postgres  libc-2.17.so       [.] _int_malloc
  1.58%  postgres  postgres           [.] MemoryContextAllocZeroAligned
  1.57%  postgres  libc-2.17.so       [.] __strcmp_sse42
  1.44%  postgres  libc-2.17.so       [.] __memcpy_ssse3_back
  1.42%  postgres  postgres           [.] expression_tree_walker
  1.37%  postgres  libc-2.17.so       [.] vfprintf
  1.35%  postgres  postgres           [.] MemoryContextAlloc
  1.32%  postgres  postgres           [.] fmgr_info_cxt_security
  1.31%  postgres  postgres           [.] fmgr_sql
  1.17%  postgres  postgres           [.] ExecInitExpr


without IMMUTABLE (i.e. VOLATILE):

Samples: 16K of event 'cycles', Event count (approx.): 14348843004
  6.78%  postgres  postgres           [.] AllocSetAlloc
  5.37%  postgres  libc-2.17.so       [.] vfprintf
  2.82%  postgres  postgres           [.] SearchCatCache
  2.82%  postgres  libc-2.17.so       [.] _int_malloc
  2.45%  postgres  postgres           [.] timesub.isra.1
  2.26%  postgres  postgres           [.] ExecInitExpr
  1.79%  postgres  postgres           [.] MemoryContextAlloc
  1.63%  postgres  postgres           [.] MemoryContextAllocZeroAligned
  1.60%  postgres  libc-2.17.so       [.] _int_free
  1.55%  postgres  postgres           [.] j2date
  1.52%  postgres  postgres           [.] fmgr_info_cxt_security
  1.41%  postgres  libc-2.17.so       [.] _IO_default_xsputn
  1.41%  postgres  postgres           [.] fmgr_sql
  1.40%  postgres  postgres           [.] expression_tree_walker
  1.39%  postgres  libc-2.17.so       [.] __memset_sse2
  1.39%  postgres  postgres           [.] timestamp2tm
  1.13%  postgres  postgres           [.] MemoryContextCreate
  1.11%  postgres  postgres           [.] standard_ExecutorStart
  1.11%  postgres  postgres           [.] ExecProject
  1.08%  postgres  postgres           [.] AllocSetFree



So ... are we re-parsing the function every time if it's declared
IMMUTABLE or something like that? If I break in base_yyparse I hit the
breakpoint 3x for the volatile case, and basically endlessly for the
immutable case, with a trace like:

> #0  base_yyparse (yyscanner=yyscanner@entry=0x1d8f868) at gram.c:19604
> #1  0x0000000000500381 in raw_parser (str=<optimized out>) at parser.c:52
> #2  0x000000000064b552 in pg_parse_query (query_string=<optimized out>) at postgres.c:564
> #3  0x0000000000587650 in init_sql_fcache (lazyEvalOK=1 '\001', collation=0, finfo=<optimized out>) at
functions.c:680
> #4  fmgr_sql (fcinfo=0x1d76300) at functions.c:1040
> #5  0x00000000005817e5 in ExecMakeFunctionResult (fcache=0x1d76290, econtext=0x1d75000, isNull=0x1d75db1 "",
isDone=0x7fff103946bc)at execQual.c:1927 
> #6  0x000000000057dd05 in ExecEvalFuncArgs (fcinfo=fcinfo@entry=0x1d75a70, argList=argList@entry=0x1d76260,
econtext=econtext@entry=0x1d75000)at execQual.c:1475 
> #7  0x00000000005816d5 in ExecMakeFunctionResult (fcache=0x1d75a00, econtext=0x1d75000, isNull=0x1d755a0 "",
isDone=0x7fff103947dc)at execQual.c:1706 
> #8  0x000000000057dd05 in ExecEvalFuncArgs (fcinfo=fcinfo@entry=0x1d75260, argList=argList@entry=0x1d76b60,
econtext=econtext@entry=0x1d75000)at execQual.c:1475 
> #9  0x00000000005816d5 in ExecMakeFunctionResult (fcache=0x1d751f0, econtext=0x1d75000, isNull=0x1d76d08 "",
isDone=0x1d76e60)at execQual.c:1706 
> #10 0x0000000000583cfd in ExecTargetList (isDone=0x7fff1039497c, itemIsDone=0x1d76e60, isnull=<optimized out>,
values=0x1d76cf0,econtext=0x1d75000, targetlist=0x1d76e30) 
>     at execQual.c:5221
> #11 ExecProject (projInfo=<optimized out>, isDone=isDone@entry=0x7fff1039497c) at execQual.c:5436
> #12 0x0000000000594a12 in ExecResult (node=node@entry=0x1d74ef0) at nodeResult.c:155
> #13 0x000000000057cff8 in ExecProcNode (node=node@entry=0x1d74ef0) at execProcnode.c:372
> #14 0x000000000057a8e0 in ExecutePlan (dest=0x1d70d50, direction=<optimized out>, numberTuples=1, sendTuples=1
'\001',operation=CMD_SELECT, planstate=0x1d74ef0,  
>     estate=0x1d74de0) at execMain.c:1395
> #15 standard_ExecutorRun (queryDesc=0x1d72f80, direction=<optimized out>, count=1) at execMain.c:303
> #16 0x0000000000587bc2 in postquel_getnext (es=0x1d70c80, es=0x1d70c80, fcache=0x1d6edc0) at functions.c:844
> #17 fmgr_sql (fcinfo=<optimized out>) at functions.c:1140
> #18 0x000000000057e602 in ExecMakeFunctionResultNoSets (fcache=0x1d849e0, econtext=0x1d848d0, isNull=0x1d859b8 "",
isDone=<optimizedout>) at execQual.c:1993 
> #19 0x0000000000583cfd in ExecTargetList (isDone=0x7fff10394bfc, itemIsDone=0x1d85ad0, isnull=<optimized out>,
values=0x1d859a0,econtext=0x1d848d0, targetlist=0x1d85aa0) 
>     at execQual.c:5221
> #20 ExecProject (projInfo=projInfo@entry=0x1d859d0, isDone=isDone@entry=0x7fff10394bfc) at execQual.c:5436
> #21 0x000000000058409a in ExecScan (node=node@entry=0x1d847c0, accessMtd=accessMtd@entry=0x594c70 <SeqNext>,
recheckMtd=recheckMtd@entry=0x594c60<SeqRecheck>) 
>     at execScan.c:207
> #22 0x0000000000594cdf in ExecSeqScan (node=node@entry=0x1d847c0) at nodeSeqscan.c:113
> #23 0x000000000057cfa8 in ExecProcNode (node=node@entry=0x1d847c0) at execProcnode.c:399
> #24 0x000000000057a8e0 in ExecutePlan (dest=0x1d67180, direction=<optimized out>, numberTuples=0, sendTuples=1
'\001',operation=CMD_SELECT, planstate=0x1d847c0,  
>     estate=0x1d84660) at execMain.c:1395
> #25 standard_ExecutorRun (queryDesc=0x1c95fd0, direction=<optimized out>, count=0) at execMain.c:303
> #26 0x000000000064eb50 in PortalRunSelect (portal=portal@entry=0x1c93fc0, forward=forward@entry=1 '\001', count=0,
count@entry=9223372036854775807,dest=dest@entry=0x1d67180) 
>     at pquery.c:944
> #27 0x000000000064fe8b in PortalRun (portal=portal@entry=0x1c93fc0, count=count@entry=9223372036854775807,
isTopLevel=isTopLevel@entry=1'\001', dest=dest@entry=0x1d67180,  
>     altdest=altdest@entry=0x1d67180, completionTag=completionTag@entry=0x7fff103950e0 "") at pquery.c:788
> #28 0x000000000064be96 in exec_simple_query (query_string=0x1d1f200 "SELECT to_datestamp_immutable(time_int) FROM
random_times;")at postgres.c:1046 
> #29 PostgresMain (argc=<optimized out>, argv=argv@entry=0x1c742a0, dbname=0x1c74158 "regress", username=<optimized
out>)at postgres.c:3959 
> #30 0x000000000060d7be in BackendRun (port=0x1c98020) at postmaster.c:3614
> #31 BackendStartup (port=0x1c98020) at postmaster.c:3304
> #32 ServerLoop () at postmaster.c:1367


... so it's looking a lot like the function is parsed for each call.
That seems like a bit of a WTF.

No time to read the code path right now, but I plan to this evening.

In the mean time, any thoughts?

--
 Craig Ringer                   http://www.2ndQuadrant.com/
 PostgreSQL Development, 24x7 Support, Training & Services