[PATCH libnbd 0/3] Support extents in libev example
The first patches improve the way we poll events and debugging. The last patch adds support for extents. With this copying real image performs similar to qemu-img convert or nbdcopy. This should be enhance later to support bigger requests for zero requests. Currently same request size (1m) is used for any kind of request. Nir Soffer (3): examples: copy-libev.c: Improve polling examples: copy-libev.c: Improve debug logs examples: copy-libev.c: Support extents examples/copy-libev.c | 279 ++++++++++++++++++++++++++++++++++++++---- 1 file changed, 256 insertions(+), 23 deletions(-) -- 2.26.2
Based on lib/poll.c, we should not invoke both notify_read() and notify_write() on the same event, since the first call may change the handle state and invalided the write event. When having both read and write event, prefer the read event since it is is a reply for older command. When returning events, use switch case for more efficient conversion from libnbd events to libev events. Signed-off-by: Nir Soffer <nsoffer@redhat.com> --- examples/copy-libev.c | 24 ++++++++++++++++-------- 1 file changed, 16 insertions(+), 8 deletions(-) diff --git a/examples/copy-libev.c b/examples/copy-libev.c index 1b1e9df..3f687a1 100644 --- a/examples/copy-libev.c +++ b/examples/copy-libev.c @@ -119,16 +119,20 @@ get_fd(struct connection *c) static inline int get_events(struct connection *c) { - int events = 0; unsigned dir = nbd_aio_get_direction (c->nbd); - if (dir & LIBNBD_AIO_DIRECTION_WRITE) - events |= EV_WRITE; + switch (dir) { + case LIBNBD_AIO_DIRECTION_READ: + return EV_READ; + case LIBNBD_AIO_DIRECTION_WRITE: + return EV_WRITE; + case LIBNBD_AIO_DIRECTION_BOTH: + return EV_READ | EV_WRITE; + default: + return 0; + } - if (dir & LIBNBD_AIO_DIRECTION_READ) - events |= EV_READ; - return events; } /* Start async copy or zero request. */ @@ -241,11 +245,15 @@ io_cb (struct ev_loop *loop, ev_io *w, int revents) { struct connection *c = (struct connection *)w; - if (revents & EV_WRITE) - nbd_aio_notify_write (c->nbd); + /* Based on lib/poll.c, we need to prefer read over write, and avoid + * invoking both notify_read() and notify_write(), since notify_read() may + * change the state of the handle. + */ if (revents & EV_READ) nbd_aio_notify_read (c->nbd); + else if (revents & EV_WRITE) + nbd_aio_notify_write (c->nbd); } static inline void -- 2.26.2
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@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
On Mon, Mar 8, 2021 at 5:14 PM Eric Blake <eblake@redhat.com> wrote:
On 3/6/21 3:21 PM, Nir Soffer wrote:
Us COPY_LIBEV_DEBUG instead of LIBNBD_DEBUG, since libnbd debug output
Use
Thanks, will fix this before pushing.
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
Handling extents is complicated, in particular when using async block status. But I could not get this working using sync block status; It seems that libnbd eats the events on the source, and then we hang forever waiting for inflight reads. Since getting extents is asynchronous, and starting new request depends on being able to get the next extent, requests have now a new a waiting state. When a request is started when extents are not available, it is marked as waiting. When extents request is completed, we start all waiting requests. Here is example log showing whats going on while copying fedora 32 image: The first request detect that we don't have extents yet, so it starts aync block status request. copy-libev: r0: start extents offset=0 count=134217728 copy-libev: r0: received 14 extents for base:allocation copy-libev: r0: extents completed time=0.001098 When extent request completes, we start al waiting requests. The first request (r0) looked into the first extent (e0) and consumed all of it: copy-libev: r0: start request offset=0 copy-libev: e0: offset=0 len=65536 zero=0 copy-libev: r0: extent offset=0 len=65536 zero=0 copy-libev: r0: start read offset=0 len=65536 The second request (r15) is looking into the second extent (e1) and consume all of it, starting a zero request: copy-libev: r15: start request offset=65536 copy-libev: e1: offset=65536 len=983040 zero=1 copy-libev: r15: extent offset=65536 len=983040 zero=1 copy-libev: r15: start zero offset=65536 len=983040 ... Request (r12) looked into the fifth extent (e4), but since this extent was large (10747904), it consume only 1m from it: copy-libev: r12: start request offset=2097152 copy-libev: e4: offset=2097152 len=10747904 zero=0 copy-libev: r12: extent offset=2097152 len=1048576 zero=0 copy-libev: r12: start read offset=2097152 len=1048576 The next request consumed the next 1m from the same extent (e4): copy-libev: r11: start request offset=3145728 copy-libev: e4: offset=3145728 len=9699328 zero=0 copy-libev: r11: extent offset=3145728 len=1048576 zero=0 copy-libev: r11: start read offset=3145728 len=1048576 copy-libev: r10: start request offset=4194304 .. The last part of extent e4 was consumed, and we switched to extent e5: copy-libev: r2: start request offset=12582912 copy-libev: e4: offset=12582912 len=262144 zero=0 copy-libev: r2: extent offset=12582912 len=262144 zero=0 copy-libev: r2: start read offset=12582912 len=262144 copy-libev: r1: start request offset=12845056 copy-libev: e5: offset=12845056 len=131072 zero=1 copy-libev: r1: extent offset=12845056 len=131072 zero=1 copy-libev: r1: start zero offset=12845056 len=131072 ... Request (r11) consumed the last extent (e13), starting a zero request. This free the extents array: copy-libev: r11: start request offset=133955584 copy-libev: e13: offset=133955584 len=262144 zero=1 copy-libev: r11: extent offset=133955584 len=262144 zero=1 copy-libev: r11: consumed all extents offset=134217728 copy-libev: r11: start zero offset=133955584 len=262144 ... Request (r12) started when extents array as cleared, so it started new block status request: copy-libev: r12: start extents offset=134217728 count=134217728 ... copy-libev: r12: received 3 extents for base:allocation copy-libev: r12: extents completed time=0.003027 ... The rest of the flow is same as before. When all requests are done, we shutdown the event loop and flush: copy-libev: r4: request completed offset=6438256640 len=1048576 time=0.000132 copy-libev: r1: read completed offset=6442385408 len=65536 copy-libev: r1: start write offset=6442385408 len=65536 copy-libev: r14: request completed offset=6439305216 len=1048576 time=0.000126 copy-libev: r8: request completed offset=6440353792 len=1048576 time=0.000151 copy-libev: r2: request completed offset=6441402368 len=983040 time=0.000143 copy-libev: r1: request completed offset=6442385408 len=65536 time=0.000142 copy-libev: flush Signed-off-by: Nir Soffer <nsoffer@redhat.com> --- examples/copy-libev.c | 232 ++++++++++++++++++++++++++++++++++++++++-- 1 file changed, 224 insertions(+), 8 deletions(-) diff --git a/examples/copy-libev.c b/examples/copy-libev.c index 84d5c03..3030955 100644 --- a/examples/copy-libev.c +++ b/examples/copy-libev.c @@ -41,6 +41,7 @@ */ #define MAX_REQUESTS 16 #define REQUEST_SIZE (1024 * 1024) +#define EXTENTS_SIZE (128 * 1024 * 1024) #define MIN(a,b) (a) < (b) ? (a) : (b) @@ -62,14 +63,18 @@ struct connection { ev_io watcher; struct nbd_handle *nbd; bool can_zero; + bool can_extents; }; struct request { + ev_timer watcher; /* For starting on next loop iteration. */ int64_t offset; size_t length; + bool zero; unsigned char *data; size_t index; ev_tstamp started; + bool waiting; /* Waiting for extents completion. */ }; static struct ev_loop *loop; @@ -77,11 +82,29 @@ static ev_prepare prepare; static struct connection src; static struct connection dst; static struct request requests[MAX_REQUESTS]; + +/* List of extents received from source server. Using the same format returned + * by libnbd, array of uint32_t pairs. The first item is the length of the + * extent, and the second is the extent flags. + * + * The number of extents is extents_len / 2. extents_pos is the index of the + * current extent. + * + * extents_in_progress flag is set when we start asynchronous block status + * request. + */ +static uint32_t *extents; +static size_t extents_len; +static size_t extents_pos; +static bool extents_in_progress; + static int64_t size; static int64_t offset; static int64_t written; static bool debug; +static inline void start_request_soon (struct request *r); +static void start_request_cb (struct ev_loop *loop, ev_timer *w, int revents); static void start_request(struct request *r); static void start_read(struct request *r); static void start_write(struct request *r); @@ -133,23 +156,206 @@ get_events(struct connection *c) default: return 0; } +} + +static int +extent_callback (void *user_data, const char *metacontext, uint64_t offset, + uint32_t *entries, size_t nr_entries, int *error) +{ + struct request *r = user_data; + + if (strcmp (metacontext, LIBNBD_CONTEXT_BASE_ALLOCATION) != 0) { + DEBUG ("Unexpected meta context: %s", metacontext); + return 1; + } + + extents = malloc (nr_entries * sizeof *extents); + if (extents == NULL) + FAIL ("Cannot allocated extents: %s", strerror (errno)); + + memcpy (extents, entries, nr_entries * sizeof *extents); + extents_len = nr_entries; + + DEBUG ("r%d: received %d extents for %s", + r->index, nr_entries / 2, metacontext); + + return 1; +} + +static int +extents_completed (void *user_data, int *error) +{ + struct request *r = (struct request *)user_data; + int i; + + DEBUG ("r%d: extents completed time=%.6f", + r->index, ev_now (loop) - r->started); + + extents_in_progress = false; + + if (extents == NULL) { + DEBUG ("r%d: received no extents, disabling extents", r->index); + src.can_extents = false; + } + /* Start requests waiting for extents completion on the next loop + * iteration, to avoid deadlock if we need to start a read. + */ + for (i = 0; i < MAX_REQUESTS; i++) { + struct request *r = &requests[i]; + if (r->waiting) { + r->waiting = false; + start_request_soon (r); + } + } + return 1; +} + +static bool +start_extents (struct request *r) +{ + size_t count = MIN (EXTENTS_SIZE, size - offset); + int64_t cookie; + + if (extents_in_progress) { + r->waiting = true; + return true; + } + + DEBUG ("r%d: start extents offset=%ld count=%ld", r->index, offset, count); + + cookie = nbd_aio_block_status ( + src.nbd, count, offset, + (nbd_extent_callback) { .callback=extent_callback, + .user_data=r }, + (nbd_completion_callback) { .callback=extents_completed, + .user_data=r }, + 0); + if (cookie == -1) { + DEBUG ("Cannot get extents: %s", nbd_get_error ()); + src.can_extents = false; + return false; + } + + r->waiting = true; + extents_in_progress = true; + + return true; +} + +/* Return next extent to process. */ +static void +next_extent (struct request *r) +{ + uint32_t limit = MIN (REQUEST_SIZE, size - offset); + uint32_t length = 0; + bool is_zero; + + assert (extents); + + is_zero = extents[extents_pos + 1] & LIBNBD_STATE_ZERO; + + while (length < limit) { + DEBUG ("e%d: offset=%ld len=%ld zero=%d", + extents_pos / 2, offset, extents[extents_pos], is_zero); + + /* If this extent is too large, steal some data from it to + * complete the request. + */ + if (length + extents[extents_pos] > limit) { + uint32_t stolen = limit - length; + + extents[extents_pos] -= stolen; + length += stolen; + break; + } + + /* Consume the entire extent and start looking at the next one. */ + length += extents[extents_pos]; + extents[extents_pos] = 0; + + if (extents_pos + 2 == extents_len) + break; + + extents_pos += 2; + + /* If next extent is different, we are done. */ + if ((extents[extents_pos + 1] & LIBNBD_STATE_ZERO) != is_zero) + break; + } + + assert (length > 0 && length <= limit); + + r->offset = offset; + r->length = length; + r->zero = is_zero; + + DEBUG ("r%d: extent offset=%ld len=%ld zero=%d", + r->index, r->offset, r->length, r->zero); + + offset += length; + + if (extents_pos + 2 == extents_len && extents[extents_pos] == 0) { + /* Processed all extents, clear extents. */ + DEBUG ("r%d: consumed all extents offset=%ld", r->index, offset); + free (extents); + extents = NULL; + extents_pos = 0; + extents_len = 0; + } +} + +static inline void +start_request_soon (struct request *r) +{ + ev_timer_init (&r->watcher, start_request_cb, 0, 0); + ev_timer_start (loop, &r->watcher); +} + +static void +start_request_cb (struct ev_loop *loop, ev_timer *w, int revents) +{ + struct request *r = (struct request *)w; + start_request (r); } /* Start async copy or zero request. */ static void start_request(struct request *r) { - assert (offset < size); + /* Cancel the request if we are done. */ + if (offset == size) + return; r->started = ev_now (loop); - r->length = MIN (REQUEST_SIZE, size - offset); - r->offset = offset; - start_read (r); - - offset += r->length; + /* If needed, get more extents from server. */ + if (src.can_extents && extents == NULL && start_extents (r)) + return; + + DEBUG ("r%d: start request offset=%ld", r->index, offset); + + if (src.can_extents) { + /* Handle the next extent. */ + next_extent (r); + if (r->zero) { + if (dst.can_zero) { + start_zero (r); + } else { + memset (r->data, 0, r->length); + start_write (r); + } + } else { + start_read (r); + } + } else { + /* Extents not available. */ + r->length = MIN (REQUEST_SIZE, size - offset); + r->offset = offset; + start_read (r); + offset += r->length; + } } static void @@ -240,9 +446,11 @@ request_completed (void *user_data, int *error) ev_break (loop, EVBREAK_ALL); } - /* If we have data to read, start a new read. */ + /* If we have more work, start a new request on the next loop + * iteration, to avoid deadlock if we need to start a zero or write. + */ if (offset < size) - start_request(r); + start_request_soon(r); return 1; } @@ -304,11 +512,19 @@ main (int argc, char *argv[]) debug = getenv ("COPY_LIBEV_DEBUG") != NULL; + /* Configure soruce to report extents. */ + + if (nbd_add_meta_context (src.nbd, LIBNBD_CONTEXT_BASE_ALLOCATION)) + FAIL ("Cannot add base:allocation: %s", nbd_get_error ()); + /* Connecting is fast, so use the syncronous API. */ if (nbd_connect_uri (src.nbd, argv[1])) FAIL ("Cannot connect to source: %s", nbd_get_error ()); + src.can_extents = nbd_can_meta_context ( + src.nbd, LIBNBD_CONTEXT_BASE_ALLOCATION) > 0; + if (nbd_connect_uri (dst.nbd, argv[2])) FAIL ("Cannot connect to destination: %s", nbd_get_error ()); -- 2.26.2
On Sat, Mar 06, 2021 at 11:21:22PM +0200, Nir Soffer wrote:
Handling extents is complicated, in particular when using async block status. But I could not get this working using sync block status; It seems that libnbd eats the events on the source, and then we hang forever waiting for inflight reads.
Is this a bug in libnbd? Also is libev going to be faster than poll(2) [as used by nbdcopy] for copying? I would imagine that it should make hardly any difference since we're only using a couple of file descriptors with poll(2) in nbdcopy, and it's my understanding that poll(2) is only pessimal when you have to poll large numbers of FDs. Anyway patch series is fine, ACK. Rich.
Since getting extents is asynchronous, and starting new request depends on being able to get the next extent, requests have now a new a waiting state. When a request is started when extents are not available, it is marked as waiting. When extents request is completed, we start all waiting requests.
Here is example log showing whats going on while copying fedora 32 image:
The first request detect that we don't have extents yet, so it starts aync block status request.
copy-libev: r0: start extents offset=0 count=134217728 copy-libev: r0: received 14 extents for base:allocation copy-libev: r0: extents completed time=0.001098
When extent request completes, we start al waiting requests. The first request (r0) looked into the first extent (e0) and consumed all of it:
copy-libev: r0: start request offset=0 copy-libev: e0: offset=0 len=65536 zero=0 copy-libev: r0: extent offset=0 len=65536 zero=0 copy-libev: r0: start read offset=0 len=65536
The second request (r15) is looking into the second extent (e1) and consume all of it, starting a zero request:
copy-libev: r15: start request offset=65536 copy-libev: e1: offset=65536 len=983040 zero=1 copy-libev: r15: extent offset=65536 len=983040 zero=1 copy-libev: r15: start zero offset=65536 len=983040
...
Request (r12) looked into the fifth extent (e4), but since this extent was large (10747904), it consume only 1m from it:
copy-libev: r12: start request offset=2097152 copy-libev: e4: offset=2097152 len=10747904 zero=0 copy-libev: r12: extent offset=2097152 len=1048576 zero=0 copy-libev: r12: start read offset=2097152 len=1048576
The next request consumed the next 1m from the same extent (e4):
copy-libev: r11: start request offset=3145728 copy-libev: e4: offset=3145728 len=9699328 zero=0 copy-libev: r11: extent offset=3145728 len=1048576 zero=0 copy-libev: r11: start read offset=3145728 len=1048576 copy-libev: r10: start request offset=4194304
..
The last part of extent e4 was consumed, and we switched to extent e5:
copy-libev: r2: start request offset=12582912 copy-libev: e4: offset=12582912 len=262144 zero=0 copy-libev: r2: extent offset=12582912 len=262144 zero=0 copy-libev: r2: start read offset=12582912 len=262144 copy-libev: r1: start request offset=12845056 copy-libev: e5: offset=12845056 len=131072 zero=1 copy-libev: r1: extent offset=12845056 len=131072 zero=1 copy-libev: r1: start zero offset=12845056 len=131072
...
Request (r11) consumed the last extent (e13), starting a zero request. This free the extents array:
copy-libev: r11: start request offset=133955584 copy-libev: e13: offset=133955584 len=262144 zero=1 copy-libev: r11: extent offset=133955584 len=262144 zero=1 copy-libev: r11: consumed all extents offset=134217728 copy-libev: r11: start zero offset=133955584 len=262144
...
Request (r12) started when extents array as cleared, so it started new block status request:
copy-libev: r12: start extents offset=134217728 count=134217728 ... copy-libev: r12: received 3 extents for base:allocation copy-libev: r12: extents completed time=0.003027
...
The rest of the flow is same as before. When all requests are done, we shutdown the event loop and flush:
copy-libev: r4: request completed offset=6438256640 len=1048576 time=0.000132 copy-libev: r1: read completed offset=6442385408 len=65536 copy-libev: r1: start write offset=6442385408 len=65536 copy-libev: r14: request completed offset=6439305216 len=1048576 time=0.000126 copy-libev: r8: request completed offset=6440353792 len=1048576 time=0.000151 copy-libev: r2: request completed offset=6441402368 len=983040 time=0.000143 copy-libev: r1: request completed offset=6442385408 len=65536 time=0.000142 copy-libev: flush
Signed-off-by: Nir Soffer <nsoffer@redhat.com> --- examples/copy-libev.c | 232 ++++++++++++++++++++++++++++++++++++++++-- 1 file changed, 224 insertions(+), 8 deletions(-)
diff --git a/examples/copy-libev.c b/examples/copy-libev.c index 84d5c03..3030955 100644 --- a/examples/copy-libev.c +++ b/examples/copy-libev.c @@ -41,6 +41,7 @@ */ #define MAX_REQUESTS 16 #define REQUEST_SIZE (1024 * 1024) +#define EXTENTS_SIZE (128 * 1024 * 1024)
#define MIN(a,b) (a) < (b) ? (a) : (b)
@@ -62,14 +63,18 @@ struct connection { ev_io watcher; struct nbd_handle *nbd; bool can_zero; + bool can_extents; };
struct request { + ev_timer watcher; /* For starting on next loop iteration. */ int64_t offset; size_t length; + bool zero; unsigned char *data; size_t index; ev_tstamp started; + bool waiting; /* Waiting for extents completion. */ };
static struct ev_loop *loop; @@ -77,11 +82,29 @@ static ev_prepare prepare; static struct connection src; static struct connection dst; static struct request requests[MAX_REQUESTS]; + +/* List of extents received from source server. Using the same format returned + * by libnbd, array of uint32_t pairs. The first item is the length of the + * extent, and the second is the extent flags. + * + * The number of extents is extents_len / 2. extents_pos is the index of the + * current extent. + * + * extents_in_progress flag is set when we start asynchronous block status + * request. + */ +static uint32_t *extents; +static size_t extents_len; +static size_t extents_pos; +static bool extents_in_progress; + static int64_t size; static int64_t offset; static int64_t written; static bool debug;
+static inline void start_request_soon (struct request *r); +static void start_request_cb (struct ev_loop *loop, ev_timer *w, int revents); static void start_request(struct request *r); static void start_read(struct request *r); static void start_write(struct request *r); @@ -133,23 +156,206 @@ get_events(struct connection *c) default: return 0; } +} + +static int +extent_callback (void *user_data, const char *metacontext, uint64_t offset, + uint32_t *entries, size_t nr_entries, int *error) +{ + struct request *r = user_data; + + if (strcmp (metacontext, LIBNBD_CONTEXT_BASE_ALLOCATION) != 0) { + DEBUG ("Unexpected meta context: %s", metacontext); + return 1; + } + + extents = malloc (nr_entries * sizeof *extents); + if (extents == NULL) + FAIL ("Cannot allocated extents: %s", strerror (errno)); + + memcpy (extents, entries, nr_entries * sizeof *extents); + extents_len = nr_entries; + + DEBUG ("r%d: received %d extents for %s", + r->index, nr_entries / 2, metacontext); + + return 1; +} + +static int +extents_completed (void *user_data, int *error) +{ + struct request *r = (struct request *)user_data; + int i; + + DEBUG ("r%d: extents completed time=%.6f", + r->index, ev_now (loop) - r->started); + + extents_in_progress = false; + + if (extents == NULL) { + DEBUG ("r%d: received no extents, disabling extents", r->index); + src.can_extents = false; + }
+ /* Start requests waiting for extents completion on the next loop + * iteration, to avoid deadlock if we need to start a read. + */ + for (i = 0; i < MAX_REQUESTS; i++) { + struct request *r = &requests[i]; + if (r->waiting) { + r->waiting = false; + start_request_soon (r); + } + }
+ return 1; +} + +static bool +start_extents (struct request *r) +{ + size_t count = MIN (EXTENTS_SIZE, size - offset); + int64_t cookie; + + if (extents_in_progress) { + r->waiting = true; + return true; + } + + DEBUG ("r%d: start extents offset=%ld count=%ld", r->index, offset, count); + + cookie = nbd_aio_block_status ( + src.nbd, count, offset, + (nbd_extent_callback) { .callback=extent_callback, + .user_data=r }, + (nbd_completion_callback) { .callback=extents_completed, + .user_data=r }, + 0); + if (cookie == -1) { + DEBUG ("Cannot get extents: %s", nbd_get_error ()); + src.can_extents = false; + return false; + } + + r->waiting = true; + extents_in_progress = true; + + return true; +} + +/* Return next extent to process. */ +static void +next_extent (struct request *r) +{ + uint32_t limit = MIN (REQUEST_SIZE, size - offset); + uint32_t length = 0; + bool is_zero; + + assert (extents); + + is_zero = extents[extents_pos + 1] & LIBNBD_STATE_ZERO; + + while (length < limit) { + DEBUG ("e%d: offset=%ld len=%ld zero=%d", + extents_pos / 2, offset, extents[extents_pos], is_zero); + + /* If this extent is too large, steal some data from it to + * complete the request. + */ + if (length + extents[extents_pos] > limit) { + uint32_t stolen = limit - length; + + extents[extents_pos] -= stolen; + length += stolen; + break; + } + + /* Consume the entire extent and start looking at the next one. */ + length += extents[extents_pos]; + extents[extents_pos] = 0; + + if (extents_pos + 2 == extents_len) + break; + + extents_pos += 2; + + /* If next extent is different, we are done. */ + if ((extents[extents_pos + 1] & LIBNBD_STATE_ZERO) != is_zero) + break; + } + + assert (length > 0 && length <= limit); + + r->offset = offset; + r->length = length; + r->zero = is_zero; + + DEBUG ("r%d: extent offset=%ld len=%ld zero=%d", + r->index, r->offset, r->length, r->zero); + + offset += length; + + if (extents_pos + 2 == extents_len && extents[extents_pos] == 0) { + /* Processed all extents, clear extents. */ + DEBUG ("r%d: consumed all extents offset=%ld", r->index, offset); + free (extents); + extents = NULL; + extents_pos = 0; + extents_len = 0; + } +} + +static inline void +start_request_soon (struct request *r) +{ + ev_timer_init (&r->watcher, start_request_cb, 0, 0); + ev_timer_start (loop, &r->watcher); +} + +static void +start_request_cb (struct ev_loop *loop, ev_timer *w, int revents) +{ + struct request *r = (struct request *)w; + start_request (r); }
/* Start async copy or zero request. */ static void start_request(struct request *r) { - assert (offset < size); + /* Cancel the request if we are done. */ + if (offset == size) + return;
r->started = ev_now (loop); - r->length = MIN (REQUEST_SIZE, size - offset); - r->offset = offset;
- start_read (r); - - offset += r->length; + /* If needed, get more extents from server. */ + if (src.can_extents && extents == NULL && start_extents (r)) + return; + + DEBUG ("r%d: start request offset=%ld", r->index, offset); + + if (src.can_extents) { + /* Handle the next extent. */ + next_extent (r); + if (r->zero) { + if (dst.can_zero) { + start_zero (r); + } else { + memset (r->data, 0, r->length); + start_write (r); + } + } else { + start_read (r); + } + } else { + /* Extents not available. */ + r->length = MIN (REQUEST_SIZE, size - offset); + r->offset = offset; + start_read (r); + offset += r->length; + } }
static void @@ -240,9 +446,11 @@ request_completed (void *user_data, int *error) ev_break (loop, EVBREAK_ALL); }
- /* If we have data to read, start a new read. */ + /* If we have more work, start a new request on the next loop + * iteration, to avoid deadlock if we need to start a zero or write. + */ if (offset < size) - start_request(r); + start_request_soon(r);
return 1; } @@ -304,11 +512,19 @@ main (int argc, char *argv[])
debug = getenv ("COPY_LIBEV_DEBUG") != NULL;
+ /* Configure soruce to report extents. */ + + if (nbd_add_meta_context (src.nbd, LIBNBD_CONTEXT_BASE_ALLOCATION)) + FAIL ("Cannot add base:allocation: %s", nbd_get_error ()); + /* Connecting is fast, so use the syncronous API. */
if (nbd_connect_uri (src.nbd, argv[1])) FAIL ("Cannot connect to source: %s", nbd_get_error ());
+ src.can_extents = nbd_can_meta_context ( + src.nbd, LIBNBD_CONTEXT_BASE_ALLOCATION) > 0; + if (nbd_connect_uri (dst.nbd, argv[2])) FAIL ("Cannot connect to destination: %s", nbd_get_error ());
-- 2.26.2
-- Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones Read my programming and virtualization blog: http://rwmj.wordpress.com virt-builder quickly builds VMs from scratch http://libguestfs.org/virt-builder.1.html
On Mon, Mar 8, 2021 at 12:25 AM Richard W.M. Jones <rjones@redhat.com> wrote:
On Sat, Mar 06, 2021 at 11:21:22PM +0200, Nir Soffer wrote:
Handling extents is complicated, in particular when using async block status. But I could not get this working using sync block status; It seems that libnbd eats the events on the source, and then we hang forever waiting for inflight reads.
Is this a bug in libnbd?
Maybe, I can try to post a simple reproducer later. Even if this is not a bug it would be nice to show how sync calls can be mixed with async call with libev (or another event loop). Also is libev going to be faster than poll(2) [as used by nbdcopy] for
copying? I would imagine that it should make hardly any difference since we're only using a couple of file descriptors with poll(2) in nbdcopy, and it's my understanding that poll(2) is only pessimal when you have to poll large numbers of FDs.
I think that poll or select should be faster for 2 file descriptors, but the difference is negligible in this context. The advantage in using an event loop is an easier way to extend the application, for example I'm using async block status, this will be much harder to do in nbdcopy. Another advantage is adding more features like handling signals, timeouts, child processes, or other other network protocols (e.g. nbd <-> http).
Anyway patch series is fine, ACK.
Rich.
Since getting extents is asynchronous, and starting new request depends on being able to get the next extent, requests have now a new a waiting state. When a request is started when extents are not available, it is marked as waiting. When extents request is completed, we start all waiting requests.
Here is example log showing whats going on while copying fedora 32 image:
The first request detect that we don't have extents yet, so it starts aync block status request.
copy-libev: r0: start extents offset=0 count=134217728 copy-libev: r0: received 14 extents for base:allocation copy-libev: r0: extents completed time=0.001098
When extent request completes, we start al waiting requests. The first request (r0) looked into the first extent (e0) and consumed all of it:
copy-libev: r0: start request offset=0 copy-libev: e0: offset=0 len=65536 zero=0 copy-libev: r0: extent offset=0 len=65536 zero=0 copy-libev: r0: start read offset=0 len=65536
The second request (r15) is looking into the second extent (e1) and consume all of it, starting a zero request:
copy-libev: r15: start request offset=65536 copy-libev: e1: offset=65536 len=983040 zero=1 copy-libev: r15: extent offset=65536 len=983040 zero=1 copy-libev: r15: start zero offset=65536 len=983040
...
Request (r12) looked into the fifth extent (e4), but since this extent was large (10747904), it consume only 1m from it:
copy-libev: r12: start request offset=2097152 copy-libev: e4: offset=2097152 len=10747904 zero=0 copy-libev: r12: extent offset=2097152 len=1048576 zero=0 copy-libev: r12: start read offset=2097152 len=1048576
The next request consumed the next 1m from the same extent (e4):
copy-libev: r11: start request offset=3145728 copy-libev: e4: offset=3145728 len=9699328 zero=0 copy-libev: r11: extent offset=3145728 len=1048576 zero=0 copy-libev: r11: start read offset=3145728 len=1048576 copy-libev: r10: start request offset=4194304
..
The last part of extent e4 was consumed, and we switched to extent e5:
copy-libev: r2: start request offset=12582912 copy-libev: e4: offset=12582912 len=262144 zero=0 copy-libev: r2: extent offset=12582912 len=262144 zero=0 copy-libev: r2: start read offset=12582912 len=262144 copy-libev: r1: start request offset=12845056 copy-libev: e5: offset=12845056 len=131072 zero=1 copy-libev: r1: extent offset=12845056 len=131072 zero=1 copy-libev: r1: start zero offset=12845056 len=131072
...
Request (r11) consumed the last extent (e13), starting a zero request. This free the extents array:
copy-libev: r11: start request offset=133955584 copy-libev: e13: offset=133955584 len=262144 zero=1 copy-libev: r11: extent offset=133955584 len=262144 zero=1 copy-libev: r11: consumed all extents offset=134217728 copy-libev: r11: start zero offset=133955584 len=262144
...
Request (r12) started when extents array as cleared, so it started new block status request:
copy-libev: r12: start extents offset=134217728 count=134217728 ... copy-libev: r12: received 3 extents for base:allocation copy-libev: r12: extents completed time=0.003027
...
The rest of the flow is same as before. When all requests are done, we shutdown the event loop and flush:
copy-libev: r4: request completed offset=6438256640 len=1048576 time=0.000132 copy-libev: r1: read completed offset=6442385408 len=65536 copy-libev: r1: start write offset=6442385408 len=65536 copy-libev: r14: request completed offset=6439305216 len=1048576 time=0.000126 copy-libev: r8: request completed offset=6440353792 len=1048576 time=0.000151 copy-libev: r2: request completed offset=6441402368 len=983040 time=0.000143 copy-libev: r1: request completed offset=6442385408 len=65536 time=0.000142 copy-libev: flush
Signed-off-by: Nir Soffer <nsoffer@redhat.com> --- examples/copy-libev.c | 232 ++++++++++++++++++++++++++++++++++++++++-- 1 file changed, 224 insertions(+), 8 deletions(-)
diff --git a/examples/copy-libev.c b/examples/copy-libev.c index 84d5c03..3030955 100644 --- a/examples/copy-libev.c +++ b/examples/copy-libev.c @@ -41,6 +41,7 @@ */ #define MAX_REQUESTS 16 #define REQUEST_SIZE (1024 * 1024) +#define EXTENTS_SIZE (128 * 1024 * 1024)
#define MIN(a,b) (a) < (b) ? (a) : (b)
@@ -62,14 +63,18 @@ struct connection { ev_io watcher; struct nbd_handle *nbd; bool can_zero; + bool can_extents; };
struct request { + ev_timer watcher; /* For starting on next loop iteration. */ int64_t offset; size_t length; + bool zero; unsigned char *data; size_t index; ev_tstamp started; + bool waiting; /* Waiting for extents completion. */ };
static struct ev_loop *loop; @@ -77,11 +82,29 @@ static ev_prepare prepare; static struct connection src; static struct connection dst; static struct request requests[MAX_REQUESTS]; + +/* List of extents received from source server. Using the same format returned + * by libnbd, array of uint32_t pairs. The first item is the length of the + * extent, and the second is the extent flags. + * + * The number of extents is extents_len / 2. extents_pos is the index of the + * current extent. + * + * extents_in_progress flag is set when we start asynchronous block status + * request. + */ +static uint32_t *extents; +static size_t extents_len; +static size_t extents_pos; +static bool extents_in_progress; + static int64_t size; static int64_t offset; static int64_t written; static bool debug;
+static inline void start_request_soon (struct request *r); +static void start_request_cb (struct ev_loop *loop, ev_timer *w, int revents); static void start_request(struct request *r); static void start_read(struct request *r); static void start_write(struct request *r); @@ -133,23 +156,206 @@ get_events(struct connection *c) default: return 0; } +} + +static int +extent_callback (void *user_data, const char *metacontext, uint64_t offset, + uint32_t *entries, size_t nr_entries, int *error) +{ + struct request *r = user_data; + + if (strcmp (metacontext, LIBNBD_CONTEXT_BASE_ALLOCATION) != 0) { + DEBUG ("Unexpected meta context: %s", metacontext); + return 1; + } + + extents = malloc (nr_entries * sizeof *extents); + if (extents == NULL) + FAIL ("Cannot allocated extents: %s", strerror (errno)); + + memcpy (extents, entries, nr_entries * sizeof *extents); + extents_len = nr_entries; + + DEBUG ("r%d: received %d extents for %s", + r->index, nr_entries / 2, metacontext); + + return 1; +} + +static int +extents_completed (void *user_data, int *error) +{ + struct request *r = (struct request *)user_data; + int i; + + DEBUG ("r%d: extents completed time=%.6f", + r->index, ev_now (loop) - r->started); + + extents_in_progress = false; + + if (extents == NULL) { + DEBUG ("r%d: received no extents, disabling extents", r->index); + src.can_extents = false; + }
+ /* Start requests waiting for extents completion on the next loop + * iteration, to avoid deadlock if we need to start a read. + */ + for (i = 0; i < MAX_REQUESTS; i++) { + struct request *r = &requests[i]; + if (r->waiting) { + r->waiting = false; + start_request_soon (r); + } + }
+ return 1; +} + +static bool +start_extents (struct request *r) +{ + size_t count = MIN (EXTENTS_SIZE, size - offset); + int64_t cookie; + + if (extents_in_progress) { + r->waiting = true; + return true; + } + + DEBUG ("r%d: start extents offset=%ld count=%ld", r->index, offset, count); + + cookie = nbd_aio_block_status ( + src.nbd, count, offset, + (nbd_extent_callback) { .callback=extent_callback, + .user_data=r }, + (nbd_completion_callback) { .callback=extents_completed, + .user_data=r }, + 0); + if (cookie == -1) { + DEBUG ("Cannot get extents: %s", nbd_get_error ()); + src.can_extents = false; + return false; + } + + r->waiting = true; + extents_in_progress = true; + + return true; +} + +/* Return next extent to process. */ +static void +next_extent (struct request *r) +{ + uint32_t limit = MIN (REQUEST_SIZE, size - offset); + uint32_t length = 0; + bool is_zero; + + assert (extents); + + is_zero = extents[extents_pos + 1] & LIBNBD_STATE_ZERO; + + while (length < limit) { + DEBUG ("e%d: offset=%ld len=%ld zero=%d", + extents_pos / 2, offset, extents[extents_pos], is_zero); + + /* If this extent is too large, steal some data from it to + * complete the request. + */ + if (length + extents[extents_pos] > limit) { + uint32_t stolen = limit - length; + + extents[extents_pos] -= stolen; + length += stolen; + break; + } + + /* Consume the entire extent and start looking at the next one. */ + length += extents[extents_pos]; + extents[extents_pos] = 0; + + if (extents_pos + 2 == extents_len) + break; + + extents_pos += 2; + + /* If next extent is different, we are done. */ + if ((extents[extents_pos + 1] & LIBNBD_STATE_ZERO) != is_zero) + break; + } + + assert (length > 0 && length <= limit); + + r->offset = offset; + r->length = length; + r->zero = is_zero; + + DEBUG ("r%d: extent offset=%ld len=%ld zero=%d", + r->index, r->offset, r->length, r->zero); + + offset += length; + + if (extents_pos + 2 == extents_len && extents[extents_pos] == 0) { + /* Processed all extents, clear extents. */ + DEBUG ("r%d: consumed all extents offset=%ld", r->index, offset); + free (extents); + extents = NULL; + extents_pos = 0; + extents_len = 0; + } +} + +static inline void +start_request_soon (struct request *r) +{ + ev_timer_init (&r->watcher, start_request_cb, 0, 0); + ev_timer_start (loop, &r->watcher); +} + +static void +start_request_cb (struct ev_loop *loop, ev_timer *w, int revents) +{ + struct request *r = (struct request *)w; + start_request (r); }
/* Start async copy or zero request. */ static void start_request(struct request *r) { - assert (offset < size); + /* Cancel the request if we are done. */ + if (offset == size) + return;
r->started = ev_now (loop); - r->length = MIN (REQUEST_SIZE, size - offset); - r->offset = offset;
- start_read (r); - - offset += r->length; + /* If needed, get more extents from server. */ + if (src.can_extents && extents == NULL && start_extents (r)) + return; + + DEBUG ("r%d: start request offset=%ld", r->index, offset); + + if (src.can_extents) { + /* Handle the next extent. */ + next_extent (r); + if (r->zero) { + if (dst.can_zero) { + start_zero (r); + } else { + memset (r->data, 0, r->length); + start_write (r); + } + } else { + start_read (r); + } + } else { + /* Extents not available. */ + r->length = MIN (REQUEST_SIZE, size - offset); + r->offset = offset; + start_read (r); + offset += r->length; + } }
static void @@ -240,9 +446,11 @@ request_completed (void *user_data, int *error) ev_break (loop, EVBREAK_ALL); }
- /* If we have data to read, start a new read. */ + /* If we have more work, start a new request on the next loop + * iteration, to avoid deadlock if we need to start a zero or write. + */ if (offset < size) - start_request(r); + start_request_soon(r);
return 1; } @@ -304,11 +512,19 @@ main (int argc, char *argv[])
debug = getenv ("COPY_LIBEV_DEBUG") != NULL;
+ /* Configure soruce to report extents. */ + + if (nbd_add_meta_context (src.nbd, LIBNBD_CONTEXT_BASE_ALLOCATION)) + FAIL ("Cannot add base:allocation: %s", nbd_get_error ()); + /* Connecting is fast, so use the syncronous API. */
if (nbd_connect_uri (src.nbd, argv[1])) FAIL ("Cannot connect to source: %s", nbd_get_error ());
+ src.can_extents = nbd_can_meta_context ( + src.nbd, LIBNBD_CONTEXT_BASE_ALLOCATION) > 0; + if (nbd_connect_uri (dst.nbd, argv[2])) FAIL ("Cannot connect to destination: %s", nbd_get_error ());
-- 2.26.2
-- Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones Read my programming and virtualization blog: http://rwmj.wordpress.com virt-builder quickly builds VMs from scratch http://libguestfs.org/virt-builder.1.html
On Mon, Mar 8, 2021 at 12:59 AM Nir Soffer <nsoffer@redhat.com> wrote:
On Mon, Mar 8, 2021 at 12:25 AM Richard W.M. Jones <rjones@redhat.com> wrote:
On Sat, Mar 06, 2021 at 11:21:22PM +0200, Nir Soffer wrote:
Handling extents is complicated, in particular when using async block status. But I could not get this working using sync block status; It seems that libnbd eats the events on the source, and then we hang forever waiting for inflight reads.
Is this a bug in libnbd?
Maybe, I can try to post a simple reproducer later. Even if this is not a bug it would be nice to show how sync calls can be mixed with async call with libev (or another event loop).
Also is libev going to be faster than poll(2) [as used by nbdcopy] for
copying? I would imagine that it should make hardly any difference since we're only using a couple of file descriptors with poll(2) in nbdcopy, and it's my understanding that poll(2) is only pessimal when you have to poll large numbers of FDs.
I think that poll or select should be faster for 2 file descriptors, but the difference is negligible in this context.
Some data when copying fredora 32 qcow2 image to nbdkit memory plugin: $ strace -c ./copy-libev $SRC $DST % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 50.07 0.271421 17 15728 4 recvfrom 39.10 0.211987 30 6928 sendto 8.25 0.044734 4 9114 epoll_wait 1.13 0.006102 4 1335 epoll_ctl 1.01 0.005484 457 12 6 wait4 0.10 0.000522 4 122 mmap 0.06 0.000311 3 78 48 openat 0.05 0.000298 49 6 clone 0.04 0.000227 5 43 read 0.03 0.000143 3 42 close 0.02 0.000135 2 52 rt_sigprocmask 0.02 0.000132 3 37 rt_sigaction 0.02 0.000105 3 32 mprotect 0.02 0.000100 3 30 15 stat 0.02 0.000095 47 2 execve 0.01 0.000061 2 29 fstat 0.01 0.000044 4 9 poll 0.01 0.000038 2 16 pread64 0.00 0.000027 5 5 pipe 0.00 0.000021 1 13 brk 0.00 0.000019 3 6 rt_sigreturn 0.00 0.000017 1 11 2 ioctl 0.00 0.000015 7 2 munmap 0.00 0.000015 7 2 connect 0.00 0.000010 5 2 socket 0.00 0.000007 3 2 shutdown 0.00 0.000007 7 1 sysinfo 0.00 0.000005 2 2 getgid 0.00 0.000004 0 5 4 access 0.00 0.000004 2 2 getsockopt 0.00 0.000004 4 1 uname 0.00 0.000004 2 2 getuid 0.00 0.000004 2 2 geteuid 0.00 0.000004 2 2 getegid 0.00 0.000004 1 4 2 arch_prctl 0.00 0.000003 1 2 2 setsockopt 0.00 0.000002 0 5 lseek 0.00 0.000000 0 1 dup2 0.00 0.000000 0 2 getpid 0.00 0.000000 0 5 1 fcntl 0.00 0.000000 0 1 getppid 0.00 0.000000 0 1 getpgrp 0.00 0.000000 0 1 set_tid_address 0.00 0.000000 0 1 set_robust_list 0.00 0.000000 0 1 eventfd2 0.00 0.000000 0 1 epoll_create1 0.00 0.000000 0 3 prlimit64 0.00 0.000000 0 1 getrandom ------ ----------- ----------- --------- --------- ---------------- 100.00 0.542115 16 33704 84 total $ strace -f -c ../copy/nbdcopy --sparse=1048576 --request-size=1048576 --requests=16 --connections=1 $SRC $DST strace: Process 1094611 attached strace: Process 1094612 attached strace: Process 1094613 attached strace: Process 1094614 attached strace: Process 1094615 attached strace: Process 1094616 attached strace: Process 1094617 attached strace: Process 1094618 attached strace: Process 1094619 attached strace: Process 1094620 attached strace: Process 1094621 attached strace: Process 1094622 attached strace: Process 1094623 attached strace: Process 1094641 attached (Not sure why we start so many threads with --connections=1 - bug?) % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 58.10 0.881783 146963 6 futex 18.70 0.283841 17 16634 2 recvfrom 17.42 0.264326 31 8398 4 sendto 2.73 0.041494 4 8877 poll 1.97 0.029895 1299 23 10 wait4 0.46 0.006970 240 29 madvise 0.13 0.001903 6 311 mmap 0.09 0.001330 190 7 execve 0.07 0.001041 40 26 munmap 0.05 0.000825 5 157 67 openat 0.04 0.000557 5 100 mprotect 0.04 0.000548 4 113 read 0.04 0.000545 38 14 clone 0.03 0.000440 2 151 6 close 0.02 0.000329 3 97 fstat 0.02 0.000267 2 125 rt_sigprocmask 0.02 0.000251 3 66 pread64 0.01 0.000214 1 148 rt_sigaction 0.01 0.000188 18 10 statfs 0.01 0.000145 5 28 brk 0.01 0.000143 3 37 write 0.01 0.000140 5 24 10 access 0.01 0.000083 1 69 31 stat 0.00 0.000063 10 6 socket 0.00 0.000049 3 15 6 ioctl 0.00 0.000047 15 3 1 lstat 0.00 0.000045 7 6 4 connect 0.00 0.000032 4 8 pipe 0.00 0.000031 2 14 7 arch_prctl 0.00 0.000028 2 10 rt_sigreturn 0.00 0.000023 2 8 prlimit64 0.00 0.000021 3 7 set_robust_list 0.00 0.000019 3 6 set_tid_address 0.00 0.000011 11 1 lgetxattr 0.00 0.000009 4 2 shutdown 0.00 0.000008 1 6 lseek 0.00 0.000007 7 1 1 getxattr 0.00 0.000006 0 15 getpid 0.00 0.000006 6 1 sysinfo 0.00 0.000005 5 1 uname 0.00 0.000004 0 16 dup2 0.00 0.000000 0 2 2 setsockopt 0.00 0.000000 0 2 getsockopt 0.00 0.000000 0 4 1 fcntl 0.00 0.000000 0 1 chdir 0.00 0.000000 0 9 getuid 0.00 0.000000 0 9 getgid 0.00 0.000000 0 9 geteuid 0.00 0.000000 0 9 getegid 0.00 0.000000 0 1 getppid 0.00 0.000000 0 1 getpgrp 0.00 0.000000 0 2 getdents64 0.00 0.000000 0 1 getrandom ------ ----------- ----------- --------- --------- ---------------- 100.00 1.517672 42 35626 152 total If you want to use poll in libev, you can: diff --git a/examples/copy-libev.c b/examples/copy-libev.c index 6e6cbcb..1878f27 100644 --- a/examples/copy-libev.c +++ b/examples/copy-libev.c @@ -530,7 +530,7 @@ main (int argc, char *argv[]) { int i; - loop = EV_DEFAULT; + loop = ev_loop_new (EVBACKEND_POLL); if (argc != 3) FAIL ("Usage: %s src-uri dst-uri", PROG); But it does not look useful: $ strace -c ./copy-libev $SRC $DST % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 48.50 0.261526 16 15626 1 recvfrom 39.01 0.210365 30 7007 sendto 8.24 0.044413 4 9214 poll The advantage in using an event loop is an easier way to extend the
application, for example I'm using async block status, this will be much harder to do in nbdcopy.
Another advantage is adding more features like handling signals, timeouts, child processes, or other other network protocols (e.g. nbd <-> http).
Anyway patch series is fine, ACK.
Rich.
Since getting extents is asynchronous, and starting new request depends on being able to get the next extent, requests have now a new a waiting state. When a request is started when extents are not available, it is marked as waiting. When extents request is completed, we start all waiting requests.
Here is example log showing whats going on while copying fedora 32 image:
The first request detect that we don't have extents yet, so it starts aync block status request.
copy-libev: r0: start extents offset=0 count=134217728 copy-libev: r0: received 14 extents for base:allocation copy-libev: r0: extents completed time=0.001098
When extent request completes, we start al waiting requests. The first request (r0) looked into the first extent (e0) and consumed all of it:
copy-libev: r0: start request offset=0 copy-libev: e0: offset=0 len=65536 zero=0 copy-libev: r0: extent offset=0 len=65536 zero=0 copy-libev: r0: start read offset=0 len=65536
The second request (r15) is looking into the second extent (e1) and consume all of it, starting a zero request:
copy-libev: r15: start request offset=65536 copy-libev: e1: offset=65536 len=983040 zero=1 copy-libev: r15: extent offset=65536 len=983040 zero=1 copy-libev: r15: start zero offset=65536 len=983040
...
Request (r12) looked into the fifth extent (e4), but since this extent was large (10747904), it consume only 1m from it:
copy-libev: r12: start request offset=2097152 copy-libev: e4: offset=2097152 len=10747904 zero=0 copy-libev: r12: extent offset=2097152 len=1048576 zero=0 copy-libev: r12: start read offset=2097152 len=1048576
The next request consumed the next 1m from the same extent (e4):
copy-libev: r11: start request offset=3145728 copy-libev: e4: offset=3145728 len=9699328 zero=0 copy-libev: r11: extent offset=3145728 len=1048576 zero=0 copy-libev: r11: start read offset=3145728 len=1048576 copy-libev: r10: start request offset=4194304
..
The last part of extent e4 was consumed, and we switched to extent e5:
copy-libev: r2: start request offset=12582912 copy-libev: e4: offset=12582912 len=262144 zero=0 copy-libev: r2: extent offset=12582912 len=262144 zero=0 copy-libev: r2: start read offset=12582912 len=262144 copy-libev: r1: start request offset=12845056 copy-libev: e5: offset=12845056 len=131072 zero=1 copy-libev: r1: extent offset=12845056 len=131072 zero=1 copy-libev: r1: start zero offset=12845056 len=131072
...
Request (r11) consumed the last extent (e13), starting a zero request. This free the extents array:
copy-libev: r11: start request offset=133955584 copy-libev: e13: offset=133955584 len=262144 zero=1 copy-libev: r11: extent offset=133955584 len=262144 zero=1 copy-libev: r11: consumed all extents offset=134217728 copy-libev: r11: start zero offset=133955584 len=262144
...
Request (r12) started when extents array as cleared, so it started new block status request:
copy-libev: r12: start extents offset=134217728 count=134217728 ... copy-libev: r12: received 3 extents for base:allocation copy-libev: r12: extents completed time=0.003027
...
The rest of the flow is same as before. When all requests are done, we shutdown the event loop and flush:
copy-libev: r4: request completed offset=6438256640 len=1048576 time=0.000132 copy-libev: r1: read completed offset=6442385408 len=65536 copy-libev: r1: start write offset=6442385408 len=65536 copy-libev: r14: request completed offset=6439305216 len=1048576 time=0.000126 copy-libev: r8: request completed offset=6440353792 len=1048576 time=0.000151 copy-libev: r2: request completed offset=6441402368 len=983040 time=0.000143 copy-libev: r1: request completed offset=6442385408 len=65536 time=0.000142 copy-libev: flush
Signed-off-by: Nir Soffer <nsoffer@redhat.com> --- examples/copy-libev.c | 232 ++++++++++++++++++++++++++++++++++++++++-- 1 file changed, 224 insertions(+), 8 deletions(-)
diff --git a/examples/copy-libev.c b/examples/copy-libev.c index 84d5c03..3030955 100644 --- a/examples/copy-libev.c +++ b/examples/copy-libev.c @@ -41,6 +41,7 @@ */ #define MAX_REQUESTS 16 #define REQUEST_SIZE (1024 * 1024) +#define EXTENTS_SIZE (128 * 1024 * 1024)
#define MIN(a,b) (a) < (b) ? (a) : (b)
@@ -62,14 +63,18 @@ struct connection { ev_io watcher; struct nbd_handle *nbd; bool can_zero; + bool can_extents; };
struct request { + ev_timer watcher; /* For starting on next loop iteration. */ int64_t offset; size_t length; + bool zero; unsigned char *data; size_t index; ev_tstamp started; + bool waiting; /* Waiting for extents completion. */ };
static struct ev_loop *loop; @@ -77,11 +82,29 @@ static ev_prepare prepare; static struct connection src; static struct connection dst; static struct request requests[MAX_REQUESTS]; + +/* List of extents received from source server. Using the same format returned + * by libnbd, array of uint32_t pairs. The first item is the length of the + * extent, and the second is the extent flags. + * + * The number of extents is extents_len / 2. extents_pos is the index of the + * current extent. + * + * extents_in_progress flag is set when we start asynchronous block status + * request. + */ +static uint32_t *extents; +static size_t extents_len; +static size_t extents_pos; +static bool extents_in_progress; + static int64_t size; static int64_t offset; static int64_t written; static bool debug;
+static inline void start_request_soon (struct request *r); +static void start_request_cb (struct ev_loop *loop, ev_timer *w, int revents); static void start_request(struct request *r); static void start_read(struct request *r); static void start_write(struct request *r); @@ -133,23 +156,206 @@ get_events(struct connection *c) default: return 0; } +} + +static int +extent_callback (void *user_data, const char *metacontext, uint64_t offset, + uint32_t *entries, size_t nr_entries, int *error) +{ + struct request *r = user_data; + + if (strcmp (metacontext, LIBNBD_CONTEXT_BASE_ALLOCATION) != 0) { + DEBUG ("Unexpected meta context: %s", metacontext); + return 1; + } + + extents = malloc (nr_entries * sizeof *extents); + if (extents == NULL) + FAIL ("Cannot allocated extents: %s", strerror (errno)); + + memcpy (extents, entries, nr_entries * sizeof *extents); + extents_len = nr_entries; + + DEBUG ("r%d: received %d extents for %s", + r->index, nr_entries / 2, metacontext); + + return 1; +} + +static int +extents_completed (void *user_data, int *error) +{ + struct request *r = (struct request *)user_data; + int i; + + DEBUG ("r%d: extents completed time=%.6f", + r->index, ev_now (loop) - r->started); + + extents_in_progress = false; + + if (extents == NULL) { + DEBUG ("r%d: received no extents, disabling extents", r->index); + src.can_extents = false; + }
+ /* Start requests waiting for extents completion on the next loop + * iteration, to avoid deadlock if we need to start a read. + */ + for (i = 0; i < MAX_REQUESTS; i++) { + struct request *r = &requests[i]; + if (r->waiting) { + r->waiting = false; + start_request_soon (r); + } + }
+ return 1; +} + +static bool +start_extents (struct request *r) +{ + size_t count = MIN (EXTENTS_SIZE, size - offset); + int64_t cookie; + + if (extents_in_progress) { + r->waiting = true; + return true; + } + + DEBUG ("r%d: start extents offset=%ld count=%ld", r->index, offset, count); + + cookie = nbd_aio_block_status ( + src.nbd, count, offset, + (nbd_extent_callback) { .callback=extent_callback, + .user_data=r }, + (nbd_completion_callback) { .callback=extents_completed, + .user_data=r }, + 0); + if (cookie == -1) { + DEBUG ("Cannot get extents: %s", nbd_get_error ()); + src.can_extents = false; + return false; + } + + r->waiting = true; + extents_in_progress = true; + + return true; +} + +/* Return next extent to process. */ +static void +next_extent (struct request *r) +{ + uint32_t limit = MIN (REQUEST_SIZE, size - offset); + uint32_t length = 0; + bool is_zero; + + assert (extents); + + is_zero = extents[extents_pos + 1] & LIBNBD_STATE_ZERO; + + while (length < limit) { + DEBUG ("e%d: offset=%ld len=%ld zero=%d", + extents_pos / 2, offset, extents[extents_pos], is_zero); + + /* If this extent is too large, steal some data from it to + * complete the request. + */ + if (length + extents[extents_pos] > limit) { + uint32_t stolen = limit - length; + + extents[extents_pos] -= stolen; + length += stolen; + break; + } + + /* Consume the entire extent and start looking at the next one. */ + length += extents[extents_pos]; + extents[extents_pos] = 0; + + if (extents_pos + 2 == extents_len) + break; + + extents_pos += 2; + + /* If next extent is different, we are done. */ + if ((extents[extents_pos + 1] & LIBNBD_STATE_ZERO) != is_zero) + break; + } + + assert (length > 0 && length <= limit); + + r->offset = offset; + r->length = length; + r->zero = is_zero; + + DEBUG ("r%d: extent offset=%ld len=%ld zero=%d", + r->index, r->offset, r->length, r->zero); + + offset += length; + + if (extents_pos + 2 == extents_len && extents[extents_pos] == 0) { + /* Processed all extents, clear extents. */ + DEBUG ("r%d: consumed all extents offset=%ld", r->index, offset); + free (extents); + extents = NULL; + extents_pos = 0; + extents_len = 0; + } +} + +static inline void +start_request_soon (struct request *r) +{ + ev_timer_init (&r->watcher, start_request_cb, 0, 0); + ev_timer_start (loop, &r->watcher); +} + +static void +start_request_cb (struct ev_loop *loop, ev_timer *w, int revents) +{ + struct request *r = (struct request *)w; + start_request (r); }
/* Start async copy or zero request. */ static void start_request(struct request *r) { - assert (offset < size); + /* Cancel the request if we are done. */ + if (offset == size) + return;
r->started = ev_now (loop); - r->length = MIN (REQUEST_SIZE, size - offset); - r->offset = offset;
- start_read (r); - - offset += r->length; + /* If needed, get more extents from server. */ + if (src.can_extents && extents == NULL && start_extents (r)) + return; + + DEBUG ("r%d: start request offset=%ld", r->index, offset); + + if (src.can_extents) { + /* Handle the next extent. */ + next_extent (r); + if (r->zero) { + if (dst.can_zero) { + start_zero (r); + } else { + memset (r->data, 0, r->length); + start_write (r); + } + } else { + start_read (r); + } + } else { + /* Extents not available. */ + r->length = MIN (REQUEST_SIZE, size - offset); + r->offset = offset; + start_read (r); + offset += r->length; + } }
static void @@ -240,9 +446,11 @@ request_completed (void *user_data, int *error) ev_break (loop, EVBREAK_ALL); }
- /* If we have data to read, start a new read. */ + /* If we have more work, start a new request on the next loop + * iteration, to avoid deadlock if we need to start a zero or write. + */ if (offset < size) - start_request(r); + start_request_soon(r);
return 1; } @@ -304,11 +512,19 @@ main (int argc, char *argv[])
debug = getenv ("COPY_LIBEV_DEBUG") != NULL;
+ /* Configure soruce to report extents. */ + + if (nbd_add_meta_context (src.nbd, LIBNBD_CONTEXT_BASE_ALLOCATION)) + FAIL ("Cannot add base:allocation: %s", nbd_get_error ()); + /* Connecting is fast, so use the syncronous API. */
if (nbd_connect_uri (src.nbd, argv[1])) FAIL ("Cannot connect to source: %s", nbd_get_error ());
+ src.can_extents = nbd_can_meta_context ( + src.nbd, LIBNBD_CONTEXT_BASE_ALLOCATION) > 0; + if (nbd_connect_uri (dst.nbd, argv[2])) FAIL ("Cannot connect to destination: %s", nbd_get_error ());
-- 2.26.2
-- Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones Read my programming and virtualization blog: http://rwmj.wordpress.com virt-builder quickly builds VMs from scratch http://libguestfs.org/virt-builder.1.html
On Mon, Mar 08, 2021 at 01:26:44AM +0200, Nir Soffer wrote:
$ strace -f -c ../copy/nbdcopy --sparse=1048576 --request-size=1048576 --requests=16 --connections=1 $SRC $DST strace: Process 1094611 attached strace: Process 1094612 attached strace: Process 1094613 attached strace: Process 1094614 attached strace: Process 1094615 attached strace: Process 1094616 attached strace: Process 1094617 attached strace: Process 1094618 attached strace: Process 1094619 attached strace: Process 1094620 attached strace: Process 1094621 attached strace: Process 1094622 attached strace: Process 1094623 attached strace: Process 1094641 attached
(Not sure why we start so many threads with --connections=1 - bug?)
I'm not sure of the exact command, so I used: $ ./run nbdcopy --sparse=1048576 --request-size=1048576 --requests=16 --connections=1 -- [ qemu-nbd -f qcow2 -t ~/fedora-32.qcow2 ] [ nbdkit memory 6G ] Temporarily adding -v shows: nbdcopy: src: nbd_ops "qemu-nbd" nbdcopy: src: size=6442450944 nbdcopy: dst: nbd_ops "nbdkit" nbdcopy: dst: size=6442450944 nbdcopy: connections=1 requests=16 threads=1 synchronous=false ^^^^^^^^^ Many threads were created but they all appeared to be associated with the ./run script, qemu-nbd and nbdkit. nbdcopy should only create one worker thread in this scenario. Rich. -- Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones Read my programming and virtualization blog: http://rwmj.wordpress.com virt-df lists disk usage of guests without needing to install any software inside the virtual machine. Supports Linux and Windows. http://people.redhat.com/~rjones/virt-df/
On Mon, Mar 8, 2021 at 11:50 AM Richard W.M. Jones <rjones@redhat.com> wrote:
On Mon, Mar 08, 2021 at 01:26:44AM +0200, Nir Soffer wrote:
$ strace -f -c ../copy/nbdcopy --sparse=1048576 --request-size=1048576 --requests=16 --connections=1 $SRC $DST strace: Process 1094611 attached strace: Process 1094612 attached strace: Process 1094613 attached strace: Process 1094614 attached strace: Process 1094615 attached strace: Process 1094616 attached strace: Process 1094617 attached strace: Process 1094618 attached strace: Process 1094619 attached strace: Process 1094620 attached strace: Process 1094621 attached strace: Process 1094622 attached strace: Process 1094623 attached strace: Process 1094641 attached
(Not sure why we start so many threads with --connections=1 - bug?)
I'm not sure of the exact command, so I used:
$ ./run nbdcopy --sparse=1048576 --request-size=1048576 --requests=16 --connections=1 -- [ qemu-nbd -f qcow2 -t ~/fedora-32.qcow2 ] [ nbdkit memory 6G ]
Temporarily adding -v shows:
nbdcopy: src: nbd_ops "qemu-nbd" nbdcopy: src: size=6442450944 nbdcopy: dst: nbd_ops "nbdkit" nbdcopy: dst: size=6442450944 nbdcopy: connections=1 requests=16 threads=1 synchronous=false ^^^^^^^^^
Many threads were created but they all appeared to be associated with the ./run script, qemu-nbd and nbdkit. nbdcopy should only create one worker thread in this scenario.
Right, I was testing the run script instead of .libs/xxx. When running the actual executable we see: $ strace -f -c ../copy/.libs/nbdcopy --flush --sparse=1048576 --request-size=1048576 --requests=16 --connections=1 $SRC $DST strace: Process 1142801 attached % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 59.70 0.914059 914059 1 futex 18.90 0.289297 17 16768 1 recvfrom 17.99 0.275497 32 8380 4 sendto 2.73 0.041852 4 8921 poll 0.50 0.007616 230 33 madvise ... $ strace -c .libs/copy-libev $SRC $DST % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 50.25 0.297711 19 15446 1 recvfrom 39.81 0.235824 34 6863 sendto 7.69 0.045573 5 8911 epoll_wait 1.04 0.006132 4 1317 epoll_ctl 0.42 0.002478 24 103 mmap ... Why do we use the run script?
On Mon, Mar 08, 2021 at 01:23:05PM +0200, Nir Soffer wrote:
Why do we use the run script?
In this case it's optional, because libtool adds some magic to copy/nbdcopy to ensure that it links against the built copy of libnbd (not the installed copy). But in general it's a useful script, for a few good reasons: (1) You're running libnbd tools written in other programming languages like Python. The run script will set all the environment variables correctly to make this just work. (2) You want to run the nbd* tools from locally built libnbd when doing something like running nbdkit's test suite, because the run script sets up $PATH correctly: nbdkit$ ../libnbd/run make check (3) You want to use the special features like valgrind support: nbdkit$ LIBNBD_VALGRIND=1 ../libnbd/run make check See also: https://gitlab.com/nbdkit/libnbd/-/blob/master/run.in Rich. -- Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones Read my programming and virtualization blog: http://rwmj.wordpress.com virt-p2v converts physical machines to virtual machines. Boot with a live CD or over the network (PXE) and turn machines into KVM guests. http://libguestfs.org/virt-v2v
On 3/7/21 5:26 PM, Nir Soffer wrote:
On Mon, Mar 8, 2021 at 12:59 AM Nir Soffer <nsoffer@redhat.com> wrote:
$ strace -f -c ../copy/nbdcopy --sparse=1048576 --request-size=1048576 --requests=16 --connections=1 $SRC $DST strace: Process 1094611 attached strace: Process 1094612 attached strace: Process 1094613 attached strace: Process 1094614 attached strace: Process 1094615 attached strace: Process 1094616 attached strace: Process 1094617 attached strace: Process 1094618 attached strace: Process 1094619 attached strace: Process 1094620 attached strace: Process 1094621 attached strace: Process 1094622 attached strace: Process 1094623 attached strace: Process 1094641 attached
(Not sure why we start so many threads with --connections=1 - bug?)
Known issue in nbdkit. Right now, nbdkit defaults a parallel plugin to 16 threads (altered when using a plugin that has a serialized thread model, or if you use the command-line option --threads=1), and starts all of those threads regardless of how many parallel requests the client actually sends. One of the TODO items is to refactor it to have nbdkit use a thread pool, which starts with just one worker thread, and can add workers up to the --threads limit, but where workers are added only when under actual pressure from parallel guest commands. -- Eric Blake, Principal Software Engineer Red Hat, Inc. +1-919-301-3226 Virtualization: qemu.org | libvirt.org
BTW we've got some interest from a GSoC student who wants to add io_uring support to libnbd and/or nbdcopy. Rich. -- Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones Read my programming and virtualization blog: http://rwmj.wordpress.com virt-p2v converts physical machines to virtual machines. Boot with a live CD or over the network (PXE) and turn machines into KVM guests. http://libguestfs.org/virt-v2v
participants (4)
-
Eric Blake -
Nir Soffer -
Nir Soffer -
Richard W.M. Jones