Thread: Performance degradation with non-null proconfig

Performance degradation with non-null proconfig

From
Alastair McKinley
Date:
Hi all,

I recently came across a subtle performance issue when working with some compiled UDFs to optimise a workload.

These UDFs accidently had "set search_path = 'public'" in their definition.  When profiling with perf, I noticed a large amount of elapsed time spent in the function

    voidAtEOXact_GUC(bool isCommit, int nestLevel)

Reading the comments it is called when exiting a function with a custom proconfig, removing it for my case gave me a very large (3x) speedup.

Below is a contrived test case that illustrates this issue (tested on 13.0, but also seen in 12.4).

create table test as
select r as row_id,
    array_agg(random()::float4) as data
from generate_series(1,100000) r,
generate_series(1,20) e
group by r;

create or replace function array_sum(float4[]) returns float4 as
$$
    select sum(e) from unnest($1) e;
$$ language sql immutable parallel safe;


create or replace function array_sum_public_search_path(float4[]) returns float4 as
$$
    select sum(e) from unnest($1) e;
$$ language sql immutable parallel safe set search_path = 'public';

\timing on
\o /dev/null
select format($q$ explain (analyze,verbose,buffers) select array_sum(data) from test $q$) from generate_series(1,10);
\gexec
select format($q$ explain (analyze,verbose,buffers) select array_sum_public_search_path(data) from test $q$) from generate_series(1,10);
\gexec

Test output:

postgres=# select format($q$ explain (analyze,verbose,buffers) select array_sum(data) from test $q$) from generate_series(1,10);
Time: 0.940 ms
postgres=# \gexec
Time: 745.988 ms
Time: 677.056 ms
Time: 653.709 ms
Time: 651.033 ms
Time: 650.063 ms
Time: 647.741 ms
Time: 650.328 ms
Time: 651.954 ms
Time: 655.384 ms
Time: 650.988 ms
Time: 0.976 ms
postgres=# select format($q$ explain (analyze,verbose,buffers) select array_sum_public_search_path(data) from test $q$) from generate_series(1,10);
Time: 0.774 ms
postgres=# \gexec
Time: 871.628 ms
Time: 853.298 ms
Time: 856.798 ms
Time: 857.794 ms
Time: 861.836 ms
Time: 858.291 ms
Time: 861.763 ms
Time: 850.221 ms
Time: 851.470 ms
Time: 858.875 ms
Time: 1.514 ms
postgres=#


I didn't see this discussed anywhere else, it might be worth adding a note to the documentation if it can't easily be addressed.

Best regards,

Alastair






Re: Performance degradation with non-null proconfig

From
Simon Riggs
Date:
On Thu, 19 Nov 2020 at 09:10, Alastair McKinley
<a.mckinley@analyticsengines.com> wrote:
>
> Hi all,
>
> I recently came across a subtle performance issue when working with some compiled UDFs to optimise a workload.
>
> These UDFs accidently had "set search_path = 'public'" in their definition.  When profiling with perf, I noticed a
largeamount of elapsed time spent in the function
 
>
>     voidAtEOXact_GUC(bool isCommit, int nestLevel)
>
> Reading the comments it is called when exiting a function with a custom proconfig, removing it for my case gave me a
verylarge (3x) speedup.
 
>
> Below is a contrived test case that illustrates this issue (tested on 13.0, but also seen in 12.4).
>
> create table test as
> select r as row_id,
>     array_agg(random()::float4) as data
> from generate_series(1,100000) r,
> generate_series(1,20) e
> group by r;
>
> create or replace function array_sum(float4[]) returns float4 as
> $$
>     select sum(e) from unnest($1) e;
> $$ language sql immutable parallel safe;
>
>
> create or replace function array_sum_public_search_path(float4[]) returns float4 as
> $$
>     select sum(e) from unnest($1) e;
> $$ language sql immutable parallel safe set search_path = 'public';
>
> \timing on
> \o /dev/null
> select format($q$ explain (analyze,verbose,buffers) select array_sum(data) from test $q$) from
generate_series(1,10);
> \gexec
> select format($q$ explain (analyze,verbose,buffers) select array_sum_public_search_path(data) from test $q$) from
generate_series(1,10);
> \gexec
>
>
> Test output:
>
> postgres=# select format($q$ explain (analyze,verbose,buffers) select array_sum(data) from test $q$) from
generate_series(1,10);
> Time: 0.940 ms
> postgres=# \gexec
> Time: 745.988 ms
> Time: 677.056 ms
> Time: 653.709 ms
> Time: 651.033 ms
> Time: 650.063 ms
> Time: 647.741 ms
> Time: 650.328 ms
> Time: 651.954 ms
> Time: 655.384 ms
> Time: 650.988 ms
> Time: 0.976 ms
> postgres=# select format($q$ explain (analyze,verbose,buffers) select array_sum_public_search_path(data) from test
$q$)from generate_series(1,10);
 
> Time: 0.774 ms
> postgres=# \gexec
> Time: 871.628 ms
> Time: 853.298 ms
> Time: 856.798 ms
> Time: 857.794 ms
> Time: 861.836 ms
> Time: 858.291 ms
> Time: 861.763 ms
> Time: 850.221 ms
> Time: 851.470 ms
> Time: 858.875 ms
> Time: 1.514 ms
> postgres=#
>
>
>
> I didn't see this discussed anywhere else, it might be worth adding a note to the documentation if it can't easily be
addressed.

I came up with a simpler test, which doesn't reproduce this

postgres=# create or replace function proconfig1() returns integer
language sql as $$ select 1; $$;
CREATE FUNCTION
postgres=# create or replace function proconfig2() returns integer
language sql as $$ select 1; $$ set search_path = 'public';
CREATE FUNCTION
postgres=# \timing
Timing is on.
postgres=# select sum(proconfig1()) from generate_series(1,10000);
  sum
-------
 10000
(1 row)
Time: 2.818 ms
postgres=# select sum(proconfig2()) from generate_series(1,10000);
  sum
-------
 10000
(1 row)
Time: 41.750 ms

So the overhead would be 4us per call? Other tests show that is
roughly the same situation for PLpgSQL functions.

Can't see anything to document as yet.

-- 
Simon Riggs                http://www.EnterpriseDB.com/