Bad CTE performance since Postgres 12

Question

I have the following query which uses a common table expression :

with cte (
    select gateway_id,
    parameters.id as parameter_id
from
    gateways
inner join capturing_devices on
    gateway_id = gateways.id
inner join capturing_device_types on
    capturing_device_type_id = capturing_device_types.id
inner join parameters on
    capturing_device_id = capturing_devices.id
where
    capturing_device_types.name = 'ENERGY_COMFOAIR'
    and inactive = false) select
    distinct gateway_id,
    null as capturing_device_id
from
    cte master
where
    not exists (
        select *
    from
        parameter_values
    inner join cte on
        parameter_values.parameter_id = cte.parameter_id
    where
        gateway_id = master.gateway_id
        and datetime >= now() - interval '120 minutes')
    and not exists (
        select *
    from
        alerts
    inner join alert_types on
        alert_type_id = alert_types.id
    where
        alert_types.name = 'gateway_offline'
        and alerts.gateway_id = master.gateway_id
        and actual_status = 0)
    and not exists (
        select *
    from
        alerts
    inner join alert_types on
        alert_type_id = alert_types.id
    where
        alert_types.name = 'one_energy_offline'
        and alerts.gateway_id = master.gateway_id
        and actual_status = 0);

This is the EXPLAIN: (I tried with ANALYSE but aborted after >1 hour running without any result).

Unique  (cost=7920.48..51410365.98 rows=1 width=36)
  CTE cte
    ->  Nested Loop  (cost=8.88..7653.69 rows=121 width=12)
          ->  Nested Loop  (cost=8.46..7633.26 rows=22 width=12)
                ->  Hash Join  (cost=8.18..7622.70 rows=23 width=12)
                      Hash Cond: (capturing_devices.capturing_device_type_id = capturing_device_types.id)
                      ->  Seq Scan on capturing_devices  (cost=0.00..7539.77 rows=28377 width=16)
                      ->  Hash  (cost=8.17..8.17 rows=1 width=8)
                            ->  Index Scan using index_capturing_device_types_on_name on capturing_device_types  (cost=0.15..8.17 rows=1 width=8)
                                  Index Cond: ((name)::text = 'ENERGY_COMFOAIR'::text)
                ->  Index Scan using gateways_pkey on gateways  (cost=0.28..0.46 rows=1 width=8)
                      Index Cond: (id = capturing_devices.gateway_id)
                      Filter: (NOT inactive)
          ->  Index Scan using parameters_type_device_unique on parameters  (cost=0.42..0.82 rows=11 width=12)
                Index Cond: (capturing_device_id = capturing_devices.id)
  ->  Merge Anti Join  (cost=266.79..51402712.28 rows=1 width=36)
        Merge Cond: (master.gateway_id = alerts.gateway_id)
        ->  Nested Loop Anti Join  (cost=266.35..51263410.78 rows=1 width=4)
              Join Filter: (cte.gateway_id = master.gateway_id)
              ->  Merge Anti Join  (cost=262.42..263.04 rows=121 width=4)
                    Merge Cond: (master.gateway_id = alerts_1.gateway_id)
                    ->  Sort  (cost=6.61..6.91 rows=121 width=4)
                          Sort Key: master.gateway_id
                          ->  CTE Scan on cte master  (cost=0.00..2.42 rows=121 width=4)
                    ->  Sort  (cost=255.81..255.81 rows=2 width=4)
                          Sort Key: alerts_1.gateway_id
                          ->  Hash Join  (cost=8.47..255.80 rows=2 width=4)
                                Hash Cond: (alerts_1.alert_type_id = alert_types_1.id)
                                ->  Index Scan using index_alerts_on_actual_status on alerts alerts_1  (cost=0.29..245.86 rows=663 width=8)
                                      Index Cond: (actual_status = 0)
                                ->  Hash  (cost=8.17..8.17 rows=1 width=8)
                                      ->  Index Scan using index_alert_types_on_name on alert_types alert_types_1  (cost=0.15..8.17 rows=1 width=8)
                                            Index Cond: ((name)::text = 'one_energy_offline'::text)
              ->  Hash Join  (cost=3.93..51257927.36 rows=306637950 width=4)
                    Hash Cond: (parameter_values_202006.parameter_id = cte.parameter_id)
                    ->  Append  (cost=0.00..46290895.48 rows=506839587 width=4)
                          Subplans Removed: 30
                          ->  Seq Scan on parameter_values_202006  (cost=0.00..452878.48 rows=446392 width=4)
                                Filter: (datetime >= (now() - '02:00:00'::interval))
                          ->  Bitmap Heap Scan on parameter_values_202007  (cost=18.19..38.98 rows=617 width=4)
                                Recheck Cond: (datetime >= (now() - '02:00:00'::interval))
                                ->  Bitmap Index Scan on parameter_values_202007_pkey  (cost=0.00..18.03 rows=617 width=0)
                                      Index Cond: (datetime >= (now() - '02:00:00'::interval))
                          ->  Bitmap Heap Scan on parameter_values_202008  (cost=18.19..38.98 rows=617 width=4)
                                Recheck Cond: (datetime >= (now() - '02:00:00'::interval))
                                ->  Bitmap Index Scan on parameter_values_202008_pkey  (cost=0.00..18.03 rows=617 width=0)
                                      Index Cond: (datetime >= (now() - '02:00:00'::interval))
                          ->  Bitmap Heap Scan on parameter_values_202009  (cost=18.19..38.98 rows=617 width=4)
                                Recheck Cond: (datetime >= (now() - '02:00:00'::interval))
                                ->  Bitmap Index Scan on parameter_values_202009_pkey  (cost=0.00..18.03 rows=617 width=0)
                                      Index Cond: (datetime >= (now() - '02:00:00'::interval))
                          ->  Bitmap Heap Scan on parameter_values_202010  (cost=18.19..38.98 rows=617 width=4)
                                Recheck Cond: (datetime >= (now() - '02:00:00'::interval))
                                ->  Bitmap Index Scan on parameter_values_202010_pkey  (cost=0.00..18.03 rows=617 width=0)
                                      Index Cond: (datetime >= (now() - '02:00:00'::interval))
                          ->  Bitmap Heap Scan on parameter_values_202011  (cost=18.19..38.98 rows=617 width=4)
                                Recheck Cond: (datetime >= (now() - '02:00:00'::interval))
                                ->  Bitmap Index Scan on parameter_values_202011_pkey  (cost=0.00..18.03 rows=617 width=0)
                                      Index Cond: (datetime >= (now() - '02:00:00'::interval))
                          ->  Bitmap Heap Scan on parameter_values_202012  (cost=18.19..38.98 rows=617 width=4)
                                Recheck Cond: (datetime >= (now() - '02:00:00'::interval))
                                ->  Bitmap Index Scan on parameter_values_202012_pkey  (cost=0.00..18.03 rows=617 width=0)
                                      Index Cond: (datetime >= (now() - '02:00:00'::interval))
                    ->  Hash  (cost=2.42..2.42 rows=121 width=12)
                          ->  CTE Scan on cte  (cost=0.00..2.42 rows=121 width=12)
        ->  Nested Loop  (cost=0.44..139301.48 rows=2 width=4)
              Join Filter: (alerts.alert_type_id = alert_types.id)
              ->  Index Scan using index_alerts_on_gateway_id on alerts  (cost=0.29..139283.37 rows=663 width=8)
                    Filter: (actual_status = 0)
              ->  Materialize  (cost=0.15..8.17 rows=1 width=8)
                    ->  Index Scan using index_alert_types_on_name on alert_types  (cost=0.15..8.17 rows=1 width=8)
                          Index Cond: ((name)::text = 'gateway_offline'::text)

This query takes > 10 minutes to run since Postgres 12 (in Postgres 11 this was well under 30 seconds).

I have tried rewriting it like:

with cte AS MATERIALIZED

which doesn't make any difference (and which is logical since that would be the default since the CTE is used more than once).

I've also rewritten as:

with cte AS NOT MATERIALIZED

which causes the query to run in 11 seconds. This is the EXPLAIN of that:

Unique  (cost=17785.43..20839996.12 rows=1 width=36) (actual time=5924.141..23039.116 rows=23 loops=1)
  Buffers: shared hit=295370
  ->  Nested Loop Anti Join  (cost=17785.43..20839996.12 rows=1 width=36) (actual time=5924.139..23039.001 rows=149 loops=1)
        Buffers: shared hit=295370
        ->  Nested Loop Anti Join  (cost=17760.41..20839959.05 rows=1 width=4) (actual time=1294.347..22785.000 rows=2713 loops=1)
              Join Filter: (capturing_devices_1.gateway_id = capturing_devices.gateway_id)
              Rows Removed by Join Filter: 145357066
              Buffers: shared hit=210823
              ->  Merge Anti Join  (cost=8088.45..8089.07 rows=121 width=4) (actual time=42.344..55.647 rows=19951 loops=1)
                    Merge Cond: (capturing_devices.gateway_id = alerts_1.gateway_id)
                    Buffers: shared hit=14452
                    ->  Sort  (cost=7832.64..7832.94 rows=121 width=4) (actual time=41.576..46.396 rows=28669 loops=1)
                          Sort Key: capturing_devices.gateway_id
                          Sort Method: quicksort  Memory: 2112kB
                          Buffers: shared hit=14095
                          ->  Nested Loop  (cost=8.88..7828.45 rows=121 width=4) (actual time=0.172..34.577 rows=28669 loops=1)
                                Buffers: shared hit=14095
                                ->  Nested Loop  (cost=8.46..7750.49 rows=22 width=12) (actual time=0.156..20.694 rows=1064 loops=1)
                                      Buffers: shared hit=10590
                                      ->  Hash Join  (cost=8.18..7622.70 rows=23 width=12) (actual time=0.111..16.987 rows=1109 loops=1)
                                            Hash Cond: (capturing_devices.capturing_device_type_id = capturing_device_types.id)
                                            Buffers: shared hit=7261
                                            ->  Seq Scan on capturing_devices  (cost=0.00..7539.77 rows=28377 width=16) (actual time=0.008..9.623 rows=28377 loops=1)
                                                  Buffers: shared hit=7256
                                            ->  Hash  (cost=8.17..8.17 rows=1 width=8) (actual time=0.015..0.016 rows=1 loops=1)
                                                  Buckets: 1024  Batches: 1  Memory Usage: 9kB
                                                  Buffers: shared hit=2
                                                  ->  Index Scan using index_capturing_device_types_on_name on capturing_device_types  (cost=0.15..8.17 rows=1 width=8) (actual time=0.011..0.012 rows=1 loops=1)
                                                        Index Cond: ((name)::text = 'ENERGY_COMFOAIR'::text)
                                                        Buffers: shared hit=2
                                      ->  Index Scan using gateways_pkey on gateways  (cost=0.28..5.56 rows=1 width=8) (actual time=0.003..0.003 rows=1 loops=1109)
                                            Index Cond: (id = capturing_devices.gateway_id)
                                            Filter: (NOT inactive)
                                            Rows Removed by Filter: 0
                                            Buffers: shared hit=3329
                                ->  Index Only Scan using index_parameters_on_capturing_device_id on parameters  (cost=0.42..3.43 rows=11 width=4) (actual time=0.004..0.008 rows=27 loops=1064)
                                      Index Cond: (capturing_device_id = capturing_devices.id)
                                      Heap Fetches: 253
                                      Buffers: shared hit=3505
                    ->  Sort  (cost=255.81..255.81 rows=2 width=4) (actual time=0.762..0.869 rows=320 loops=1)
                          Sort Key: alerts_1.gateway_id
                          Sort Method: quicksort  Memory: 40kB
                          Buffers: shared hit=357
                          ->  Hash Join  (cost=8.47..255.80 rows=2 width=4) (actual time=0.055..0.665 rows=321 loops=1)
                                Hash Cond: (alerts_1.alert_type_id = alert_types_1.id)
                                Buffers: shared hit=357
                                ->  Index Scan using index_alerts_on_actual_status on alerts alerts_1  (cost=0.29..245.86 rows=663 width=8) (actual time=0.021..0.448 rows=689 loops=1)
                                      Index Cond: (actual_status = 0)
                                      Buffers: shared hit=355
                                ->  Hash  (cost=8.17..8.17 rows=1 width=8) (actual time=0.013..0.013 rows=1 loops=1)
                                      Buckets: 1024  Batches: 1  Memory Usage: 9kB
                                      Buffers: shared hit=2
                                      ->  Index Scan using index_alert_types_on_name on alert_types alert_types_1  (cost=0.15..8.17 rows=1 width=8) (actual time=0.010..0.011 rows=1 loops=1)
                                            Index Cond: ((name)::text = 'one_energy_offline'::text)
                                            Buffers: shared hit=2
              ->  Materialize  (cost=9671.97..20822017.28 rows=386130 width=4) (actual time=0.039..0.508 rows=7287 loops=19951)
                    Buffers: shared hit=196371
                    ->  Hash Join  (cost=9671.97..20818577.63 rows=386130 width=4) (actual time=766.869..1211.087 rows=42765 loops=1)
                          Hash Cond: (capturing_devices_1.gateway_id = gateways_1.id)
                          Buffers: shared hit=196371
                          ->  Gather  (cost=8504.71..20816314.46 rows=417152 width=4) (actual time=764.591..1195.184 rows=42765 loops=1)
                                Workers Planned: 4
                                Workers Launched: 4
                                Buffers: shared hit=195316
                                ->  Parallel Hash Join  (cost=7504.71..20773599.26 rows=104288 width=4) (actual time=725.830..1219.735 rows=8553 loops=5)
                                      Hash Cond: (parameter_values_202006.parameter_id = parameters_1.id)
                                      Buffers: shared hit=195316
                                      ->  Parallel Append  (cost=0.00..20290503.38 rows=126709895 width=4) (actual time=552.325..1178.649 rows=76567 loops=5)
                                            Buffers: shared hit=160027
                                            Subplans Removed: 30
                                            ->  Parallel Seq Scan on parameter_values_202006  (cost=0.00..233239.87 rows=111598 width=4) (actual time=552.319..1166.660 rows=76567 loops=5)
                                                  Filter: (datetime >= (now() - '02:00:00'::interval))
                                                  Rows Removed by Filter: 3278945
                                                  Buffers: shared hit=160027
                                            ->  Parallel Seq Scan on parameter_values_202007  (cost=0.00..29.04 rows=363 width=4) (actual time=0.002..0.002 rows=0 loops=1)
                                                  Filter: (datetime >= (now() - '02:00:00'::interval))
                                            ->  Parallel Seq Scan on parameter_values_202008  (cost=0.00..29.04 rows=363 width=4) (actual time=0.001..0.001 rows=0 loops=2)
                                                  Filter: (datetime >= (now() - '02:00:00'::interval))
                                            ->  Parallel Seq Scan on parameter_values_202009  (cost=0.00..29.04 rows=363 width=4) (actual time=0.001..0.001 rows=0 loops=1)
                                                  Filter: (datetime >= (now() - '02:00:00'::interval))
                                            ->  Parallel Seq Scan on parameter_values_202010  (cost=0.00..29.04 rows=363 width=4) (actual time=0.000..0.001 rows=0 loops=2)
                                                  Filter: (datetime >= (now() - '02:00:00'::interval))
                                            ->  Parallel Seq Scan on parameter_values_202011  (cost=0.00..29.04 rows=363 width=4) (actual time=0.001..0.001 rows=0 loops=1)
                                                  Filter: (datetime >= (now() - '02:00:00'::interval))
                                            ->  Parallel Seq Scan on parameter_values_202012  (cost=0.00..29.04 rows=363 width=4) (actual time=0.002..0.002 rows=0 loops=1)
                                                  Filter: (datetime >= (now() - '02:00:00'::interval))
                                      ->  Parallel Hash  (cost=7504.05..7504.05 rows=53 width=12) (actual time=16.491..16.491 rows=5876 loops=5)
                                            Buckets: 32768 (originally 1024)  Batches: 1 (originally 1)  Memory Usage: 1976kB
                                            Buffers: shared hit=35169
                                            ->  Nested Loop  (cost=8.60..7504.05 rows=53 width=12) (actual time=0.091..10.976 rows=5876 loops=5)
                                                  Buffers: shared hit=35169
                                                  ->  Hash Join  (cost=8.18..7413.57 rows=10 width=12) (actual time=0.062..3.879 rows=222 loops=5)
                                                        Hash Cond: (capturing_devices_1.capturing_device_type_id = capturing_device_types_1.id)
                                                        Buffers: shared hit=7270
                                                        ->  Parallel Seq Scan on capturing_devices capturing_devices_1  (cost=0.00..7374.24 rows=11824 width=16) (actual time=0.003..2.111 rows=5675 loops=5)
                                                              Buffers: shared hit=7256
                                                        ->  Hash  (cost=8.17..8.17 rows=1 width=8) (actual time=0.026..0.026 rows=1 loops=5)
                                                              Buckets: 1024  Batches: 1  Memory Usage: 9kB
                                                              Buffers: shared hit=14
                                                              ->  Index Scan using index_capturing_device_types_on_name on capturing_device_types capturing_device_types_1  (cost=0.15..8.17 rows=1 width=8) (actual time=0.019..0.019 rows=1 loops=5)
                                                                    Index Cond: ((name)::text = 'ENERGY_COMFOAIR'::text)
                                                                    Buffers: shared hit=14
                                                  ->  Index Scan using index_parameters_on_capturing_device_id on parameters parameters_1  (cost=0.42..8.94 rows=11 width=12) (actual time=0.007..0.027 rows=26 loops=1109)
                                                        Index Cond: (capturing_device_id = capturing_devices_1.id)
                                                        Buffers: shared hit=27899
                          ->  Hash  (cost=1107.04..1107.04 rows=4817 width=8) (actual time=2.262..2.262 rows=2201 loops=1)
                                Buckets: 8192  Batches: 1  Memory Usage: 150kB
                                Buffers: shared hit=1055
                                ->  Seq Scan on gateways gateways_1  (cost=0.00..1107.04 rows=4817 width=8) (actual time=0.014..1.743 rows=2201 loops=1)
                                      Filter: (NOT inactive)
                                      Rows Removed by Filter: 177
                                      Buffers: shared hit=1055
        ->  Nested Loop  (cost=25.02..37.06 rows=1 width=4) (actual time=0.091..0.091 rows=1 loops=2713)
              Join Filter: (alerts.alert_type_id = alert_types.id)
              Rows Removed by Join Filter: 0
              Buffers: shared hit=84547
              ->  Bitmap Heap Scan on alerts  (cost=24.87..28.88 rows=1 width=8) (actual time=0.079..0.079 rows=1 loops=2713)
                    Recheck Cond: ((gateway_id = capturing_devices.gateway_id) AND (actual_status = 0))
                    Heap Blocks: exact=2598
                    Buffers: shared hit=79349
                    ->  BitmapAnd  (cost=24.87..24.87 rows=1 width=0) (actual time=0.074..0.074 rows=0 loops=2713)
                          Buffers: shared hit=76652
                          ->  Bitmap Index Scan on index_alerts_on_gateway_id  (cost=0.00..3.19 rows=37 width=0) (actual time=0.014..0.014 rows=57 loops=2713)
                                Index Cond: (gateway_id = capturing_devices.gateway_id)
                                Buffers: shared hit=6114
                          ->  Bitmap Index Scan on index_alerts_on_actual_status  (cost=0.00..21.26 rows=663 width=0) (actual time=0.056..0.056 rows=730 loops=2713)
                                Index Cond: (actual_status = 0)
                                Buffers: shared hit=70538
              ->  Index Scan using index_alert_types_on_name on alert_types  (cost=0.15..8.17 rows=1 width=8) (actual time=0.006..0.006 rows=1 loops=2599)
                    Index Cond: ((name)::text = 'gateway_offline'::text)
                    Buffers: shared hit=5198
Planning Time: 6.546 ms
Execution Time: 23040.043 ms

If I run the CTE part alone it executes in 63ms and returns 200 rows.

When I rewrite the complete query with a temporary table like below it executes in 4 seconds.

select gateway_id, parameters.id as parameter_id 
into temporary tmp_gateway_params
from
    gateways
inner join capturing_devices on
    gateway_id = gateways.id
inner join capturing_device_types on
    capturing_device_type_id = capturing_device_types.id
inner join parameters on
    capturing_device_id = capturing_devices.id
where
    capturing_device_types.name = 'ENERGY_COMFOAIR'
    and inactive = false;

select
    distinct gateway_id,
    null as capturing_device_id
from
    tmp_gateway_params master
where
    not exists (
        select *
    from
        parameter_values
    inner join tmp_gateway_params on
        parameter_values.parameter_id = tmp_gateway_params.parameter_id
    where
        gateway_id = master.gateway_id
        and datetime >= now() - interval '120 minutes')
    and not exists (
        select *
    from
        alerts
    inner join alert_types on
        alert_type_id = alert_types.id
    where
        alert_types.name = 'gateway_offline'
        and alerts.gateway_id = master.gateway_id
        and actual_status = 0)
    and not exists (
        select *
    from
        alerts
    inner join alert_types on
        alert_type_id = alert_types.id
    where
        alert_types.name = 'one_energy_offline'
        and alerts.gateway_id = master.gateway_id
        and actual_status = 0);

This is the execution plan:

First part:

https://pastebin.com/WN0e9NnU

Second part

https://pastebin.com/jYeCyi9v

I already found some other person having performance issues with CTE's after the upgrade and he was able to solve it with:

set jit = off;

Unfortunately this doesn't make any difference.

EDIT:

After the weekend running the exact same query again returns results after less than 5 seconds.

This is the EXPLAIN (ANALYSE, BUFFERS):

https://pastebin.com/f74X1FfW

Please add `EXPLAIN (ANALYZE, BUFFERS)` output for the slow and the fast query, as well as for the queries with the temp table. Why not use the temp table if it is fast? — Laurenz Albe, Jun 05 '20 at 13:47
@LaurenzAlbe I've added the EXPLAIN, however for the slow query I had to abort after one hour without any results. I'm using a temp table for now as a workaround, it just doesn't feel right. Especially the fact that the query now takes over an hour, while in previous Postgres it was less than 10 seconds... — rept, Jun 05 '20 at 15:00
What is your goal? It looks like you already know how to fix the problem with two different work-arounds. Do you want to get the planner improved for some distant future version (probably 14 at least, as 13 is already in feature freeze)? Do you think this is a back-patchable (into v12) bug? I really doubt that it is. — jjanes, Jun 05 '20 at 17:36
Could you also show the EXPLAIN (ANALYZE) you are finding when run under v11? Is the partitioning set up the same between versions? — jjanes, Jun 05 '20 at 17:37
The estimates are bad. Does it get faster if you set `enable_nestloop = off` for the duration of the query? — Laurenz Albe, Jun 05 '20 at 19:54
@jjanes my goal is to indeed to get the planner improved for some distant future version. Especially the fact that it worked fast in version PG11 causes me concern. I don't have the PG11 version online (DB is >300 GB). Partitioning set didn't change. — rept, Jun 08 '20 at 07:28
@LaurenzAlbe YES it does get faster with enable_nestloop = off !! 4 seconds. — rept, Jun 08 '20 at 07:28
@LaurenzAlbe if I run it now without the enable_nestloop (in a new session) it's also 4 seconds? How is this possible? — rept, Jun 08 '20 at 07:42
My standard trick is to avoid the CTE (especially if you expect a large number of records in it) and rewrite it to a TEMP VIEW, which will be pulled into the main query plan. — wildplasser, Jun 08 '20 at 08:28
BTW: the estimates are bad. Did you run ANALYZE after import? `WITH NOT MATERIALIZED ...` (available since PG12) could produce the same effect as `enable_nestloop=off;` — wildplasser, Jun 08 '20 at 09:12

Bad CTE performance since Postgres 12

0 Answers0