Message-ID: <520AEF9C.5030701@2ndquadrant.com>
Date: Wed, 14 Aug 2013 10:46:52 +0800
From: Craig Ringer <craig@2ndquadrant.com>
Organization: 2nd Quadrant
User-Agent: Mozilla/5.0 (X11; Linux x86_64;
 rv:17.0) Gecko/20130625 Thunderbird/17.0.7
MIME-Version: 1.0
To: "pgsql-performance@postgresql.org" <pgsql-performance@postgresql.org>
Subject: Re: Interesting case of IMMUTABLE significantly hurting
 performance
References: <520AD240.9060508@2ndquadrant.com>
In-Reply-To: <520AD240.9060508@2ndquadrant.com>
Content-Type: text/plain; charset=ISO-8859-1
Content-Transfer-Encoding: 7bit
Precedence: bulk
Sender: pgsql-performance-owner@postgresql.org

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@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance