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

   >  -----Original Message-----
   >  From: Justin Pryzby <pryzby@telsasoft.com>
   >  Sent: Sunday, August 22, 2021 11:48
   >  To: Ranier Vilela <ranier.vf@gmail.com>
   >  Cc: ldh@laurent-hasson.com; Tom Lane <tgl@sss.pgh.pa.us>; pgsql-
   >  performance@postgresql.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