Обсуждение: 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=1loops=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=1loops=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=1loops=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/

On 6/30/08, Dean Rasheed <dean_rasheed@hotmail.com> wrote:
>  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.

+1 for including it in whatever form.  It is useful.

We actually already use in live settings (8.2 / 8,3).

>  (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.

I don't have strong opinion either way,  It seems its more question
on style than any technical details.  Just that plain EXPLAN MORE is
not enough, it would bo good have a way to turn it on in global/session
level for all queries.

-- 
marko

On Mon, Jun 30, 2008 at 6:34 AM, Dean Rasheed <dean_rasheed@hotmail.com> wrote:
>
> 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.

<snip>

> 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?

Its certainly not useful to *me* in its current form.  It would
produce way to much (usless) output.  However if it were tied to
log_min_duration_statement so I get auto explains for long running
queries... That would be very useful indeed.  Even if it has to
explain everything just to toss out the explain if it did not meet
log_min_duration_statement.  Unless I missed something and thats
exactly what it does?

> Its certainly not useful to *me* in its current form. It would
> produce way to much (usless) output. However if it were tied to
> log_min_duration_statement so I get auto explains for long running
> queries... That would be very useful indeed. Even if it has to
> explain everything just to toss out the explain if it did not meet
> log_min_duration_statement. Unless I missed something and thats
> exactly what it does?

Thanks for the feedback. I agree, it does need a way to limit the
output, and target just the slow-running queries.

I also remember now the problem I had last time:- since this debug
output is produced at a lower level than the other statement logging
(so it can explain *all* SQL executed, not just top-level statements), it
is difficult to control using the normal statement logging parameters.

It would be easy to add another parameter, debug_explain_min_duration,
specific to this option, to limit it to slow low-level queries.

This would allow setting debug_explain_min_duration to be smaller than
log_min_duration_statement, which makes sense, since the latter
controls logging of top-level statements which may result in multiple
low-level queries.

Doing it this way would mean instrumenting all queries, but only
explaining the slow ones, when debug_explain_plan is on.
I'll have a play and see how it goes...

Regards, Dean

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