Re: Interesting case of IMMUTABLE significantly hurting 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(at)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(at)entry=0x1d75a70, argList=argList(at)entry=0x1d76260, econtext=econtext(at)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(at)entry=0x1d75260, argList=argList(at)entry=0x1d76b60, econtext=econtext(at)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(at)entry=0x7fff1039497c) at execQual.c:5436
> #12 0x0000000000594a12 in ExecResult (node=node(at)entry=0x1d74ef0) at nodeResult.c:155
> #13 0x000000000057cff8 in ExecProcNode (node=node(at)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=<optimized out>) 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(at)entry=0x1d859d0, isDone=isDone(at)entry=0x7fff10394bfc) at execQual.c:5436
> #21 0x000000000058409a in ExecScan (node=node(at)entry=0x1d847c0, accessMtd=accessMtd(at)entry=0x594c70 <SeqNext>, recheckMtd=recheckMtd(at)entry=0x594c60 <SeqRecheck>)
> at execScan.c:207
> #22 0x0000000000594cdf in ExecSeqScan (node=node(at)entry=0x1d847c0) at nodeSeqscan.c:113
> #23 0x000000000057cfa8 in ExecProcNode (node=node(at)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(at)entry=0x1c93fc0, forward=forward(at)entry=1 '\001', count=0, count(at)entry=9223372036854775807, dest=dest(at)entry=0x1d67180)
> at pquery.c:944
> #27 0x000000000064fe8b in PortalRun (portal=portal(at)entry=0x1c93fc0, count=count(at)entry=9223372036854775807, isTopLevel=isTopLevel(at)entry=1 '\001', dest=dest(at)entry=0x1d67180,
> altdest=altdest(at)entry=0x1d67180, completionTag=completionTag(at)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(at)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