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

Peter Eisentraut wrote:
> Tom Lane writes:
>
> > I would prefer to see the log entries look like
> >
> >     LOG: query: select * from pg_class;
> >     LOG: duration: nn.nnn msec
>
> I'm not fond of the abbrevation "msec" or even "msecs".  The official
> abbreviation is "ms".

Yep.  Someone suggested "msec" in their example, so I used that, but I
like "ms" better too:

    LOG:  duration: 0.950 ms; select 1;
    LOG:  duration: 0.269 ms; set log_min_duration_statement = 1;

Patch attached.

> Btw., I was wondering, are we kidding ourselves when we display
> microsecond precision to the user?  What accuracy do these measurements
> have in respect to what they are actually supposed to measure?

Not sure.  I think the microsecond stuff is accurate to some degree, but
not sure how much.  I think the tick is 10ms, but I thought the timing
was much more accurate than that.

--
  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    5 Oct 2003 14:12:20 -0000
***************
*** 1691,1702 ****
           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>
--- 1691,1702 ----
           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 will print
!          all queries with their durations.  Minus-one (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>
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    5 Oct 2003 14:12:23 -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 ? "; " : "",
                              print_statement ? query_string : "")));
      }

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    5 Oct 2003 14:12:28 -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    5 Oct 2003 14:12:29 -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!