Re: fix log_min_duration_statement logic error - Mailing list pgsql-patches

Tom Lane wrote:
> Bruce Momjian <pgman@candle.pha.pa.us> writes:
> > Are those lines sent to the elog as one write() or separate ones --- do
> > they always appear together in the log?
>
> Currently they are sent in a single fprintf(stderr), which might or
> might not be good enough to ensure atomicity.  We could hack this
> to a direct write() if you don't mind depending on fileno(stderr),
> but I think that'd create some portability issues on non-Unix
> platforms.
>
> If you're using syslog then I think all bets are off anyway.
>
> > I had a new idea on output format.  Instead of converting newline to
> > "\n", and double-escaping backslashes, we add a tab after any newline,
>
> That's a thought... seems less invasive than the backslashing.  Not sure
> how well it'll work for syslog output though.

OK, new version attached that puts a tab before any elog continuation
line in the server logs.  This will give us consistent multi-line server
log output.  It does not affect the client output, which I think is
correct.

Output looks like:

LOG:  duration: 4.138 ms  query: select *
        from pg_language;
LOG:  duration: 7.560 ms  query: select * from pg_class;

Now, this does not address Tom's objection that you have can't use grep
anyway to pull lines from the server logs, but it is closer to usable
for scripts, and easier for people to read in the file.

The problem with doing statement and duration on separate lines is this:

LOG:  duration: 4.138 ms
LOG:  query: select *
        from pg_language;
LOG:  duration: 7.560 ms
LOG:  query: select * from pg_class;

It isn't clear which duration goes with which line, even if they don't
intermingle.  If you output on separate lines, you would have to use
log_pid.  However, since people can use log_duration and log_statement
separately already anyway, I think this merged line is easier for casual
users.

--
  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-server/doc/src/sgml/runtime.sgml,v
retrieving revision 1.210
diff -c -c -r1.210 runtime.sgml
*** doc/src/sgml/runtime.sgml    3 Oct 2003 19:26:49 -0000    1.210
--- doc/src/sgml/runtime.sgml    6 Oct 2003 21:33:06 -0000
***************
*** 1689,1704 ****
         <listitem>
          <para>
           Sets a minimum statement execution time (in milliseconds)
!          above which a statement will be logged.  All SQL statements
!          that run longer than the time specified will be logged together
!          with their actual duration.  Setting this to zero (the default)
!      disables time-based logging.  For example, if you set it
!          to <literal>250</literal> then all SQL statements that run longer
!          than 250ms will be logged.  Enabling this
!          option can be useful in tracking down unoptimized queries in
!          your applications.
!          Only superusers can increase this or set it to zero if this option
!          is set to non-zero by the administrator.
          </para>
         </listitem>
        </varlistentry>
--- 1689,1704 ----
         <listitem>
          <para>
           Sets a minimum statement execution time (in milliseconds)
!          for statement to be logged.  All SQL statements
!          that run in the time specified or longer will be logged with
!          their duration.  Setting this to zero will print
!          all queries and their durations.  Minus-one (the default)
!          disables this.  For example, if you set it to
!          <literal>250</literal> then all SQL statements that run 250ms
!          or longer will be logged.  Enabling this option can be
!          useful in tracking down unoptimized queries in your applications.
!          Only superusers can increase this or set it to minus-one if this
!          option is set by the administrator.
          </para>
         </listitem>
        </varlistentry>
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql-server/src/backend/tcop/postgres.c,v
retrieving revision 1.370
diff -c -c -r1.370 postgres.c
*** src/backend/tcop/postgres.c    4 Oct 2003 02:47:04 -0000    1.370
--- src/backend/tcop/postgres.c    6 Oct 2003 21:33:11 -0000
***************
*** 694,700 ****
       * because gettimeofday() wasn't called. Similarly,
       * log_statement_stats has to be captured once.
       */
!     if (save_log_duration || save_log_min_duration_statement > 0)
          gettimeofday(&start_t, NULL);

      if (save_log_statement_stats)
--- 694,700 ----
       * because gettimeofday() wasn't called. Similarly,
       * log_statement_stats has to be captured once.
       */
!     if (save_log_duration || save_log_min_duration_statement != -1)
          gettimeofday(&start_t, NULL);

      if (save_log_statement_stats)
***************
*** 940,946 ****
       * Combine processing here as we need to calculate the query duration
       * in both instances.
       */
!     if (save_log_duration || save_log_min_duration_statement > 0)
      {
          long        usecs;
          bool        print_statement;
--- 940,946 ----
       * Combine processing here as we need to calculate the query duration
       * in both instances.
       */
!     if (save_log_duration || save_log_min_duration_statement != -1)
      {
          long        usecs;
          bool        print_statement;
***************
*** 957,971 ****
           * Output a duration_statement to the log if the query has exceeded
           * the min duration, or if we are to print all durations.
           */
!         print_statement = (save_log_min_duration_statement > 0 &&
!                            usecs >= save_log_min_duration_statement * 1000);

          if (save_log_duration || print_statement)
              ereport(LOG,
!                     (errmsg("duration(secs): %ld.%06ld%s%s",
!                             (long) (stop_t.tv_sec - start_t.tv_sec),
!                             (long) (stop_t.tv_usec - start_t.tv_usec),
!                             print_statement ? " " : "",
                              print_statement ? query_string : "")));
      }

--- 957,973 ----
           * Output a duration_statement to the log if the query has exceeded
           * the min duration, or if we are to print all durations.
           */
!         print_statement = (save_log_min_duration_statement == 0 ||
!                            (save_log_min_duration_statement > 0 &&
!                             usecs >= save_log_min_duration_statement * 1000));

          if (save_log_duration || print_statement)
              ereport(LOG,
!                     (errmsg("duration: %ld.%03ld ms%s%s",
!                             (long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
!                             (stop_t.tv_usec - start_t.tv_usec) / 1000),
!                             (long) (stop_t.tv_usec - start_t.tv_usec) % 1000,
!                             print_statement ? "  query: " : "",
                              print_statement ? query_string : "")));
      }

***************
*** 3196,3198 ****
--- 3198,3201 ----

      pfree(str.data);
  }
+
Index: src/backend/utils/error/elog.c
===================================================================
RCS file: /cvsroot/pgsql-server/src/backend/utils/error/elog.c,v
retrieving revision 1.123
diff -c -c -r1.123 elog.c
*** src/backend/utils/error/elog.c    25 Sep 2003 06:58:05 -0000    1.123
--- src/backend/utils/error/elog.c    6 Oct 2003 21:33:12 -0000
***************
*** 145,150 ****
--- 145,151 ----
  static const char *error_severity(int elevel);
  static const char *print_timestamp(void);
  static const char *print_pid(void);
+ static char *str_prepend_tabs(const char *str);


  /*
***************
*** 1135,1140 ****
--- 1136,1143 ----
      /* Write to stderr, if enabled */
      if (Use_syslog <= 1 || whereToSendOutput == Debug)
      {
+         char *p = str_prepend_tabs(buf.data);
+
          /*
           * Timestamp and PID are only used for stderr output --- we assume
           * the syslog daemon will supply them for us in the other case.
***************
*** 1142,1148 ****
          fprintf(stderr, "%s%s%s",
                  Log_timestamp ? print_timestamp() : "",
                  Log_pid ? print_pid() : "",
!                 buf.data);
      }

      pfree(buf.data);
--- 1145,1152 ----
          fprintf(stderr, "%s%s%s",
                  Log_timestamp ? print_timestamp() : "",
                  Log_pid ? print_pid() : "",
!                 p);
!         pfree(p);
      }

      pfree(buf.data);
***************
*** 1449,1452 ****
--- 1453,1477 ----

      snprintf(buf, sizeof(buf), "[%d] ", (int) MyProcPid);
      return buf;
+ }
+
+ /*
+  *    str_prepend_tabs
+  *
+  *    This string prepends a tab to message continuation lines.
+  */
+ static char *str_prepend_tabs(const char *str)
+ {
+     char *outstr = palloc(strlen(str) * 2 + 1);
+     int    len = strlen(str);
+     int i, outlen = 0;
+
+     for (i = 0; i < len; i++)
+     {
+         outstr[outlen++] = str[i];
+         if (str[i] == '\n' && str[i+1] != '\0' )
+             outstr[outlen++] = '\t';
+     }
+     outstr[outlen++]    = '\0';
+     return outstr;
  }
Index: src/backend/utils/misc/guc.c
===================================================================
RCS file: /cvsroot/pgsql-server/src/backend/utils/misc/guc.c,v
retrieving revision 1.162
diff -c -c -r1.162 guc.c
*** src/backend/utils/misc/guc.c    3 Oct 2003 19:26:49 -0000    1.162
--- src/backend/utils/misc/guc.c    6 Oct 2003 21:33:17 -0000
***************
*** 128,134 ****
  int            log_min_messages = NOTICE;
  int            client_min_messages = NOTICE;

! int            log_min_duration_statement = 0;


  /*
--- 128,134 ----
  int            log_min_messages = NOTICE;
  int            client_min_messages = NOTICE;

! int            log_min_duration_statement = -1;


  /*
***************
*** 1185,1194 ****
          {"log_min_duration_statement", PGC_USERLIMIT, LOGGING_WHEN,
              gettext_noop("minimum execution time in milliseconds above which statements will "
                           "be logged"),
!             gettext_noop("The default is 0 (turning this feature off).")
          },
          &log_min_duration_statement,
!         0, 0, INT_MAX / 1000, NULL, NULL
      },

      /* End-of-list marker */
--- 1185,1194 ----
          {"log_min_duration_statement", PGC_USERLIMIT, LOGGING_WHEN,
              gettext_noop("minimum execution time in milliseconds above which statements will "
                           "be logged"),
!             gettext_noop("Zero prints all queries.  The default is -1 (turning this feature off).")
          },
          &log_min_duration_statement,
!         -1, -1, INT_MAX / 1000, NULL, NULL
      },

      /* End-of-list marker */
Index: src/backend/utils/misc/postgresql.conf.sample
===================================================================
RCS file: /cvsroot/pgsql-server/src/backend/utils/misc/postgresql.conf.sample,v
retrieving revision 1.91
diff -c -c -r1.91 postgresql.conf.sample
*** src/backend/utils/misc/postgresql.conf.sample    3 Oct 2003 19:26:49 -0000    1.91
--- src/backend/utils/misc/postgresql.conf.sample    6 Oct 2003 21:33:17 -0000
***************
*** 157,165 ****
                   #   debug5, debug4, debug3, debug2, debug1,
                   #   info, notice, warning, error, panic(off)

! #log_min_duration_statement = 0  # Log all statements whose
                   # execution time exceeds the value, in
!                  # milliseconds.  Zero disables.

  #silent_mode = false         # DO NOT USE without Syslog!

--- 157,166 ----
                   #   debug5, debug4, debug3, debug2, debug1,
                   #   info, notice, warning, error, panic(off)

! #log_min_duration_statement = -1 # Log all statements whose
                   # execution time exceeds the value, in
!                  # milliseconds.  Zero prints all queries.
!                  # Minus-one disables.

  #silent_mode = false         # DO NOT USE without Syslog!