Re: Auto-explain patch

> On Mon, 2008-01-28 at 09:21 +0000, Dean Rasheed wrote:
>> This is the patch allows logging of the explain plan for each query run, as described here:
>>
>> http://archives.postgresql.org/pgsql-performance/2008-01/msg00245.php
>>
>> I hope this is useful.
>
> This looks very good, though I don't think its finished yet.
>

Thanks for your comments. They all sound like fair points, but I have
a few questions - I am still pretty new to postgresql and this is the
first time I have looked at the source code, so I may not have fully
understood everything you said.

> We definitely don't want "----------- query plan ---------------" to be
> logged each time we execute each SQL statement. I think we should put
> the EXPLAIN output as the main message, not as additional detail.
>

OK, that's easy to change. I based the message/detail formatting on
the way debug_print_plan produces its output.

> I also think we should only log the EXPLAIN if we have logged the SQL
> statement. It's not much use on its own anyway. This then allows this
> feature to work neatly with log_statement and
> log_min_duration_statement.
>

Wouldn't that mean that only superusers could use it?

Even without logging of the SQL statement, I have found it quite
useful in practice for debugging SQL executed from stored procedures,
where the logged CONTEXT is good enough to identify the SQL being
exectued. Also, from an interactive session logging of the original
SQL doesn't matter so much.

> We need this to work effectively when using v3 protocol prepared
> queries. Since we only plan a query once, printing an EXPLAIN for all
> executions is probably too much information for tuning smaller queries.
>
> So I suggest we call this "log_explain" with settings {off | plan |
> execute}, default off. For simple non-prepared queries plan and execute
> work identically: If log_min_duration_statement> -1 or we are logging
> the statement with log_statement then we will instrument each statement
> to allow us to produce EXPLAIN ANALYZE output if the statement is
> logged. If it is set to "plan" then it will print out the EXPLAIN only
> when the query is planned (on first bind, when replanned etc), so it is
> an EXPLAIN not an EXPLAIN ANALYZE. In this mode it will *not* instrument
> each execution, nor will it print the plan in those cases.
>

I originally anticipated 2 use-cases:

1). A normal user from an interactive session, debugging individual
SQL statements and SQL embedded in stored procudures/triggers.

2). An administrator checking database access (eg. from a web app),
looking for inefficient queries.

I guess that what I have so far is more suited to (1), which is mostly
what I have been using it for (debug output not going to the log file).
I originally thought of doing this as an extra option to EXPLAIN, such
as EXAPLAIN [ANALYSE] ALL, but I thought that it would be easier to
use (and implement) as a settable parameter, mirroring Oracle's
AUTOTRACE.

For (2) I agree that it really needs a way to control the verbosity of
the output, as you suggested. And I guess that this ought to go to
level LOG rather than DEBUG1, to be consistent with the other logging
parameters.

This suggests having 2 separate parameters, one for debugging and one
for logging.

> If that last paragraph sounds too much, perhaps we should just go for on
> | off for the next version of the patch.
>

When you describe logging plans for logged statements only, are you
thinking of just explaining the top-level statement, or would this
include nested statements as well? Perhaps the latter is a 4th,
extra-verbose option "log_explain=all", which would produce EXPLAIN
ANALYSE output for each logged statement, and recursively for each
statement resulting from that top-level statement.

Dean

_________________________________________________________________
The next generation of Windows Live is here
http://www.windowslive.co.uk/get-live