Date: Sun, 22 Aug 2021 10:47:58 -0500
From: Justin Pryzby <pryzby@telsasoft.com>
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
Message-ID: <20210822154758.GZ10479@telsasoft.com>
References: 
 <MN2PR15MB2560AE2A878FBBE88DCFF33385C29@MN2PR15MB2560.namprd15.prod.outlook.com>
 <2092859.1629558281@sss.pgh.pa.us>
 <MN2PR15MB25607BDC72A325CA9B9D3E3385C29@MN2PR15MB2560.namprd15.prod.outlook.com>
 <2136207.1629569846@sss.pgh.pa.us>
 <20210821191950.GW10479@telsasoft.com>
 <MN2PR15MB2560ED2A8F967B14E7D7881E85C29@MN2PR15MB2560.namprd15.prod.outlook.com>
 <20210821221729.GY10479@telsasoft.com>
 <MN2PR15MB2560FB03666CEABB651FB32185C29@MN2PR15MB2560.namprd15.prod.outlook.com>
 <MN2PR15MB256034533A31A7C11E3C347985C39@MN2PR15MB2560.namprd15.prod.outlook.com>
 <CAEudQAocYZieAMgCtXa8Oau8=dVJ1_R1r0coLeF1LfiYkBCTNA@mail.gmail.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: 
 <CAEudQAocYZieAMgCtXa8Oau8=dVJ1_R1r0coLeF1LfiYkBCTNA@mail.gmail.com>
User-Agent: Mutt/1.9.4 (2018-02-28)
Archived-At: 
 <https://www.postgresql.org/message-id/20210822154758.GZ10479%40telsasoft.com>
Precedence: bulk

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