Thread: 8.0.0beta3 duration logging patch

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

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
Index: doc/src/sgml/runtime.sgml
===================================================================
RCS file: /cvsroot/pgsql/doc/src/sgml/runtime.sgml,v
retrieving revision 1.287
diff -c -c -r1.287 runtime.sgml
*** doc/src/sgml/runtime.sgml    9 Oct 2004 23:12:53 -0000    1.287
--- doc/src/sgml/runtime.sgml    15 Oct 2004 16:47:40 -0000
***************
*** 2355,2367 ****
        <term><varname>log_duration</varname> (<type>boolean</type>)</term>
        <listitem>
         <para>
!         Causes the duration of every completed statement to be logged.
!         To use this option, it is recommended that you also enable
!         <varname>log_statement</> and if not using <application>syslog</>
!         log the PID using <varname>log_line_prefix</> so that you
!         can link the statement to the duration using the process
!         ID. The default is off.  Only superusers can turn off this
!         option if it is enabled by the administrator.
         </para>
        </listitem>
       </varlistentry>
--- 2355,2368 ----
        <term><varname>log_duration</varname> (<type>boolean</type>)</term>
        <listitem>
         <para>
!         Causes the duration of every completed statement which satisfies
!         <varname>log_statement</> to be logged.  When using this option,
!         if you are not using <application>syslog</>, it is recommended
!         that you log the PID or session ID using <varname>log_line_prefix</>
!         or log the session ID so that you can link the statement to the
!         duration using the process ID or session ID. The default is off.
!         Only superusers can turn off this option if it is enabled by the
!         administrator.
         </para>
        </listitem>
       </varlistentry>
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/tcop/postgres.c,v
retrieving revision 1.435
diff -c -c -r1.435 postgres.c
*** src/backend/tcop/postgres.c    12 Oct 2004 21:54:40 -0000    1.435
--- src/backend/tcop/postgres.c    15 Oct 2004 16:47:52 -0000
***************
*** 81,86 ****
--- 81,89 ----

  LogStmtLevel log_statement = LOGSTMT_NONE;

+ /* flag indicating if the statement satisfies log_statement */
+ bool        statement_logged;
+
  /* GUC variable for maximum stack depth (measured in kilobytes) */
  int            max_stack_depth = 2048;

***************
*** 463,471 ****
--- 466,478 ----
      List       *raw_parsetree_list;
      ListCell   *parsetree_item;

+     statement_logged = false;
      if (log_statement == LOGSTMT_ALL)
+     {
          ereport(LOG,
                  (errmsg("statement: %s", query_string)));
+         statement_logged = true;
+     }

      if (log_parser_stats)
          ResetUsage();
***************
*** 501,506 ****
--- 508,514 ----
              {
                  ereport(LOG,
                          (errmsg("statement: %s", query_string)));
+                 statement_logged = true;
                  break;
              }
              commandTag = CreateCommandTag(parsetree);
***************
*** 512,517 ****
--- 520,526 ----
              {
                  ereport(LOG,
                          (errmsg("statement: %s", query_string)));
+                 statement_logged = true;
                  break;
              }
          }
***************
*** 1003,1009 ****
          }
          usecs = (long) (stop_t.tv_sec - start_t.tv_sec) * 1000000 + (long) (stop_t.tv_usec - start_t.tv_usec);

!         if (save_log_duration)
              ereport(LOG,
                      (errmsg("duration: %ld.%03ld ms",
                          (long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
--- 1012,1019 ----
          }
          usecs = (long) (stop_t.tv_sec - start_t.tv_sec) * 1000000 + (long) (stop_t.tv_usec - start_t.tv_usec);

!         /* Only print duration if we previously printed the statement. */
!         if (statement_logged && save_log_duration)
              ereport(LOG,
                      (errmsg("duration: %ld.%03ld ms",
                          (long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +