Original-Subject: I don't understand that EXPLAIN PLAN timings
Original-From: Jean-Christophe Boggio <postgresql@thefreecat.org>
Message-ID: <61e642df-5f48-4e4e-b4c3-58936f90ddaa@thefreecat.org>
Date: Fri, 19 Jan 2024 07:48:52 +0100
MIME-Version: 1.0
User-Agent: Mozilla Thunderbird
Content-Language: fr-FR, en-US
To: 
  "pgsql-performance@lists.postgresql.org"
 <pgsql-performance@lists.postgresql.org>
From: Jean-Christophe Boggio <postgresql@thefreecat.org>
Subject: I don't understand that EXPLAIN PLAN timings
Content-Type: text/plain; charset=UTF-8; format=flowed
Content-Transfer-Encoding: 8bit
Archived-At: 
 <https://www.postgresql.org/message-id/61e642df-5f48-4e4e-b4c3-58936f90ddaa%40thefreecat.org>
Precedence: bulk

Hello,

This EXPLAIN ANALYZE tells me the actual time was 11.xxx ms but the 
final Execution time says 493.xxx ms (this last one is true : about 1/2 
second).

I would like to optimize this query but with this inconsistency, it will 
be difficult. This query is really a function so I added the "params" 
CTE to do the tests.

Thanks for your help,

JC

PS: PostgreSQL 14.10 (Ubuntu 14.10-1.pgdg23.10+1) on 
x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 13.2.0-4ubuntu3) 13.2.0, 64-bit

and JIT is disabled


Nested Loop Left Join  (cost=36411048684.11..36411051002.22 rows=54228 
width=116) (actual time=11.609..11.620 rows=0 loops=1)
   Join Filter: (u_g_internalvalidation.idinternalvalidation IS NOT NULL)
   CTE params
     ->  Result  (cost=0.00..0.01 rows=1 width=41) (actual 
time=0.001..0.001 rows=1 loops=1)
   CTE u
     ->  Nested Loop  (cost=0.25..12.77 rows=250 width=368) (never executed)
           ->  CTE Scan on params  (cost=0.00..0.02 rows=1 width=41) 
(never executed)
           ->  Function Scan on get_user  (cost=0.25..10.25 rows=250 
width=327) (never executed)
                 Filter: ((NOT isgroup) AND (NOT istemplate))
   CTE internalvalidation
     ->  Hash Join  (cost=13988.95..14336.16 rows=436 width=42) (actual 
time=11.601..11.606 rows=0 loops=1)
           Hash Cond: (files.idfile = i_1.idfile)
           ->  HashAggregate  (cost=13929.87..14039.58 rows=10971 
width=4) (actual time=11.480..11.527 rows=243 loops=1)
                 Group Key: files.idfile
                 Batches: 1  Memory Usage: 417kB
                 ->  Append  (cost=0.00..13902.45 rows=10971 width=4) 
(actual time=6.593..11.423 rows=243 loops=1)
                       ->  Nested Loop  (cost=0.00..10139.01 rows=10766 
width=4) (actual time=5.143..5.145 rows=0 loops=1)
                             Join Filter: ((files.idfile = 
(unnest(params_2.fn_idfile))) OR ((params_1.fn_idrealm = 
files.idrealminitial) AND params_1.fn_canseesubfiles))
                             ->  Seq Scan on files (cost=0.00..2985.74 
rows=40874 width=8) (actual time=0.002..2.396 rows=40766 loops=1)
                             ->  Materialize  (cost=0.00..0.35 rows=10 
width=9) (actual time=0.000..0.000 rows=0 loops=40766)
                                   ->  Nested Loop (cost=0.00..0.30 
rows=10 width=9) (actual time=0.003..0.003 rows=0 loops=1)
                                         ->  CTE Scan on params 
params_1  (cost=0.00..0.02 rows=1 width=5) (actual time=0.002..0.003 
rows=0 loops=1)
                                               Filter: (fn_idfile IS NOT 
NULL)
                                               Rows Removed by Filter: 1
                                         ->  ProjectSet (cost=0.00..0.08 
rows=10 width=4) (never executed)
                                               ->  CTE Scan on params 
params_2  (cost=0.00..0.02 rows=1 width=32) (never executed)
                       ->  Nested Loop  (cost=0.00..3598.87 rows=205 
width=4) (actual time=1.448..6.267 rows=243 loops=1)
                             Join Filter: (((params_3.fn_idfile IS NULL) 
AND (files_1.idrealm = params_3.fn_idrealm)) OR ((files_1.idrealminitial 
= params_3.fn_idrealm) AND params_3.fn_canseesubfiles))
                             Rows Removed by Join Filter: 40523
                             ->  CTE Scan on params params_3 
(cost=0.00..0.02 rows=1 width=37) (actual time=0.001..0.001 rows=1 loops=1)
                                   Filter: ((fn_idfile IS NULL) OR 
fn_canseesubfiles)
                             ->  Seq Scan on files files_1 
(cost=0.00..2985.74 rows=40874 width=12) (actual time=0.002..1.946 
rows=40766 loops=1)
           ->  Hash  (cost=58.94..58.94 rows=11 width=42) (actual 
time=0.059..0.060 rows=6 loops=1)
                 Buckets: 1024  Batches: 1  Memory Usage: 9kB
                 ->  Nested Loop Left Join  (cost=0.29..58.94 rows=11 
width=42) (actual time=0.031..0.055 rows=6 loops=1)
                       ->  Seq Scan on internalvalidations i_1 
(cost=0.00..9.81 rows=11 width=26) (actual time=0.012..0.033 rows=6 loops=1)
                             Filter: isvisible
                             Rows Removed by Filter: 453
                       ->  Memoize  (cost=0.29..7.58 rows=1 width=20) 
(actual time=0.003..0.003 rows=1 loops=6)
                             Cache Key: i_1.idclaimer
                             Cache Mode: logical
                             Hits: 5  Misses: 1  Evictions: 0 Overflows: 
0  Memory Usage: 1kB
                             ->  Index Scan using users_pkey on users 
users_1  (cost=0.28..7.57 rows=1 width=20) (actual time=0.012..0.013 
rows=1 loops=1)
                                   Index Cond: (iduser = i_1.idclaimer)
   CTE u_g_internalvalidation_without_u_status
     ->  Recursive Union  (cost=23.65..7914563.16 rows=220606936 
width=19) (never executed)
           ->  Nested Loop  (cost=23.65..9280.10 rows=1936 width=19) 
(never executed)
                 Join Filter: (uhi.iduser = gu.iduser)
                 ->  Nested Loop  (cost=23.40..80.70 rows=733 width=15) 
(never executed)
                       ->  Hash Join  (cost=23.11..42.43 rows=733 
width=10) (never executed)
                             Hash Cond: 
(internalvalidation.idinternalvalidation = uhi.idinternalvalidation)
                             ->  CTE Scan on internalvalidation 
(cost=0.00..8.72 rows=436 width=4) (never executed)
                             ->  Hash  (cost=13.05..13.05 rows=805 
width=10) (never executed)
                                   ->  Seq Scan on 
users_has_internalvalidations uhi  (cost=0.00..13.05 rows=805 width=10) 
(never executed)
                       ->  Memoize  (cost=0.29..1.67 rows=1 width=5) 
(never executed)
                             Cache Key: uhi.iduser
                             Cache Mode: logical
                             ->  Index Scan using users_pkey on users v  
(cost=0.28..1.66 rows=1 width=5) (never executed)
                                   Index Cond: (iduser = uhi.iduser)
                 ->  Function Scan on get_user gu (cost=0.25..12.75 
rows=4 width=5) (never executed)
                       Filter: ((canvalidate OR v.isgroup) AND (v.iduser 
= iduser))
           ->  Nested Loop  (cost=750.89..349314.43 rows=22060500 
width=19) (never executed)
                 ->  Merge Join  (cost=750.63..1200.96 rows=29414 
width=18) (never executed)
                       Merge Cond: (uhg.idgroup = ugiwus.idusergroup)
                       ->  Sort  (cost=126.96..131.52 rows=1823 width=8) 
(never executed)
                             Sort Key: uhg.idgroup
                             ->  Seq Scan on users_has_groups uhg  
(cost=0.00..28.23 rows=1823 width=8) (never executed)
                       ->  Sort  (cost=623.67..631.74 rows=3227 
width=18) (never executed)
                             Sort Key: ugiwus.idusergroup
                             ->  WorkTable Scan on 
u_g_internalvalidation_without_u_status ugiwus  (cost=0.00..435.60 
rows=3227 width=18) (never executed)
                                   Filter: (isgroup AND (level < 25))
                 ->  Memoize  (cost=0.26..10.26 rows=750 width=5) (never 
executed)
                       Cache Key: uhg.iduser
                       Cache Mode: binary
                       ->  Function Scan on get_user gu_1 
(cost=0.25..10.25 rows=750 width=5) (never executed)
                             Filter: (canvalidate OR isgroup)
   ->  Hash Join  (cost=36403119772.02..36403120996.38 rows=436 
width=120) (actual time=11.609..11.611 rows=0 loops=1)
         Hash Cond: (ug1.idinternalvalidation = i.idinternalvalidation)
         ->  Merge Left Join (cost=36403119757.85..36403120966.35 
rows=200 width=75) (never executed)
               Merge Cond: (ug1.idinternalvalidation = 
u_g_internalvalidation.idinternalvalidation)
               ->  GroupAggregate (cost=36397604572.80..36397605775.80 
rows=200 width=70) (never executed)
                     Group Key: ug1.idinternalvalidation
                     ->  Sort (cost=36397604572.80..36397604772.80 
rows=80000 width=27) (never executed)
                           Sort Key: ug1.idinternalvalidation
                           ->  Hash Left Join 
(cost=36397596247.48..36397598057.72 rows=80000 width=27) (never executed)
                                 Hash Cond: (ug1.idusergroup = users.iduser)
                                 ->  HashAggregate 
(cost=36397595908.85..36397596708.85 rows=80000 width=43) (never executed)
                                       Group Key: 
ug1.idinternalvalidation, ug1.idusergroup, ug1.atleastonemustvalidate
                                       ->  Merge Left Join 
(cost=77330317.34..21265069958.96 rows=1210602075991 width=13) (never 
executed)
                                             Merge Cond: 
((ug1.idinternalvalidation = ug2.idinternalvalidation) AND (ug1.iduser = 
ug2.iduser))
                                             ->  Sort 
(cost=38754984.35..39306501.69 rows=220606936 width=15) (never executed)
                                                   Sort Key: 
ug1.idinternalvalidation, ug1.iduser
                                                   ->  CTE Scan on 
u_g_internalvalidation_without_u_status ug1 (cost=0.00..4412138.72 
rows=220606936 width=15) (never executed)
                                             ->  Materialize 
(cost=38575332.99..39672852.50 rows=219503901 width=10) (never executed)
                                                   ->  Sort 
(cost=38575332.99..39124092.74 rows=219503901 width=10) (never executed)
                                                         Sort Key: 
ug2.idinternalvalidation, ug2.iduser
                                                         ->  CTE Scan on 
u_g_internalvalidation_without_u_status ug2 (cost=0.00..4412138.72 
rows=219503901 width=10) (never executed)
Filter: (hasvalidate IS NOT NULL)
                                 ->  Hash  (cost=289.95..289.95 
rows=3895 width=20) (never executed)
                                       ->  Seq Scan on users 
(cost=0.00..289.95 rows=3895 width=20) (never executed)
               ->  Sort  (cost=5515185.04..5515185.54 rows=200 width=5) 
(never executed)
                     Sort Key: u_g_internalvalidation.idinternalvalidation
                     ->  Subquery Scan on u_g_internalvalidation  
(cost=5515173.40..5515177.40 rows=200 width=5) (never executed)
                           ->  HashAggregate 
(cost=5515173.40..5515175.40 rows=200 width=5) (never executed)
                                 Group Key: ugi.idinternalvalidation
                                 ->  CTE Scan on 
u_g_internalvalidation_without_u_status ugi (cost=0.00..4412138.72 
rows=220606936 width=5) (never executed)
         ->  Hash  (cost=8.72..8.72 rows=436 width=49) (actual 
time=11.603..11.603 rows=0 loops=1)
               Buckets: 1024  Batches: 1  Memory Usage: 8kB
               ->  CTE Scan on internalvalidation i (cost=0.00..8.72 
rows=436 width=49) (actual time=11.603..11.603 rows=0 loops=1)
   ->  CTE Scan on u  (cost=0.00..5.00 rows=125 width=4) (never executed)
         Filter: canvalidate
Planning Time: 1.037 ms
Execution Time: 493.815 ms


And here is the query in case it can help :


explain analyze
WITH RECURSIVE
     params AS (
         SELECT
             4 AS fn_iduser
             , 1 AS fn_idrealm
             , NULL::INT[] AS fn_idfile
             , TRUE AS fn_canseesubfiles
     ),
     r AS (
     SELECT realms.*
     FROM realms
     CROSS JOIN params
     WHERE idrealm=fn_idrealm
)
,u AS (
     SELECT *
     FROM PARAMS
     CROSS JOIN get_user(fn_iduser)
     WHERE NOT isgroup
     AND NOT istemplate
)
,allfiles AS (
     SELECT files.idfile --idfile devrait suffire
     FROM params
     CROSS JOIN (
         SELECT UNNEST(fn_idfile) as idfile FROM params
     ) AS unnestedfiles
     JOIN files ON files.idfile = unnestedfiles.idfile OR (
         -- see sub files
         fn_idrealm = files.idrealminitial
         AND
         fn_canseesubfiles
     )
     WHERE fn_idfile IS NOT NULL

     UNION

     SELECT files.idfile --idfile devrait suffire
     FROM files
     CROSS JOIN params
     WHERE fn_idfile IS NULL
     AND files.idrealm = fn_idrealm OR ( files.idrealminitial = 
fn_idrealm AND fn_canseesubfiles )
)
,internalvalidation as (
     SELECT i.*, users.name
     FROM allfiles pfu
     JOIN internalvalidations i ON i.idfile = pfu.idfile AND i.isvisible
     LEFT JOIN users ON users.iduser = i.idclaimer
)
,u_g_internalvalidation_without_u_status AS (
     SELECT uhi.idinternalvalidation
             ,uhi.iduser as idusergroup
             ,uhi.hasvalidate
             ,uhi.atleastonemustvalidate
             ,v.iduser
             ,v.isgroup
             , 0 level
     FROM internalvalidation
     JOIN users_has_internalvalidations uhi ON uhi.idinternalvalidation 
= internalvalidation.idinternalvalidation
     JOIN users v on uhi.iduser = v.iduser
     JOIN get_user(v.iduser) gu ON gu.iduser = v.iduser AND ( 
gu.canvalidate OR v.isgroup )

     UNION

     SELECT
         ugiwus.idinternalvalidation
         ,ugiwus.iduser as idusergroup
         ,ugiwus.hasvalidate
         ,ugiwus.atleastonemustvalidate
         ,gu.iduser
         ,gu.isgroup
         , ugiwus.level + 1
     FROM u_g_internalvalidation_without_u_status ugiwus
     JOIN users_has_groups uhg ON uhg.idgroup = ugiwus.idusergroup AND 
ugiwus.isgroup
     JOIN get_user(uhg.iduser) gu ON ( gu.canvalidate OR gu.isgroup )
     WHERE ugiwus.level < 25
)
--    SELECT * FROM u_g_internalvalidation_without_u_status;
,u_g_internalvalidation AS (
     SELECT ugi.idinternalvalidation, 
bool_or(COALESCE(ugi.hasvalidate,false)) currentuserhasvalidate--, 
bool_or( ugi.iduser = u.iduser ) /* à quoi sert ce champ ? */
     FROM u_g_internalvalidation_without_u_status ugi
--    CROSS JOIN u /* et donc à quoi sert cette table ? */
--    WHERE u.iduser = ugi.iduser
     GROUP BY ugi.idinternalvalidation
)
,regroup_users as (
     SELECT -- regroup users by group etc ...
         ug1.idinternalvalidation
         ,ug1.idusergroup
         ,BOOL_OR( COALESCE( ug2.hasvalidate, ug1.hasvalidate,false)) 
FILTER ( WHERE NOT ug1.isgroup OR ug2.isgroup ) AS atleastoneuserhasvalidate
         ,BOOL_AND( COALESCE( ug2.hasvalidate, ug1.hasvalidate,false)) 
FILTER ( WHERE NOT ug1.isgroup OR ug2.isgroup ) AS everyuserhasvalidate
         ,ARRAY_AGG( DISTINCT ug1.iduser) AS iduser
         ,ug1.atleastonemustvalidate
     FROM u_g_internalvalidation_without_u_status ug1
     LEFT JOIN u_g_internalvalidation_without_u_status ug2 ON 
ug2.idinternalvalidation = ug1.idinternalvalidation AND ug2.iduser = 
ug1.iduser AND ug2.hasvalidate IS NOT NULL
     GROUP BY 
ug1.idinternalvalidation,ug1.idusergroup,ug1.atleastonemustvalidate
)
,regroup_internvalvalidations AS (
     SELECT
         r.idinternalvalidation
         ,ARRAY_AGG(r.idusergroup) AS iduser
         ,ARRAY_AGG(users.name) AS name
         ,BOOL_OR(v.validate) AS atleastoneuserhasvalidate
         ,BOOL_AND(v.validate) AS everyusershasvalidate
     FROM regroup_users r
     LEFT JOIN users ON users.iduser = r.idusergroup
     CROSS JOIN LATERAL (
         SELECT CASE
             WHEN r.atleastonemustvalidate THEN r.atleastoneuserhasvalidate
             ELSE r.everyuserhasvalidate
         END AS validate
     ) AS v
     GROUP BY r.idinternalvalidation
)
SELECT
     ri.idinternalvalidation
     ,ri.iduser
     ,ri.name
     ,ri.atleastoneuserhasvalidate
     ,ri.everyusershasvalidate
     ,i.ttl
     ,i.idfile
     ,i.idclaimer
     ,i.name AS claimername
     ,CASE WHEN i.atleastonemustvalidate THEN 
ri.atleastoneuserhasvalidate ELSE ri.everyusershasvalidate END AS 
internalvalidationisdone
     ,CASE WHEN u.iduser IS NULL THEN NULL::BOOLEAN ELSE 
u_g_internalvalidation.currentuserhasvalidate END AS currentuserhasvalidate
FROM regroup_internvalvalidations ri
JOIN internalvalidation i ON i.idinternalvalidation = 
ri.idinternalvalidation
LEFT JOIN u_g_internalvalidation ON 
u_g_internalvalidation.idinternalvalidation = ri.idinternalvalidation
LEFT JOIN u ON u_g_internalvalidation.idinternalvalidation IS NOT NULL 
AND u.canvalidate