Обсуждение: Reporting query duration

There is a TODO item:
* Allow logging of query durations

Currently there is no easy way to get a list of query durations in the
server log file.  My idea is to add query duration to the end of the
query string for 'debug_print_query'.  My only problem is that to print
the duration, I would have to print the query _after_ it is executed,
rather than before.  This may make it difficult to look at the server
logs to see what queries are running, plus if the query errors, I have
to still print it, I assume, though actually Gavin's new GUC option will
add printing of error queries, so I may be OK to just print the
successful ones.

I imagine this timing would be used by administrators to find out which
queries where slow.

Comments?

Also, looking at the GUC options:
#debug_print_query = false#debug_print_parse = false#debug_print_rewritten = false#debug_print_plan =
false#debug_pretty_print= false
 

I notice Peter is correct that debug_print_query really is a log_*
option, rather than a debug option.  The others are for server
debugging, while debug_print_query is more of a log queries option. 
Should we rename it and support both log_print_query and
debug_print_query for one release?

--  Bruce Momjian                        |  http://candle.pha.pa.us pgman@candle.pha.pa.us               |  (610)
359-1001+  If your life is a hard drive,     |  13 Roberts Road +  Christ can be your backup.        |  Newtown Square,
Pennsylvania19073
 

Bruce Momjian <pgman@candle.pha.pa.us> writes:
> There is a TODO item:
>     * Allow logging of query durations

> Currently there is no easy way to get a list of query durations in the
> server log file.  My idea is to add query duration to the end of the
> query string for 'debug_print_query'.  My only problem is that to print
> the duration, I would have to print the query _after_ it is executed,
> rather than before.

Well, that's what makes it a bad idea, eh?

I think the log entries should be separate: print the query text when
you start, print the duration when you're done.  A little bit of
postprocessing can reassemble the two entries.

> Should we rename it and support both log_print_query and
> debug_print_query for one release?

If we're gonna rename config variables, let's just rename them.
People don't try to pipe their old postgresql.conf files into psql,
so I don't think there's a really good argument for supporting old
variable names for a long time.
        regards, tom lane

Tom Lane wrote:
> Bruce Momjian <pgman@candle.pha.pa.us> writes:
> > There is a TODO item:
> >     * Allow logging of query durations
> 
> > Currently there is no easy way to get a list of query durations in the
> > server log file.  My idea is to add query duration to the end of the
> > query string for 'debug_print_query'.  My only problem is that to print
> > the duration, I would have to print the query _after_ it is executed,
> > rather than before.
> 
> Well, that's what makes it a bad idea, eh?
> 
> I think the log entries should be separate: print the query text when
> you start, print the duration when you're done.  A little bit of
> postprocessing can reassemble the two entries.

How would someone reassemble them?  You would have to have the pid, I
assume.  Do we auto-enable pid output when we enable duration?  Yuck.
Maybe print the pid just for the query and timing lines if pid print
isn't enabled?

I would think printing it out together at the end would work.  We
already have several ways to see running queries.

--  Bruce Momjian                        |  http://candle.pha.pa.us pgman@candle.pha.pa.us               |  (610)
359-1001+  If your life is a hard drive,     |  13 Roberts Road +  Christ can be your backup.        |  Newtown Square,
Pennsylvania19073
 

Bruce Momjian <pgman@candle.pha.pa.us> writes:
>> I think the log entries should be separate: print the query text when
>> you start, print the duration when you're done.  A little bit of
>> postprocessing can reassemble the two entries.

> How would someone reassemble them?  You would have to have the pid, I
> assume.

Sure.

> Do we auto-enable pid output when we enable duration?  Yuck.

No, you expect the user to select the options he needs.  Let's not
over-engineer a perfectly simple feature.
        regards, tom lane

Tom Lane wrote:
> Bruce Momjian <pgman@candle.pha.pa.us> writes:
> >> I think the log entries should be separate: print the query text when
> >> you start, print the duration when you're done.  A little bit of
> >> postprocessing can reassemble the two entries.
> 
> > How would someone reassemble them?  You would have to have the pid, I
> > assume.
> 
> Sure.
> 
> > Do we auto-enable pid output when we enable duration?  Yuck.
> 
> No, you expect the user to select the options he needs.  Let's not
> over-engineer a perfectly simple feature.

OK, so I will rename debug_print_query to log_print_query, and Gavin's
new print query on error will also be a log_*.

I will add a new GUC variable to print the query duration, and recommend
in the docs that log_pid be enabled at the same time so you can match
the duration with the query.

Originally, I wanted to make the time just print whenever you enabled
print_query, but with them on separate lines, it should be a separate
GUC variable.

--  Bruce Momjian                        |  http://candle.pha.pa.us pgman@candle.pha.pa.us               |  (610)
359-1001+  If your life is a hard drive,     |  13 Roberts Road +  Christ can be your backup.        |  Newtown Square,
Pennsylvania19073