On Thu, 19 Nov 2020 at 09:10, Alastair McKinley <a.mckinley@xxxxxxxxxxxxxxxxxxxx> 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 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. 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/
