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

OK, here is a patch that uses the zero value to print all queries:

 LOG:  duration: 0.310 msecs,  select 1;
 LOG:  duration: 8.108 msecs,  select * from pg_class;
 LOG:  duration: 1.992 msecs,  select * from pg_class, pg_proc limit 1;
 LOG:  duration: 2.797 msecs,  select * from pg_class, pg_proc order by pg_proc.oid limit 1;
 LOG:  duration: 16190.962 msecs,  select * from pg_class, pg_proc order by pg_proc.oid;

Comments?

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

Bruce Momjian wrote:
> Tom Lane wrote:
> > Bruce Momjian <pgman@candle.pha.pa.us> writes:
> > > Tom Lane wrote:
> > >> I would prefer to see the log entries look like
> > >>
> > >> LOG: query: select * from pg_class;
> > >> LOG: duration: nn.nnn msec
> >
> > > The problem with two lines is that another log message could get between
> > > them.
> >
> > That was true already with log_statement and log_duration as separate
> > operations.  People use log_pid to deal with it.
>
> Attached are some emails I sent while we were discussing this feature in
> March.
>
> The idea was for the parameter to show query and duration --- a
> combination that is asked for frequently and easily grep'ed, unlike
> joining on pid, which because of pid wrap-around, isn't even fool-proof.
>
> One thing that isn't implemented in current CVS is to allow 0 to always
> print the duration and query (-1 disables it and is the default).  I can
> see that being _very_ valuable, and used enough to warrant the fact that
> it isn't orthoginal (we already have log_statement).  The reason we
> needed to do it this way was so we could print the statement _after_ it
> completes so we could include the duration.
>
> --
>   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

> >From pgman Wed Feb 12 15:03:03 2003
> Subject: Re: [HACKERS] log_duration
> In-Reply-To: <87smuurif6.fsf@stark.dyndns.tv>
> To: Greg Stark <gsstark@mit.edu>
> Date: Wed, 12 Feb 2003 16:49:58 -0500 (EST)
> cc: pgsql-hackers@postgresql.org
> X-Mailer: ELM [version 2.4ME+ PL99 (25)]
> MIME-Version: 1.0
> Content-Transfer-Encoding: 7bit
> Content-Type: text/plain; charset=US-ASCII
> Content-Length:  3288
> Status: OR
>
> Greg Stark wrote:
> > Tom Lane <tgl@sss.pgh.pa.us> writes:
> >
> > > "Christopher Kings-Lynne" <chriskl@familyhealth.com.au> writes:
> > > > Looking at the log_duration postgresql.conf option.  How about adding an
> > > > option log_duration_min which is a value in milliseconds that is the minimum
> > > > time a query must run for before being logged.
> > >
> > > Fine with me --- but you'll need to add more logic than that.  Right
> > > now, log_duration *only* causes the query duration to be printed out;
> > > if you ain't got log_statement on, you're in the dark as to what the
> > > query itself was.  You'll need to add some code to print the query
> > > (the log_min_error_statement logic might be a useful source of
> > > inspiration).  Not sure how this should interact with the case where
> > > log_duration is set and the min-duration isn't.  But maybe that case
> > > is silly, and we should just redefine log_duration as a minimum runtime
> > > that causes the query *and* its runtime to be printed to the log.
>
> Tom is right here.  log_duration _just_ prints the duration, so we would
> need to basically create a merged param that does log_duration and
> log_statement and have it activate only if the statement takes more than
> X milliseconds, something like log_long_statement, or something like
> that.
>
> Here are the log_* params we have:
>
>     log_connections = false
>     log_hostname = false
>     log_source_port = false
>     log_pid = false
>     log_statement = false
>     log_duration = false
>     log_timestamp = false
>
> Basically, log_pid pulls them all together.  Without that, you don't
> have any way to pull together individual lines in the log, and with pid
> wraparound, you can't even do that 100%.  I wonder if we should put a
> number before the pid and increment it on every pid wraparound.
>
> One nice thing is that each element is orthoginal.  But, for the
> functionality desired, we have to merge log_statement and log_duration
> and have it print for statements taking over X milliseconds.  I have no
> problem adding it, but it has to be clear it isn't orthoginal but is a
> conditional combination of two other parameters.
>
> > Is it even guaranteed to be properly ordered on a busy server with multiple
> > processors anyways?
> >
> > One option is to have log_query output an identifier with the query such as a
> > hash of the query or the pointer value for the plan, suppressing duplicates.
> > Then log_duration prints the identifier with the duration.
> >
> > This means on a busy server running lots of prepared queries you would see a
> > whole bunch of queries on startup, then hopefully no durations. Any durations
> > printed could cause alarms to go off. To find the query you grep the logs for
> > the identifier in the duration message.
>
> Actually, log_pid is the proper way to do this.  You can then add log
> connections, and get a full snapshot of what is happening for that
> session.
>
> > This only really works if you're using prepared queries everywhere. But in the
> > long run that will be the case for OLTP systems, which is where log_duration
> > is really useful.
>
> --
>   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
>
> >From pgman Wed Feb 12 15:03:03 2003
> Subject: Re: [HACKERS] log_duration
> In-Reply-To: <GNELIHDDFBOCMGBFGEFOMEIGCFAA.chriskl@familyhealth.com.au>
> To: Christopher Kings-Lynne <chriskl@familyhealth.com.au>
> Date: Wed, 12 Feb 2003 21:32:05 -0500 (EST)
> cc: Greg Stark <gsstark@mit.edu>, pgsql-hackers@postgresql.org
> X-Mailer: ELM [version 2.4ME+ PL99 (25)]
> MIME-Version: 1.0
> Content-Transfer-Encoding: 7bit
> Content-Type: text/plain; charset=US-ASCII
> Content-Length:  1245
> Status: OR
>
> Christopher Kings-Lynne wrote:
> > > Tom is right here.  log_duration _just_ prints the duration, so we would
> > > need to basically create a merged param that does log_duration and
> > > log_statement and have it activate only if the statement takes more than
> > > X milliseconds, something like log_long_statement, or something like
> > > that.
> > >
> > > Here are the log_* params we have:
> > >
> > >     log_connections = false
> > >     log_hostname = false
> > >     log_source_port = false
> > >     log_pid = false
> > >     log_statement = false
> > >     log_duration = false
> > >     log_timestamp = false
> >
> > OK, while I'm doing all this benchmarking and stuff - is there any sort of
> > option where I can see it logged when a sort doesn't have enought sort
> > memory and hence hits the disk?  eg. an elog(LOG) is emitted?
>
> Someone asked about this at FOSDEM. The only way I know to do it is look
> in the pgsql_temp directory, but they disappear pretty quickly.  Folks,
> do we need something to report sort file usage?
>
> --
>   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
>
> >From pgman Wed Feb 12 15:03:03 2003
> Subject: Re: [HACKERS] log_duration
> In-Reply-To: <GNELIHDDFBOCMGBFGEFOGEIHCFAA.chriskl@familyhealth.com.au>
> To: Christopher Kings-Lynne <chriskl@familyhealth.com.au>
> Date: Wed, 12 Feb 2003 22:07:04 -0500 (EST)
> cc: Greg Stark <gsstark@mit.edu>, pgsql-hackers@postgresql.org
> X-Mailer: ELM [version 2.4ME+ PL99 (25)]
> MIME-Version: 1.0
> Content-Transfer-Encoding: 7bit
> Content-Type: text/plain; charset=US-ASCII
> Content-Length:  1366
> Status: OR
>
>
> Well, part of the issue here is that it isn't always bad to use sort
> file;  certainly it is better to use them than to swap.
>
> We have a checkpoint_warning in 7.4 that will warn about excessive
> checkpointing.  What would our criteria be for warning about sort_mem?
> Seems we would have to know how much free memory there is available, and
> in fact, if there is lots of free memory, the sort files will just sit
> in the kernel disk cache anyway.
>
> I am not saying this is a bad idea --- we just need to define it clearer.
>
> ---------------------------------------------------------------------------
>
> Christopher Kings-Lynne wrote:
> > > Someone asked about this at FOSDEM. The only way I know to do it is look
> > > in the pgsql_temp directory, but they disappear pretty quickly.  Folks,
> > > do we need something to report sort file usage?
> >
> > How about a new GUC variable: log_sort_tempfiles
> >
> > And in the code that creates the temp file, if the GUC variable is true,
> > then do:
> >
> > elog(LOG, "Sort needed temp file.  Sort required 2456K.  Try increasing
> > sort_mem.");
> >
> > Or something?
> >
> > Chris
> >
> >
>
> --
>   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
>
> >From pgman Wed Feb 12 15:03:03 2003
> Subject: Re: [HACKERS] log_duration
> In-Reply-To: <10231.1045109729@sss.pgh.pa.us>
> To: Tom Lane <tgl@sss.pgh.pa.us>
> Date: Wed, 12 Feb 2003 23:46:11 -0500 (EST)
> cc: Greg Stark <gsstark@mit.edu>, pgsql-hackers@postgresql.org
> X-Mailer: ELM [version 2.4ME+ PL99 (25)]
> MIME-Version: 1.0
> Content-Transfer-Encoding: 7bit
> Content-Type: text/plain; charset=US-ASCII
> Content-Length:  1792
> Status: OR
>
> Tom Lane wrote:
> > Bruce Momjian <pgman@candle.pha.pa.us> writes:
> > > One nice thing is that each element is orthoginal.  But, for the
> > > functionality desired, we have to merge log_statement and log_duration
> > > and have it print for statements taking over X milliseconds.  I have no
> > > problem adding it, but it has to be clear it isn't orthoginal but is a
> > > conditional combination of two other parameters.
> >
> > Actually, I was wondering if we shouldn't *replace* the current
> > log_duration with a combined form (that specifies a minimum interesting
> > duration).  I can't quite see the need for orthogonality here.  The
> > only reason you'd care about query duration is that you're looking for
> > the slow ones, no?  So why bother logging the fast ones?  Besides, you
> > can specify min-duration zero if you really want 'em all.
>
> We did talk about this a while ago, and folks wanted the query printed
> _before_ it was executed, so they could see the query in the logs at the
> time it was issued, both for monitoring and for showing the time the
> query started when log_timestamp is enabled.
>
> Seems the clearest option would be for log_duration to print the query
> string too, and convert it to an integer field.  I can see zero meaning
> print all queries and durations.  What value do we use to turn it off?
> -1?
>
> This would give us log_statement that prints at query start, and
> log_duration that prints query and duration at query end.  How is that?
>
> Maybe we should rename them as log_statement_start and
> log_statement_duration.
>
> --
>   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
>
> >From pgman Fri Mar 14 09:01:29 2003
> Subject: Re: [HACKERS] log_duration
> In-Reply-To: <200302130446.h1D4kBF29082@candle.pha.pa.us>
> To: Bruce Momjian <pgman@candle.pha.pa.us>
> Date: Fri, 14 Mar 2003 14:27:38 -0500 (EST)
> cc: Tom Lane <tgl@sss.pgh.pa.us>, Greg Stark <gsstark@mit.edu>,
>     pgsql-hackers@postgresql.org
> X-Mailer: ELM [version 2.4ME+ PL99 (25)]
> MIME-Version: 1.0
> Content-Transfer-Encoding: 7bit
> Content-Type: text/plain; charset=US-ASCII
> Content-Length:  2472
> Status: OR
>
>
> Added to TODO:
>
>     * Add GUC log_statement_duration to print statement and >= min duration
>
> ---------------------------------------------------------------------------
>
> Bruce Momjian wrote:
> > Tom Lane wrote:
> > > Bruce Momjian <pgman@candle.pha.pa.us> writes:
> > > > One nice thing is that each element is orthoginal.  But, for the
> > > > functionality desired, we have to merge log_statement and log_duration
> > > > and have it print for statements taking over X milliseconds.  I have no
> > > > problem adding it, but it has to be clear it isn't orthoginal but is a
> > > > conditional combination of two other parameters.
> > >
> > > Actually, I was wondering if we shouldn't *replace* the current
> > > log_duration with a combined form (that specifies a minimum interesting
> > > duration).  I can't quite see the need for orthogonality here.  The
> > > only reason you'd care about query duration is that you're looking for
> > > the slow ones, no?  So why bother logging the fast ones?  Besides, you
> > > can specify min-duration zero if you really want 'em all.
> >
> > We did talk about this a while ago, and folks wanted the query printed
> > _before_ it was executed, so they could see the query in the logs at the
> > time it was issued, both for monitoring and for showing the time the
> > query started when log_timestamp is enabled.
> >
> > Seems the clearest option would be for log_duration to print the query
> > string too, and convert it to an integer field.  I can see zero meaning
> > print all queries and durations.  What value do we use to turn it off?
> > -1?
> >
> > This would give us log_statement that prints at query start, and
> > log_duration that prints query and duration at query end.  How is that?
> >
> > Maybe we should rename them as log_statement_start and
> > log_statement_duration.
> >
> > --
> >   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
> >
> > ---------------------------(end of broadcast)---------------------------
> > TIP 1: subscribe and unsubscribe commands go 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
>

>
> ---------------------------(end of broadcast)---------------------------
> TIP 4: Don't 'kill -9' the postmaster

--
  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 03:10:51 -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 03:10:54 -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,970 ****
           * 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,972 ----
           * 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 msecs, %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 03:10:58 -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 03:10:58 -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!