8.0.0beta3 duration logging patch

Ed L. wrote:

The attached patch forces queryless duration log statements to be turned off
in step with the log_statement directive. Without this patch, and with
log_statement = 'mod' and log_duration = true, there is no way to silence
SELECT query duration logging when quieting the logging of SELECT queries.

Note this patch changes the semantics of log_duration from logging the
duration of "every completed statement" to "every completed statement that
satisfies log_statement directive". I argue this semantic change is
justified given 1) the docs themselves recommend turning log_statement
sufficiently up to be able to make this mapping, and 2) I can see it being
quite common that folks only want to log queries (and durations) that
change the database, while I fail to see the usefulness of queryless
durations (and I'm trying to scratch my own itch with a small effort).
It's possible someone else feels strongly about their queryless durations
for reasons I cannot imagine. If so, then another more conservative
approach may be in order.

Note also this patch is independent of queries and durations logged due to
the log_min_duration_statement directive. If, for example, log_statement =
'all', log_min_duration_statement = 1 (ms), and a SELECT query takes longer
than 1ms, it's duration will be logged twice, with the 2nd log entry
including the statement with the duration.

Let me tell you how log_duration used to work. You would turn on
log_pid, log_statement, and log_duration, and you would use pid to link
together the query and the duration. That was kind of hard so we added
log_min_duration_statement that when set to zero prints all statements
and their durations, but it does it _after_ the query has run. Now that
log_statement is not a boolean but rather has four possible values, it
isn't as clear that you turn on log_statement and log_duration at the
same time and have them synchronized.

Your issue brings up that the boolean API doesn't really work well, and
in fact highlights the fact that printing the duration as an independent
capability really made no sense at all. Perhaps your approach is the
proper solution --- to link them together.

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

Bruce Momjian <pgman@candle.pha.pa.us> writes:

Your issue brings up that the boolean API doesn't really work well, and
in fact highlights the fact that printing the duration as an independent
capability really made no sense at all. Perhaps your approach is the
proper solution --- to link them together.

I thought we had fixed things so that log_duration would print the
statement if it hadn't already been logged for other reasons. Did
that fix get broken again?

regards, tom lane

On Tuesday September 28 2004 7:59, Tom Lane wrote:

Bruce Momjian <pgman@candle.pha.pa.us> writes:

Your issue brings up that the boolean API doesn't really work well, and
in fact highlights the fact that printing the duration as an
independent capability really made no sense at all. Perhaps your
approach is the proper solution --- to link them together.

I thought we had fixed things so that log_duration would print the
statement if it hadn't already been logged for other reasons. Did
that fix get broken again?

I guess so. If you set log_min_statement_duration = 0, you get

"duration: %ld.%03ld ms statement: %s"

regardless of your log_duration or log_statement settings. But log_duration
does not heed log_statement, thus no way to quiet durations in sync with
log_statement setting. In beta3, the logic is...

if ( log_duration = true ||
(log_min_statement_duration = 0 ||
(log_min_statement_duration > 0 &&
duration > log_min_statement_duration)))

Going back to the issue of usefulness of queryless durations, I guess I can
imagine that if someone wanted to measure average duration similar to a
speedometer, they might want to log only durations, not queries, just to
know how hot the DB is running. I have a 7.3 perl script to do just that.
Maybe a better patch would be to make log_duration have the same options as
log_statement (none, mod, ddl, all)? That would preserve the previous
functionality and enable the more common usage as well. I would leave
log_min_statement_duration alone since I can see where it would be useful
to be able to visually distinguish between durations printed because they
exceeded log_min_statement_duration. For example, logging all
data-changing queries (mod) and also any overly slow SELECTs.

Ed

Patch applied. Thanks.

I made some small wording adjustments. Patch attached.

---------------------------------------------------------------------------

Ed L. wrote:

The attached patch forces queryless duration log statements to be turned off
in step with the log_statement directive. Without this patch, and with
log_statement = 'mod' and log_duration = true, there is no way to silence
SELECT query duration logging when quieting the logging of SELECT queries.

Note this patch changes the semantics of log_duration from logging the
duration of "every completed statement" to "every completed statement that
satisfies log_statement directive". I argue this semantic change is
justified given 1) the docs themselves recommend turning log_statement
sufficiently up to be able to make this mapping, and 2) I can see it being
quite common that folks only want to log queries (and durations) that
change the database, while I fail to see the usefulness of queryless
durations (and I'm trying to scratch my own itch with a small effort).
It's possible someone else feels strongly about their queryless durations
for reasons I cannot imagine. If so, then another more conservative
approach may be in order.

Note also this patch is independent of queries and durations logged due to
the log_min_duration_statement directive. If, for example, log_statement =
'all', log_min_duration_statement = 1 (ms), and a SELECT query takes longer
than 1ms, it's duration will be logged twice, with the 2nd log entry
including the statement with the duration.

Ed

[ Attachment, skipping... ]

---------------------------(end of broadcast)---------------------------
TIP 7: don't forget to increase your free space map settings

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