Be more predictable about reporting "lock timeout" vs "statement timeout".

If both timeout indicators are set when we arrive at ProcessInterrupts,
we've historically just reported "lock timeout".  However, some buildfarm
members have been observed to fail isolationtester's timeouts test by
reporting "lock timeout" when the statement timeout was expected to fire
first.  The cause seems to be that the process is allowed to sleep longer
than expected (probably due to heavy machine load) so that the lock
timeout happens before we reach the point of reporting the error, and
then this arbitrary tiebreak rule does the wrong thing.  We can improve
matters by comparing the scheduled timeout times to decide which error
to report.

I had originally proposed greatly reducing the 1-second window between
the two timeouts in the test cases.  On reflection that is a bad idea,
at least for the case where the lock timeout is expected to fire first,
because that would assume that it takes negligible time to get from
statement start to the beginning of the lock wait.  Thus, this patch
doesn't completely remove the risk of test failures on slow machines.
Empirically, however, the case this handles is the one we are seeing
in the buildfarm.  The explanation may be that the other case requires
the scheduler to take the CPU away from a busy process, whereas the
case fixed here only requires the scheduler to not give the CPU back
right away to a process that has been woken from a multi-second sleep
(and, perhaps, has been swapped out meanwhile).

Back-patch to 9.3 where the isolationtester timeouts test was added.

Discussion: <8693.1464314819@sss.pgh.pa.us>

diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 225ebd18512ce1fb8a82122fadc45ea2dbfa98cb..f7219c05be39c05a64bbdfdbd04e592ab0189a1f 100644 (file)
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -2913,6 +2913,9 @@ ProcessInterrupts(void)
 
        if (QueryCancelPending)
        {
+               bool            lock_timeout_occurred;
+               bool            stmt_timeout_occurred;
+
                /*
                 * Don't allow query cancel interrupts while reading input from the
                 * client, because we might lose sync in the FE/BE protocol.  (Die
@@ -2946,12 +2949,24 @@ ProcessInterrupts(void)
 
                /*
                 * If LOCK_TIMEOUT and STATEMENT_TIMEOUT indicators are both set, we
-                * prefer to report the former; but be sure to clear both.
+                * need to clear both, so always fetch both.
                 */
-               if (get_timeout_indicator(LOCK_TIMEOUT, true))
+               lock_timeout_occurred = get_timeout_indicator(LOCK_TIMEOUT, true);
+               stmt_timeout_occurred = get_timeout_indicator(STATEMENT_TIMEOUT, true);
+
+               /*
+                * If both were set, we want to report whichever timeout completed
+                * earlier; this ensures consistent behavior if the machine is slow
+                * enough that the second timeout triggers before we get here.  A tie
+                * is arbitrarily broken in favor of reporting a lock timeout.
+                */
+               if (lock_timeout_occurred && stmt_timeout_occurred &&
+                       get_timeout_finish_time(STATEMENT_TIMEOUT) < get_timeout_finish_time(LOCK_TIMEOUT))
+                       lock_timeout_occurred = false;          /* report stmt timeout */
+
+               if (lock_timeout_occurred)
                {
                        ImmediateInterruptOK = false;           /* not idle anymore */
-                       (void) get_timeout_indicator(STATEMENT_TIMEOUT, true);
                        LockErrorCleanup();
                        DisableNotifyInterrupt();
                        DisableCatchupInterrupt();
@@ -2959,7 +2974,7 @@ ProcessInterrupts(void)
                                        (errcode(ERRCODE_LOCK_NOT_AVAILABLE),
                                         errmsg("canceling statement due to lock timeout")));
                }
-               if (get_timeout_indicator(STATEMENT_TIMEOUT, true))
+               if (stmt_timeout_occurred)
                {
                        ImmediateInterruptOK = false;           /* not idle anymore */
                        LockErrorCleanup();

diff --git a/src/backend/utils/misc/timeout.c b/src/backend/utils/misc/timeout.c
index 51f5df1c13b501bda66f93b9f11378f5639d72a9..f300467b0d216ac00c69eab177d92deec491c9cd 100644 (file)
--- a/src/backend/utils/misc/timeout.c
+++ b/src/backend/utils/misc/timeout.c
@@ -34,7 +34,7 @@ typedef struct timeout_params
        timeout_handler_proc timeout_handler;
 
        TimestampTz start_time;         /* time that timeout was last activated */
-       TimestampTz fin_time;           /* if active, time it is due to fire */
+       TimestampTz fin_time;           /* time it is, or was last, due to fire */
 } timeout_params;
 
 /*
@@ -688,3 +688,17 @@ get_timeout_start_time(TimeoutId id)
 {
        return all_timeouts[id].start_time;
 }
+
+/*
+ * Return the time when the timeout is, or most recently was, due to fire
+ *
+ * Note: will return 0 if timeout has never been activated in this process.
+ * However, we do *not* reset the fin_time when a timeout occurs, so as
+ * not to create a race condition if SIGALRM fires just as some code is
+ * about to fetch the value.
+ */
+TimestampTz
+get_timeout_finish_time(TimeoutId id)
+{
+       return all_timeouts[id].fin_time;
+}

diff --git a/src/include/utils/timeout.h b/src/include/utils/timeout.h
index 759ee24774bb8ba0079150c1d710726f9629fbf4..dad73e8459617ac10b7955a37c512e4619420fe4 100644 (file)
--- a/src/include/utils/timeout.h
+++ b/src/include/utils/timeout.h
@@ -80,5 +80,6 @@ extern void disable_all_timeouts(bool keep_indicators);
 /* accessors */
 extern bool get_timeout_indicator(TimeoutId id, bool reset_indicator);
 extern TimestampTz get_timeout_start_time(TimeoutId id);
+extern TimestampTz get_timeout_finish_time(TimeoutId id);
 
 #endif   /* TIMEOUT_H */