Re: log_min_duration_statement #2 - Mailing list pgsql-patches

OK, patch applied.  I adjusted the documentation to not mention the
maximum (seemed unnecessary).  I also adjusted the output to be clearer
by placing the duration at the start, with no 'sec' legend:

  LOG:  duration_statement: 0.020185 select * from pg_language, pg_class;

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

Christopher Kings-Lynne wrote:
> OK,
>
> This limits max value to INT_MAX / 1000.
>
> Chris

[ Attachment, skipping... ]

>
> ---------------------------(end of broadcast)---------------------------
> TIP 3: if posting/reading through Usenet, please send an appropriate
> subscribe-nomail command to majordomo@postgresql.org so that your
> message can get through to the mailing list cleanly

--
  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.182
diff -c -c -r1.182 runtime.sgml
*** doc/src/sgml/runtime.sgml    27 May 2003 17:49:45 -0000    1.182
--- doc/src/sgml/runtime.sgml    11 Jun 2003 17:51:45 -0000
***************
*** 1052,1057 ****
--- 1052,1074 ----
       </varlistentry>

       <varlistentry>
+       <term><varname>LOG_MIN_DURATION_STATEMENT</varname> (<type>integer</type>)</term>
+       <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 the duration, in seconds.  The default is <literal>0</literal>
+     (turning this feature off).  For example, if you set it
+     to <literal>250</literal> then all SQL statements that run longer
+     than 250ms will be logged along with the duration.  Enabling this
+     option can be useful in tracking down unoptimized queries in
+     your applications.
+        </para>
+       </listitem>
+      </varlistentry>
+
+      <varlistentry>
        <term><varname>LOG_MIN_ERROR_STATEMENT</varname> (<type>string</type>)</term>
        <listitem>
         <para>
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql-server/src/backend/tcop/postgres.c,v
retrieving revision 1.346
diff -c -c -r1.346 postgres.c
*** src/backend/tcop/postgres.c    27 May 2003 17:49:46 -0000    1.346
--- src/backend/tcop/postgres.c    11 Jun 2003 17:51:48 -0000
***************
*** 663,668 ****
--- 663,669 ----
      struct timeval start_t,
                  stop_t;
      bool        save_log_duration = log_duration;
+     int            save_log_min_duration_statement = log_min_duration_statement;
      bool        save_log_statement_stats = log_statement_stats;

      /*
***************
*** 673,683 ****
      pgstat_report_activity(query_string);

      /*
!      * We use save_log_duration so "SET log_duration = true" doesn't
!      * report incorrect time because gettimeofday() wasn't called.
       * Similarly, log_statement_stats has to be captured once.
       */
!     if (save_log_duration)
          gettimeofday(&start_t, NULL);

      if (save_log_statement_stats)
--- 674,685 ----
      pgstat_report_activity(query_string);

      /*
!      * We use save_log_* so "SET log_duration = true"  and
!      * "SET log_min_duration_statement = true" don't report incorrect
!      * time 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)
***************
*** 915,933 ****
      QueryContext = NULL;

      /*
!      * Finish up monitoring.
       */
!     if (save_log_duration)
      {
          gettimeofday(&stop_t, NULL);
          if (stop_t.tv_usec < start_t.tv_usec)
          {
              stop_t.tv_sec--;
              stop_t.tv_usec += 1000000;
          }
!         elog(LOG, "duration: %ld.%06ld sec",
!              (long) (stop_t.tv_sec - start_t.tv_sec),
!              (long) (stop_t.tv_usec - start_t.tv_usec));
      }

      if (save_log_statement_stats)
--- 917,954 ----
      QueryContext = NULL;

      /*
!      * 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;
          gettimeofday(&stop_t, NULL);
          if (stop_t.tv_usec < start_t.tv_usec)
          {
              stop_t.tv_sec--;
              stop_t.tv_usec += 1000000;
          }
!         usecs = (long) (stop_t.tv_sec - start_t.tv_sec) * 1000000 + (long) (stop_t.tv_usec - start_t.tv_usec);
!
!         /*
!          * Output a duration_query to the log if the query has exceeded the
!          * min duration.
!          */
!         if (usecs >= save_log_min_duration_statement * 1000)
!             elog(LOG, "duration_statement: %ld.%06ld %s",
!                 (long) (stop_t.tv_sec - start_t.tv_sec),
!                 (long) (stop_t.tv_usec - start_t.tv_usec),
!                 query_string);
!
!         /*
!          * If the user is requesting logging of all durations, then log
!          * that as well.
!          */
!         if (save_log_duration)
!             elog(LOG, "duration: %ld.%06ld sec",
!                  (long) (stop_t.tv_sec - start_t.tv_sec),
!                  (long) (stop_t.tv_usec - start_t.tv_usec));
      }

      if (save_log_statement_stats)
Index: src/backend/utils/misc/guc.c
===================================================================
RCS file: /cvsroot/pgsql-server/src/backend/utils/misc/guc.c,v
retrieving revision 1.128
diff -c -c -r1.128 guc.c
*** src/backend/utils/misc/guc.c    11 Jun 2003 05:04:51 -0000    1.128
--- src/backend/utils/misc/guc.c    11 Jun 2003 17:51:52 -0000
***************
*** 55,60 ****
--- 55,62 ----
  #include "utils/pg_locale.h"
  #include "pgstat.h"

+ int            log_min_duration_statement = 0;
+

  #ifndef PG_KRB_SRVTAB
  #define PG_KRB_SRVTAB ""
***************
*** 733,738 ****
--- 735,745 ----
      {
          {"extra_float_digits", PGC_USERSET}, &extra_float_digits,
          0, -15, 2, NULL, NULL
+     },
+
+     {
+         {"log_min_duration_statement", PGC_USERSET}, &log_min_duration_statement,
+         0, 0, INT_MAX / 1000, NULL, NULL
      },

      {
Index: src/backend/utils/misc/postgresql.conf.sample
===================================================================
RCS file: /cvsroot/pgsql-server/src/backend/utils/misc/postgresql.conf.sample,v
retrieving revision 1.79
diff -c -c -r1.79 postgresql.conf.sample
*** src/backend/utils/misc/postgresql.conf.sample    11 Jun 2003 05:04:51 -0000    1.79
--- src/backend/utils/misc/postgresql.conf.sample    11 Jun 2003 17:51:52 -0000
***************
*** 140,145 ****
--- 140,149 ----
                   #   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.
+
  #debug_print_parse = false
  #debug_print_rewritten = false
  #debug_print_plan = false
Index: src/bin/psql/tab-complete.c
===================================================================
RCS file: /cvsroot/pgsql-server/src/bin/psql/tab-complete.c,v
retrieving revision 1.77
diff -c -c -r1.77 tab-complete.c
*** src/bin/psql/tab-complete.c    14 May 2003 03:26:02 -0000    1.77
--- src/bin/psql/tab-complete.c    11 Jun 2003 17:51:53 -0000
***************
*** 538,543 ****
--- 538,544 ----
          "lc_time",
          "log_duration",
          "log_executor_stats",
+         "log_min_duration_statement",
          "log_min_error_statement",
          "log_min_messages",
          "log_parser_stats",
Index: src/include/utils/guc.h
===================================================================
RCS file: /cvsroot/pgsql-server/src/include/utils/guc.h,v
retrieving revision 1.31
diff -c -c -r1.31 guc.h
*** src/include/utils/guc.h    6 May 2003 20:26:28 -0000    1.31
--- src/include/utils/guc.h    11 Jun 2003 17:51:54 -0000
***************
*** 142,145 ****
--- 142,147 ----
  void read_nondefault_variables(void);
  #endif

+ extern int    log_min_duration_statement;
+
  #endif   /* GUC_H */