Re: plan cache overhead on plpgsql expression

Hi,

On Sun, Feb 16, 2020 at 11:13 PM Pavel Stehule <pavel.stehule@gmail.com> wrote:
> when I do some profiling of plpgsql, usually I surprised how significant overhead has expression execution. Any calculations are very slow.
>
> This is not typical example of plpgsql, but it shows cleanly where is a overhead
>
> CREATE OR REPLACE FUNCTION public.foo()
>  RETURNS void
>  LANGUAGE plpgsql
>  IMMUTABLE
> AS $function$
> declare i bigint = 0;
> begin
>   while i < 100000000
>   loop
>     i := i + 1;
>   end loop;
> end;
> $function$
>
> Profile of development  version
>
>   10,04%  plpgsql.so                          [.] exec_eval_simple_expr
>    9,17%  postgres                            [.] AcquireExecutorLocks
>    7,01%  postgres                            [.] ExecInterpExpr
>    5,86%  postgres                            [.] OverrideSearchPathMatchesCurrent
>    4,71%  postgres                            [.] GetCachedPlan
>    4,14%  postgres                            [.] AcquirePlannerLocks
>    3,72%  postgres                            [.] RevalidateCachedQuery
>    3,56%  postgres                            [.] MemoryContextReset
>    3,43%  plpgsql.so                          [.] plpgsql_param_eval_var

I was thinking about this overhead many months back and had even
written a patch to avoid going to the planner for "simple"
expressions, which can be handled by the executor.  Here is what the
performance looks like:

HEAD:

latency: 31979.393 ms

    18.32%  postgres  postgres           [.] ExecInterpExpr
    11.37%  postgres  plpgsql.so         [.] exec_eval_expr
     8.58%  postgres  plpgsql.so         [.] plpgsql_param_eval_var
     8.31%  postgres  plpgsql.so         [.] exec_stmt
     6.44%  postgres  postgres           [.] GetCachedPlan
     5.47%  postgres  postgres           [.] AcquireExecutorLocks
     5.30%  postgres  postgres           [.] RevalidateCachedQuery
     4.79%  postgres  plpgsql.so         [.] exec_assign_value
     4.41%  postgres  postgres           [.] SPI_plan_get_cached_plan
     4.36%  postgres  postgres           [.] MemoryContextReset
     4.22%  postgres  postgres           [.] ReleaseCachedPlan
     4.03%  postgres  postgres           [.] OverrideSearchPathMatchesCurrent
     2.63%  postgres  plpgsql.so         [.] exec_assign_expr
     2.11%  postgres  postgres           [.] int84lt
     1.95%  postgres  postgres           [.] ResourceOwnerForgetPlanCacheRef
     1.71%  postgres  postgres           [.] int84pl
     1.57%  postgres  postgres           [.] ResourceOwnerRememberPlanCacheRef
     1.38%  postgres  postgres           [.] recomputeNamespacePath
     1.35%  postgres  postgres           [.] ScanQueryForLocks
     1.24%  postgres  plpgsql.so         [.] exec_cast_value
     0.38%  postgres  postgres           [.] ResourceOwnerEnlargePlanCacheRefs
     0.05%  postgres  [kernel.kallsyms]  [k] __do_softirq
     0.03%  postgres  postgres           [.] GetUserId

Patched:

latency: 21011.871 ms

    28.26%  postgres  postgres           [.] ExecInterpExpr
    12.26%  postgres  plpgsql.so         [.] plpgsql_param_eval_var
    12.02%  postgres  plpgsql.so         [.] exec_stmt
    11.10%  postgres  plpgsql.so         [.] exec_eval_expr
    10.05%  postgres  postgres           [.] SPI_plan_is_valid
     7.09%  postgres  postgres           [.] MemoryContextReset
     6.65%  postgres  plpgsql.so         [.] exec_assign_value
     3.53%  postgres  plpgsql.so         [.] exec_assign_expr
     2.91%  postgres  postgres           [.] int84lt
     2.61%  postgres  postgres           [.] int84pl
     2.42%  postgres  plpgsql.so         [.] exec_cast_value
     0.86%  postgres  postgres           [.] CachedPlanIsValid
     0.16%  postgres  plpgsql.so         [.] SPI_plan_is_valid@plt
     0.05%  postgres  [kernel.kallsyms]  [k] __do_softirq
     0.03%  postgres  [kernel.kallsyms]  [k] finish_task_switch

I didn't send the patch, because it didn't handle the cases where a
simple expression consists of an inline-able function(s) in it, which
are better handled by a full-fledged planner call backed up by the
plan cache.  If we don't do that then every evaluation of such
"simple" expression needs to invoke the planner.  For example:

Consider this inline-able SQL function:

create or replace function sql_incr(a bigint)
returns int
immutable language sql as $$
select a+1;
$$;

Then this revised body of your function foo():

CREATE OR REPLACE FUNCTION public.foo()
 RETURNS int
 LANGUAGE plpgsql
 IMMUTABLE
AS $function$
declare i bigint = 0;
begin
  while i < 1000000
  loop
    i := sql_incr(i);
  end loop; return i;
end;
$function$
;

With HEAD `select foo()` finishes in 786 ms, whereas with the patch,
it takes 5102 ms.

I think the patch might be good idea to reduce the time to compute
simple expressions in plpgsql, if we can address the above issue.

Thanks,
Amit