Re: Auto-explain patch

Hi,

This is a small patch I posted a few months back, and then kinda forgot
about / got distracted with other things.

Is there any interest in this? If so I am willing to put more work into
it, if people like it or have suggested improvements. Otherwise I'll let it
drop.

Here's what is does:

As it stands, basically it's just another debug parameter, called
debug_explain_plan, similar to debug_print_plan, except that the
output is in the form of EXPLAIN ANALYSE.

The main advantage it offers over a standard EXPLAIN ANALYSE is that
it explains *all* SQL executed, including any from within stored
prodecures and triggers, so it is quite useful for debugging these.

With a suitable logging level, it can also be used to produce very
verbose logfile output to help spot any inefficient database access by
other applications.

Example usage:

test=# SET debug_explain_plan=on;
SET
test=# SET client_min_messages=debug1;
SET
test=# CREATE TABLE foo(a int primary key);
NOTICE: CREATE TABLE / PRIMARY KEY will create implicit index "foo_pkey" for table "foo"
CREATE TABLE
test=# INSERT INTO foo VALUES (1), (2), (3), (4), (5);
DEBUG: ------------------- query plan -------------------
DETAIL: Values Scan on "*VALUES*" (cost=0.00..0.06 rows=5 width=4) (actual time=0.001..0.006 rows=5 loops=1)
Query runtime: 0.329 ms
INSERT 0 5
test=# CREATE FUNCTION foo() RETURNS int as 'select max(a) from foo;' LANGUAGE SQL STABLE;
CREATE FUNCTION
test=# SELECT * FROM foo WHERE a=foo();
DEBUG: ------------------- query plan -------------------
DETAIL: Result (cost=0.04..0.05 rows=1 width=0) (actual time=0.044..0.044 rows=1 loops=1)
InitPlan
-> Limit (cost=0.00..0.04 rows=1 width=4) (actual time=0.032..0.034 rows=1 loops=1)
-> Index Scan Backward using foo_pkey on foo (cost=0.00..84.25 rows=2400 width=4) (actual time=0.025..0.025 rows=1 loops=1)
Filter: (a IS NOT NULL)
Query runtime: 0.050 ms
CONTEXT: SQL function "foo" statement 1
DEBUG: ------------------- query plan -------------------
DETAIL: Result (cost=0.04..0.05 rows=1 width=0) (actual time=0.037..0.037 rows=1 loops=1)
InitPlan
-> Limit (cost=0.00..0.04 rows=1 width=4) (actual time=0.027..0.029 rows=1 loops=1)
-> Index Scan Backward using foo_pkey on foo (cost=0.00..84.25 rows=2400 width=4) (actual time=0.021..0.021 rows=1 loops=1)
Filter: (a IS NOT NULL)
Query runtime: 0.044 ms
CONTEXT: SQL function "foo" statement 1
DEBUG: ------------------- query plan -------------------
DETAIL: Index Scan using foo_pkey on foo (cost=0.25..8.52 rows=1 width=4) (actual time=1.638..1.642 rows=1 loops=1)
Index Cond: (a = foo())
Query runtime: 1.686 ms
a
---
5
(1 row)

test=# EXPLAIN SELECT * FROM foo WHERE a=foo();
DEBUG: ------------------- query plan -------------------
DETAIL: Result (cost=0.04..0.05 rows=1 width=0) (actual time=0.012..0.012 rows=1 loops=1)
InitPlan
-> Limit (cost=0.00..0.04 rows=1 width=4) (actual time=0.011..0.011 rows=1 loops=1)
-> Index Scan Backward using foo_pkey on foo (cost=0.00..84.25 rows=2400 width=4) (actual time=0.010..0.010 rows=1 loops=1)
Filter: (a IS NOT NULL)
Query runtime: 0.014 ms
CONTEXT: SQL function "foo" statement 1
QUERY PLAN
--------------------------------------------------------------------
Index Scan using foo_pkey on foo (cost=0.25..8.52 rows=1 width=4)
Index Cond: (a = foo())
(2 rows)

(The last example shows foo() being called during the planning of this
query, which explains why it is called twice during the previous execution)

Simon Riggs reviewed this last time and said that what this patch
currently does is probably not exactly what is wanted for PostgreSQL.
Possible improvements might be to integrate this with the EXPLAIN
command (eg. EXPLAIN TRACE query) and have a separate parameter
(log_explain) for logging purposes.

Comments?

Regards, Dean

_________________________________________________________________
Live Search Charades - guess correctly and find hidden videos
http://www.searchcharades.com/