Обсуждение: BUG #16223: Performance regression between 11.6 and 12.1 in an SQL query with a recursive CTE based on function

The following bug has been logged on the website:

Bug reference:      16223
Logged by:          ChristianS
Email address:      schwaderer@ivocotec.de
PostgreSQL version: 12.1
Operating system:   Ubuntu 18.04
Description:

I have a query that runs significantly slower in Postgres 12.1 than it does
in Postgres 11.6.

(I have asked on dba.stackexchange

https://dba.stackexchange.com/questions/257759/recursive-cte-based-on-function-values-significantly-slower-on-postgres-12-than
- hoping that someone would jump in and tell me why this is my fault and why
it has nothing to do with PostgreSQL itself. However, since there is still
no reaction after two days, I can be somewhat sure that it's not a very
obvious mistake of mine and maybe something you might want to
investigate.)


First, we create this simple function


CREATE OR REPLACE FUNCTION public.my_test_function()
 RETURNS SETOF record
 LANGUAGE sql
 IMMUTABLE SECURITY DEFINER
AS $function$ 

SELECT 
        1::integer AS id,
        '2019-11-20'::date AS "startDate",
        '2020-01-01'::date AS "endDate"

$function$;


Then for the actual query


WITH  "somePeriods" AS  (
      SELECT * FROM my_test_function() AS 
      f(id integer, "startDate" date, "endDate" date)
),

"maxRecursiveEndDate" AS (

SELECT "startDate", "endDate", id, 
( 
  WITH RECURSIVE prep("startDateParam", "endDateParam") AS (

  SELECT "startDate","endDate" FROM "somePeriods" WHERE id = od.id
  UNION
  SELECT "startDate","endDate" FROM "somePeriods", prep
  WHERE
    "startDate" <= ("endDateParam" + '1 day'::interval ) AND ("endDateParam"
+ '1 day'::interval ) <= "endDate"
  )
  SELECT max("endDateParam") FROM prep
) AS "endDateNew"

FROM "somePeriods" AS od

)

SELECT * FROM "maxRecursiveEndDate";


What this actually does it not so important here, I guess. The important
point is: It runs very fast on Postgres 11.6 (like ca 4ms) and much slower
on PostgreSQL 12.1 (ca 150ms). The output of EXPLAIN ANALYZE did not give me
further hints.
A crucial point might or might be not, that are multiple CTEs involved,
including a RECURSIVE one. However, that's speculation.

What I tried out:
- I did try without my_test_function, i.e. putting the values directly into
the first CTE without using a function. This way, there was no problem at
all. Like this, it runs equally fast both on 12.1 and on 11.6.
- On Postgres 12, I played around with MATERIALIZED, but could not see any
effect. The query still runs as slow as before.

Note on reproducibility:
I was able to reproduce the phenomenon on various systems: on multiple VMs
in VirtualBox; via Docker on two different physical machines. (See below for
Docker commands.) However, strange enough, I cannot reproduce it on
https://www.db-fiddle.com/ (no difference to be seen there, both are
fast).


Docker commands:

# First, pull images of both versions

docker pull postgres:12.1
docker pull postgres:11.6

# Now, run Postgres 12

docker run -d --name my_postgres_12_container postgres:12.1

# Now, execute the query

docker exec my_postgres_12_container psql -U postgres -c "

CREATE OR REPLACE FUNCTION public.my_test_function()
 RETURNS SETOF record
 LANGUAGE sql
 IMMUTABLE SECURITY DEFINER
AS \$function\$ 

SELECT 
        1::integer AS id,
        '2019-11-20'::date AS \"startDate\",
        '2020-01-01'::date AS \"endDate\"

\$function\$;

EXPLAIN ANALYZE WITH  \"somePeriods\" AS  (
      SELECT * FROM my_test_function() AS 
      f(id integer, \"startDate\" date, \"endDate\" date)
),

\"maxRecursiveEndDate\" AS (

SELECT \"startDate\", \"endDate\", id, 
( 
  WITH RECURSIVE prep(\"startDateParam\", \"endDateParam\") AS (

  SELECT \"startDate\",\"endDate\" FROM \"somePeriods\" WHERE id = od.id
  UNION
  SELECT \"startDate\",\"endDate\" FROM \"somePeriods\", prep
  WHERE
    \"startDate\" <= (\"endDateParam\" + '1 day'::interval ) AND
(\"endDateParam\" + '1 day'::interval ) <= \"endDate\"
  )
  SELECT max(\"endDateParam\") FROM prep
) AS \"endDateNew\"

FROM \"somePeriods\" AS od

)

SELECT * FROM \"maxRecursiveEndDate\";
"

# Stop the Postgres 12 container

docker stop my_postgres_12_container

# Start Postgres 11 for comparison

docker run -d --name my_postgres_11_container postgres:11.6

# Execute the query in Postgres 11

docker exec my_postgres_11_container psql -U postgres -c "

CREATE OR REPLACE FUNCTION public.my_test_function()
 RETURNS SETOF record
 LANGUAGE sql
 IMMUTABLE SECURITY DEFINER
AS \$function\$ 

SELECT 
        1::integer AS id,
        '2019-11-20'::date AS \"startDate\",
        '2020-01-01'::date AS \"endDate\"

\$function\$;

EXPLAIN ANALYZE WITH  \"somePeriods\" AS  (
      SELECT * FROM my_test_function() AS 
      f(id integer, \"startDate\" date, \"endDate\" date)
),

\"maxRecursiveEndDate\" AS (

SELECT \"startDate\", \"endDate\", id, 
( 
  WITH RECURSIVE prep(\"startDateParam\", \"endDateParam\") AS (

  SELECT \"startDate\",\"endDate\" FROM \"somePeriods\" WHERE id = od.id
  UNION
  SELECT \"startDate\",\"endDate\" FROM \"somePeriods\", prep
  WHERE
    \"startDate\" <= (\"endDateParam\" + '1 day'::interval ) AND
(\"endDateParam\" + '1 day'::interval ) <= \"endDate\"
  )
  SELECT max(\"endDateParam\") FROM prep
) AS \"endDateNew\"

Dear all,

I want to add to the bug report below that I have also tested with 
PostgreSQL 12.0 - same problem, as behavior as 12.1. So, the regression 
seems to have happened between 11.x and 12.0

Do you need any more information? I had assumed that providing docker 
commands would be enough, but if I can be of further assistance, please 
let me know.

Just for clarification: While the expressions "significantly slower" and 
"performance regression" used in my bug report might seem like a tiny 
issue, this is a big deal right now for my project. A query duration 
increase from 4ms to 150ms is negligible in absolute numbers, but in my 
real-life case, this adds up! Some queries run 300 times slower in 
Postgres 12 than in 11. Imagine, for a big data-set, a query runs 2 
seconds - which is still sort of acceptable. Now, it would be 600 
seconds ~ 5 minutes. Such delays could break the whole system. So, 
ultimately, this issue prevents my project from upgrading to PostgreSQL 
12 - which is sad.

This is speculation, but for me, it seems like the point "Allow common 
table expressions (CTEs) to be inlined into the outer query (Andreas 
Karlsson, Andrew Gierth, David Fetter, Tom Lane)" mentioned in release 
notes (https://www.postgresql.org/docs/release/12.0/) could be the 
problem here.
So, I would be thankful if any of these four gentlemen could have a look 
at it. (Or someone else, of course.)

Best regards
Christian

On 22.01.20 07:02, PG Bug reporting form wrote:
> The following bug has been logged on the website:
>
> Bug reference:      16223
> Logged by:          ChristianS
> Email address:      schwaderer@ivocotec.de
> PostgreSQL version: 12.1
> Operating system:   Ubuntu 18.04
> Description:
>
> I have a query that runs significantly slower in Postgres 12.1 than it does
> in Postgres 11.6.
>
> (I have asked on dba.stackexchange
>
https://dba.stackexchange.com/questions/257759/recursive-cte-based-on-function-values-significantly-slower-on-postgres-12-than
> - hoping that someone would jump in and tell me why this is my fault and why
> it has nothing to do with PostgreSQL itself. However, since there is still
> no reaction after two days, I can be somewhat sure that it's not a very
> obvious mistake of mine and maybe something you might want to
> investigate.)
>
>
> First, we create this simple function
>
>
> CREATE OR REPLACE FUNCTION public.my_test_function()
>   RETURNS SETOF record
>   LANGUAGE sql
>   IMMUTABLE SECURITY DEFINER
> AS $function$
>
> SELECT
>          1::integer AS id,
>          '2019-11-20'::date AS "startDate",
>          '2020-01-01'::date AS "endDate"
>
> $function$;
>
>
> Then for the actual query
>
>
> WITH  "somePeriods" AS  (
>        SELECT * FROM my_test_function() AS
>        f(id integer, "startDate" date, "endDate" date)
> ),
>
> "maxRecursiveEndDate" AS (
>
> SELECT "startDate", "endDate", id,
> (
>    WITH RECURSIVE prep("startDateParam", "endDateParam") AS (
>
>    SELECT "startDate","endDate" FROM "somePeriods" WHERE id = od.id
>    UNION
>    SELECT "startDate","endDate" FROM "somePeriods", prep
>    WHERE
>      "startDate" <= ("endDateParam" + '1 day'::interval ) AND ("endDateParam"
> + '1 day'::interval ) <= "endDate"
>    )
>    SELECT max("endDateParam") FROM prep
> ) AS "endDateNew"
>
> FROM "somePeriods" AS od
>
> )
>
> SELECT * FROM "maxRecursiveEndDate";
>
>
> What this actually does it not so important here, I guess. The important
> point is: It runs very fast on Postgres 11.6 (like ca 4ms) and much slower
> on PostgreSQL 12.1 (ca 150ms). The output of EXPLAIN ANALYZE did not give me
> further hints.
> A crucial point might or might be not, that are multiple CTEs involved,
> including a RECURSIVE one. However, that's speculation.
>
> What I tried out:
> - I did try without my_test_function, i.e. putting the values directly into
> the first CTE without using a function. This way, there was no problem at
> all. Like this, it runs equally fast both on 12.1 and on 11.6.
> - On Postgres 12, I played around with MATERIALIZED, but could not see any
> effect. The query still runs as slow as before.
>
> Note on reproducibility:
> I was able to reproduce the phenomenon on various systems: on multiple VMs
> in VirtualBox; via Docker on two different physical machines. (See below for
> Docker commands.) However, strange enough, I cannot reproduce it on
> https://www.db-fiddle.com/ (no difference to be seen there, both are
> fast).
>
>
> Docker commands:
>
> # First, pull images of both versions
>
> docker pull postgres:12.1
> docker pull postgres:11.6
>
> # Now, run Postgres 12
>
> docker run -d --name my_postgres_12_container postgres:12.1
>
> # Now, execute the query
>
> docker exec my_postgres_12_container psql -U postgres -c "
>
> CREATE OR REPLACE FUNCTION public.my_test_function()
>   RETURNS SETOF record
>   LANGUAGE sql
>   IMMUTABLE SECURITY DEFINER
> AS \$function\$
>
> SELECT
>          1::integer AS id,
>          '2019-11-20'::date AS \"startDate\",
>          '2020-01-01'::date AS \"endDate\"
>
> \$function\$;
>
> EXPLAIN ANALYZE WITH  \"somePeriods\" AS  (
>        SELECT * FROM my_test_function() AS
>        f(id integer, \"startDate\" date, \"endDate\" date)
> ),
>
> \"maxRecursiveEndDate\" AS (
>
> SELECT \"startDate\", \"endDate\", id,
> (
>    WITH RECURSIVE prep(\"startDateParam\", \"endDateParam\") AS (
>
>    SELECT \"startDate\",\"endDate\" FROM \"somePeriods\" WHERE id = od.id
>    UNION
>    SELECT \"startDate\",\"endDate\" FROM \"somePeriods\", prep
>    WHERE
>      \"startDate\" <= (\"endDateParam\" + '1 day'::interval ) AND
> (\"endDateParam\" + '1 day'::interval ) <= \"endDate\"
>    )
>    SELECT max(\"endDateParam\") FROM prep
> ) AS \"endDateNew\"
>
> FROM \"somePeriods\" AS od
>
> )
>
> SELECT * FROM \"maxRecursiveEndDate\";
> "
>
> # Stop the Postgres 12 container
>
> docker stop my_postgres_12_container
>
> # Start Postgres 11 for comparison
>
> docker run -d --name my_postgres_11_container postgres:11.6
>
> # Execute the query in Postgres 11
>
> docker exec my_postgres_11_container psql -U postgres -c "
>
> CREATE OR REPLACE FUNCTION public.my_test_function()
>   RETURNS SETOF record
>   LANGUAGE sql
>   IMMUTABLE SECURITY DEFINER
> AS \$function\$
>
> SELECT
>          1::integer AS id,
>          '2019-11-20'::date AS \"startDate\",
>          '2020-01-01'::date AS \"endDate\"
>
> \$function\$;
>
> EXPLAIN ANALYZE WITH  \"somePeriods\" AS  (
>        SELECT * FROM my_test_function() AS
>        f(id integer, \"startDate\" date, \"endDate\" date)
> ),
>
> \"maxRecursiveEndDate\" AS (
>
> SELECT \"startDate\", \"endDate\", id,
> (
>    WITH RECURSIVE prep(\"startDateParam\", \"endDateParam\") AS (
>
>    SELECT \"startDate\",\"endDate\" FROM \"somePeriods\" WHERE id = od.id
>    UNION
>    SELECT \"startDate\",\"endDate\" FROM \"somePeriods\", prep
>    WHERE
>      \"startDate\" <= (\"endDateParam\" + '1 day'::interval ) AND
> (\"endDateParam\" + '1 day'::interval ) <= \"endDate\"
>    )
>    SELECT max(\"endDateParam\") FROM prep
> ) AS \"endDateNew\"
>
-- 
Christian Schwaderer, Software-Entwickler/software developer
------------------------------------------------------------
ivocoTec GmbH
Entwicklungsabteilung/IT department

Postplatz 3
D-16761 Hennigsdorf

https://ivocotec.de
Telefon/phone +49 (0)3302 20 63 230

> On 27 Jan 2020, at 06:39, Christian Schwaderer <schwaderer@ivocotec.de> wrote:

Please don't top-post.

> Just for clarification: While the expressions "significantly slower" and "performance regression" used in my bug
reportmight seem like a tiny issue, this is a big deal right now for my project. A query duration increase from 4ms to
150msis negligible in absolute numbers, but in my real-life case, this adds up! Some queries run 300 times slower in
Postgres12 than in 11. Imagine, for a big data-set, a query runs 2 seconds - which is still sort of acceptable. Now, it
wouldbe 600 seconds ~ 5 minutes. Such delays could break the whole system. So, ultimately, this issue prevents my
projectfrom upgrading to PostgreSQL 12 - which is sad. 

I can't reproduce the effects that you are seeing.  The query runs in ~ 0.2ms
in the latest 11 as well as the latest 12 release for me.  Any difference in
runtime is too insignificant to be considered with my unscientific testing
process (running explain analyze N times and inspecting).

You mention running in VMs and Docker etc, are the environments where you
examine the results equivalent?  Can you try running postgres without
virtualization to see?  Even 4ms seems a tad on the slow side for such a
trivial query.

> This is speculation, but for me, it seems like the point "Allow common table expressions (CTEs) to be inlined into
theouter query (Andreas Karlsson, Andrew Gierth, David Fetter, Tom Lane)" mentioned in release notes
(https://www.postgresql.org/docs/release/12.0/)could be the problem here. 

Why do you think that particular feature is the culprit?  Your original email
already states that you've tried using AS NOT MATERIALIZED with no change on
the end result.

cheers ./daniel

On 27.01.20 11:20, Daniel Gustafsson wrote:

>> On 27 Jan 2020, at 06:39, Christian Schwaderer <schwaderer@ivocotec.de> wrote:

>> Just for clarification: While the expressions "significantly slower" and "performance regression" used in my bug
reportmight seem like a tiny issue, this is a big deal right now for my project. A query duration increase from 4ms to
150msis negligible in absolute numbers, but in my real-life case, this adds up! Some queries run 300 times slower in
Postgres12 than in 11. Imagine, for a big data-set, a query runs 2 seconds - which is still sort of acceptable. Now, it
wouldbe 600 seconds ~ 5 minutes. Such delays could break the whole system. So, ultimately, this issue prevents my
projectfrom upgrading to PostgreSQL 12 - which is sad.
 
> I can't reproduce the effects that you are seeing.  The query runs in ~ 0.2ms
> in the latest 11 as well as the latest 12 release for me.  Any difference in
> runtime is too insignificant to be considered with my unscientific testing
> process (running explain analyze N times and inspecting).
>
> You mention running in VMs and Docker etc, are the environments where you
> examine the results equivalent?  Can you try running postgres without
> virtualization to see?  Even 4ms seems a tad on the slow side for such a
> trivial query.

I only tested on those virtual environments mentioned (Virtual Box and 
Docker) as they resemble my real life scenarios. Environments were 
equivalent except for the PostgreSQL version. As you can see, I used 
Docker images from the official PostgreSQL docker repo ( 
https://hub.docker.com/_/postgres ) and did nothing with them except 
running the query.

Thanks for testing without virtualization! So, it seems we can narrow 
down the issue to virtual environments. Strange enough, if you ask me.


-- 
Christian Schwaderer, Software-Entwickler/software developer
------------------------------------------------------------
ivocoTec GmbH
Entwicklungsabteilung/IT department

Postplatz 3
D-16761 Hennigsdorf

https://ivocotec.de
Telefon/phone +49 (0)3302 20 63 230

Christian Schwaderer <schwaderer@ivocotec.de> writes:
> I only tested on those virtual environments mentioned (Virtual Box and 
> Docker) as they resemble my real life scenarios. Environments were 
> equivalent except for the PostgreSQL version. As you can see, I used 
> Docker images from the official PostgreSQL docker repo ( 
> https://hub.docker.com/_/postgres ) and did nothing with them except 
> running the query.

> Thanks for testing without virtualization! So, it seems we can narrow 
> down the issue to virtual environments. Strange enough, if you ask me.

Or it could be the specific builds you used.  Some of our packagers
tend to enable debug options on early releases of a given major version;
if that was the case for the v12 build you tested, it could account for
at least some of the difference.  Comparing pg_config output from the
two installations (particularly the configure options) would be
informative.

Another thing that could be relevant is JIT, which is on by default
in v12 (if enabled in configuration), and which is still suffering
a lot of teething pains performance-wise.  I'd check if that's
on and try disabling it if so.

            regards, tom lane

On 27.01.20 16:31, Tom Lane wrote:
> Christian Schwaderer <schwaderer@ivocotec.de> writes:
>> I only tested on those virtual environments mentioned (Virtual Box and
>> Docker) as they resemble my real life scenarios. Environments were
>> equivalent except for the PostgreSQL version. As you can see, I used
>> Docker images from the official PostgreSQL docker repo (
>> https://hub.docker.com/_/postgres ) and did nothing with them except
>> running the query.
>> Thanks for testing without virtualization! So, it seems we can narrow
>> down the issue to virtual environments. Strange enough, if you ask me.
> Or it could be the specific builds you used.  Some of our packagers
> tend to enable debug options on early releases of a given major version;
> if that was the case for the v12 build you tested, it could account for
> at least some of the difference.  Comparing pg_config output from the
> two installations (particularly the configure options) would be
> informative.
>
> Another thing that could be relevant is JIT, which is on by default
> in v12 (if enabled in configuration), and which is still suffering
> a lot of teething pains performance-wise.  I'd check if that's
> on and try disabling it if so.
>
>             regards, tom lane
>

Sorry for replying so late, I was busy with something else.

As I already pointed out, I'm able to reproduce this issue on images 
from the official PostgreSQL docker repo on two different versions (12.0 
and 12.1). I did not change anything in the config, just pulling the 
images, executing the query and that's it. So, if actually there is 
debugging code in both those builds or the default config is somewhat 
problematic for this query, I think, this would be actually an issue, a 
minor one of course.

Anyway: Here are the details of versions and pg_config

I) Postgres 12.1 on a virtual Ubuntu 18.04 running in VirtualBox
Output of SELECT version();
PostgreSQL 12.1 (Ubuntu 12.1-1.pgdg18.04+1) on x86_64-pc-linux-gnu, 
compiled by gcc (Ubuntu 7.4.0-1ubuntu1~18.04.1) 7.4.0, 64-bit

Output of SELECT pg_config();
   (BINDIR,/usr/lib/postgresql/12/bin)
  (DOCDIR,/usr/share/doc/postgresql-doc-12)
  (HTMLDIR,/usr/share/doc/postgresql-doc-12)
  (INCLUDEDIR,/usr/include/postgresql)
  (PKGINCLUDEDIR,/usr/include/postgresql)
  (INCLUDEDIR-SERVER,/usr/include/postgresql/12/server)
  (LIBDIR,/usr/lib/x86_64-linux-gnu)
  (PKGLIBDIR,/usr/lib/postgresql/12/lib)
  (LOCALEDIR,/usr/share/locale)
  (MANDIR,/usr/share/postgresql/12/man)
  (SHAREDIR,/usr/share/postgresql/12)
  (SYSCONFDIR,/etc/postgresql-common)
  (PGXS,/usr/lib/postgresql/12/lib/pgxs/src/makefiles/pgxs.mk)
  (CONFIGURE,"'--build=x86_64-linux-gnu' '--prefix=/usr' 
'--includedir=/usr/include' '--mandir=/usr/share/man' 
'--infodir=/usr/share/info' '--sysconfdir=/etc' '--localstatedir=/var' 
'--disable-silent-rules' '--libdir=/usr/lib/x86_64-linux-gnu' 
'--libexecdir=/usr/lib/x86_64-linux-gnu' '--disable-maintainer-mode' 
'--disable-dependency-tracking' '--with-icu' '--with-tcl' '--with-perl' 
'--with-python' '--with-pam' '--with-openssl' '--with-libxml' 
'--with-libxslt' 'PYTHON=/usr/bin/python3' 
'--mandir=/usr/share/postgresql/12/man' 
'--docdir=/usr/share/doc/postgresql-doc-12' 
'--sysconfdir=/etc/postgresql-common' '--datarootdir=/usr/share/' 
'--datadir=/usr/share/postgresql/12' 
'--bindir=/usr/lib/postgresql/12/bin' 
'--libdir=/usr/lib/x86_64-linux-gnu/' 
'--libexecdir=/usr/lib/postgresql/' 
'--includedir=/usr/include/postgresql/' '--with-extra-version= (Ubuntu 
12.1-1.pgdg18.04+1)' '--enable-nls' '--enable-integer-datetimes' 
'--enable-thread-safety' '--enable-tap-tests' '--enable-debug' 
'--enable-dtrace' '--disable-rpath' '--with-uuid=e2fs' '--with-gnu-ld' 
'--with-pgport=5432' '--with-system-tzdata=/usr/share/zoneinfo' 
'--with-llvm' 'LLVM_CONFIG=/usr/bin/llvm-config-6.0' 
'CLANG=/usr/bin/clang-6.0' '--with-systemd' '--with-selinux' 
'MKDIR_P=/bin/mkdir -p' 'TAR=/bin/tar' 'CFLAGS=-g -O2 
-fstack-protector-strong -Wformat -Werror=format-security 
-fno-omit-frame-pointer' 'LDFLAGS=-Wl,-Bsymbolic-functions -Wl,-z,relro 
-Wl,-z,now' '--with-gssapi' '--with-ldap' 
'--with-includes=/usr/include/mit-krb5' '--with-libs=/usr/lib/mit-krb5' 
'--with-libs=/usr/lib/x86_64-linux-gnu/mit-krb5' 
'build_alias=x86_64-linux-gnu' 'CPPFLAGS=-Wdate-time 
-D_FORTIFY_SOURCE=2' 'CXXFLAGS=-g -O2 -fstack-protector-strong -Wformat 
-Werror=format-security'")
  (CC,gcc)
  (CPPFLAGS,"-Wdate-time -D_FORTIFY_SOURCE=2 -D_GNU_SOURCE 
-I/usr/include/libxml2 -I/usr/include/mit-krb5")
  (CFLAGS,"-Wall -Wmissing-prototypes -Wpointer-arith 
-Wdeclaration-after-statement -Werror=vla -Wendif-labels 
-Wmissing-format-attribute -Wformat-security -fno-strict-aliasing 
-fwrapv -fexcess-precision=standard -Wno-format-truncation -g -g -O2 
-fstack-protector-strong -Wformat -Werror=format-security 
-fno-omit-frame-pointer")
  (CFLAGS_SL,-fPIC)
  (LDFLAGS,"-Wl,-Bsymbolic-functions -Wl,-z,relro -Wl,-z,now 
-L/usr/lib/llvm-6.0/lib -L/usr/lib/x86_64-linux-gnu/mit-krb5 
-Wl,--as-needed")
  (LDFLAGS_EX,"")
  (LDFLAGS_SL,"")
  (LIBS,"-lpgcommon -lpgport -lpthread -lselinux -lxslt -lxml2 -lpam 
-lssl -lcrypto -lgssapi_krb5 -lz -ledit -lrt -lcrypt -ldl -lm ")
  (VERSION,"PostgreSQL 12.1 (Ubuntu 12.1-1.pgdg18.04+1)")


II) Postgres 12.1 from official PostgreSQL docker repo

Output of SELECT version();
PostgreSQL 12.1 (Debian 12.1-1.pgdg100+1) on x86_64-pc-linux-gnu, 
compiled by gcc (Debian 8.3.0-6) 8.3.0, 64-bit

Output of SELECT pg_config();
  (BINDIR,/usr/lib/postgresql/12/bin)
  (DOCDIR,/usr/share/doc/postgresql-doc-12)
  (HTMLDIR,/usr/share/doc/postgresql-doc-12)
  (INCLUDEDIR,/usr/include/postgresql)
  (PKGINCLUDEDIR,/usr/include/postgresql)
  (INCLUDEDIR-SERVER,/usr/include/postgresql/12/server)
  (LIBDIR,/usr/lib/x86_64-linux-gnu)
  (PKGLIBDIR,/usr/lib/postgresql/12/lib)
  (LOCALEDIR,/usr/share/locale)
  (MANDIR,/usr/share/postgresql/12/man)
  (SHAREDIR,/usr/share/postgresql/12)
  (SYSCONFDIR,/etc/postgresql-common)
  (PGXS,/usr/lib/postgresql/12/lib/pgxs/src/makefiles/pgxs.mk)
  (CONFIGURE,"'--build=x86_64-linux-gnu' '--prefix=/usr' 
'--includedir=/usr/include' '--mandir=/usr/share/man' 
'--infodir=/usr/share/info' '--sysconfdir=/etc' '--localstatedir=/var' 
'--disable-silent-rules' '--libdir=/usr/lib/x86_64-linux-gnu' 
'--libexecdir=/usr/lib/x86_64-linux-gnu' '--disable-maintainer-mode' 
'--disable-dependency-tracking' '--with-icu' '--with-tcl' '--with-perl' 
'--with-python' '--with-pam' '--with-openssl' '--with-libxml' 
'--with-libxslt' 'PYTHON=/usr/bin/python3' 
'--mandir=/usr/share/postgresql/12/man' 
'--docdir=/usr/share/doc/postgresql-doc-12' 
'--sysconfdir=/etc/postgresql-common' '--datarootdir=/usr/share/' 
'--datadir=/usr/share/postgresql/12' 
'--bindir=/usr/lib/postgresql/12/bin' 
'--libdir=/usr/lib/x86_64-linux-gnu/' 
'--libexecdir=/usr/lib/postgresql/' 
'--includedir=/usr/include/postgresql/' '--with-extra-version= (Debian 
12.1-1.pgdg100+1)' '--enable-nls' '--enable-integer-datetimes' 
'--enable-thread-safety' '--enable-tap-tests' '--enable-debug' 
'--enable-dtrace' '--disable-rpath' '--with-uuid=e2fs' '--with-gnu-ld' 
'--with-pgport=5432' '--with-system-tzdata=/usr/share/zoneinfo' 
'--with-llvm' 'LLVM_CONFIG=/usr/bin/llvm-config-7' 
'CLANG=/usr/bin/clang-7' '--with-systemd' '--with-selinux' 
'MKDIR_P=/bin/mkdir -p' 'TAR=/bin/tar' 'CFLAGS=-g -O2 
-fstack-protector-strong -Wformat -Werror=format-security 
-fno-omit-frame-pointer' 'LDFLAGS=-Wl,-z,relro -Wl,-z,now' 
'--with-gssapi' '--with-ldap' '--with-includes=/usr/include/mit-krb5' 
'--with-libs=/usr/lib/mit-krb5' 
'--with-libs=/usr/lib/x86_64-linux-gnu/mit-krb5' 
'build_alias=x86_64-linux-gnu' 'CPPFLAGS=-Wdate-time 
-D_FORTIFY_SOURCE=2' 'CXXFLAGS=-g -O2 -fstack-protector-strong -Wformat 
-Werror=format-security'")
  (CC,gcc)
  (CPPFLAGS,"-Wdate-time -D_FORTIFY_SOURCE=2 -D_GNU_SOURCE 
-I/usr/include/libxml2 -I/usr/include/mit-krb5")
  (CFLAGS,"-Wall -Wmissing-prototypes -Wpointer-arith 
-Wdeclaration-after-statement -Werror=vla -Wendif-labels 
-Wmissing-format-attribute -Wformat-security -fno-strict-aliasing
-fwrapv -fexcess-precision=standard -Wno-format-truncation 
-Wno-stringop-truncation -g -g -O2 -fstack-protector-strong -Wformat 
-Werror=format-security -fno-omit-frame-pointer")
  (CFLAGS_SL,-fPIC)
  (LDFLAGS,"-Wl,-z,relro -Wl,-z,now -L/usr/lib/llvm-7/lib 
-L/usr/lib/x86_64-linux-gnu/mit-krb5 -Wl,--as-needed")
  (LDFLAGS_EX,"")
  (LDFLAGS_SL,"")
  (LIBS,"-lpgcommon -lpgport -lpthread -lselinux -lxslt -lxml2 -lpam 
-lssl -lcrypto -lgssapi_krb5 -lz -ledit -lrt -lcrypt -ldl -lm ")
  (VERSION,"PostgreSQL 12.1 (Debian 12.1-1.pgdg100+1)")


III) Postgres 12.0 from official PostgreSQL docker repo
Output of SELECT version();
PostgreSQL 12.0 (Debian 12.0-2.pgdg100+1) on x86_64-pc-linux-gnu, 
compiled by gcc (Debian 8.3.0-6) 8.3.0, 64-bit

Output of SELECT pg_config();
   (BINDIR,/usr/lib/postgresql/12/bin)
  (DOCDIR,/usr/share/doc/postgresql-doc-12)
  (HTMLDIR,/usr/share/doc/postgresql-doc-12)
  (INCLUDEDIR,/usr/include/postgresql)
  (PKGINCLUDEDIR,/usr/include/postgresql)
  (INCLUDEDIR-SERVER,/usr/include/postgresql/12/server)
  (LIBDIR,/usr/lib/x86_64-linux-gnu)
  (PKGLIBDIR,/usr/lib/postgresql/12/lib)
  (LOCALEDIR,/usr/share/locale)
  (MANDIR,/usr/share/postgresql/12/man)
  (SHAREDIR,/usr/share/postgresql/12)
  (SYSCONFDIR,/etc/postgresql-common)
  (PGXS,/usr/lib/postgresql/12/lib/pgxs/src/makefiles/pgxs.mk)
  (CONFIGURE,"'--build=x86_64-linux-gnu' '--prefix=/usr' 
'--includedir=/usr/include' '--mandir=/usr/share/man' 
'--infodir=/usr/share/info' '--sysconfdir=/etc' '--localstatedir=/var' 
'--disable-silent-rules' '--libdir=/usr/lib/x86_64-linux-gnu' 
'--libexecdir=/usr/lib/x86_64-linux-gnu' '--disable-maintainer-mode' 
'--disable-dependency-tracking' '--with-icu' '--with-tcl' '--with-perl' 
'--with-python' '--with-pam' '--with-openssl' '--with-libxml' 
'--with-libxslt' 'PYTHON=/usr/bin/python3' 
'--mandir=/usr/share/postgresql/12/man' 
'--docdir=/usr/share/doc/postgresql-doc-12' 
'--sysconfdir=/etc/postgresql-common' '--datarootdir=/usr/share/' 
'--datadir=/usr/share/postgresql/12' 
'--bindir=/usr/lib/postgresql/12/bin' 
'--libdir=/usr/lib/x86_64-linux-gnu/' 
'--libexecdir=/usr/lib/postgresql/' 
'--includedir=/usr/include/postgresql/' '--with-extra-version= (Debian 
12.0-2.pgdg100+1)' '--enable-nls' '--enable-integer-datetimes' 
'--enable-thread-safety' '--enable-tap-tests' '--enable-debug' 
'--enable-dtrace' '--disable-rpath' '--with-uuid=e2fs' '--with-gnu-ld' 
'--with-pgport=5432' '--with-system-tzdata=/usr/share/zoneinfo' 
'--with-llvm' 'LLVM_CONFIG=/usr/bin/llvm-config-7' 
'CLANG=/usr/bin/clang-7' '--with-systemd' '--with-selinux' 
'MKDIR_P=/bin/mkdir -p' 'TAR=/bin/tar' 'CFLAGS=-g -O2 
-fstack-protector-strong -Wformat -Werror=format-security 
-fno-omit-frame-pointer' 'LDFLAGS=-Wl,-z,relro -Wl,-z,now' 
'--with-gssapi' '--with-ldap' '--with-includes=/usr/include/mit-krb5' 
'--with-libs=/usr/lib/mit-krb5' 
'--with-libs=/usr/lib/x86_64-linux-gnu/mit-krb5' 
'build_alias=x86_64-linux-gnu' 'CPPFLAGS=-Wdate-time 
-D_FORTIFY_SOURCE=2' 'CXXFLAGS=-g -O2 -fstack-protector-strong -Wformat 
-Werror=format-security'")
  (CC,gcc)
  (CPPFLAGS,"-Wdate-time -D_FORTIFY_SOURCE=2 -D_GNU_SOURCE 
-I/usr/include/libxml2 -I/usr/include/mit-krb5")
  (CFLAGS,"-Wall -Wmissing-prototypes -Wpointer-arith 
-Wdeclaration-after-statement -Werror=vla -Wendif-labels 
-Wmissing-format-attribute -Wformat-security -fno-strict-aliasing 
-fwrapv -fexcess-precision=standard -Wno-format-truncation 
-Wno-stringop-truncation -g -g -O2 -fstack-protector-strong -Wformat 
-Werror=format-security -fno-omit-frame-pointer")
  (CFLAGS_SL,-fPIC)
  (LDFLAGS,"-Wl,-z,relro -Wl,-z,now -L/usr/lib/llvm-7/lib 
-L/usr/lib/x86_64-linux-gnu/mit-krb5 -Wl,--as-needed")
  (LDFLAGS_EX,"")
  (LDFLAGS_SL,"")
  (LIBS,"-lpgcommon -lpgport -lpthread -lselinux -lxslt -lxml2 -lpam 
-lssl -lcrypto -lgssapi_krb5 -lz -ledit -lrt -lcrypt -ldl -lm ")
  (VERSION,"PostgreSQL 12.0 (Debian 12.0-2.pgdg100+1)")


  IV) For comparison: Output of Postgres 11.6 where everything seems 
fine (also official PostgreSQL docker repo):
  Output of SELECT version();
  PostgreSQL 11.6 (Debian 11.6-1.pgdg90+1) on x86_64-pc-linux-gnu, 
compiled by gcc (Debian 6.3.0-18+deb9u1) 6.3.0 20170516, 64-bit

  Output of SELECT pg_config();
   (BINDIR,/usr/lib/postgresql/11/bin)
  (DOCDIR,/usr/share/doc/postgresql-doc-11)
  (HTMLDIR,/usr/share/doc/postgresql-doc-11)
  (INCLUDEDIR,/usr/include/postgresql)
  (PKGINCLUDEDIR,/usr/include/postgresql)
  (INCLUDEDIR-SERVER,/usr/include/postgresql/11/server)
  (LIBDIR,/usr/lib/x86_64-linux-gnu)
  (PKGLIBDIR,/usr/lib/postgresql/11/lib)
  (LOCALEDIR,/usr/share/locale)
  (MANDIR,/usr/share/postgresql/11/man)
  (SHAREDIR,/usr/share/postgresql/11)
  (SYSCONFDIR,/etc/postgresql-common)
  (PGXS,/usr/lib/postgresql/11/lib/pgxs/src/makefiles/pgxs.mk)
  (CONFIGURE,"'--build=x86_64-linux-gnu' '--prefix=/usr' 
'--includedir=/usr/include' '--mandir=/usr/share/man' 
'--infodir=/usr/share/info' '--sysconfdir=/etc' '--localstatedir=/var' 
'--disable-silent-rules' '--libdir=/usr/lib/x86_64-linux-gnu' 
'--libexecdir=/usr/lib/x86_64-linux-gnu' '--disable-maintainer-mode' 
'--disable-dependency-tracking' '--with-icu' '--with-tcl' '--with-perl' 
'--with-python' '--with-pam' '--with-openssl' '--with-libxml' 
'--with-libxslt' 'PYTHON=/usr/bin/python3' 
'--mandir=/usr/share/postgresql/11/man' 
'--docdir=/usr/share/doc/postgresql-doc-11' 
'--sysconfdir=/etc/postgresql-common' '--datarootdir=/usr/share/' 
'--datadir=/usr/share/postgresql/11' 
'--bindir=/usr/lib/postgresql/11/bin' 
'--libdir=/usr/lib/x86_64-linux-gnu/' 
'--libexecdir=/usr/lib/postgresql/' 
'--includedir=/usr/include/postgresql/' '--with-extra-version= (Debian 
11.6-1.pgdg90+1)' '--enable-nls' '--enable-integer-datetimes' 
'--enable-thread-safety' '--enable-tap-tests' '--enable-debug' 
'--enable-dtrace' '--disable-rpath' '--with-uuid=e2fs' '--with-gnu-ld' 
'--with-pgport=5432' '--with-system-tzdata=/usr/share/zoneinfo' 
'--with-llvm' 'LLVM_CONFIG=/usr/bin/llvm-config-6.0' 
'CLANG=/usr/bin/clang-6.0' '--with-systemd' '--with-selinux' 
'MKDIR_P=/bin/mkdir -p' 'TAR=/bin/tar' 'CFLAGS=-g -O2 
-fstack-protector-strong -Wformat -Werror=format-security 
-fno-omit-frame-pointer' 'LDFLAGS=-Wl,-z,relro -Wl,-z,now' 
'--with-gssapi' '--with-ldap' '--with-includes=/usr/include/mit-krb5' 
'--with-libs=/usr/lib/mit-krb5' 
'--with-libs=/usr/lib/x86_64-linux-gnu/mit-krb5' 
'build_alias=x86_64-linux-gnu' 'CPPFLAGS=-Wdate-time 
-D_FORTIFY_SOURCE=2' 'CXXFLAGS=-g -O2 -fstack-protector-strong -Wformat 
-Werror=format-security'")
  (CC,gcc)
  (CPPFLAGS,"-Wdate-time -D_FORTIFY_SOURCE=2 -D_GNU_SOURCE 
-I/usr/include/libxml2 -I/usr/include/mit-krb5")
  (CFLAGS,"-Wall -Wmissing-prototypes -Wpointer-arith 
-Wdeclaration-after-statement -Wendif-labels -Wmissing-format-attribute 
-Wformat-security -fno-strict-aliasing -fwrapv 
-fexcess-precision=standard -g -g -O2 -fstack-protector-strong -Wformat 
-Werror=format-security -fno-omit-frame-pointer")
  (CFLAGS_SL,-fPIC)
  (LDFLAGS,"-Wl,-z,relro -Wl,-z,now -L/usr/lib/llvm-6.0/lib 
-L/usr/lib/x86_64-linux-gnu/mit-krb5 -Wl,--as-needed")
  (LDFLAGS_EX,"")
  (LDFLAGS_SL,"")
  (LIBS,"-lpgcommon -lpgport -lpthread -lselinux -lxslt -lxml2 -lpam 
-lssl -lcrypto -lgssapi_krb5 -lz -ledit -lrt -lcrypt -ldl -lm ")
  (VERSION,"PostgreSQL 11.6 (Debian 11.6-1.pgdg90+1)"



Hope this helps.

Best,
Christian



-- 
Christian Schwaderer, Software-Entwickler/software developer
------------------------------------------------------------
ivocoTec GmbH
Entwicklungsabteilung/IT department

Postplatz 3
D-16761 Hennigsdorf

https://ivocotec.de
Telefon/phone +49 (0)3302 20 63 230

Christian Schwaderer <schwaderer@ivocotec.de> writes:
> On 27.01.20 16:31, Tom Lane wrote:
>> Another thing that could be relevant is JIT, which is on by default
>> in v12 (if enabled in configuration), and which is still suffering
>> a lot of teething pains performance-wise.  I'd check if that's
>> on and try disabling it if so.

> Anyway: Here are the details of versions and pg_config

I see JIT support (--with-llvm) in those configurations, so
did you heed the above advice?

            regards, tom lane

Hi,

On 2020-01-29 15:31:05 +0000, Kieran McCusker wrote:
> I've just checked you query. The slowdown is due to JIT.
>
> *With JIT enabled:*
>
> CTE Scan on "somePeriods" od  (cost=10.25..17494052.75 rows=1000 width=16)
> (actual time=724.235..724.235 rows=1 loops=1)

That's clearly a fairly absurd cost for this query. I think it largely
comes from:

>   CTE somePeriods
>     ->  Function Scan on my_test_function f  (cost=0.25..10.25 rows=1000
> width=12) (actual time=0.293..0.294 rows=1 loops=1)
>   SubPlan 3
>     ->  Aggregate  (cost=17494.01..17494.02 rows=1 width=4) (actual
> time=0.135..0.136 rows=1 loops=1)

This subplan being executed once for each row returned assumed to be
returned by my_test_function() - the default assumption is 1000. It's
only because it ends up only returning 1 row that it's not easily
visible in the plan.

which is compounded by:
>                         ->  CTE Scan on "somePeriods" "somePeriods_1"
>  (cost=0.00..20.00 rows=1000 width=8) (actual time=0.000..0.000 rows=1
> loops=1)

i.e. that somePeriods again is assumed to return 1000 rows. So you
basically end up with a quadratic increase in cost.


And the reason that the function doesn't just get inlined, allowing the
planner to have much better insights, is that it's defined as a security
definer function for some reason:

CREATE OR REPLACE FUNCTION public.my_test_function()
 RETURNS SETOF record
 LANGUAGE sql
 IMMUTABLE SECURITY DEFINER
AS $function$

SELECT
        1::integer AS id,
        '2019-11-20'::date AS "startDate",
        '2020-01-01'::date AS "endDate"

$function$;

And we never inline security definer functions.


It's more obvious if one makes the function return two rows:

 CTE Scan on "somePeriods" od  (cost=10.25..17494052.75 rows=1000 width=16) (actual time=159.875..159.907 rows=2
loops=1)
   Output: od."startDate", od."endDate", od.id, (SubPlan 3)
   CTE somePeriods
     ->  Function Scan on public.my_test_function f  (cost=0.25..10.25 rows=1000 width=12) (actual time=0.046..0.047
rows=2loops=1)
 
           Output: f.id, f."startDate", f."endDate"
           Function Call: my_test_function()
   SubPlan 3
     ->  Aggregate  (cost=17494.01..17494.02 rows=1 width=4) (actual time=0.044..0.044 rows=1 loops=2)
           Output: max(prep_1."endDateParam")
           CTE prep
             ->  Recursive Union  (cost=0.00..16243.80 rows=55565 width=8) (actual time=0.002..0.004 rows=1 loops=2)


If one makes the function not be a security definer one, the whole thing
looks a lot more reasonable:

 CTE Scan on "somePeriods" od  (cost=0.03..16.77 rows=2 width=16) (actual time=0.073..0.091 rows=2 loops=1)
   Output: od."startDate", od."endDate", od.id, (SubPlan 3)
   CTE somePeriods
     ->  Append  (cost=0.00..0.03 rows=2 width=12) (actual time=0.004..0.028 rows=2 loops=1)
           ->  Result  (cost=0.00..0.01 rows=1 width=12) (actual time=0.003..0.024 rows=1 loops=1)
                 Output: 1, '2019-11-20'::date, '2020-01-01'::date
           ->  Result  (cost=0.00..0.01 rows=1 width=12) (actual time=0.002..0.002 rows=1 loops=1)
                 Output: 2, '2019-11-20'::date, '2020-01-01'::date
   SubPlan 3
     ->  Aggregate  (cost=8.34..8.35 rows=1 width=4) (actual time=0.036..0.036 rows=1 loops=2)
           Output: max(prep_1."endDateParam")
           CTE prep
             ->  Recursive Union  (cost=0.00..7.87 rows=21 width=8) (actual time=0.005..0.028 rows=1 loops=2)

and it obviously doesn't get JIT compiled anymore.


I assume this is just a reproducer?  If so, I'm not really sure it's a
good one to look at, because when the costs are 6 orders of magnitude
off due to an artificial plan barrier, and artifical row estimates, you'll
get all sorts of odd behaviour.


> JIT:
>   Functions: 18
>   Options: Inlining true, Optimization true, Expressions true, Deforming
> true
>   Timing: Generation 8.586 ms, Inlining 17.901 ms, Optimization 514.256 ms,
> Emission 191.174 ms, Total 731.917 ms
> Execution Time: 733.276 ms

While not enough to alleviate the problem, I do get significantly
lower costs:

JIT:
  Functions: 18
  Options: Inlining true, Optimization true, Expressions true, Deforming true
  Timing: Generation 7.035 ms, Inlining 43.069 ms, Optimization 175.358 ms, Emission 43.862 ms, Total 269.323 ms

Is this a debug build of LLVM?

Greetings,

Andres Freund