> -----Original Message-----
> From: ldh@xxxxxxxxxxxxxxxxxx <ldh@xxxxxxxxxxxxxxxxxx>
> Sent: Sunday, August 22, 2021 14:37
> To: Tom Lane <tgl@xxxxxxxxxxxxx>; Justin Pryzby
> <pryzby@xxxxxxxxxxxxx>
> Cc: Ranier Vilela <ranier.vf@xxxxxxxxx>; pgsql-
> performance@xxxxxxxxxxxxxx
> Subject: RE: Big Performance drop of Exceptions in UDFs between V11.2
> and 13.4
>
>
>
> > -----Original Message-----
> > From: Tom Lane <tgl@xxxxxxxxxxxxx>
> > Sent: Sunday, August 22, 2021 13:51
> > To: Justin Pryzby <pryzby@xxxxxxxxxxxxx>
> > Cc: Ranier Vilela <ranier.vf@xxxxxxxxx>; ldh@xxxxxxxxxxxxxxxxxx;
> > pgsql-performance@xxxxxxxxxxxxxx
> > Subject: Re: Big Performance drop of Exceptions in UDFs between
> V11.2
> > and 13.4
> >
> > Justin Pryzby <pryzby@xxxxxxxxxxxxx> writes:
> > > 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 ()
> >
> > Hmm ... we should not be there unless there are active timeout
> events,
> > which there aren't by default. I wonder whether either Ranier or
> > Laurent have statement_timeout or some similar option enabled.
> >
> > I tried setting statement_timeout = '1 min' just to see if that would
> affect
> > the results. It does, but only incrementally on my Linux box (on v13,
> the
> > exception-causing query slows from ~13sec to ~14sec). It's possible
> that
> > our Windows version of
> > setitimer() is far slower, but that doesn't make a lot of sense really ---
> the
> > client side of that just briefly takes a critical section. It shouldn't be
> > blocking.
> >
> > Also, the Windows version (src/backend/port/win32/timer.c) hasn't
> > changed at all since before v11. So even if it's slow, that doesn't tell
> us
> > what changed.
> >
> > There is a patch in v14 (09cf1d522) that drastically reduces the rate
> at
> > which we make setitimer() calls, which would likely be enough to fix
> any
> > performance problem that may exist here.
> > But it's still unclear what's different between v11 and v13.
> >
> > regards, tom lane
>
>
> Hello Tom,
>
> On both my clean 13.4 install and current 11.2 install, I have
> #statement_timeout = 0 # in milliseconds, 0 is
> disabled
>
> Note that the 13.4 clean install I gave last measurements for has all stock
> settings.
>
> Thank you,
> Laurent.
>
>
One more fresh install, of 11.13 this time and the issue is not there... 😊
Aggregate (cost=14778.40..14778.41 rows=1 width=4) (actual time=1963.573..1963.574 rows=1 loops=1)
Buffers: shared hit=6377
-> Seq Scan on sampletest (cost=0.00..11975.60 rows=560560 width=32) (actual time=0.027..110.896 rows=1000000 loops=1)
Buffers: shared hit=6370
Planning Time: 0.427 ms
Execution Time: 1963.981 ms
Aggregate (cost=21370.00..21370.01 rows=1 width=4) (actual time=31685.853..31685.853 rows=1 loops=1)
Buffers: shared hit=6370
-> Seq Scan on sampletest (cost=0.00..16370.00 rows=1000000 width=15) (actual time=0.029..180.664 rows=1000000 loops=1)
Buffers: shared hit=6370
Planning Time: 0.092 ms
Execution Time: 31685.904 ms
I am still experiencing a larger slowdown in the "with-exceptions" scenario being 16x slower compared to other measurements you have all produced.. But at least, it's manageable compared to the multi 100x times.
So, now, in summary:
- I have tried V13.4, V12.3, 11.13, 11.2, 11.1 on several Windows VMs and my personal laptop (no VM).
- All V11.x seem to behave uniformly.
- Starting with 12.3, I am experiencing the major slowdown in the "with exceptions" scenario.
So, I was thinking about stuff and a lot of your intuitions seem to drive towards an issue with the compiler used to compile the Winx64 version... But is it possible that the JIT is getting in there and making things weird? Given that it's a major change in V12 and this is when I am starting to see the issue popup, I figured it might be another avenue to look into?
Thank you,
Laurent Hasson.
