pg.ddx.io pgsql-performance@postgresql.org mailing list archive help / color / mirror / Atom feed From: Craig Ringer <craig@2ndquadrant.com>
To: pgsql-performance@postgresql.org <pgsql-performance@postgresql.org>
Subject: Re: Interesting case of IMMUTABLE significantly hurting performance
Date: Wed, 14 Aug 2013 10:46:52 +0800
Message-ID: <520AEF9C.5030701@2ndquadrant.com> (raw )
In-Reply-To: <520AD240.9060508@2ndquadrant.com >
References: <520AD240.9060508@2ndquadrant.com >
List-Unsubscribe: <mailto:majordomo@postgresql.org?body=unsub%20pgsql-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=<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
view thread (7+ messages) latest in thread
Message-ID: <520AEF9C.5030701@2ndquadrant.com>
Permalink: ../520AEF9C.5030701@2ndquadrant.com/
Also on: postgresql.org/message-id/520AEF9C.5030701@2ndquadrant.com
copy link · copy postgr.es
reply Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-performance@postgresql.org
Cc: craig@2ndquadrant.com
Subject: Re: Interesting case of IMMUTABLE significantly hurting performance
In-Reply-To: <520AEF9C.5030701@2ndquadrant.com>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox