RE: Big Performance drop of Exceptions in UDFs between V11.2 and 13.4

> -----Original Message-----
> From: Justin Pryzby <pryzby(at)telsasoft(dot)com>
> Sent: Sunday, August 22, 2021 11:48
> To: Ranier Vilela <ranier(dot)vf(at)gmail(dot)com>
> Cc: ldh(at)laurent-hasson(dot)com; Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us>; pgsql-
> performance(at)postgresql(dot)org
> Subject: Re: Big Performance drop of Exceptions in UDFs between V11.2
> and 13.4
>
> On Sun, Aug 22, 2021 at 10:50:47AM -0300, Ranier Vilela wrote:
> > > Tried to check this with Very Sleepy at Windows 10 (bare metal).
> > > Not sure it can help if someone can guide how to test this better?
>
> > explain (analyze,buffers,COSTS,TIMING) select MAX(toFloat(a, null)) as
> > "a" from sampletest;
>
> Your 100sec result *seems* to reproduce the problem, but it'd be more
> clear if you showed the results of both queries (toFloat(a) vs toFloat(b)).
> Laurent's queries took 800sec vs 2sec.
>
> > postgres.png (print screen from Very Sleepy) postgres.csv
>
> This looks useful, thanks. It seems like maybe win64 builds are very slow
> running this:
>
> exec_stmt_block() /
> BeginInternalSubTransaction() /
> AbortSubTransaction() /
> reschedule_timeouts() /
> schedule_alarm() /
> setitimer() /
> pg_timer_thread() /
> WaitForSingleObjectEx ()
>
> We should confirm whether there's a dramatic regression caused by
> postgres source code (and not by compilation environment or windows
> version changes).
> Test if there's a dramatic difference between v11 and v12, or v12 and
> v13.
> To be clear, the ~4x difference in v11 between Laurent's "exceptional"
> and "nonexceptional" cases is expected. But the 400x difference in v13
> is not.
>
> If it's due to a change in postgres source code, we should find what
> commit caused the regression.
>
> First, check if v12 is affected. Right now, we know that v11.2 is ok and
> v13.4 is not ok. Then (unless someone has a hunch where to look), you
> could use git bisect to find the culprit commit.
>
> Git log shows 85 commits affecting those files across the 2 branches -
> once we determine whether v12 is affected, that alone eliminates a
> significant fraction of the commits to be checked.
>
> git log --oneline --cherry-pick
> origin/REL_11_STABLE...origin/REL_13_STABLE
> src/backend/access/transam/xact.c src/backend/port/win32/timer.c
> src/backend/utils/misc/timeout.c src/pl/plpgsql/src/pl_exec.c
>
> --
> Justin

So, I have other installs of Postgres I can also test on my laptop. No VM, straight install of Windows 10.

PostgreSQL 12.3, compiled by Visual C++ build 1914, 64-bit install
No-exceptions scenario
---------------------------------------
Aggregate (cost=14778.40..14778.41 rows=1 width=4) (actual time=1462.836..1462.837 rows=1 loops=1)
Buffers: shared hit=6379
-> Seq Scan on sampletest (cost=0.00..11975.60 rows=560560 width=32) (actual time=0.020..86.506 rows=1000000 loops=1)
Buffers: shared hit=6370
Planning Time: 0.713 ms
Execution Time: 1463.359 ms

Exceptions scenario
---------------------------------------
I canceled the query after 18mn...

PostgreSQL 11.1, compiled by Visual C++ build 1914, 64-bit
No-exceptions scenario
---------------------------------------
Aggregate (cost=14778.40..14778.41 rows=1 width=4) (actual time=1784.915..1784.915 rows=1 loops=1)
Buffers: shared hit=6377
-> Seq Scan on sampletest (cost=0.00..11975.60 rows=560560 width=32) (actual time=0.026..107.194 rows=1000000 loops=1)
Buffers: shared hit=6370
Planning Time: 0.374 ms
Execution Time: 1785.203 ms

Exceptions scenario
---------------------------------------
Aggregate (cost=14778.40..14778.41 rows=1 width=4) (actual time=33891.778..33891.778 rows=1 loops=1)
Buffers: shared hit=6372
-> Seq Scan on sampletest (cost=0.00..11975.60 rows=560560 width=32) (actual time=0.015..171.325 rows=1000000 loops=1)
Buffers: shared hit=6370
Planning Time: 0.090 ms
Execution Time: 33891.806 ms