Re: BUG #16223: Performance regression between 11.6 and 12.1 in anSQL query with a recursive CTE based on function - Mailing list pgsql-bugs

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