Reporting query duration

Started by Bruce Momjianover 23 years ago5 messageshackers

bruce@momjian.us

over 23 years ago

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, Pennsylvania 19073

Tom Lane

tgl@sss.pgh.pa.us

over 23 years ago

In reply to: Bruce Momjian (#1)

Re: Reporting query duration

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

Bruce Momjian

bruce@momjian.us

over 23 years ago

In reply to: Tom Lane (#2)

Re: Reporting query duration

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, Pennsylvania 19073

Tom Lane

tgl@sss.pgh.pa.us

over 23 years ago

In reply to: Bruce Momjian (#3)

Re: Reporting query duration

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

Bruce Momjian

bruce@momjian.us

over 23 years ago

In reply to: Tom Lane (#4)

Re: Reporting query duration

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, Pennsylvania 19073