Re: [EXTERNAL] Re: Add non-blocking version of PQcancel - Mailing list pgsql-hackers

Alexander Lakhin <exclusion@gmail.com> writes:
> 17.11.2024 05:33, Tom Lane wrote:
>> Yeah.  This has been happening off-and-on in the buildfarm ever
>> since we added that test.  I'm not sure if it's just "the test
>> is unstable" or if it's telling us there's a problem with the
>> cancel logic.  Scraping the last 3 months worth of buildfarm
>> logs finds these instances:

> Yes, I counted those bf failures at [1] too and posted my explanation
> upthread [2].

Sorry, I'd forgotten about that.  I added some more debug logging
to the modifications you made, and confirmed your theory that the
remote session is ignoring the cancel request because it receives it
while DoingCommandRead is true; which must mean that it hasn't started
the slow query yet.

This implies that the 100ms delay in query_cancel.sql is not reliably
enough for the remote to receive the command, which surprises me,
especially since the failing animals aren't particularly slow ones.
Maybe there is something else happening?  But I do reproduce the
failure after adding your delays, and the patch I'm about to propose
does fix it.

Anyway, given that info, Jelte's unapplied 0002 patch earlier in the
thread is not the answer, because this is about dropping a query
cancel not about losing a timeout interrupt.  The equivalent thing
to what he suggested would be to not clear the cancel request flag
during DoingCommandRead, instead letting it kill the next query.
But I didn't like the idea for timeouts, and I like it even less for
query cancel.  What I think we should do instead is to re-issue
the cancel request if we've waited a little and nothing came of it.
This corresponds more or less to what a human user would likely do
(or at least this human would).  The attached patch is set up to
re-cancel after 1 second, then 2 more seconds, then 4 more, etc
until we reach the 30-second "it's dead Jim" threshold.

This seems to fix the problem here.  Thoughts?

BTW, while I didn't do it in the attached, I'm tempted to greatly
reduce the 100ms delay in query_cancel.sql.  If this does make it
more robust, we shouldn't need that much time anymore.

            regards, tom lane

diff --git a/contrib/postgres_fdw/connection.c b/contrib/postgres_fdw/connection.c
index 2326f391d3..7a8cac83cb 100644
--- a/contrib/postgres_fdw/connection.c
+++ b/contrib/postgres_fdw/connection.c
@@ -95,6 +95,13 @@ static uint32 pgfdw_we_get_result = 0;
  */
 #define CONNECTION_CLEANUP_TIMEOUT    30000

+/*
+ * Milliseconds to wait before issuing another cancel request.  This covers
+ * the race condition where the remote session ignored our cancel request
+ * because it arrived while idle.
+ */
+#define RE_CANCEL_TIMEOUT    1000
+
 /* Macro for constructing abort command to be sent */
 #define CONSTRUCT_ABORT_COMMAND(sql, entry, toplevel) \
     do { \
@@ -145,6 +152,7 @@ static void pgfdw_reset_xact_state(ConnCacheEntry *entry, bool toplevel);
 static bool pgfdw_cancel_query(PGconn *conn);
 static bool pgfdw_cancel_query_begin(PGconn *conn, TimestampTz endtime);
 static bool pgfdw_cancel_query_end(PGconn *conn, TimestampTz endtime,
+                                   TimestampTz recanceltime,
                                    bool consume_input);
 static bool pgfdw_exec_cleanup_query(PGconn *conn, const char *query,
                                      bool ignore_errors);
@@ -154,6 +162,7 @@ static bool pgfdw_exec_cleanup_query_end(PGconn *conn, const char *query,
                                          bool consume_input,
                                          bool ignore_errors);
 static bool pgfdw_get_cleanup_result(PGconn *conn, TimestampTz endtime,
+                                     TimestampTz recanceltime,
                                      PGresult **result, bool *timed_out);
 static void pgfdw_abort_cleanup(ConnCacheEntry *entry, bool toplevel);
 static bool pgfdw_abort_cleanup_begin(ConnCacheEntry *entry, bool toplevel,
@@ -1322,18 +1331,25 @@ pgfdw_reset_xact_state(ConnCacheEntry *entry, bool toplevel)
 static bool
 pgfdw_cancel_query(PGconn *conn)
 {
+    TimestampTz now = GetCurrentTimestamp();
     TimestampTz endtime;
+    TimestampTz recanceltime;

     /*
      * If it takes too long to cancel the query and discard the result, assume
      * the connection is dead.
      */
-    endtime = TimestampTzPlusMilliseconds(GetCurrentTimestamp(),
-                                          CONNECTION_CLEANUP_TIMEOUT);
+    endtime = TimestampTzPlusMilliseconds(now, CONNECTION_CLEANUP_TIMEOUT);
+
+    /*
+     * Also, lose patience and re-issue the cancel request after a little bit.
+     * (This serves to close some race conditions.)
+     */
+    recanceltime = TimestampTzPlusMilliseconds(now, RE_CANCEL_TIMEOUT);

     if (!pgfdw_cancel_query_begin(conn, endtime))
         return false;
-    return pgfdw_cancel_query_end(conn, endtime, false);
+    return pgfdw_cancel_query_end(conn, endtime, recanceltime, false);
 }

 /*
@@ -1359,9 +1375,10 @@ pgfdw_cancel_query_begin(PGconn *conn, TimestampTz endtime)
 }

 static bool
-pgfdw_cancel_query_end(PGconn *conn, TimestampTz endtime, bool consume_input)
+pgfdw_cancel_query_end(PGconn *conn, TimestampTz endtime,
+                       TimestampTz recanceltime, bool consume_input)
 {
-    PGresult   *result = NULL;
+    PGresult   *result;
     bool        timed_out;

     /*
@@ -1380,7 +1397,8 @@ pgfdw_cancel_query_end(PGconn *conn, TimestampTz endtime, bool consume_input)
     }

     /* Get and discard the result of the query. */
-    if (pgfdw_get_cleanup_result(conn, endtime, &result, &timed_out))
+    if (pgfdw_get_cleanup_result(conn, endtime, recanceltime,
+                                 &result, &timed_out))
     {
         if (timed_out)
             ereport(WARNING,
@@ -1453,7 +1471,7 @@ pgfdw_exec_cleanup_query_end(PGconn *conn, const char *query,
                              TimestampTz endtime, bool consume_input,
                              bool ignore_errors)
 {
-    PGresult   *result = NULL;
+    PGresult   *result;
     bool        timed_out;

     Assert(query != NULL);
@@ -1471,7 +1489,7 @@ pgfdw_exec_cleanup_query_end(PGconn *conn, const char *query,
     }

     /* Get the result of the query. */
-    if (pgfdw_get_cleanup_result(conn, endtime, &result, &timed_out))
+    if (pgfdw_get_cleanup_result(conn, endtime, endtime, &result, &timed_out))
     {
         if (timed_out)
             ereport(WARNING,
@@ -1495,28 +1513,36 @@ pgfdw_exec_cleanup_query_end(PGconn *conn, const char *query,
 }

 /*
- * Get, during abort cleanup, the result of a query that is in progress.  This
- * might be a query that is being interrupted by transaction abort, or it might
- * be a query that was initiated as part of transaction abort to get the remote
- * side back to the appropriate state.
+ * Get, during abort cleanup, the result of a query that is in progress.
+ * This might be a query that is being interrupted by a cancel request or by
+ * transaction abort, or it might be a query that was initiated as part of
+ * transaction abort to get the remote side back to the appropriate state.
  *
  * endtime is the time at which we should give up and assume the remote
- * side is dead.  Returns true if the timeout expired or connection trouble
- * occurred, false otherwise.  Sets *result except in case of a timeout.
- * Sets timed_out to true only when the timeout expired.
+ * side is dead.  recanceltime is the time at which we should issue a fresh
+ * cancel request (pass the same value as endtime if this is not wanted).
+ *
+ * Returns true if the timeout expired or connection trouble occurred,
+ * false otherwise.  Sets *result except in case of a true result.
+ * Sets *timed_out to true only when the timeout expired.
  */
 static bool
-pgfdw_get_cleanup_result(PGconn *conn, TimestampTz endtime, PGresult **result,
+pgfdw_get_cleanup_result(PGconn *conn, TimestampTz endtime,
+                         TimestampTz recanceltime,
+                         PGresult **result,
                          bool *timed_out)
 {
     volatile bool failed = false;
     PGresult   *volatile last_res = NULL;

+    *result = NULL;
     *timed_out = false;

     /* In what follows, do not leak any PGresults on an error. */
     PG_TRY();
     {
+        int            canceldelta = RE_CANCEL_TIMEOUT * 2;
+
         for (;;)
         {
             PGresult   *res;
@@ -1527,8 +1553,33 @@ pgfdw_get_cleanup_result(PGconn *conn, TimestampTz endtime, PGresult **result,
                 TimestampTz now = GetCurrentTimestamp();
                 long        cur_timeout;

+                /* If timeout has expired, give up. */
+                if (now >= endtime)
+                {
+                    *timed_out = true;
+                    failed = true;
+                    goto exit;
+                }
+
+                /* If we need to re-issue the cancel request, do that. */
+                if (now >= recanceltime)
+                {
+                    /* We ignore failure to issue the repeated request. */
+                    (void) libpqsrv_cancel(conn, endtime);
+
+                    /* Recompute "now" in case that took measurable time. */
+                    now = GetCurrentTimestamp();
+
+                    /* Adjust re-cancel timeout in increasing steps. */
+                    recanceltime = TimestampTzPlusMilliseconds(now,
+                                                               canceldelta);
+                    canceldelta += canceldelta;
+                }
+
                 /* If timeout has expired, give up, else get sleep time. */
-                cur_timeout = TimestampDifferenceMilliseconds(now, endtime);
+                cur_timeout = TimestampDifferenceMilliseconds(now,
+                                                              Min(endtime,
+                                                                  recanceltime));
                 if (cur_timeout <= 0)
                 {
                     *timed_out = true;
@@ -1849,7 +1900,9 @@ pgfdw_finish_abort_cleanup(List *pending_entries, List *cancel_requested,
         foreach(lc, cancel_requested)
         {
             ConnCacheEntry *entry = (ConnCacheEntry *) lfirst(lc);
+            TimestampTz now = GetCurrentTimestamp();
             TimestampTz endtime;
+            TimestampTz recanceltime;
             char        sql[100];

             Assert(entry->changing_xact_state);
@@ -1863,10 +1916,13 @@ pgfdw_finish_abort_cleanup(List *pending_entries, List *cancel_requested,
              * remaining entries in the list, leading to slamming that entry's
              * connection shut.
              */
-            endtime = TimestampTzPlusMilliseconds(GetCurrentTimestamp(),
+            endtime = TimestampTzPlusMilliseconds(now,
                                                   CONNECTION_CLEANUP_TIMEOUT);
+            recanceltime = TimestampTzPlusMilliseconds(now,
+                                                       RE_CANCEL_TIMEOUT);

-            if (!pgfdw_cancel_query_end(entry->conn, endtime, true))
+            if (!pgfdw_cancel_query_end(entry->conn, endtime,
+                                        recanceltime, true))
             {
                 /* Unable to cancel running query */
                 pgfdw_reset_xact_state(entry, toplevel);