GUC changes to log query durations

The attached patch adds 'log_duration' to GUC, showing the duration of
each query.  It is to be used with LOG_PID and LOG_STATEMENT:

 [22602]  LOG:  query: SELECT usesuper FROM pg_catalog.pg_user WHERE usename = 'postgres'
 [22602]  LOG:  duration: 0.666637 sec
 [22602]  LOG:  query: SELECT * FROM pg_language;
 [22602]  LOG:  duration: 0.079464 sec

The patch also changes debug_print_query to log_statement and
show_query_statistics to show_statement_statistics.  I believe Peter has
suggested similar changes recently, making the debug_print_query a log_
option because it really isn't for debugging the server, and changing
'query' to 'statement' to be more precise.

--
  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/func.sgml
===================================================================
RCS file: /cvsroot/pgsql-server/doc/src/sgml/func.sgml,v
retrieving revision 1.118
diff -c -c -r1.118 func.sgml
*** doc/src/sgml/func.sgml    29 Aug 2002 05:17:55 -0000    1.118
--- doc/src/sgml/func.sgml    31 Aug 2002 19:44:53 -0000
***************
*** 5241,5247 ****
      <literal>false</literal> instead. It is the equivalent to the SQL
      <command>SET</command> command. For example:
  <programlisting>
! select set_config('show_query_stats','off','f');
   set_config
  ------------
   off
--- 5241,5247 ----
      <literal>false</literal> instead. It is the equivalent to the SQL
      <command>SET</command> command. For example:
  <programlisting>
! select set_config('show_statement_stats','off','f');
   set_config
  ------------
   off
Index: doc/src/sgml/runtime.sgml
===================================================================
RCS file: /cvsroot/pgsql-server/doc/src/sgml/runtime.sgml,v
retrieving revision 1.130
diff -c -c -r1.130 runtime.sgml
*** doc/src/sgml/runtime.sgml    30 Aug 2002 16:50:49 -0000    1.130
--- doc/src/sgml/runtime.sgml    31 Aug 2002 19:45:06 -0000
***************
*** 928,934 ****
       </varlistentry>

       <varlistentry>
-       <term><varname>DEBUG_PRINT_QUERY</varname> (<type>boolean</type>)</term>
        <term><varname>DEBUG_PRINT_PARSE</varname> (<type>boolean</type>)</term>
        <term><varname>DEBUG_PRINT_REWRITTEN</varname> (<type>boolean</type>)</term>
        <term><varname>DEBUG_PRINT_PLAN</varname> (<type>boolean</type>)</term>
--- 928,933 ----
***************
*** 993,998 ****
--- 992,1017 ----
       </varlistentry>

       <varlistentry>
+       <term><varname>LOG_STATEMENT</varname> (<type>boolean</type>)</term>
+       <listitem>
+        <para>
+         Prints each query received.
+        </para>
+       </listitem>
+      </varlistentry>
+
+      <varlistentry>
+       <term><varname>LOG_DURATION</varname> (<type>boolean</type>)</term>
+       <listitem>
+        <para>
+         Prints the duration of every completed query.  To use this option,
+         enable LOG_STATEMENT and LOG_PID so you can link the original query
+         to the duration using the process id.
+        </para>
+       </listitem>
+      </varlistentry>
+
+      <varlistentry>
        <term><varname>LOG_TIMESTAMP</varname> (<type>boolean</type>)</term>
        <listitem>
         <para>
***************
*** 1003,1009 ****
       </varlistentry>

       <varlistentry>
!       <term><varname>SHOW_QUERY_STATS</varname> (<type>boolean</type>)</term>
        <term><varname>SHOW_PARSER_STATS</varname> (<type>boolean</type>)</term>
        <term><varname>SHOW_PLANNER_STATS</varname> (<type>boolean</type>)</term>
        <term><varname>SHOW_EXECUTOR_STATS</varname> (<type>boolean</type>)</term>
--- 1022,1028 ----
       </varlistentry>

       <varlistentry>
!       <term><varname>SHOW_STATEMENT_STATS</varname> (<type>boolean</type>)</term>
        <term><varname>SHOW_PARSER_STATS</varname> (<type>boolean</type>)</term>
        <term><varname>SHOW_PLANNER_STATS</varname> (<type>boolean</type>)</term>
        <term><varname>SHOW_EXECUTOR_STATS</varname> (<type>boolean</type>)</term>
***************
*** 2049,2055 ****
         </row>
         <row>
          <entry><option>-s</option></entry>
!         <entry><literal>show_query_stats = on</></entry>
          <entry>*</entry>
         </row>
         <row>
--- 2068,2074 ----
         </row>
         <row>
          <entry><option>-s</option></entry>
!         <entry><literal>show_statement_stats = on</></entry>
          <entry>*</entry>
         </row>
         <row>
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql-server/src/backend/tcop/postgres.c,v
retrieving revision 1.286
diff -c -c -r1.286 postgres.c
*** src/backend/tcop/postgres.c    29 Aug 2002 23:39:05 -0000    1.286
--- src/backend/tcop/postgres.c    31 Aug 2002 19:45:19 -0000
***************
*** 372,378 ****
  {
      List       *raw_parsetree_list;

!     if (Debug_print_query)
          elog(LOG, "query: %s", query_string->data);

      if (Show_parser_stats)
--- 372,378 ----
  {
      List       *raw_parsetree_list;

!     if (Log_statement)
          elog(LOG, "query: %s", query_string->data);

      if (Show_parser_stats)
***************
*** 561,569 ****
--- 561,574 ----
      MemoryContext oldcontext;
      List       *parsetree_list,
                 *parsetree_item;
+     struct timezone tz;
+     struct timeval start_t, stop_t;

      debug_query_string = query_string->data;    /* used by pgmonitor */

+     if (Log_duration)
+         gettimeofday(&start_t, &tz);
+
      /*
       * Start up a transaction command.    All queries generated by the
       * query_string will be in this same command block, *unless* we find a
***************
*** 850,855 ****
--- 855,873 ----
      if (xact_started)
          finish_xact_command();

+     if (Log_duration)
+     {
+         gettimeofday(&stop_t, &tz);
+         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 int) stop_t.tv_sec - start_t.tv_sec,
+             (long int) stop_t.tv_usec - start_t.tv_usec);
+     }
+
      debug_query_string = NULL;    /* used by pgmonitor */
  }

***************
*** 1234,1240 ****
                          if (atoi(optarg) >= 1)
                              SetConfigOption("log_connections", "true", ctx, gucsource);
                          if (atoi(optarg) >= 2)
!                             SetConfigOption("debug_print_query", "true", ctx, gucsource);
                          if (atoi(optarg) >= 3)
                              SetConfigOption("debug_print_parse", "true", ctx, gucsource);
                          if (atoi(optarg) >= 4)
--- 1252,1258 ----
                          if (atoi(optarg) >= 1)
                              SetConfigOption("log_connections", "true", ctx, gucsource);
                          if (atoi(optarg) >= 2)
!                             SetConfigOption("log_statement", "true", ctx, gucsource);
                          if (atoi(optarg) >= 3)
                              SetConfigOption("debug_print_parse", "true", ctx, gucsource);
                          if (atoi(optarg) >= 4)
***************
*** 1377,1383 ****
                  /*
                   * s - report usage statistics (timings) after each query
                   */
!                 SetConfigOption("show_query_stats", "true", ctx, gucsource);
                  break;

              case 't':
--- 1395,1401 ----
                  /*
                   * s - report usage statistics (timings) after each query
                   */
!                 SetConfigOption("show_statement_stats", "true", ctx, gucsource);
                  break;

              case 't':
***************
*** 1489,1499 ****
      /*
       * Post-processing for command line options.
       */
!     if (Show_query_stats &&
          (Show_parser_stats || Show_planner_stats || Show_executor_stats))
      {
          elog(WARNING, "Query statistics are disabled because parser, planner, or executor statistics are on.");
!         SetConfigOption("show_query_stats", "false", ctx, gucsource);
      }

      if (!IsUnderPostmaster)
--- 1507,1517 ----
      /*
       * Post-processing for command line options.
       */
!     if (Show_statement_stats &&
          (Show_parser_stats || Show_planner_stats || Show_executor_stats))
      {
          elog(WARNING, "Query statistics are disabled because parser, planner, or executor statistics are on.");
!         SetConfigOption("show_statement_stats", "false", ctx, gucsource);
      }

      if (!IsUnderPostmaster)
***************
*** 1887,1893 ****
                       * Note: transaction command start/end is now done within
                       * pg_exec_query_string(), not here.
                       */
!                     if (Show_query_stats)
                          ResetUsage();

                      pgstat_report_activity(parser_input->data);
--- 1905,1911 ----
                       * Note: transaction command start/end is now done within
                       * pg_exec_query_string(), not here.
                       */
!                     if (Show_statement_stats)
                          ResetUsage();

                      pgstat_report_activity(parser_input->data);
***************
*** 1896,1902 ****
                                           whereToSendOutput,
                                           QueryContext);

!                     if (Show_query_stats)
                          ShowUsage("QUERY STATISTICS");
                  }
                  break;
--- 1914,1920 ----
                                           whereToSendOutput,
                                           QueryContext);

!                     if (Show_statement_stats)
                          ShowUsage("QUERY STATISTICS");
                  }
                  break;
Index: src/backend/utils/misc/guc.c
===================================================================
RCS file: /cvsroot/pgsql-server/src/backend/utils/misc/guc.c,v
retrieving revision 1.88
diff -c -c -r1.88 guc.c
*** src/backend/utils/misc/guc.c    30 Aug 2002 16:50:50 -0000    1.88
--- src/backend/utils/misc/guc.c    31 Aug 2002 19:45:27 -0000
***************
*** 76,82 ****
  #ifdef USE_ASSERT_CHECKING
  bool        assert_enabled = true;
  #endif
! bool        Debug_print_query = false;
  bool        Debug_print_plan = false;
  bool        Debug_print_parse = false;
  bool        Debug_print_rewritten = false;
--- 76,83 ----
  #ifdef USE_ASSERT_CHECKING
  bool        assert_enabled = true;
  #endif
! bool        Log_statement = false;
! bool        Log_duration = false;
  bool        Debug_print_plan = false;
  bool        Debug_print_parse = false;
  bool        Debug_print_rewritten = false;
***************
*** 85,91 ****
  bool        Show_parser_stats = false;
  bool        Show_planner_stats = false;
  bool        Show_executor_stats = false;
! bool        Show_query_stats = false;    /* this is sort of all three above
                                           * together */
  bool        Show_btree_build_stats = false;

--- 86,92 ----
  bool        Show_parser_stats = false;
  bool        Show_planner_stats = false;
  bool        Show_executor_stats = false;
! bool        Show_statement_stats = false;    /* this is sort of all three above
                                           * together */
  bool        Show_btree_build_stats = false;

***************
*** 361,367 ****
  #endif

      {
!         { "debug_print_query", PGC_USERSET }, &Debug_print_query,
          false, NULL, NULL
      },
      {
--- 362,372 ----
  #endif

      {
!         { "log_statement", PGC_USERSET }, &Log_statement,
!         false, NULL, NULL
!     },
!     {
!         { "log_duration", PGC_USERSET }, &Log_duration,
          false, NULL, NULL
      },
      {
***************
*** 394,400 ****
          false, NULL, NULL
      },
      {
!         { "show_query_stats", PGC_USERSET }, &Show_query_stats,
          false, NULL, NULL
      },
  #ifdef BTREE_BUILD_STATS
--- 399,405 ----
          false, NULL, NULL
      },
      {
!         { "show_statement_stats", PGC_USERSET }, &Show_statement_stats,
          false, NULL, NULL
      },
  #ifdef BTREE_BUILD_STATS
Index: src/backend/utils/misc/postgresql.conf.sample
===================================================================
RCS file: /cvsroot/pgsql-server/src/backend/utils/misc/postgresql.conf.sample,v
retrieving revision 1.49
diff -c -c -r1.49 postgresql.conf.sample
*** src/backend/utils/misc/postgresql.conf.sample    29 Aug 2002 21:02:12 -0000    1.49
--- src/backend/utils/misc/postgresql.conf.sample    31 Aug 2002 19:45:33 -0000
***************
*** 104,110 ****
  #geqo = true
  #geqo_selection_bias = 2.0    # range 1.5-2.0
  #geqo_threshold = 11
! #geqo_pool_size = 0        # default based on tables in query,
                  # range 128-1024
  #geqo_effort = 1
  #geqo_generations = 0
--- 104,110 ----
  #geqo = true
  #geqo_selection_bias = 2.0    # range 1.5-2.0
  #geqo_threshold = 11
! #geqo_pool_size = 0        # default based on tables in statement,
                  # range 128-1024
  #geqo_effort = 1
  #geqo_generations = 0
***************
*** 124,133 ****
  #silent_mode = false

  #log_connections = false
- #log_timestamp = false
  #log_pid = false

- #debug_print_query = false
  #debug_print_parse = false
  #debug_print_rewritten = false
  #debug_print_plan = false
--- 124,134 ----
  #silent_mode = false

  #log_connections = false
  #log_pid = false
+ #log_statement = false
+ #log_duration = false
+ #log_timestamp = false

  #debug_print_parse = false
  #debug_print_rewritten = false
  #debug_print_plan = false
***************
*** 153,159 ****
  #show_parser_stats = false
  #show_planner_stats = false
  #show_executor_stats = false
! #show_query_stats = false

  # requires BTREE_BUILD_STATS
  #show_btree_build_stats = false
--- 154,160 ----
  #show_parser_stats = false
  #show_planner_stats = false
  #show_executor_stats = false
! #show_statement_stats = false

  # requires BTREE_BUILD_STATS
  #show_btree_build_stats = false
Index: src/bin/psql/tab-complete.c
===================================================================
RCS file: /cvsroot/pgsql-server/src/bin/psql/tab-complete.c,v
retrieving revision 1.59
diff -c -c -r1.59 tab-complete.c
*** src/bin/psql/tab-complete.c    30 Aug 2002 18:15:23 -0000    1.59
--- src/bin/psql/tab-complete.c    31 Aug 2002 19:45:38 -0000
***************
*** 231,237 ****
          "server_min_messages",
          "client_min_messages",
          "debug_assertions",
!         "debug_print_query",
          "debug_print_parse",
          "debug_print_rewritten",
          "debug_print_plan",
--- 231,238 ----
          "server_min_messages",
          "client_min_messages",
          "debug_assertions",
!         "log_statement",
!         "log_duration",
          "debug_print_parse",
          "debug_print_rewritten",
          "debug_print_plan",
***************
*** 239,245 ****
          "show_parser_stats",
          "show_planner_stats",
          "show_executor_stats",
!         "show_query_stats",
          "trace_notify",
          "explain_pretty_print",
          "sql_inheritance",
--- 240,246 ----
          "show_parser_stats",
          "show_planner_stats",
          "show_executor_stats",
!         "show_statement_stats",
          "trace_notify",
          "explain_pretty_print",
          "sql_inheritance",
Index: src/include/utils/guc.h
===================================================================
RCS file: /cvsroot/pgsql-server/src/include/utils/guc.h,v
retrieving revision 1.20
diff -c -c -r1.20 guc.h
*** src/include/utils/guc.h    30 Jul 2002 16:20:03 -0000    1.20
--- src/include/utils/guc.h    31 Aug 2002 19:45:40 -0000
***************
*** 100,106 ****
  extern ArrayType *GUCArrayAdd(ArrayType *array, const char *name, const char *value);
  extern ArrayType *GUCArrayDelete(ArrayType *array, const char *name);

! extern bool Debug_print_query;
  extern bool Debug_print_plan;
  extern bool Debug_print_parse;
  extern bool Debug_print_rewritten;
--- 100,107 ----
  extern ArrayType *GUCArrayAdd(ArrayType *array, const char *name, const char *value);
  extern ArrayType *GUCArrayDelete(ArrayType *array, const char *name);

! extern bool Log_statement;
! extern bool Log_duration;
  extern bool Debug_print_plan;
  extern bool Debug_print_parse;
  extern bool Debug_print_rewritten;
***************
*** 109,115 ****
  extern bool Show_parser_stats;
  extern bool Show_planner_stats;
  extern bool Show_executor_stats;
! extern bool Show_query_stats;
  extern bool Show_btree_build_stats;

  extern bool Explain_pretty_print;
--- 110,116 ----
  extern bool Show_parser_stats;
  extern bool Show_planner_stats;
  extern bool Show_executor_stats;
! extern bool Show_statement_stats;
  extern bool Show_btree_build_stats;

  extern bool Explain_pretty_print;