aio: Improve debug logging around waiting for IOs

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

diff --git a/src/backend/storage/aio/aio.c b/src/backend/storage/aio/aio.c
index e2a133cfac604bfc0f69066b4fda8609baa8c5b4..57b9cf3dcab365766b5f74c9c21ad40d5253f3f9 100644 (file)
--- a/src/backend/storage/aio/aio.c
+++ b/src/backend/storage/aio/aio.c
@@ -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);
        }