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(a)redhat.com&gt; --- 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