aio: Improve debug logging around waiting for IOs
authorAndres Freund <andres@anarazel.de>
Fri, 25 Apr 2025 16:31:42 +0000 (12:31 -0400)
committerAndres Freund <andres@anarazel.de>
Fri, 25 Apr 2025 17:31:25 +0000 (13:31 -0400)
Trying to investigate a bug report by Alexander Lakhin made it apparent that
the debug logging around waiting for IO completion is insufficient. Fix that.

Discussion: https://postgr.es/m/h4in2db37vepagmi2oz5vvqymjasc5gyb4lpqkunj4eusu274i@37jpd3c2spd3

src/backend/storage/aio/aio.c

index e2a133cfac604bfc0f69066b4fda8609baa8c5b4..57b9cf3dcab365766b5f74c9c21ad40d5253f3f9 100644 (file)
@@ -711,8 +711,10 @@ pgaio_io_wait_for_free(void)
 {
    int         reclaimed = 0;
 
-   pgaio_debug(DEBUG2, "waiting for self with %d pending",
-               pgaio_my_backend->num_staged_ios);
+   pgaio_debug(DEBUG2, "waiting for free IO with %d pending, %d in-flight, %d idle IOs",
+               pgaio_my_backend->num_staged_ios,
+               dclist_count(&pgaio_my_backend->in_flight_ios),
+               dclist_is_empty(&pgaio_my_backend->idle_ios));
 
    /*
     * First check if any of our IOs actually have completed - when using
@@ -743,7 +745,12 @@ pgaio_io_wait_for_free(void)
        pgaio_submit_staged();
 
    if (dclist_count(&pgaio_my_backend->in_flight_ios) == 0)
-       elog(ERROR, "no free IOs despite no in-flight IOs");
+       ereport(ERROR,
+               errmsg_internal("no free IOs despite no in-flight IOs"),
+               errdetail_internal("%d pending, %d in-flight, %d idle IOs",
+                                  pgaio_my_backend->num_staged_ios,
+                                  dclist_count(&pgaio_my_backend->in_flight_ios),
+                                  dclist_is_empty(&pgaio_my_backend->idle_ios)));
 
    /*
     * Wait for the oldest in-flight IO to complete.
@@ -1136,7 +1143,13 @@ pgaio_closing_fd(int fd)
     * For now just submit all staged IOs - we could be more selective, but
     * it's probably not worth it.
     */
-   pgaio_submit_staged();
+   if (pgaio_my_backend->num_staged_ios > 0)
+   {
+       pgaio_debug(DEBUG2,
+                   "submitting %d IOs before FD %d gets closed",
+                   pgaio_my_backend->num_staged_ios, fd);
+       pgaio_submit_staged();
+   }
 
    /*
     * If requested by the IO method, wait for all IOs that use the
@@ -1168,6 +1181,10 @@ pgaio_closing_fd(int fd)
            if (!ioh)
                break;
 
+           pgaio_debug_io(DEBUG2, ioh,
+                          "waiting for IO before FD %d gets closed, %d in-flight IOs",
+                          fd, dclist_count(&pgaio_my_backend->in_flight_ios));
+
            /* see comment in pgaio_io_wait_for_free() about raciness */
            pgaio_io_wait(ioh, ioh->generation);
        }
@@ -1199,6 +1216,10 @@ pgaio_shutdown(int code, Datum arg)
    {
        PgAioHandle *ioh = dclist_head_element(PgAioHandle, node, &pgaio_my_backend->in_flight_ios);
 
+       pgaio_debug_io(DEBUG2, ioh,
+                      "waiting for IO to complete during shutdown, %d in-flight IOs",
+                      dclist_count(&pgaio_my_backend->in_flight_ios));
+
        /* see comment in pgaio_io_wait_for_free() about raciness */
        pgaio_io_wait(ioh, ioh->generation);
    }