[Libguestfs] [PATCH libnbd 2/2] examples: copy-libev: Log request sleeps

[Nir Soffer]

Log when request are put to sleep and wake up. This helps to understand
what's going on when we wait for extents request completion.

Looking at the new logs, when copying to very fast target (e.g. nbdkit
memory plugin), we finish pending writes before the extents request
completes, and most of the requests are sleeping, waiting for extents
completion. When copying to slow target (my laptop ssd), only few
requests are sleeping, and the total sleep time is much lower.

Here is example log showing how requests are sleeping when starting
extents request:

copy-libev: r11: start extents offset=134217728 count=134217728
copy-libev: r12: zero completed offset=119275520 len=14942208, time=0.000316
copy-libev: r12: sleeping
copy-libev: r10: write completed offset=105381888 len=1048576, time=0.007689
copy-libev: r10: sleeping
copy-libev: r8: read completed offset=106430464 len=1048576
copy-libev: r8: start write offset=106430464 len=1048576
copy-libev: r8: write completed offset=106430464 len=1048576, time=0.007855
copy-libev: r8: sleeping
...

And later wake up when the request completes:

copy-libev: r11: extents completed time=0.004500
copy-libev: r0: woke up time=0.000104
copy-libev: r2: woke up time=0.001976
copy-libev: r3: woke up time=0.001321
...

Sleep time when copying to fast target:

$ COPY_LIBEV_DEBUG=1 .libs/copy-libev $SRC $DST 2>&1 | awk -F= '/woke up/ {total+=$2} END{print total}'
0.561214

And slow target:

$ COPY_LIBEV_DEBUG=1 .libs/copy-libev $SRC $DST 2>&1 | awk -F= '/woke up/ {total+=$2} END{print total}'
0.031874

Signed-off-by: Nir Soffer <nsoffer at redhat.com>
---
 examples/copy-libev.c | 35 ++++++++++++++++++++++++++---------
 1 file changed, 26 insertions(+), 9 deletions(-)

diff --git a/examples/copy-libev.c b/examples/copy-libev.c
index e988cd9..51ff9fb 100644
--- a/examples/copy-libev.c
+++ b/examples/copy-libev.c
@@ -215,11 +215,32 @@ extent_callback (void *user_data, const char *metacontext, uint64_t offset,
     return 1;
 }
 
+static inline void put_to_sleep (struct request *r)
+{
+    DEBUG ("r%zu: sleeping", r->index);
+    r->state = SLEEP;
+}
+
+static void wake_up_requests ()
+{
+    /* Start requests on the next loop iteration to avoid a deadlock if
+     * this is called from source nbd callback, and we need to start a
+     * read.
+     */
+    for (int i = 0; i < MAX_REQUESTS; i++) {
+        struct request *r = &requests[i];
+        if (r->state == SLEEP) {
+            DEBUG ("r%zu: woke up time=%.6f",
+                   r->index, ev_now (loop) - r->started);
+            start_request_soon (r);
+        }
+    }
+}
+
 static int
 extents_completed (void *user_data, int *error)
 {
     struct request *r = (struct request *)user_data;
-    int i;
 
     DEBUG ("r%zu: extents completed time=%.6f",
            r->index, ev_now (loop) - r->started);
@@ -234,14 +255,10 @@ extents_completed (void *user_data, int *error)
     /* Start the request to process recvievd extents. This must be done on the
      * next loop iteration, to avoid deadlock if we need to start a read.
      */
-    start_request_soon(r);
+    start_request_soon (r);
 
-    /* Wake up requests waiting for extents completion */
-    for (i = 0; i < MAX_REQUESTS; i++) {
-        struct request *r = &requests[i];
-        if (r->state == SLEEP)
-            start_request_soon (r);
-    }
+    /* Also wake up requests waiting for extents completion */
+    wake_up_requests ();
 
     return 1;
 }
@@ -370,7 +387,7 @@ start_request(struct request *r)
     /* If needed, get more extents from server. */
     if (src.can_extents && extents == NULL) {
         if (extents_in_progress) {
-            r->state = SLEEP;
+            put_to_sleep (r);
             return;
         }
 
-- 
2.26.3