Thread: Confusing numbers in actual time in explain analyze output of recursive query when jit is used

Hello nice people.

I would like to report one problem with EXPLAIN ANALYZE output from recursive query when JIT is ON and OS supports jit, so JIT was used. It is most likely not new , but it was very confusing for the client and online research did not help them. Therefore, I want to send this email also as a reference for the future.

Client had recursive query using quite complicated underlying views, resulting in scans over multiple tables. They optimized the most problematic steps with new indexes but then the explain analyze output suddenly showed a long run on previously quick step. And there was seemingly nothing else to optimize on this step.

Since total time of the recursive loop in the output roughly corresponded to the total JIT time, we asked the client to run query with JIT = OFF. And problem was gone and query much quicker.

Problem was that JIT time was added always to the slowest step in the recursive loop, which caused very paradoxical behavior - previously quick step suddenly seemingly slowed down without any clear reason.

Details:

* Client has recursive query which uses quite complicated underlying views resulting in processing of multiple tables:

with recursive traversal as
(select "Type", "Id", 0 as level, '' as rel_type from myview1 where "Id" = 'xxxxxx'
union
select t2."Type", t2."Id", level+1, e."Type"
from
traversal t1
join
myview2 e on t1."Id" = e."FromId" and e."Type" = 'xxx'
join
myview1 t2 on e."ToId" = t2."Id"
)
select * from traversal;


* They did several optimization but Recursive Union part stayed slow in all cases with roughly similar run time:

-> Recursive Union (cost=0.28..1313656908.74 rows=104384767268 width=84) (actual time=228.732..228.833 rows=2 loops=1)
-> Recursive Union (cost=0.28..1313352949.93 rows=104360450528 width=84) (actual time=240.739..240.877 rows=2 loops=1)


* Very confusing was that previously quick step in the first run was suddenly very slow in the second run without any change at all in this step.
* first run:             -> Index Only Scan using "mytable_pkey" on myschema."mytable" t_7 (cost=0.43..1.55 rows=1 width=48) (actual time=0.014..0.015 rows=1 loops=1)
* second run:      -> Index Only Scan using "mytable_pkey" on myschema."mytable" t_7 (cost=0.43..1.55 rows=1 width=48) (actual time=240.650..240.652 rows=1 loops=1)"


* Difference was that optimized step was now quicker that this one and the JIT time was roughly added in the explain analyze output to this now slowest step of recursive loop.

JIT:
Functions: 48
Options: Inlining true, Optimization true, Expressions true, Deforming true
Timing: Generation 3.489 ms, Inlining 16.984 ms, Optimization 115.833 ms, Emission 107.853 ms, Total 244.158 ms


* Without JIT query ends in just few milliseconds.

Best regards