Rationalizing EXPLAIN VERBOSE output

Rationalizing EXPLAIN VERBOSE output

Post by Tom La » Mon, 11 Mar 2002 04:11:52



Now that Bruce has done some work on rationalizing elog() output, seems
like we ought to take another look at EXPLAIN VERBOSE.  Currently, that
command does this:

1. A non-pretty-printed plan dump (nodeToString output) is sent to
elog(INFO).  Formerly that always output to both postmaster log and
client, but now it'll typically go only to the client.

2. The short-form output (same as non-VERBOSE EXPLAIN) is sent to
elog(INFO).  See above.

3. The pretty-printed plan dump is sent to postmaster stdout.

Now postmaster stdout is just about the least good destination we
could possibly use.  It may well end up in the bit bucket (if someone is
only saving stderr output, and/or is using syslog logging instead of
stderr).  In any case it's not necessarily an easy place for the client
to get at.

Also, I find the non-pretty-printed dump format damn near unreadable,
although I have seen comments suggesting that there are some people who
actually like it.  I don't see the point of giving it pride of place on
the client's terminal.

What I would suggest is that EXPLAIN VERBOSE ought to emit either
non-pretty-print or pretty-print dump format, not both (probably control
this with debug_pretty_print or another newly-invented GUC parameter;
IMHO the factory default should be pretty-printing).  Furthermore, the
output should go to elog(INFO) in either case.  This will take some work
to make the prettyprinter capable of that, but it's not a big job.
(A side effect of this is that pprint dumps logged by the
debug_print_plan and so forth options could go through elog as well,
which they don't now.)

A disadvantage of elog(INFO) output for pretty-printed plans is that
AFAIK psql doesn't currently have any way of capturing NOTICE output
into a file.  I find it much better to look at pretty-printed dumps
in Emacs than on a terminal window, mainly because Emac's M-C-f and
M-C-b commands understand the nesting structure so it's easy to move
around in the dump with them.  How hard would it be to get psql to
send notice output into a \g file?

Comments?  In particular, should EXPLAIN use the existing
debug_pretty_print GUC variable, or have its own?

                        regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 6: Have you searched our list archives?

http://archives.postgresql.org

 
 
 

Rationalizing EXPLAIN VERBOSE output

Post by Bruce Momji » Mon, 11 Mar 2002 08:50:38



> Now that Bruce has done some work on rationalizing elog() output, seems
> like we ought to take another look at EXPLAIN VERBOSE.  Currently, that
> command does this:

Yes, the elog() tags finally match some reality.  :-)

Quote:> 1. A non-pretty-printed plan dump (nodeToString output) is sent to
> elog(INFO).  Formerly that always output to both postmaster log and
> client, but now it'll typically go only to the client.

> 2. The short-form output (same as non-VERBOSE EXPLAIN) is sent to
> elog(INFO).  See above.

> 3. The pretty-printed plan dump is sent to postmaster stdout.

> Now postmaster stdout is just about the least good destination we
> could possibly use.  It may well end up in the bit bucket (if someone is
> only saving stderr output, and/or is using syslog logging instead of
> stderr).  In any case it's not necessarily an easy place for the client
> to get at.

Seems EXPLAIN may need a level capability like DEBUG1-5 now.  We have
EXPLAIN and EXPLAIN VERBOSE.  Now have pretty print vs. "jumble" print,
which some people do actually prefer.  They must have better cognitive
skills than me.

We now also have the index clause printing that you mentioned.  Should
we go with some kind of numeric level to EXPLAIN that would control
this?

That is the only simple solution I can think of.  GUC seems way beyond
what someone would want.  Having SET control EXPLAIN just seems overkill
because EXPLAIN should be able to control itself.

Also, clearly, we need to fix the output of pretty print to honor ELOG
control, and in any other places we may have missed it.

How about?

        EXPLAIN select * from pg_class;
        EXPLAIN VERBOSE select * from pg_class;
        EXPLAIN VERBOSE 1 select * from pg_class;
        EXPLAIN VERBOSE 5 select * from pg_class;

Seems pretty clear.  VERBOSE takes an optional argument that controls
the level of detail.

--
  Bruce Momjian                        |  http://candle.pha.pa.us

  +  If your life is a hard drive,     |  830 Blythe Avenue
  +  Christ can be your backup.        |  Drexel Hill, Pennsylvania 19026

---------------------------(end of broadcast)---------------------------
TIP 5: Have you checked our extensive FAQ?

http://www.postgresql.org/users-lounge/docs/faq.html

 
 
 

Rationalizing EXPLAIN VERBOSE output

Post by Tom La » Tue, 12 Mar 2002 01:53:19



> How about?
>    EXPLAIN select * from pg_class;
>    EXPLAIN VERBOSE select * from pg_class;
>    EXPLAIN VERBOSE 1 select * from pg_class;
>    EXPLAIN VERBOSE 5 select * from pg_class;

Seems kinda ugly.  But maybe same idea with repeated VERBOSE,
a la some Unix commands ("more -v's get you more detail"):

        EXPLAIN [ANALYZE] [VERBOSE] [ VERBOSE ... ] statement;

I'd sugggest

EXPLAIN select * from pg_class;

        Default output: same as now

EXPLAIN VERBOSE select * from pg_class;

        Add prettyprinted qual clauses

EXPLAIN VERBOSE VERBOSE select * from pg_class;

        Add full plan-tree dump

and there's room for expansion if we need it.

There's still the question of how to format the plan-tree dump.
I still rather like a GUC variable for that choice, since it seems
to be a personal preference that's unlikely to change from one
command to the next.

                        regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 2: you can get off all lists at once with the unregister command

 
 
 

Rationalizing EXPLAIN VERBOSE output

Post by Peter Eisentra » Tue, 12 Mar 2002 11:22:25


Quote:Tom Lane writes:
> What I would suggest is that EXPLAIN VERBOSE ought to emit either
> non-pretty-print or pretty-print dump format, not both (probably control
> this with debug_pretty_print or another newly-invented GUC parameter;
> IMHO the factory default should be pretty-printing).

Sounds good.  I think we can reuse the parameter.

Quote:> A disadvantage of elog(INFO) output for pretty-printed plans is that
> AFAIK psql doesn't currently have any way of capturing NOTICE output
> into a file.  I find it much better to look at pretty-printed dumps
> in Emacs than on a terminal window, mainly because Emac's M-C-f and
> M-C-b commands understand the nesting structure so it's easy to move
> around in the dump with them.  How hard would it be to get psql to
> send notice output into a \g file?

\g (and \o) send only the query results to a file.  The idea is that you
want to save the results, but if there's a warning or error, you want to
see it.  We could add alternative commands (\G and \O?) that save the
notices and errors as well.  Not sure if this is useful beyond this
application.  In non-interactive situations you'd usually use shell
redirections to save all output.

--

---------------------------(end of broadcast)---------------------------
TIP 5: Have you checked our extensive FAQ?

http://www.postgresql.org/users-lounge/docs/faq.html

 
 
 

Rationalizing EXPLAIN VERBOSE output

Post by Tom La » Tue, 12 Mar 2002 11:29:43



> Tom Lane writes:
>> ... How hard would it be to get psql to
>> send notice output into a \g file?
> \g (and \o) send only the query results to a file.  The idea is that you
> want to save the results, but if there's a warning or error, you want to
> see it.  We could add alternative commands (\G and \O?) that save the
> notices and errors as well.  Not sure if this is useful beyond this
> application.  In non-interactive situations you'd usually use shell
> redirections to save all output.

The other possibility is to make EXPLAIN output look like a SELECT
result.  Not sure how hard this would be to do, but in the long run
I suppose that would be the direction to move in.

                        regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 3: if posting/reading through Usenet, please send an appropriate

message can get through to the mailing list cleanly

 
 
 

Rationalizing EXPLAIN VERBOSE output

Post by Bruce Momji » Tue, 12 Mar 2002 11:32:33



> Tom Lane writes:

> > What I would suggest is that EXPLAIN VERBOSE ought to emit either
> > non-pretty-print or pretty-print dump format, not both (probably control
> > this with debug_pretty_print or another newly-invented GUC parameter;
> > IMHO the factory default should be pretty-printing).

> Sounds good.  I think we can reuse the parameter.

Agreed.  I like parameter reuse.

Quote:> > A disadvantage of elog(INFO) output for pretty-printed plans is that
> > AFAIK psql doesn't currently have any way of capturing NOTICE output
> > into a file.  I find it much better to look at pretty-printed dumps
> > in Emacs than on a terminal window, mainly because Emac's M-C-f and
> > M-C-b commands understand the nesting structure so it's easy to move
> > around in the dump with them.  How hard would it be to get psql to
> > send notice output into a \g file?

> \g (and \o) send only the query results to a file.  The idea is that you
> want to save the results, but if there's a warning or error, you want to
> see it.  We could add alternative commands (\G and \O?) that save the
> notices and errors as well.  Not sure if this is useful beyond this
> application.  In non-interactive situations you'd usually use shell
> redirections to save all output.

Could we send notices to the \g, \o file and to the terminal, and send
normal output only to the file?  Seems that would make sense.

--
  Bruce Momjian                        |  http://candle.pha.pa.us

  +  If your life is a hard drive,     |  830 Blythe Avenue
  +  Christ can be your backup.        |  Drexel Hill, Pennsylvania 19026

---------------------------(end of broadcast)---------------------------
TIP 4: Don't 'kill -9' the postmaster

 
 
 

Rationalizing EXPLAIN VERBOSE output

Post by Bruce Momji » Tue, 12 Mar 2002 11:33:52




> > Tom Lane writes:
> >> ... How hard would it be to get psql to
> >> send notice output into a \g file?

> > \g (and \o) send only the query results to a file.  The idea is that you
> > want to save the results, but if there's a warning or error, you want to
> > see it.  We could add alternative commands (\G and \O?) that save the
> > notices and errors as well.  Not sure if this is useful beyond this
> > application.  In non-interactive situations you'd usually use shell
> > redirections to save all output.

> The other possibility is to make EXPLAIN output look like a SELECT
> result.  Not sure how hard this would be to do, but in the long run
> I suppose that would be the direction to move in.

Seems EXPLAIN as SELECT would break our elog() control of output to the
server logs.

--
  Bruce Momjian                        |  http://candle.pha.pa.us

  +  If your life is a hard drive,     |  830 Blythe Avenue
  +  Christ can be your backup.        |  Drexel Hill, Pennsylvania 19026

---------------------------(end of broadcast)---------------------------
TIP 5: Have you checked our extensive FAQ?

http://www.postgresql.org/users-lounge/docs/faq.html

 
 
 

Rationalizing EXPLAIN VERBOSE output

Post by Tom La » Tue, 12 Mar 2002 11:37:12



> Seems EXPLAIN as SELECT would break our elog() control of output to the
> server logs.

EXPLAIN as SELECT would mean that the server log is out of the picture
entirely, which is not necessarily a bad thing.  Is there a good reason
for logging EXPLAIN output?  I can't see one other than "we've always
done it that way".

                        regards, tom lane

---------------------------(end of broadcast)---------------------------

 
 
 

Rationalizing EXPLAIN VERBOSE output

Post by Bruce Momji » Tue, 12 Mar 2002 11:49:13




> > Seems EXPLAIN as SELECT would break our elog() control of output to the
> > server logs.

> EXPLAIN as SELECT would mean that the server log is out of the picture
> entirely, which is not necessarily a bad thing.  Is there a good reason
> for logging EXPLAIN output?  I can't see one other than "we've always
> done it that way".

I can't think of a good reason, but making it a select output makes
EXPLAIN one of the few things you can't get into the server logs, even
if you want to.  At DEBUG5, you get almost everything about a query.
Seems you may want to capture EXPLAIN in there too, but because we can
control those with print_* using various SET parameters, I guess it is
OK.

There are other INFO types that are sent to the client that can't be
captured in psql output, like VACUUM VERBOSE.  I guess I would rather
see NOTICES go to the \g/\o output file and to the terminal as a fix
that would solve the problem easily.

--
  Bruce Momjian                        |  http://candle.pha.pa.us

  +  If your life is a hard drive,     |  830 Blythe Avenue
  +  Christ can be your backup.        |  Drexel Hill, Pennsylvania 19026

---------------------------(end of broadcast)---------------------------
TIP 3: if posting/reading through Usenet, please send an appropriate

message can get through to the mailing list cleanly

 
 
 

Rationalizing EXPLAIN VERBOSE output

Post by Tom La » Tue, 12 Mar 2002 12:45:54



> I can't think of a good reason, but making it a select output makes
> EXPLAIN one of the few things you can't get into the server logs, even
> if you want to.  At DEBUG5, you get almost everything about a query.

... including the query plan dump, no?  I don't see the point here.

One reason in favor of SELECT-like output is that a lot of user
interfaces are not prepared for large NOTICE outputs.  (Even psql
isn't really, since it can't paginate NOTICE output.)

                        regards, tom lane

---------------------------(end of broadcast)---------------------------

 
 
 

Rationalizing EXPLAIN VERBOSE output

Post by Peter Eisentra » Tue, 12 Mar 2002 13:22:07


Quote:Tom Lane writes:
> The other possibility is to make EXPLAIN output look like a SELECT
> result.  Not sure how hard this would be to do, but in the long run
> I suppose that would be the direction to move in.

You could internally rewrite it to something like

select explain('select * from pg_class;');

--

---------------------------(end of broadcast)---------------------------
TIP 5: Have you checked our extensive FAQ?

http://www.postgresql.org/users-lounge/docs/faq.html

 
 
 

Rationalizing EXPLAIN VERBOSE output

Post by Bruce Momji » Tue, 12 Mar 2002 13:36:31




> > I can't think of a good reason, but making it a select output makes
> > EXPLAIN one of the few things you can't get into the server logs, even
> > if you want to.  At DEBUG5, you get almost everything about a query.

> ... including the query plan dump, no?  I don't see the point here.

> One reason in favor of SELECT-like output is that a lot of user
> interfaces are not prepared for large NOTICE outputs.  (Even psql
> isn't really, since it can't paginate NOTICE output.)

Pagination is a good point.  EXPLAIN is one of the few cases where the
output is clearly multi-line.  I am concerned that making explain like
SELECT means it is on the one piece of debug info you can't get into the
server logs.  Query dump can already get into the query logs, but not
EXPLAIN non-verbose.

In fact, as Peter explains it, NOTICE \g goes to the terminal because it
is assumed to be an error.  Maybe we need to make psql smarter and only
send ERROR/WARNING to terminal, and INFO/NOTICE to the log file.  With
new elog() levels, seems this is needed anyway.

--
  Bruce Momjian                        |  http://candle.pha.pa.us

  +  If your life is a hard drive,     |  830 Blythe Avenue
  +  Christ can be your backup.        |  Drexel Hill, Pennsylvania 19026

---------------------------(end of broadcast)---------------------------
TIP 6: Have you searched our list archives?

http://archives.postgresql.org

 
 
 

Rationalizing EXPLAIN VERBOSE output

Post by Peter Eisentra » Tue, 12 Mar 2002 13:43:35


Quote:Bruce Momjian writes:
> In fact, as Peter explains it, NOTICE \g goes to the terminal because it
> is assumed to be an error.  Maybe we need to make psql smarter and only
> send ERROR/WARNING to terminal, and INFO/NOTICE to the log file.  With
> new elog() levels, seems this is needed anyway.

INFO is just as irrelevant to the query results as WARNING is.

--

---------------------------(end of broadcast)---------------------------
TIP 4: Don't 'kill -9' the postmaster

 
 
 

Rationalizing EXPLAIN VERBOSE output

Post by Tom La » Tue, 12 Mar 2002 13:44:00



> ... I am concerned that making explain like
> SELECT means it is on the one piece of debug info you can't get into the
> server logs.  Query dump can already get into the query logs, but not
> EXPLAIN non-verbose.

A week ago you were willing to set things up so that INFO output could
not get into the server logs period.  Why so concerned now?  EXPLAIN
output does not seem like suitable data for logs to me, any more than
the output of SELECT queries does.  It's only a historical artifact
that we are accustomed to thinking of it as being loggable.

Quote:> In fact, as Peter explains it, NOTICE \g goes to the terminal because it
> is assumed to be an error.  Maybe we need to make psql smarter and only
> send ERROR/WARNING to terminal, and INFO/NOTICE to the log file.

While I suggested that to start with, it seems like a bad idea on
further thought.  Mixing INFO/NOTICE with query output would be just
like piping stdout and stderr to the same place.  There's usually
good reason to keep them separate.

                        regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 2: you can get off all lists at once with the unregister command

 
 
 

Rationalizing EXPLAIN VERBOSE output

Post by Bruce Momji » Tue, 12 Mar 2002 13:45:33




> > How about?

> >       EXPLAIN select * from pg_class;
> >       EXPLAIN VERBOSE select * from pg_class;
> >       EXPLAIN VERBOSE 1 select * from pg_class;
> >       EXPLAIN VERBOSE 5 select * from pg_class;

> Seems kinda ugly.  But maybe same idea with repeated VERBOSE,
> a la some Unix commands ("more -v's get you more detail"):

>    EXPLAIN [ANALYZE] [VERBOSE] [ VERBOSE ... ] statement;

> I'd sugggest

> EXPLAIN select * from pg_class;

>    Default output: same as now

> EXPLAIN VERBOSE select * from pg_class;

>    Add prettyprinted qual clauses

> EXPLAIN VERBOSE VERBOSE select * from pg_class;

>    Add full plan-tree dump

> and there's room for expansion if we need it.

I was never a fan of the -v -v more-verbose options, and I don't see any
case where we use such behavior in our code.  We do use detail levels
for debug, and that is fairly common.

How about:

Quote:> >       EXPLAIN select * from pg_class;
> >       EXPLAIN VERBOSE select * from pg_class;
> >       EXPLAIN LEVEL 1 select * from pg_class;
> >       EXPLAIN LEVEL 5 select * from pg_class;

Here I use LEVEL to tell how much detail you want.

--
  Bruce Momjian                        |  http://candle.pha.pa.us

  +  If your life is a hard drive,     |  830 Blythe Avenue
  +  Christ can be your backup.        |  Drexel Hill, Pennsylvania 19026

---------------------------(end of broadcast)---------------------------
TIP 5: Have you checked our extensive FAQ?

http://www.postgresql.org/users-lounge/docs/faq.html

 
 
 

1. output from EXPLAIN VERBOSE

I am writing an Emacs based navigation/editing tool. I would like to have the
backend parse a query, EXPLAIN VERBOSE it .... I want to know for every non
functional column the source (table/attribute). How to interpret the parse tree?

---------------------------(end of broadcast)---------------------------
TIP 6: Have you searched our list archives?

http://www.postgresql.org/search.mpl

2. Problems with Data grid

3. turning off verbose output of pl/sql?

4. Error 18204

5. Verbose output with VC++/ODBC or sqlnet?

6. SSD 97

7. History and Output Verbose Levels

8. SQL Enterprise install fails - MSDE already installed

9. Vacuum verbose output?

10. syslog output from explain looks weird...

11. Explain Output made Colorful

12. output of set explain ?

13. Explain Output made Colourful