Test patch for timing EXPLAIN - Mailing list pgsql-general

From Martijn van Oosterhout
Subject Test patch for timing EXPLAIN
Date
Msg-id 20010720000101.B2213@svana.org
Whole thread Raw
List pgsql-general
Hi,

Here is a snapshot of the code I'm fiddling with at the moment which
actually tracks how much time is spent executing which parts of the query
plan. It still has some issues but it has restored my faith in Postgres'
estimation system. It's within an order of magnitude in the tests I've done
and that much better than before.

Before anyone complains that it uglifies explain.c, I know. I just havn't
decided if it's query that happens to output statistics, an explain that
happens to run the query or something new altogether.

It's against latest CVS. I'm pretty sure it handles query interleaving fine.

Things known to be wrong:
* Certain types of nodes seem to go wrong. Group is miscounted and one node
got skipped completely.

It does seem to count the number of rows processed correctly, which is
possibly the most important. All times are in milliseconds.

Example output (wide):

Aggregate  (cost=51479.55..51507.07 rows=550 width=48) actual (time=25278.68..26080.44 rows=156 loops=1)
  ->  Group  (cost=51479.55..51493.31 rows=5503 width=48) actual (time=25278.64..25278.65 rows=2 loops=1)
        ->  Sort  (cost=51479.55..51479.55 rows=5503 width=48) actual (time=25278.62..25281.77 rows=2029 loops=1)
              ->  Hash Join  (cost=676.79..51137.62 rows=5503 width=48) actual (time=3618.79..25259.53 rows=2029
loops=1)
                    ->  Seq Scan on dailycalls  (cost=0.00..50150.07 rows=32262 width=12) actual (time=61.91..24831.90
rows=41045loops=1) 
                    ->  Hash  (cost=671.31..671.31 rows=2193 width=36) actual (time=146.56..146.56 rows=0 loops=1)
                          ->  Merge Join  (cost=260.50..671.31 rows=2193 width=36) actual (time=37.37..131.11 rows=1330
loops=1)
                                ->  Index Scan using clines_cid on clines  (cost=0.00..364.36 rows=6308 width=20)
                                ->  Sort  (cost=260.50..260.50 rows=1305 width=16) actual (time=36.91..38.40 rows=1337
loops=1)
                                      ->  Seq Scan on company  (cost=0.00..192.94 rows=1305 width=16) actual
(time=0.10..22.70rows=1314 loops=1) 

I'm still getting a lot of debug messages so there is still some work to do.
Any comments?

(Oops, just thought of one issue: Merge Join will not exhaust it's subnodes
because it can stop early).

http://svana.org/kleptog/pgsql/timing-explain.patch
--
Martijn van Oosterhout <kleptog@svana.org>
http://svana.org/kleptog/
> It would be nice if someone came up with a certification system that
> actually separated those who can barely regurgitate what they crammed over
> the last few weeks from those who command secret ninja networking powers.

pgsql-general by date:

Previous
From: Tony Grant
Date:
Subject: Re: rot13.org and Dobrica Pavlinusic - ???
Next
From: wsheldah@lexmark.com
Date:
Subject: Re: Re: PG rules! (RULES being the word ;->)