Re: BUG #16035: STATEMENT_TIMEOUT not working when we have single quote usage inside CTE which is used in inner sql

Tatsuo Ishii <ishii@sraoss.co.jp> writes:
>>> tl;dr: I do not think this is buggy in v10.  But arguably there's
>>> a bug in later branches, and they need to go back to behaving
>>> like v10.

>> I understand the original reporter's complain. Also I understand Tom's
>> complain to v11's behavior. I will look into the v11 (and above) code.

> I admit v11's current behavior is inconstant, but I am not sue going
> to back V10's behavior is a good idea.
> With attached patch (against master), SET STATEMENT_TIMEOUT
> immediately affects to subsequent commands in the multi statement. I
> think this is not only more intuitive than v10's behavior but it meets
> the original reporter's expectation.

Hm.  So, okay, that is a nicer API probably, but note that it also
has the effect that the timeout starts over again for each statement
in the string, while before it applied to the string as a whole.
Are we okay with that change?  (I've not yet looked to see if it's
documented anywhere that it works that way...)  It's kind of tossing
some of the optimization intended by f8e5f156b overboard, since when
a timeout is active we'll be doing timeout calculations for each
statement in the string.

Anyway, granting that we want the definitional change, I still
don't like anything about this patch.  The proposed test

+        if (!doing_extended_query_message ||
+            (!stmt_timeout_active && doing_extended_query_message))

is unreadably complicated and repetitive, and it's undocumented,
and it makes timeout handling work quite differently in the simple
and extended query paths, and it will cause excess timeout calculations
(over and above the newly-necessary ones) because it will force a new
timeout calculation for each start_xact_command call in the simple query
path (yes, we do more than one of those per statement in common cases).
Plus it makes the semantics of stmt_timeout_active rather unclear.

I think if we want to do this, the way to do it is to add another
disable_statement_timeout call while finishing up a non-last query
in exec_simple_query, as per 0001 below.  That adds no extra overhead
unless we have a multi-statement string, and it is much more parallel
to the way things are done for extended protocol.

However ... as I was looking at this, I realized that I didn't like
anything about commit f8e5f156b either.  It introduces private state
in postgres.c that has to be kept in sync with state in timeout.c.
We already found one bug in that (cf be42015fc), and I have little
faith that there aren't others, and no faith at all that we won't
introduce more later.  The right way to manage that, I think, is to
extend timeout.c to allow inquiring whether the timeout is active,
as per 0002 below, so that timeout.c's state is the single source of
truth about this.  Maintaining the extra state needed to make this
cheap allows some other small simplifications/speedups, too, mainly
that we can skip useless searches of the active_timeouts[] array.

Not sure what I think about back-patching this.  We probably can't
back-patch 0001; that's enough of a behavioral change that the cure
seems worse than the disease.  I'm tempted though to argue that we
should back-patch 0002, on the grounds that it prevents possible
bugs and should save a few cycles too.

            regards, tom lane

diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index e8d8e6f..1ecaba0 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -1270,6 +1270,13 @@ exec_simple_query(const char *query_string)
              * those that start or end a transaction block.
              */
             CommandCounterIncrement();
+
+            /*
+             * Disable statement timeout between queries of a multi-query
+             * string, so that the timeout applies separately to each query.
+             * (Our next loop iteration will start a fresh timeout.)
+             */
+            disable_statement_timeout();
         }

         /*
@@ -2135,7 +2142,10 @@ exec_execute_message(const char *portal_name, long max_rows)
              */
             CommandCounterIncrement();

-            /* full command has been executed, reset timeout */
+            /*
+             * Disable statement timeout whenever we complete an Execute
+             * message.  The next protocol message will start a fresh timeout.
+             */
             disable_statement_timeout();
         }

diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 1ecaba0..4bec40a 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -146,11 +146,6 @@ static bool doing_extended_query_message = false;
 static bool ignore_till_sync = false;

 /*
- * Flag to keep track of whether statement timeout timer is active.
- */
-static bool stmt_timeout_active = false;
-
-/*
  * If an unnamed prepared statement exists, it's stored here.
  * We keep it separate from the hashtable kept by commands/prepare.c
  * in order to reduce overhead for short-lived queries.
@@ -4029,7 +4024,6 @@ PostgresMain(int argc, char *argv[],
          */
         disable_all_timeouts(false);
         QueryCancelPending = false; /* second to avoid race condition */
-        stmt_timeout_active = false;

         /* Not reading from the client anymore. */
         DoingCommandRead = false;
@@ -4711,14 +4705,14 @@ enable_statement_timeout(void)

     if (StatementTimeout > 0)
     {
-        if (!stmt_timeout_active)
-        {
+        if (!get_timeout_active(STATEMENT_TIMEOUT))
             enable_timeout_after(STATEMENT_TIMEOUT, StatementTimeout);
-            stmt_timeout_active = true;
-        }
     }
     else
-        disable_timeout(STATEMENT_TIMEOUT, false);
+    {
+        if (get_timeout_active(STATEMENT_TIMEOUT))
+            disable_timeout(STATEMENT_TIMEOUT, false);
+    }
 }

 /*
@@ -4727,10 +4721,6 @@ enable_statement_timeout(void)
 static void
 disable_statement_timeout(void)
 {
-    if (stmt_timeout_active)
-    {
+    if (get_timeout_active(STATEMENT_TIMEOUT))
         disable_timeout(STATEMENT_TIMEOUT, false);
-
-        stmt_timeout_active = false;
-    }
 }
diff --git a/src/backend/utils/misc/timeout.c b/src/backend/utils/misc/timeout.c
index b56259c..a2a4bb6 100644
--- a/src/backend/utils/misc/timeout.c
+++ b/src/backend/utils/misc/timeout.c
@@ -27,7 +27,8 @@ typedef struct timeout_params
 {
     TimeoutId    index;            /* identifier of timeout reason */

-    /* volatile because it may be changed from the signal handler */
+    /* volatile because these may be changed from the signal handler */
+    volatile bool active;        /* true if timeout is in active_timeouts[] */
     volatile bool indicator;    /* true if timeout has occurred */

     /* callback function for timeout, or NULL if timeout not registered */
@@ -105,6 +106,9 @@ insert_timeout(TimeoutId id, int index)
         elog(FATAL, "timeout index %d out of range 0..%d", index,
              num_active_timeouts);

+    Assert(!all_timeouts[id].active);
+    all_timeouts[id].active = true;
+
     for (i = num_active_timeouts - 1; i >= index; i--)
         active_timeouts[i + 1] = active_timeouts[i];

@@ -125,6 +129,9 @@ remove_timeout_index(int index)
         elog(FATAL, "timeout index %d out of range 0..%d", index,
              num_active_timeouts - 1);

+    Assert(active_timeouts[index]->active);
+    active_timeouts[index]->active = false;
+
     for (i = index + 1; i < num_active_timeouts; i++)
         active_timeouts[i - 1] = active_timeouts[i];

@@ -147,9 +154,8 @@ enable_timeout(TimeoutId id, TimestampTz now, TimestampTz fin_time)
      * If this timeout was already active, momentarily disable it.  We
      * interpret the call as a directive to reschedule the timeout.
      */
-    i = find_active_timeout(id);
-    if (i >= 0)
-        remove_timeout_index(i);
+    if (all_timeouts[id].active)
+        remove_timeout_index(find_active_timeout(id));

     /*
      * Find out the index where to insert the new timeout.  We sort by
@@ -349,6 +355,7 @@ InitializeTimeouts(void)
     for (i = 0; i < MAX_TIMEOUTS; i++)
     {
         all_timeouts[i].index = i;
+        all_timeouts[i].active = false;
         all_timeouts[i].indicator = false;
         all_timeouts[i].timeout_handler = NULL;
         all_timeouts[i].start_time = 0;
@@ -524,8 +531,6 @@ enable_timeouts(const EnableTimeoutParams *timeouts, int count)
 void
 disable_timeout(TimeoutId id, bool keep_indicator)
 {
-    int            i;
-
     /* Assert request is sane */
     Assert(all_timeouts_initialized);
     Assert(all_timeouts[id].timeout_handler != NULL);
@@ -534,9 +539,8 @@ disable_timeout(TimeoutId id, bool keep_indicator)
     disable_alarm();

     /* Find the timeout and remove it from the active list. */
-    i = find_active_timeout(id);
-    if (i >= 0)
-        remove_timeout_index(i);
+    if (all_timeouts[id].active)
+        remove_timeout_index(find_active_timeout(id));

     /* Mark it inactive, whether it was active or not. */
     if (!keep_indicator)
@@ -571,13 +575,11 @@ disable_timeouts(const DisableTimeoutParams *timeouts, int count)
     for (i = 0; i < count; i++)
     {
         TimeoutId    id = timeouts[i].id;
-        int            idx;

         Assert(all_timeouts[id].timeout_handler != NULL);

-        idx = find_active_timeout(id);
-        if (idx >= 0)
-            remove_timeout_index(idx);
+        if (all_timeouts[id].active)
+            remove_timeout_index(find_active_timeout(id));

         if (!timeouts[i].keep_indicator)
             all_timeouts[id].indicator = false;
@@ -595,6 +597,8 @@ disable_timeouts(const DisableTimeoutParams *timeouts, int count)
 void
 disable_all_timeouts(bool keep_indicators)
 {
+    int            i;
+
     disable_alarm();

     /*
@@ -613,16 +617,27 @@ disable_all_timeouts(bool keep_indicators)

     num_active_timeouts = 0;

-    if (!keep_indicators)
+    for (i = 0; i < MAX_TIMEOUTS; i++)
     {
-        int            i;
-
-        for (i = 0; i < MAX_TIMEOUTS; i++)
+        all_timeouts[i].active = false;
+        if (!keep_indicators)
             all_timeouts[i].indicator = false;
     }
 }

 /*
+ * Return true if the timeout is active (enabled and not yet fired)
+ *
+ * This is, of course, subject to race conditions, as the timeout could fire
+ * immediately after we look.
+ */
+bool
+get_timeout_active(TimeoutId id)
+{
+    return all_timeouts[id].active;
+}
+
+/*
  * Return the timeout's I've-been-fired indicator
  *
  * If reset_indicator is true, reset the indicator when returning true.
diff --git a/src/include/utils/timeout.h b/src/include/utils/timeout.h
index 9244a2a..ae5389e 100644
--- a/src/include/utils/timeout.h
+++ b/src/include/utils/timeout.h
@@ -80,6 +80,7 @@ extern void disable_timeouts(const DisableTimeoutParams *timeouts, int count);
 extern void disable_all_timeouts(bool keep_indicators);

 /* accessors */
+extern bool get_timeout_active(TimeoutId id);
 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);