Libguestfs - Mar 2021 - [PATCH libnbd 2/3] examples: copy-libev.c: Improve debug logs

Us COPY_LIBEV_DEBUG instead of LIBNBD_DEBUG, since libnbd debug output
is huge and not helpful for debugging the libev integration.

Add request index, and log the request index in all debug message, to
make it easier to follow all events on a particular request.

Log also the time from starting the request until the request was
completed.

Here is an example output when copying fedora 32 image:

copy-libev: r0: start read offset=0 len=1048576
copy-libev: r1: start read offset=1048576 len=1048576
copy-libev: r2: start read offset=2097152 len=1048576
copy-libev: r3: start read offset=3145728 len=1048576
...
copy-libev: r0: read completed offset=0 len=1048576
copy-libev: r0: start write offset=0 len=1048576
copy-libev: r1: read completed offset=1048576 len=1048576
copy-libev: r1: start write offset=1048576 len=1048576
copy-libev: r0: request completed offset=0 len=1048576 time=0.009660
copy-libev: r0: start read offset=16777216 len=1048576
copy-libev: r2: read completed offset=2097152 len=1048576
copy-libev: r2: start write offset=2097152 len=1048576
...
copy-libev: r15: request completed offset=6439305216 len=1048576 time=0.001415
copy-libev: r5: request completed offset=6440353792 len=1048576 time=0.001301
copy-libev: r7: request completed offset=6441402368 len=1048576 time=0.001359
copy-libev: flush

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

diff --git a/examples/copy-libev.c b/examples/copy-libev.c
index 3f687a1..84d5c03 100644
--- a/examples/copy-libev.c
+++ b/examples/copy-libev.c
@@ -13,7 +13,7 @@
  *
  * To debug it:
  *
- *     LIBNBD_DEBUG=1 ./copy-ev ...
+ *     COPY_LIBEV_DEBUG=1 ./copy-ev ...
  */
 
 #include <assert.h>
@@ -68,6 +68,8 @@ struct request {
     int64_t offset;
     size_t length;
     unsigned char *data;
+    size_t index;
+    ev_tstamp started;
 };
 
 static struct ev_loop *loop;
@@ -141,6 +143,7 @@ start_request(struct request *r)
 {
     assert (offset < size);
 
+    r->started = ev_now (loop);
     r->length = MIN (REQUEST_SIZE, size - offset);
     r->offset = offset;
 
@@ -154,7 +157,8 @@ start_read(struct request *r)
 {
     int64_t cookie;
 
-    DEBUG ("start read offset=%ld len=%ld", r->offset,
r->length);
+    DEBUG ("r%d: start read offset=%ld len=%ld",
+           r->index, r->offset, r->length);
 
     cookie = nbd_aio_pread (
         src.nbd, r->data, r->length, r->offset,
@@ -170,7 +174,8 @@ read_completed (void *user_data, int *error)
 {
     struct request *r = (struct request *)user_data;
 
-    DEBUG ("read completed offset=%ld len=%ld", r->offset,
r->length);
+    DEBUG ("r%d: read completed offset=%ld len=%ld",
+           r->index, r->offset, r->length);
 
     if (dst.can_zero && is_zero (r->data, r->length))
         start_zero (r);
@@ -185,7 +190,8 @@ start_write(struct request *r)
 {
     int64_t cookie;
 
-    DEBUG ("start write offset=%ld len=%ld", r->offset,
r->length);
+    DEBUG ("r%d: start write offset=%ld len=%ld",
+           r->index, r->offset, r->length);
 
     cookie = nbd_aio_pwrite (
         dst.nbd, r->data, r->length, r->offset,
@@ -201,7 +207,8 @@ start_zero(struct request *r)
 {
     int64_t cookie;
 
-    DEBUG ("start zero offset=%ld len=%ld", r->offset,
r->length);
+    DEBUG ("r%d: start zero offset=%ld len=%ld",
+           r->index, r->offset, r->length);
 
     cookie = nbd_aio_zero (
         dst.nbd, r->length, r->offset,
@@ -220,7 +227,8 @@ request_completed (void *user_data, int *error)
 
     written += r->length;
 
-    DEBUG ("request completed offset=%ld len=%ld", r->offset,
r->length);
+    DEBUG ("r%d: request completed offset=%ld len=%ld time=%.6f",
+           r->index, r->offset, r->length, ev_now (loop) -
r->started);
 
     if (written == size) {
         /* The last write completed. Stop all watchers and break out
@@ -294,7 +302,7 @@ main (int argc, char *argv[])
     if (dst.nbd == NULL)
         FAIL ("Cannot create destination: %s", nbd_get_error ());
 
-    debug = nbd_get_debug (src.nbd);
+    debug = getenv ("COPY_LIBEV_DEBUG") != NULL;
 
     /* Connecting is fast, so use the syncronous API. */
 
@@ -319,6 +327,7 @@ main (int argc, char *argv[])
     for (i = 0; i < MAX_REQUESTS && offset < size; i++) {
         struct request *r = &requests[i];
 
+        r->index = i;
         r->data = malloc (REQUEST_SIZE);
         if (r->data == NULL)
             FAIL ("Cannot allocate buffer: %s", strerror (errno));
-- 
2.26.2

On 3/6/21 3:21 PM, Nir Soffer wrote:
> Us COPY_LIBEV_DEBUG instead of LIBNBD_DEBUG, since libnbd debug output
Use
> is huge and not helpful for debugging the libev integration.
> 
> Add request index, and log the request index in all debug message, to
> make it easier to follow all events on a particular request.
> 
> Log also the time from starting the request until the request was
> completed.
> 
-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3226
Virtualization:  qemu.org | libvirt.org