Test patch for timing EXPLAIN

From: Martijn van Oosterhout <kleptog(at)svana(dot)org>
To: Postgresql General <pgsql-general(at)postgresql(dot)org>
Subject: Test patch for timing EXPLAIN
Date: 2001-07-19 14:01:01
Message-ID: 20010720000101.B2213@svana.org
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: 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=41045 loops=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.70 rows=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(at)svana(dot)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.

Browse pgsql-general by date

  From Date Subject
Next Message Karel Zak 2001-07-19 14:06:11 ANNOUNCE: Mape, release 0.1
Previous Message wsheldah 2001-07-19 14:00:55 Re: Re: PG rules! (RULES being the word ;->)