Thread: Interesting case of IMMUTABLE significantly hurting performance

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.

http://stackoverflow.com/q/18220761/398670

CREATE OR REPLACE FUNCTION
  to_datestamp_immutable(time_int double precision) RETURNS date AS $$
  SELECT date_trunc('day', to_timestamp($1))::date;
$$ LANGUAGE SQL IMMUTABLE;

With IMMUTABLE:  33060.918
With STABLE:     6063.498

The plans are the same for both, though the cost estimate for the
IMMUTABLE variant is (surprisingly) massively higher.

The question contains detailed instructions to reproduce the issue, and
I can confirm the same results on my machine.

It looks like the difference is created by to_timestamp , in that if
to_timestamp is replaced with interval maths the difference goes away.

I'm very curious and am doing a quick profile now, but I wanted to raise
this on the list for comment/opinions, since it's very
counter-intuitive. IIRC docs don't suggest that IMMUTABLE can ever be
more expensive.

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

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

On 08/14/2013 11:52 AM, Pavel Stehule wrote:
>
> If I understand, a used IMMUTABLE flag disables inlining. What you see,
> is SQL eval overflow.
>
> My rule is - don't use flags in SQL functions, when it is possible.

Interesting. I knew that was the case for STRICT, but am surprised to
hear it's the case for IMMUTABLE as well. That seems ...
counter-intuitive. Not to mention undocumented as far as I can see.

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

Craig Ringer <craig@2ndquadrant.com> writes:
> 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.

> http://stackoverflow.com/q/18220761/398670

> CREATE OR REPLACE FUNCTION
>   to_datestamp_immutable(time_int double precision) RETURNS date AS $$
>   SELECT date_trunc('day', to_timestamp($1))::date;
> $$ LANGUAGE SQL IMMUTABLE;

[ shrug... ]  Using IMMUTABLE to lie about the mutability of a function
(in this case, date_trunc) is a bad idea.  It's likely to lead to wrong
answers, never mind performance issues.  In this particular case, I
imagine the performance problem comes from having suppressed the option
to inline the function body ... but you should be more worried about
whether you aren't getting flat-out bogus answers in other cases.

            regards, tom lane

On 08/14/2013 12:17 PM, Tom Lane wrote:
> [ shrug... ]  Using IMMUTABLE to lie about the mutability of a function
> (in this case, date_trunc) is a bad idea.  It's likely to lead to wrong
> answers, never mind performance issues.  In this particular case, I
> imagine the performance problem comes from having suppressed the option
> to inline the function body ... but you should be more worried about
> whether you aren't getting flat-out bogus answers in other cases.

Oh, I totally agree, and I'd never do this myself. I was just curious
about the behaviour.

It's interesting that this variant doesn't seem to be slow:

create or replace function to_datestamp_immutable(
    time_int double precision
) returns date as $$
  select date_trunc('day', timestamp 'epoch' + $1 * interval '1
second')::date;
$$ language sql immutable;


and there's no sign it's parsed each time. So it's not just the
IMMUTABLE flag.

If nothing else this strongly suggests that the docs don't cover this
area particularly comprehensively.


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

Craig Ringer <craig@2ndquadrant.com> writes:
> It's interesting that this variant doesn't seem to be slow:

> create or replace function to_datestamp_immutable(
>     time_int double precision
> ) returns date as $$
>   select date_trunc('day', timestamp 'epoch' + $1 * interval '1
> second')::date;
> $$ language sql immutable;

> and there's no sign it's parsed each time. So it's not just the
> IMMUTABLE flag.

If you're working with timestamp not timestamptz, I think the functions
being called here actually are immutable (they don't have any dependency
on the timezone parameter).  So this function is safely inline-able
and there's no performance hit from multiple executions.

As Pavel mentioned upthread, the safest rule of thumb for SQL functions
that you want to get inlined is to not mark them as to either mutability
or strictness.  That lets the planner inline them without any possible
change of semantics.  (The basic point here is that a function marked
volatile can be expanded to its contained functions even if they're
immutable; but the other way around represents a potential semantic
change, so the planner won't do it.)

            regards, tom lane