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=<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@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 -- Sent via pgsql-performance mailing list (pgsql-performance@xxxxxxxxxxxxxx) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-performance
