Recursive query slow on strange conditions

Question

The following query is part of a much bigger one that runs perfectly fast on a filled DB but on a nearly empty one it is very long.

In this simplified form, it takes ~400ms to execute but if you remove either line (1) or lines (2) and (3) then it takes ~35ms. Why ? And how do I make it work normally ?

Some background about the DB :

DB is VACUUMed and ANALYZEd
ctract is empty
contrats contains only 2 lines, none of which has a idtypecontrat IN (4,5)
so tmpctr1 is empty
copyrightad contains 280 rows, only one matches the filters idoeu=13 and role IN ('E','CE')
in all cases, query returns ONE row (the one returned by the first part of the recursive CTE)
line (1) is absolutely not used in this version but removing it hides the problem for some reason

    WITH RECURSIVE tmpctr1 AS (
        SELECT ced.idad AS cedant, ced.idclient
        FROM contrats c
        JOIN CtrAct ced ON c.idcontrat=ced.idcontrat AND ced.isassignor
        JOIN CtrAct ces ON c.idcontrat=ces.idcontrat AND NOT COALESCE(ces.isassignor,FALSE)  --(1)
        WHERE idtypecontrat IN (4,5)
    )
    ,rec1 AS (
        SELECT ca.idoeu,ca.idad AS chn,1 AS idclient, 1 AS level
        FROM copyrightad ca 
        WHERE ca.role IN ('E','CE')
        AND ca.idoeu = 13

        UNION

        SELECT r.idoeu,0, 0, r.level+1
        FROM rec1 r
        LEFT JOIN tmpctr1 c ON r.chn=c.cedant
        LEFT JOIN tmpctr1 c2 ON r.idclient=c2.idclient  -- (2)
        WHERE r.level<20
        AND (c.cedant is not null 
          OR c2.cedant is not null  --(3)
        )
    )
    select * from rec1

Query plan #1 : slow

QUERY PLAN
CTE Scan on rec1  (cost=1662106.61..2431078.65 rows=38448602 width=16) (actual time=384.975..398.182 rows=1 loops=1)    
  CTE tmpctr1   
    ->  Hash Join  (cost=36.06..116.37 rows=148225 width=8) (actual time=0.009..0.010 rows=0 loops=1)   
          Hash Cond: (c.idcontrat = ces.idcontrat)  
          ->  Hash Join  (cost=1.04..28.50 rows=385 width=16) (actual time=0.009..0.009 rows=0 loops=1) 
                Hash Cond: (ced.idcontrat = c.idcontrat)    
                ->  Seq Scan on ctract ced  (cost=0.00..25.40 rows=770 width=12) (actual time=0.008..0.008 rows=0 loops=1)  
                      Filter: isassignor    
                ->  Hash  (cost=1.02..1.02 rows=1 width=4) (never executed) 
                      ->  Seq Scan on contrats c  (cost=0.00..1.02 rows=1 width=4) (never executed) 
                            Filter: (idtypecontrat = ANY ('{4,5}'::integer[]))  
          ->  Hash  (cost=25.40..25.40 rows=770 width=4) (never executed)   
                ->  Seq Scan on ctract ces  (cost=0.00..25.40 rows=770 width=4) (never executed)    
                      Filter: (NOT COALESCE(isassignor, false)) 
  CTE rec1  
    ->  Recursive Union  (cost=0.00..1661990.25 rows=38448602 width=16) (actual time=384.973..398.179 rows=1 loops=1)   
          ->  Seq Scan on copyrightad ca  (cost=0.00..8.20 rows=2 width=16) (actual time=384.970..384.981 rows=1 loops=1)   
                Filter: (((role)::text = ANY ('{E,CE}'::text[])) AND (idoeu = 13))  
                Rows Removed by Filter: 279 
          ->  Merge Left Join  (cost=21618.01..89301.00 rows=3844860 width=16) (actual time=13.193..13.193 rows=0 loops=1)  
                Merge Cond: (r.idclient = c2.idclient)  
                Filter: ((c_1.cedant IS NOT NULL) OR (c2.cedant IS NOT NULL))   
                Rows Removed by Filter: 1   
                ->  Sort  (cost=3892.89..3905.86 rows=5188 width=16) (actual time=13.179..13.180 rows=1 loops=1)    
                      Sort Key: r.idclient  
                      Sort Method: quicksort  Memory: 25kB  
                      ->  Hash Right Join  (cost=0.54..3572.76 rows=5188 width=16) (actual time=13.170..13.171 rows=1 loops=1)  
                            Hash Cond: (c_1.cedant = r.chn) 
                            ->  CTE Scan on tmpctr1 c_1  (cost=0.00..2964.50 rows=148225 width=4) (actual time=0.011..0.011 rows=0 loops=1) 
                            ->  Hash  (cost=0.45..0.45 rows=7 width=16) (actual time=13.150..13.150 rows=1 loops=1) 
                                  Buckets: 1024  Batches: 1  Memory Usage: 9kB  
                                  ->  WorkTable Scan on rec1 r  (cost=0.00..0.45 rows=7 width=16) (actual time=13.138..13.140 rows=1 loops=1)   
                                        Filter: (level < 20)    
                ->  Materialize  (cost=17725.12..18466.25 rows=148225 width=8) (actual time=0.008..0.008 rows=0 loops=1)    
                      ->  Sort  (cost=17725.12..18095.68 rows=148225 width=8) (actual time=0.007..0.007 rows=0 loops=1) 
                            Sort Key: c2.idclient   
                            Sort Method: quicksort  Memory: 25kB    
                            ->  CTE Scan on tmpctr1 c2  (cost=0.00..2964.50 rows=148225 width=8) (actual time=0.000..0.000 rows=0 loops=1)  
Planning Time: 0.270 ms 
JIT:    
  Functions: 53 
  Options: Inlining true, Optimization true, Expressions true, Deforming true   
  Timing: Generation 5.064 ms, Inlining 4.491 ms, Optimization 236.336 ms, Emission 155.206 ms, Total 401.097 ms    
Execution Time: 403.549 ms

Query plan #2 : fast : line (1) is hidden

QUERY PLAN
CTE Scan on rec1  (cost=240.86..245.90 rows=252 width=16) (actual time=0.030..0.058 rows=1 loops=1) 
  CTE tmpctr1   
    ->  Hash Join  (cost=1.04..28.50 rows=385 width=8) (actual time=0.001..0.001 rows=0 loops=1)    
          Hash Cond: (ced.idcontrat = c.idcontrat)  
          ->  Seq Scan on ctract ced  (cost=0.00..25.40 rows=770 width=12) (actual time=0.001..0.001 rows=0 loops=1)    
                Filter: isassignor  
          ->  Hash  (cost=1.02..1.02 rows=1 width=4) (never executed)   
                ->  Seq Scan on contrats c  (cost=0.00..1.02 rows=1 width=4) (never executed)   
                      Filter: (idtypecontrat = ANY ('{4,5}'::integer[]))    
  CTE rec1  
    ->  Recursive Union  (cost=0.00..212.35 rows=252 width=16) (actual time=0.029..0.056 rows=1 loops=1)    
          ->  Seq Scan on copyrightad ca  (cost=0.00..8.20 rows=2 width=16) (actual time=0.027..0.041 rows=1 loops=1)   
                Filter: (((role)::text = ANY ('{E,CE}'::text[])) AND (idoeu = 13))  
                Rows Removed by Filter: 279 
          ->  Hash Right Join  (cost=9.97..19.91 rows=25 width=16) (actual time=0.013..0.013 rows=0 loops=1)    
                Hash Cond: (c2.idclient = r.idclient)   
                Filter: ((c_1.cedant IS NOT NULL) OR (c2.cedant IS NOT NULL))   
                Rows Removed by Filter: 1   
                ->  CTE Scan on tmpctr1 c2  (cost=0.00..7.70 rows=385 width=8) (actual time=0.000..0.000 rows=0 loops=1)    
                ->  Hash  (cost=9.81..9.81 rows=13 width=16) (actual time=0.009..0.009 rows=1 loops=1)  
                      Buckets: 1024  Batches: 1  Memory Usage: 9kB  
                      ->  Hash Right Join  (cost=0.54..9.81 rows=13 width=16) (actual time=0.008..0.008 rows=1 loops=1) 
                            Hash Cond: (c_1.cedant = r.chn) 
                            ->  CTE Scan on tmpctr1 c_1  (cost=0.00..7.70 rows=385 width=4) (actual time=0.001..0.001 rows=0 loops=1)   
                            ->  Hash  (cost=0.45..0.45 rows=7 width=16) (actual time=0.003..0.003 rows=1 loops=1)   
                                  Buckets: 1024  Batches: 1  Memory Usage: 9kB  
                                  ->  WorkTable Scan on rec1 r  (cost=0.00..0.45 rows=7 width=16) (actual time=0.002..0.002 rows=1 loops=1) 
                                        Filter: (level < 20)    
Planning Time: 0.330 ms 
Execution Time: 0.094 ms

Query plan #3 : fast : lines (2) and (3) are hidden

QUERY PLAN
CTE Scan on rec1  (cost=1829.46..2907.50 rows=53902 width=16) (actual time=0.050..0.074 rows=1 loops=1) 
  CTE rec1  
    ->  Recursive Union  (cost=0.00..1829.46 rows=53902 width=16) (actual time=0.049..0.072 rows=1 loops=1) 
          ->  Seq Scan on copyrightad ca  (cost=0.00..8.20 rows=2 width=16) (actual time=0.046..0.067 rows=1 loops=1)   
                Filter: (((role)::text = ANY ('{E,CE}'::text[])) AND (idoeu = 13))  
                Rows Removed by Filter: 279 
          ->  Hash Join  (cost=30.45..74.32 rows=5390 width=16) (actual time=0.003..0.003 rows=0 loops=1)   
                Hash Cond: (c.idcontrat = ced.idcontrat)    
                ->  Hash Join  (cost=1.04..28.50 rows=385 width=8) (actual time=0.002..0.002 rows=0 loops=1)    
                      Hash Cond: (ces.idcontrat = c.idcontrat)  
                      ->  Seq Scan on ctract ces  (cost=0.00..25.40 rows=770 width=4) (actual time=0.002..0.002 rows=0 loops=1) 
                            Filter: (NOT COALESCE(isassignor, false))   
                      ->  Hash  (cost=1.02..1.02 rows=1 width=4) (never executed)   
                            ->  Seq Scan on contrats c  (cost=0.00..1.02 rows=1 width=4) (never executed)   
                                  Filter: (idtypecontrat = ANY ('{4,5}'::integer[]))    
                ->  Hash  (cost=29.08..29.08 rows=27 width=12) (never executed) 
                      ->  Hash Join  (cost=0.54..29.08 rows=27 width=12) (never executed)   
                            Hash Cond: (ced.idad = r.chn)   
                            ->  Seq Scan on ctract ced  (cost=0.00..25.40 rows=766 width=8) (never executed)    
                                  Filter: (isassignor AND (idad IS NOT NULL))   
                            ->  Hash  (cost=0.45..0.45 rows=7 width=12) (never executed)    
                                  ->  WorkTable Scan on rec1 r  (cost=0.00..0.45 rows=7 width=12) (never executed)  
                                        Filter: (level < 20)    
Planning Time: 0.310 ms 
Execution Time: 0.179 ms

PostgreSQL 12.2

Edit: the same query on the same DB on PostgreSQL 11.6 runs fast (still highly over-estimating rows on some parts) so I guess this is a regression.

Erwin Brandstetter · Answer 1 · 2020-05-07T00:36:16.733

Why?

The immediate reason for the big difference in query execution time is "Just-in-Time compilation", which is active by default in Postgres 12. Quoting the release notes:

Enable Just-in-Time (JIT) compilation by default, if the server has been built with support for it (Andres Freund)

Note that this support is not built by default, but has to be selected explicitly while configuring the build.

Turn it off in your session and test again:

SET jit = off

But JIT only amplifies the underlying problem: Estimates are way off in the query plan, which leads Postgres to assume a huge number of rows resulting from the joins in CTE tmpctr1, and assume that JIT would pay off.

Keep PostgreSQL from sometimes choosing a bad query plan

You asserted that ...

DB is VACUUMed and ANALYZEd

ctract is empty

But Postgres expects to find 770 rows in a sequential scan:

 ->  Seq Scan on ctract ced  (cost=0.00..25.40 rows=770 width=12) (actual time=0.008..0.008 rows=0 loops=1)  
       Filter: isassignor

Bold emphasis mine. The number 770 comes directly from pg_class.reltuples, meaning that statistic is completely out of date. Maybe you relied on autovacuum but something kept it from kicking in, or its settings are not aggressive enough? Run this manually and retry:

ANALYZE ctract;

There is probably more potential to optimize, but I stopped processing here.

In a populated database, indexes will help a lot. Are you aware that partial or expression indexes can help with customized statistics? See:

Abount (1):

JOIN CtrAct ces ON c.idcontrat=ces.idcontrat AND NOT COALESCE(ces.isassignor,FALSE)  --(1)

Try replacing it with the equivalent:

JOIN CtrAct ces ON c.idcontrat=ces.idcontrat AND ces.isassignor IS NOT TRUE

It's clearer in any case. The convoluted expression may prevent index usage or better estimates (not the problem here).

`CtrAct` contains links between ACTors and ConTRacts. There is one assignor (aliased as `ced`) and one assignee (aliased `ces`), thus the opposite tests. And yes, there *are* results. I will try the `IS NOT TRUE` way of avoiding the `COALESCE`, didn't know about that construct. — JC Boggio, May 04 '20 at 08:11
@JCBoggio: There may be results, but not from the CTE `tmpctr1`. I elaborated a bit. — Erwin Brandstetter, May 04 '20 at 14:00
Yes ! Suppose I have idcontrat=1 and 2 records for CtrAct, both with idcontrat=1 but one is assignor and the other isn't. `ced` will map to the assignor and `ces` to the assignee, these are 2 distinct records in CtrAct. I should have mentionned that `idcontrat` is not the primary key of `CtrAct`, it's a foreign key to `contrats`. — JC Boggio, May 05 '20 at 15:07
@JCBoggio: Oh, I was under the wrong impression that `CtrAct.idcontrat` was the primary key. I deleted the misguided second half of my answer. (Actual `CREATE TABLE` statements would have clarified.) — Erwin Brandstetter, May 05 '20 at 16:20
yes I should have provided the `CREATE TABLE`, sorry. BTW, the `IS NOT TRUE` makes the query far more readable, thanks. — JC Boggio, May 05 '20 at 21:01
@JCBoggio: I had another look and added a proper answer (or so I think). — Erwin Brandstetter, May 07 '20 at 00:36

Recursive query slow on strange conditions

1 Answers1

Why?

Abount (1):