Re: plan cache overhead on plpgsql expression

Hi,

On Sun, Feb 16, 2020 at 11:13 PM Pavel Stehule <pavel(dot)stehule(at)gmail(dot)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(at)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