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

Em sáb., 21 de ago. de 2021 às 21:15, ldh(at)laurent-hasson(dot)com <
ldh(at)laurent-hasson(dot)com> escreveu:

>
>
> > -----Original Message-----
> > From: ldh(at)laurent-hasson(dot)com <ldh(at)laurent-hasson(dot)com>
> > Sent: Saturday, August 21, 2021 19:02
> > To: Justin Pryzby <pryzby(at)telsasoft(dot)com>
> > Cc: 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
> >
> >
> >
> > > -----Original Message-----
> > > From: Justin Pryzby <pryzby(at)telsasoft(dot)com>
> > > Sent: Saturday, August 21, 2021 18:17
> > > To: ldh(at)laurent-hasson(dot)com
> > > Cc: 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
> > >
> > > Could you send SELECT * FROM pg_config() and try to find the
> CPU
> > > model ?
> > >
> > > I think it's possible the hypervisor is trapping and emulating
> > unhandled
> > > CPU instructions.
> > >
> > > Actually, it would be interesting to see if the performance
> differs
> > > between
> > > 11.2 and 11.13. It's possible that EDB compiled 11.13 on a
> newer
> > CPU
> > > (or a newer compiler) than 11.2 was compiled.
> > >
> > > If you test that, it should be on a separate VM, unless the
> existing
> > data
> > > dir can be restored from backup. Once you've started a
> cluster with
> > > updated binaries, you should avoid downgrading the binaries.
> >
> >
> >
> > Hello all,
> >
> > OK, I was able to do a clean install of 13.4 on the VM. All stock
> settings,
> > no extensions loaded, pure clean straight out of the install.
> >
> > create table sampletest (a varchar, b varchar);
> > -- truncate table sampletest;
> > insert into sampletest (a, b)
> > select substr(md5(random()::text), 0, 15),
> > (100000000*random())::integer::varchar
> > from generate_series(1,1000000);
> >
> > CREATE OR REPLACE FUNCTION toFloat(str varchar, val real) RETURNS
> > real AS $$ BEGIN
> > RETURN case when str is null then val else str::real end; EXCEPTION
> > WHEN OTHERS THEN
> > RETURN val;
> > END;
> > $$ LANGUAGE plpgsql COST 1 IMMUTABLE;
> >
> >
> > explain (analyze,buffers,COSTS,TIMING) select MAX(toFloat(b, null))
> as
> > "b" from sampletest
> >
> > Aggregate (cost=21370.00..21370.01 rows=1 width=4) (actual
> > time=1780.561..1780.563 rows=1 loops=1)
> > Buffers: shared hit=6387
> > -> Seq Scan on sampletest (cost=0.00..16370.00 rows=1000000
> > width=8) (actual time=0.053..97.329 rows=1000000 loops=1)
> > Buffers: shared hit=6370
> > Planning:
> > Buffers: shared hit=36
> > Planning Time: 2.548 ms
> > Execution Time: 1,810.330 ms
> >
> >
> > explain (analyze,buffers,COSTS,TIMING) select MAX(toFloat(a, null))
> as
> > "a" from sampletest
> >
> > Aggregate (cost=21370.00..21370.01 rows=1 width=4) (actual
> > time=863243.876..863243.877 rows=1 loops=1)
> > Buffers: shared hit=6373
> > -> Seq Scan on sampletest (cost=0.00..16370.00 rows=1000000
> > width=15) (actual time=0.009..301.553 rows=1000000 loops=1)
> > Buffers: shared hit=6370
> > Planning:
> > Buffers: shared hit=44
> > Planning Time: 0.469 ms
> > Execution Time: 863,243.911 ms
> >
> >
> > So I am still able to reproduce this on a different VM and a clean
> install
> > of 13.4 ☹
> >
> >
> > SELECT * FROM pg_config();
> >
> > BINDIR C:/PROGRA~1/POSTGR~1/13/bin
> > DOCDIR C:/PROGRA~1/POSTGR~1/13/doc
> > HTMLDIR C:/PROGRA~1/POSTGR~1/13/doc
> > INCLUDEDIR C:/PROGRA~1/POSTGR~1/13/include
> > PKGINCLUDEDIR C:/PROGRA~1/POSTGR~1/13/include
> > INCLUDEDIR-SERVER C:/PROGRA~1/POSTGR~1/13/include/server
> > LIBDIR C:/PROGRA~1/POSTGR~1/13/lib
> > PKGLIBDIR C:/PROGRA~1/POSTGR~1/13/lib
> > LOCALEDIR C:/PROGRA~1/POSTGR~1/13/share/locale
> > MANDIR C:/Program Files/PostgreSQL/13/man
> > SHAREDIR C:/PROGRA~1/POSTGR~1/13/share
> > SYSCONFDIR C:/Program Files/PostgreSQL/13/etc
> > PGXS C:/Program Files/PostgreSQL/13/lib/pgxs/src/makefiles/
> pgxs.mk
> > CONFIGURE --enable-thread-safety --enable-nls --with-ldap --with-
> > openssl --with-uuid --with-libxml --with-libxslt --with-icu
> --with-tcl --with-
> > perl --with-python
> > CC not recorded
> > CPPFLAGS not recorded
> > CFLAGS not recorded
> > CFLAGS_SL not recorded
> > LDFLAGS not recorded
> > LDFLAGS_EX not recorded
> > LDFLAGS_SL not recorded
> > LIBS not recorded
> > VERSION PostgreSQL 13.4
> >
> >
> > And here is SYSINFO:
> >
> > C:\Users\LHASSON>systeminfo
> >
> > Host Name: PRODDB
> > OS Name: Microsoft Windows Server 2012 R2 Standard
> > OS Version: 6.3.9600 N/A Build 9600
> > OS Manufacturer: Microsoft Corporation
> > OS Configuration: Member Server
> > OS Build Type: Multiprocessor Free
> > Original Install Date: 2015-09-19, 18:19:41
> > System Boot Time: 2021-07-22, 11:45:09
> > System Manufacturer: VMware, Inc.
> > System Model: VMware Virtual Platform
> > System Type: x64-based PC
> > Processor(s): 4 Processor(s) Installed.
> > [01]: Intel64 Family 6 Model 79 Stepping
> 1 GenuineIntel
> > ~2397 Mhz
> > [02]: Intel64 Family 6 Model 79 Stepping
> 1 GenuineIntel
> > ~2397 Mhz
> > [03]: Intel64 Family 6 Model 79 Stepping
> 1 GenuineIntel
> > ~2397 Mhz
> > [04]: Intel64 Family 6 Model 79 Stepping
> 1 GenuineIntel
> > ~2397 Mhz
> > BIOS Version: Phoenix Technologies LTD 6.00, 2020-05-28
> > Windows Directory: C:\Windows
> > System Directory: C:\Windows\system32
> > Boot Device: \Device\HarddiskVolume1
> > System Locale: en-us;English (United States)
> > Input Locale: en-us;English (United States)
> > Time Zone: (UTC-05:00) Eastern Time (US & Canada)
> > Total Physical Memory: 65,535 MB
> > Available Physical Memory: 57,791 MB
> > Virtual Memory: Max Size: 75,263 MB
> > Virtual Memory: Available: 66,956 MB
> > Virtual Memory: In Use: 8,307 MB
> > Page File Location(s): C:\pagefile.sys
> >
>
>
> And by the way, I reproduced this again on my personal laptop with a fresh
> clean base-line install of 13.4.
>
> Systeminfo
> -------------------
> OS Name: Microsoft Windows 10 Pro
> OS Version: 10.0.19043 N/A Build 19043
> OS Manufacturer: Microsoft Corporation
> OS Configuration: Standalone Workstation
> OS Build Type: Multiprocessor Free
> Registered Owner: Windows User
> Registered Organization:
> Product ID: 00330-50535-98614-AAOEM
> Original Install Date: 2021-04-04, 09:50:59
> System Boot Time: 2021-08-19, 10:18:03
> System Manufacturer: LENOVO
> System Model: 20HRCTO1WW
> System Type: x64-based PC
> Processor(s): 1 Processor(s) Installed.
> [01]: Intel64 Family 6 Model 142 Stepping 9
> GenuineIntel ~801 Mhz
> BIOS Version: LENOVO N1MET64W (1.49 ), 2020-10-14
> Windows Directory: C:\WINDOWS
> System Directory: C:\WINDOWS\system32
> Boot Device: \Device\HarddiskVolume1
> System Locale: en-us;English (United States)
> Input Locale: en-us;English (United States)
> Time Zone: (UTC-05:00) Eastern Time (US & Canada)
> Total Physical Memory: 16,219 MB
> Available Physical Memory: 4,971 MB
> Virtual Memory: Max Size: 32,603 MB
> Virtual Memory: Available: 12,168 MB
> Virtual Memory: In Use: 20,435 MB
> Page File Location(s): C:\pagefile.sys
>
>
> SELECT * FROM pg_config();
> --------------------------------------------
> BINDIR C:/PROGRA~1/POSTGR~1/13/bin
> DOCDIR C:/PROGRA~1/POSTGR~1/13/doc
> HTMLDIR C:/PROGRA~1/POSTGR~1/13/doc
> INCLUDEDIR C:/PROGRA~1/POSTGR~1/13/include
> PKGINCLUDEDIR C:/PROGRA~1/POSTGR~1/13/include
> INCLUDEDIR-SERVER C:/PROGRA~1/POSTGR~1/13/include/server
> LIBDIR C:/PROGRA~1/POSTGR~1/13/lib
> PKGLIBDIR C:/PROGRA~1/POSTGR~1/13/lib
> LOCALEDIR C:/PROGRA~1/POSTGR~1/13/share/locale
> MANDIR C:/Program Files/PostgreSQL/13/man
> SHAREDIR C:/PROGRA~1/POSTGR~1/13/share
> SYSCONFDIR C:/Program Files/PostgreSQL/13/etc
> PGXS C:/Program Files/PostgreSQL/13/lib/pgxs/src/makefiles/pgxs.mk
> CONFIGURE --enable-thread-safety --enable-nls --with-ldap
> --with-openssl --with-uuid --with-libxml --with-libxslt --with-icu
> --with-tcl --with-perl --with-python
> CC not recorded
> CPPFLAGS not recorded
> CFLAGS not recorded
> CFLAGS_SL not recorded
> LDFLAGS not recorded
> LDFLAGS_EX not recorded
> LDFLAGS_SL not recorded
> LIBS not recorded
> VERSION PostgreSQL 13.4
>
> 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?

Postgres (head)
Debug build with msvc 2019 64 bits.

explain (analyze,buffers,COSTS,TIMING) select MAX(toFloat(a, null)) as "a"
from sampletest;

1. Postgres (head) with normal startup:
postgres=# explain (analyze,buffers,COSTS,TIMING) select MAX(toFloat(a,
null)) as "a" from sampletest;
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=21370.00..21370.01 rows=1 width=4) (actual
time=103064.061..103064.062 rows=1 loops=1)
Buffers: shared hit=6370
-> Seq Scan on sampletest (cost=0.00..16370.00 rows=1000000 width=15)
(actual time=0.037..1253.552 rows=1000000 loops=1)
Buffers: shared hit=6370
Planning Time: 0.252 ms
Execution Time: 103064.136 ms
(6 rows)

Files:
postgres.png (print screen from Very Sleepy)
postgres.csv
postgres.capture

2. Postgres (head) with --single startup:
backend> explain (analyze,buffers,COSTS,TIMING) select MAX(toFloat(a,
null)) as "a" from sampletest;
1: QUERY PLAN (typeid = 25, len = -1, typmod = -1, byval = f)
----
1: QUERY PLAN = "Aggregate (cost=21370.00..21370.01 rows=1
width=4) (actual time=61820.815..61820.816 rows=1 loops=1)" (typeid
= 25, len = -1, typmod = -1, byval = f)
----
1: QUERY PLAN = " Buffers: shared hit=11 read=6379" (typeid =
25, len = -1, typmod = -1, byval = f)
----
1: QUERY PLAN = " -> Seq Scan on sampletest
(cost=0.00..16370.00 rows=1000000 width=15) (actual time=0.113..1607.444
rows=1000000 loops=1)" (typeid = 25, len = -1, typmod = -1, byval = f)
----
1: QUERY PLAN = " Buffers: shared read=6370" (typeid =
25, len = -1, typmod = -1, byval = f)
----
1: QUERY PLAN = "Planning:" (typeid = 25, len = -1, typmod =
-1, byval = f)
----
1: QUERY PLAN = " Buffers: shared hit=51 read=24" (typeid =
25, len = -1, typmod = -1, byval = f)
----
1: QUERY PLAN = "Planning Time: 21.647 ms" (typeid = 25, len =
-1, typmod = -1, byval = f)
----
1: QUERY PLAN = "Execution Time: 61835.470 ms" (typeid = 25, len =
-1, typmod = -1, byval = f)

postgres_single.png (print screen from Very Sleepy)

Attached some files with results.

regards,
Ranier Vilela