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

OK, patch attached and applied.  Changes are:

    "query:" now "statement:"
    log_duration also now prints when log_min_duration_statement prints


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

Peter Eisentraut wrote:
> Bruce Momjian writes:
>
> > > Imagine someone always having log_statement on and doing some sort of
> > > aggregate query counting, say like grep '^LOG: query:' | wc -l.  Now that
> > > someone (or maybe the admin on the night shift, to make it more dramatic)
> > > also turns on log_min_statement_duration (or whatever it's spelled), say
> > > to find the slowest queries: grep '^LOG: duration:' | sort -xyz | head
> > > -10.  In order to guarantee the consistency of both results, you'd have to
> > > log each query twice in this case.
> >
> > I guess.
>
> Can we agree to this?
>
> * If log_statement is on, then we log
>
> query: %s
>
> (Should it be "statement: %s"?)  %s has newlines suitable escaped; exactly
> how is independent of this discussion.
>
> * If log_duration is on, then we log
>
> duration: x.xxx ms
>
> The user can use log_pid to link it to the statement.  (If the user
> doesn't like this, he can use log_min_duration_statement=0.)
>
> * If log_min_duration_statement is triggered, then we log
>
> duration: x.xxx ms; query: %s
>
> * If log_statement is on and log_min_duration_statement is triggered, then
> we (pick one):
>
> (a) log both as per above, or
> (b) log only log_min_duration_statement
>
> * If log_duration is on and log_min_duration_statement is triggered, then
> we (pick one):
>
> (a) log both as per above, or
> (b) log only log_min_duration_statement
>
> --
> Peter Eisentraut   peter_e@gmx.net
>
>
> ---------------------------(end of broadcast)---------------------------
> TIP 2: you can get off all lists at once with the unregister command
>     (send "unregister YourEmailAddressHere" to majordomo@postgresql.org)
>

--
  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: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql-server/src/backend/tcop/postgres.c,v
retrieving revision 1.371
diff -c -c -r1.371 postgres.c
*** src/backend/tcop/postgres.c    8 Oct 2003 03:49:37 -0000    1.371
--- src/backend/tcop/postgres.c    9 Oct 2003 02:37:19 -0000
***************
*** 461,467 ****

      if (log_statement)
          ereport(LOG,
!                 (errmsg("query: %s", query_string)));

      if (log_parser_stats)
          ResetUsage();
--- 461,467 ----

      if (log_statement)
          ereport(LOG,
!                 (errmsg("statement: %s", query_string)));

      if (log_parser_stats)
          ResetUsage();
***************
*** 943,949 ****
      if (save_log_duration || save_log_min_duration_statement != -1)
      {
          long        usecs;
-         bool        print_statement;

          gettimeofday(&stop_t, NULL);
          if (stop_t.tv_usec < start_t.tv_usec)
--- 943,948 ----
***************
*** 953,974 ****
          }
          usecs = (long) (stop_t.tv_sec - start_t.tv_sec) * 1000000 + (long) (stop_t.tv_usec - start_t.tv_usec);

          /*
           * 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 : "")));
      }

      if (save_log_statement_stats)
--- 952,977 ----
          }
          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 +
+                             (stop_t.tv_usec - start_t.tv_usec) / 1000),
+                             (long) (stop_t.tv_usec - start_t.tv_usec) % 1000)));
+
          /*
           * Output a duration_statement to the log if the query has exceeded
           * the min duration, or if we are to print all durations.
           */
!         if (save_log_min_duration_statement == 0 ||
!             (save_log_min_duration_statement > 0 &&
!              usecs >= save_log_min_duration_statement * 1000))
              ereport(LOG,
!                     (errmsg("duration: %ld.%03ld ms  statement: %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,
!                             query_string)));
      }

      if (save_log_statement_stats)