Re: I don't understand that EXPLAIN PLAN timings

Hello,

No answer to my previous email, here is a simpler query with the same
problem: explain says actual time between 1.093→1.388 but final
execution time says 132.880ms?!?

Thanks for your help,

explain analyze
       WITH RECURSIVE u AS (
               SELECT idrealm, canseesubrealm
               FROM get_user(256)
       )
       ,realm_list as (
               -- get the tree view of all visible realms by the user
               SELECT u.idrealm, 0 AS level
               FROM u

               UNION

               SELECT realms.idrealm, rl.level+1
               FROM realms
               JOIN realm_list rl ON rl.idrealm = realms.idrealmparent
               CROSS JOIN u
               WHERE u.canseesubrealm
               AND rl.level < 20
       )
       SELECT
               r.idrealm
               ,r.idrealmparent
               ,r.name
               ,r.istemplate
               ,r.mustvalidate
               ,r.filesdirectory
               ,r.dbname
               ,r.iconrealm
               ,r.dbhost
               ,r.email
               ,r.urlrealm
               ,r.dbport
               ,r.dbpassword
               ,r.dbloginname
               ,r.dbowner
               ,rl.level
               ,r.pricetag
       FROM realm_list rl
       JOIN realms r ON r.idrealm=rl.idrealm;
                                                                       QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------

Hash Join  (cost=520303.68..854752.18 rows=13123940 width=258) (actual
time=1.093..1.388 rows=167 loops=1)
  Hash Cond: (rl.idrealm = r.idrealm)
  CTE u
    ->  Function Scan on get_user  (cost=0.25..10.25 rows=1000 width=5)
(actual time=0.996..0.997 rows=1 loops=1)
  CTE realm_list
    ->  Recursive Union  (cost=0.00..520273.42 rows=14746000 width=8)
(actual time=1.000..1.228 rows=167 loops=1)
          ->  CTE Scan on u  (cost=0.00..20.00 rows=1000 width=8)
(actual time=0.998..0.999 rows=1 loops=1)
          ->  Nested Loop  (cost=266.66..22533.34 rows=1474500 width=8)
(actual time=0.014..0.038 rows=42 loops=4)
                ->  CTE Scan on u u_1  (cost=0.00..20.00 rows=500
width=0) (actual time=0.000..0.001 rows=1 loops=4)
                      Filter: canseesubrealm
                ->  Materialize  (cost=266.66..403.22 rows=2949
width=8) (actual time=0.012..0.034 rows=42 loops=4)
                      ->  Hash Join  (cost=266.66..388.47 rows=2949
width=8) (actual time=0.012..0.026 rows=42 loops=4)
                            Hash Cond: (realms.idrealmparent =
rl_1.idrealm)
                            ->  Seq Scan on realms  (cost=0.00..17.78
rows=178 width=8) (actual time=0.000..0.009 rows=167 loops=4)
                            ->  Hash  (cost=225.00..225.00 rows=3333
width=8) (actual time=0.006..0.006 rows=42 loops=4)
                                  Buckets: 4096  Batches: 1  Memory
Usage: 38kB
                                  ->  WorkTable Scan on realm_list rl_1
 (cost=0.00..225.00 rows=3333 width=8) (actual time=0.000..0.003
rows=42 loops=4)
                                        Filter: (level < 20)
  ->  CTE Scan on realm_list rl  (cost=0.00..294920.00 rows=14746000
width=8) (actual time=1.001..1.254 rows=167 loops=1)
  ->  Hash  (cost=17.78..17.78 rows=178 width=254) (actual
time=0.085..0.085 rows=167 loops=1)
        Buckets: 1024  Batches: 1  Memory Usage: 30kB
        ->  Seq Scan on realms r  (cost=0.00..17.78 rows=178 width=254)
(actual time=0.006..0.043 rows=167 loops=1)
Planning Time: 0.457 ms
Execution Time: 132.880 ms
(24 lignes)

Temps : 134,292 ms

# select version();
                                                           version
-------------------------------------------------------------------------------------------------------------------------------

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