Re: statement_timeout logging

Simon Riggs wrote:
> On Fri, 2005-09-16 at 20:48 -0400, Bruce Momjian wrote:
> > We can go three ways.  We can add a boolean GUC to control printing of
> > the query during a timeout, but that seems like overkill.  We can add a
> > new level for log_min_error_statement that is just above error, but that
> > seems confusing.  I think the right solution would be to allow
> > log_min_duration_statement to work for canceled queries.  Right now,
> > log_min_duration_statement doesn't work for canceled queries because the
> > query never completes to give a final duration and hit the test code.
> > Should that be fixed now or added to the TODO list?
>
> The last one seems the right way to go.

OK.  I tested it and it actually works, and I added documentation
suggesting its usage.  I was a little confused above because the
STATEMENT: line is only output to the server logs because of the way
elog.c handles a STATEMENT print for log_min_error_statement.  It does
not output to the client no matter what log_min_messages is set to, and
if someone is concerned about that we can fix it.  Technically STATEMENT
is not a log level message.

So, if I do:

    test=> SET statement_timeout = 1;
    SET
    test=> SET log_min_error_statement = 'ERROR';
    SET
    test=> SELECT * FROM pg_class;
    ERROR:  canceling statement due to statement timeout

in the logs I see:

    ERROR:  canceling statement due to statement timeout
    STATEMENT:  select * from pg_class;

> So, reformat the message at statement_timeout, so that the log looks
> exactly like log_min_duration_statement:
>
> e.g.
>
> LOG: statement_timeout has been activated to cancel statement
> LOG: duration 1625652ms statement SELECT * from bigOne
> LOG: query has been cancelled by user action

Not really.  The problem here is that the last line is wrong --- it was
not cancelled by user action.  The attached, applied patch adds a
"cancel_from_timeout" variable that properly records if the cancel was
because of a timeout or user interaction, and displays the proper log
message.

> Perhaps we should change the message from kill() to be "statement"
> rather than "query" also...

kill() is the wrong place to print the message.  You will see the
attached patch does it in a cleaner way.

> I'd vote fix now, but I guess that seems to be becoming a regular
> viewpoint from me.

OK, fixed.

--
  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/config.sgml
===================================================================
RCS file: /cvsroot/pgsql/doc/src/sgml/config.sgml,v
retrieving revision 1.17
diff -c -c -r1.17 config.sgml
*** doc/src/sgml/config.sgml    13 Sep 2005 15:24:56 -0000    1.17
--- doc/src/sgml/config.sgml    19 Sep 2005 16:58:53 -0000
***************
*** 3232,3238 ****
        <listitem>
         <para>
          Abort any statement that takes over the specified number of
!         milliseconds.  A value of zero (the default) turns off the limitation.
         </para>
        </listitem>
       </varlistentry>
--- 3232,3241 ----
        <listitem>
         <para>
          Abort any statement that takes over the specified number of
!         milliseconds.  If <varname>log_min_error_statement</> is set to
!         <literal>ERROR</> or lower, the statement that timed out will also be
!         logged.  A value of zero (the default) turns off the
!         limitation.
         </para>
        </listitem>
       </varlistentry>
Index: src/backend/storage/lmgr/proc.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/storage/lmgr/proc.c,v
retrieving revision 1.163
diff -c -c -r1.163 proc.c
*** src/backend/storage/lmgr/proc.c    20 Aug 2005 23:26:24 -0000    1.163
--- src/backend/storage/lmgr/proc.c    19 Sep 2005 16:58:55 -0000
***************
*** 78,83 ****
--- 78,84 ----
  /* Mark these volatile because they can be changed by signal handler */
  static volatile bool statement_timeout_active = false;
  static volatile bool deadlock_timeout_active = false;
+ volatile bool cancel_from_timeout = false;

  /* statement_fin_time is valid only if statement_timeout_active is true */
  static struct timeval statement_fin_time;
***************
*** 1058,1063 ****
--- 1059,1065 ----
          Assert(!deadlock_timeout_active);
          statement_fin_time = fin_time;
          statement_timeout_active = true;
+         cancel_from_timeout = false;
      }
      else if (statement_timeout_active)
      {
***************
*** 1128,1141 ****
          MemSet(&timeval, 0, sizeof(struct itimerval));
          if (setitimer(ITIMER_REAL, &timeval, NULL))
          {
!             statement_timeout_active = deadlock_timeout_active = false;
              return false;
          }
  #else
          /* BeOS doesn't have setitimer, but has set_alarm */
          if (set_alarm(B_INFINITE_TIMEOUT, B_PERIODIC_ALARM) < 0)
          {
!             statement_timeout_active = deadlock_timeout_active = false;
              return false;
          }
  #endif
--- 1130,1147 ----
          MemSet(&timeval, 0, sizeof(struct itimerval));
          if (setitimer(ITIMER_REAL, &timeval, NULL))
          {
!             statement_timeout_active = false;
!             cancel_from_timeout = false;
!             deadlock_timeout_active = false;
              return false;
          }
  #else
          /* BeOS doesn't have setitimer, but has set_alarm */
          if (set_alarm(B_INFINITE_TIMEOUT, B_PERIODIC_ALARM) < 0)
          {
!             statement_timeout_active = false;
!             cancel_from_timeout = false;
!             deadlock_timeout_active = false;
              return false;
          }
  #endif
***************
*** 1146,1152 ****
--- 1152,1161 ----

      /* Cancel or reschedule statement timeout */
      if (is_statement_timeout)
+     {
          statement_timeout_active = false;
+         cancel_from_timeout = false;
+     }
      else if (statement_timeout_active)
      {
          if (!CheckStatementTimeout())
***************
*** 1179,1184 ****
--- 1188,1194 ----
      {
          /* Time to die */
          statement_timeout_active = false;
+         cancel_from_timeout = true;
          kill(MyProcPid, SIGINT);
      }
      else
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/tcop/postgres.c,v
retrieving revision 1.459
diff -c -c -r1.459 postgres.c
*** src/backend/tcop/postgres.c    16 Sep 2005 19:31:04 -0000    1.459
--- src/backend/tcop/postgres.c    19 Sep 2005 16:58:58 -0000
***************
*** 1979,1985 ****
          /* Set statement timeout running, if any */
          if (StatementTimeout > 0)
              enable_sig_alarm(StatementTimeout, true);
!
          xact_started = true;
      }
  }
--- 1979,1987 ----
          /* Set statement timeout running, if any */
          if (StatementTimeout > 0)
              enable_sig_alarm(StatementTimeout, true);
!         else
!             cancel_from_timeout = false;
!
          xact_started = true;
      }
  }
***************
*** 2203,2211 ****
          ImmediateInterruptOK = false;    /* not idle anymore */
          DisableNotifyInterrupt();
          DisableCatchupInterrupt();
!         ereport(ERROR,
!                 (errcode(ERRCODE_QUERY_CANCELED),
!                  errmsg("canceling query due to user request or statement timeout")));
      }
      /* If we get here, do nothing (probably, QueryCancelPending was reset) */
  }
--- 2205,2218 ----
          ImmediateInterruptOK = false;    /* not idle anymore */
          DisableNotifyInterrupt();
          DisableCatchupInterrupt();
!         if (cancel_from_timeout)
!             ereport(ERROR,
!                     (errcode(ERRCODE_QUERY_CANCELED),
!                      errmsg("canceling statement due to statement timeout")));
!         else
!             ereport(ERROR,
!                     (errcode(ERRCODE_QUERY_CANCELED),
!                      errmsg("canceling statement due to user request")));
      }
      /* If we get here, do nothing (probably, QueryCancelPending was reset) */
  }
Index: src/include/storage/proc.h
===================================================================
RCS file: /cvsroot/pgsql/src/include/storage/proc.h,v
retrieving revision 1.81
diff -c -c -r1.81 proc.h
*** src/include/storage/proc.h    20 Aug 2005 23:26:34 -0000    1.81
--- src/include/storage/proc.h    19 Sep 2005 16:58:59 -0000
***************
*** 117,122 ****
--- 117,124 ----
  extern int    DeadlockTimeout;
  extern int    StatementTimeout;

+ extern volatile bool cancel_from_timeout;
+

  /*
   * Function Prototypes
Index: src/test/regress/expected/prepared_xacts.out
===================================================================
RCS file: /cvsroot/pgsql/src/test/regress/expected/prepared_xacts.out,v
retrieving revision 1.2
diff -c -c -r1.2 prepared_xacts.out
*** src/test/regress/expected/prepared_xacts.out    16 Sep 2005 19:39:02 -0000    1.2
--- src/test/regress/expected/prepared_xacts.out    19 Sep 2005 16:59:00 -0000
***************
*** 159,165 ****
  -- pxtest3 should be locked because of the pending DROP
  set statement_timeout to 1000;
  SELECT * FROM pxtest3;
! ERROR:  canceling query due to user request or statement timeout
  reset statement_timeout;
  -- Disconnect, we will continue testing in a different backend
  \c -
--- 159,165 ----
  -- pxtest3 should be locked because of the pending DROP
  set statement_timeout to 1000;
  SELECT * FROM pxtest3;
! ERROR:  canceling statement due to statement timeout
  reset statement_timeout;
  -- Disconnect, we will continue testing in a different backend
  \c -
***************
*** 174,180 ****
  -- pxtest3 should still be locked because of the pending DROP
  set statement_timeout to 1000;
  SELECT * FROM pxtest3;
! ERROR:  canceling query due to user request or statement timeout
  reset statement_timeout;
  -- Commit table creation
  COMMIT PREPARED 'regress-one';
--- 174,180 ----
  -- pxtest3 should still be locked because of the pending DROP
  set statement_timeout to 1000;
  SELECT * FROM pxtest3;
! ERROR:  canceling statement due to statement timeout
  reset statement_timeout;
  -- Commit table creation
  COMMIT PREPARED 'regress-one';