Re: 8.0.0beta3 duration logging patch - Mailing list pgsql-patches

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 +