From 8dd1d507524c970b1d4cce173fbaf53e54abf38c Mon Sep 17 00:00:00 2001 From: "Richard W.M. Jones" Date: Sun, 8 Jun 2025 13:20:57 +0100 Subject: [PATCH] vddk: Improve statistics related: RHEL-94825 --- ...s-instead-of-Unicode-s-for-microseco.patch | 34 ++++ ...-stats-Line-up-the-columns-correctly.patch | 26 +++ ...d-the-byte-count-of-each-QueryAlloca.patch | 61 ++++++ ...ct-elapsed-time-for-ReadAsync-and-Wr.patch | 178 ++++++++++++++++++ nbdkit.spec | 10 +- 5 files changed, 307 insertions(+), 2 deletions(-) create mode 100644 0027-vddk-stats-Use-us-instead-of-Unicode-s-for-microseco.patch create mode 100644 0028-vddk-stats-Line-up-the-columns-correctly.patch create mode 100644 0029-vddk-stats-Record-the-byte-count-of-each-QueryAlloca.patch create mode 100644 0030-vddk-stats-Collect-elapsed-time-for-ReadAsync-and-Wr.patch diff --git a/0027-vddk-stats-Use-us-instead-of-Unicode-s-for-microseco.patch b/0027-vddk-stats-Use-us-instead-of-Unicode-s-for-microseco.patch new file mode 100644 index 0000000..b1590e0 --- /dev/null +++ b/0027-vddk-stats-Use-us-instead-of-Unicode-s-for-microseco.patch @@ -0,0 +1,34 @@ +From 72d9a049af483990d446de740e6da9f0420f723a Mon Sep 17 00:00:00 2001 +From: "Richard W.M. Jones" +Date: Sun, 8 Jun 2025 10:44:32 +0100 +Subject: [PATCH] =?UTF-8?q?vddk:=20stats:=20Use=20"us"=20instead=20of=20(U?= + =?UTF-8?q?nicode)=20"=C2=B5s"=20for=20microseconds?= +MIME-Version: 1.0 +Content-Type: text/plain; charset=UTF-8 +Content-Transfer-Encoding: 8bit + +nbdkit_debug uses C-style escaping for non-ASCII characters in debug +strings, so in logs what we actually see is "\xc2\xb5s" which messes +up the columns. + +(cherry picked from commit 1f09bb4abefe8f3f052e8c0b6b34d314887b3c32) +--- + plugins/vddk/stats.c | 2 +- + 1 file changed, 1 insertion(+), 1 deletion(-) + +diff --git a/plugins/vddk/stats.c b/plugins/vddk/stats.c +index 7f63333a..59cfee5a 100644 +--- a/plugins/vddk/stats.c ++++ b/plugins/vddk/stats.c +@@ -98,7 +98,7 @@ display_stats (void) + + nbdkit_debug ("VDDK function stats (-D vddk.stats=1):"); + nbdkit_debug ("%-24s %15s %5s %15s", +- "VixDiskLib_...", "µs", "calls", "bytes"); ++ "VixDiskLib_...", "us", "calls", "bytes"); + for (i = 0; i < stats.len; ++i) { + if (stats.ptr[i].usecs) { + if (stats.ptr[i].bytes > 0) +-- +2.47.1 + diff --git a/0028-vddk-stats-Line-up-the-columns-correctly.patch b/0028-vddk-stats-Line-up-the-columns-correctly.patch new file mode 100644 index 0000000..5b262b2 --- /dev/null +++ b/0028-vddk-stats-Line-up-the-columns-correctly.patch @@ -0,0 +1,26 @@ +From a36ec14b115a84c9aa8a1341e5f0a8a4576c7e02 Mon Sep 17 00:00:00 2001 +From: "Richard W.M. Jones" +Date: Sun, 8 Jun 2025 11:04:41 +0100 +Subject: [PATCH] vddk: stats: Line up the columns correctly + +(cherry picked from commit 7da09b07148cc12c3214b18bc96c65ed45625dde) +--- + plugins/vddk/stats.c | 2 +- + 1 file changed, 1 insertion(+), 1 deletion(-) + +diff --git a/plugins/vddk/stats.c b/plugins/vddk/stats.c +index 59cfee5a..b551fc5a 100644 +--- a/plugins/vddk/stats.c ++++ b/plugins/vddk/stats.c +@@ -97,7 +97,7 @@ display_stats (void) + qsort (stats.ptr, stats.len, sizeof stats.ptr[0], stat_compare); + + nbdkit_debug ("VDDK function stats (-D vddk.stats=1):"); +- nbdkit_debug ("%-24s %15s %5s %15s", ++ nbdkit_debug ("%-24s %15s %5s %15s", + "VixDiskLib_...", "us", "calls", "bytes"); + for (i = 0; i < stats.len; ++i) { + if (stats.ptr[i].usecs) { +-- +2.47.1 + diff --git a/0029-vddk-stats-Record-the-byte-count-of-each-QueryAlloca.patch b/0029-vddk-stats-Record-the-byte-count-of-each-QueryAlloca.patch new file mode 100644 index 0000000..84bd06d --- /dev/null +++ b/0029-vddk-stats-Record-the-byte-count-of-each-QueryAlloca.patch @@ -0,0 +1,61 @@ +From 3cbde587c10dbe4da016eaf6a2d45dc09fac1858 Mon Sep 17 00:00:00 2001 +From: "Richard W.M. Jones" +Date: Sun, 8 Jun 2025 10:40:26 +0100 +Subject: [PATCH] vddk: stats: Record the byte count of each + QueryAllocatedBlocks call + +In -D vddk.stats=1 output, keep track of the size of each call to +QueryAllocatedBlocks, and display that at the end. + +After this change, we see the number of bytes scanned in the "bytes" +column (previously this column was empty for this call): + +nbdkit: debug: VixDiskLib_... us calls bytes +nbdkit: debug: Open 27051497 2 +nbdkit: debug: GetInfo 12538428 4 +nbdkit: debug: ConnectEx 6944819 2 +nbdkit: debug: QueryAllocatedBlocks 4563503 3 21474967552 +nbdkit: debug: Close 1440271 2 +nbdkit: debug: Exit 1001407 1 +(cherry picked from commit 2db1ede27bb529b36b0075eab337f0c585d1a7ec) +--- + plugins/vddk/worker.c | 9 ++++++--- + 1 file changed, 6 insertions(+), 3 deletions(-) + +diff --git a/plugins/vddk/worker.c b/plugins/vddk/worker.c +index 3925fb91..feb8d96f 100644 +--- a/plugins/vddk/worker.c ++++ b/plugins/vddk/worker.c +@@ -327,7 +327,8 @@ test_can_extents (struct vddk_handle *h) + 0, VIXDISKLIB_MIN_CHUNK_SIZE, + VIXDISKLIB_MIN_CHUNK_SIZE, + &block_list); +- VDDK_CALL_END (VixDiskLib_QueryAllocatedBlocks, 0); ++ VDDK_CALL_END (VixDiskLib_QueryAllocatedBlocks, ++ VIXDISKLIB_MIN_CHUNK_SIZE * VIXDISKLIB_SECTOR_SIZE); + error_suppression = 0; + if (err == VIX_OK) { + VDDK_CALL_START (VixDiskLib_FreeBlockList, "block_list") +@@ -435,7 +436,8 @@ get_extents_slow (struct command *cmd, struct vddk_handle *h) + start_sector, nr_sectors, + VIXDISKLIB_MIN_CHUNK_SIZE, + &block_list); +- VDDK_CALL_END (VixDiskLib_QueryAllocatedBlocks, 0); ++ VDDK_CALL_END (VixDiskLib_QueryAllocatedBlocks, ++ nr_sectors * VIXDISKLIB_SECTOR_SIZE); + if (err != VIX_OK) { + VDDK_ERROR (err, "VixDiskLib_QueryAllocatedBlocks"); + return -1; +@@ -532,7 +534,8 @@ pre_cache_extents (struct vddk_handle *h) + start_sector, nr_sectors, + VIXDISKLIB_MIN_CHUNK_SIZE, + &block_list); +- VDDK_CALL_END (VixDiskLib_QueryAllocatedBlocks, 0); ++ VDDK_CALL_END (VixDiskLib_QueryAllocatedBlocks, ++ nr_sectors * VIXDISKLIB_SECTOR_SIZE); + if (err != VIX_OK) { + VDDK_ERROR (err, "VixDiskLib_QueryAllocatedBlocks"); + nbdkit_extents_free (extents); +-- +2.47.1 + diff --git a/0030-vddk-stats-Collect-elapsed-time-for-ReadAsync-and-Wr.patch b/0030-vddk-stats-Collect-elapsed-time-for-ReadAsync-and-Wr.patch new file mode 100644 index 0000000..a368bd5 --- /dev/null +++ b/0030-vddk-stats-Collect-elapsed-time-for-ReadAsync-and-Wr.patch @@ -0,0 +1,178 @@ +From 9de0cd7c25acb8eaa47cb128fa15053235eb433f Mon Sep 17 00:00:00 2001 +From: "Richard W.M. Jones" +Date: Sun, 8 Jun 2025 10:59:57 +0100 +Subject: [PATCH] vddk: stats: Collect elapsed time for ReadAsync and + WriteAsync + +A major existing problem with -D vddk.stats=1 is that it did not +accurately account for the time taken in these asynchronous calls. +This change records the elapsed time. (It's not possible to collect +the actual time spent "working on" these calls, we just add up the +total elapsed time, which is fine.) + +In the remote case, here's how the output changes from before this +change: + +nbdkit: debug: VixDiskLib_... us calls bytes +nbdkit: debug: ReadAsync 18 1 8192 + +to after this change: + +nbdkit: debug: VixDiskLib_... us calls bytes +nbdkit: debug: ReadAsync 243745 1 8192 + +An interesting thing about this is that in the local case this +actually reduces the apparent elapsed time, I think because VDDK calls +complete_command directly from the Read/WriteAsync function. It only +increases the apparent elapsed time in the remote case. + +(cherry picked from commit a224d7fd8d839287c63cb4a063569283dd974b48) +--- + plugins/vddk/nbdkit-vddk-plugin.pod | 3 +-- + plugins/vddk/vddk.h | 37 ++++++++++++++++++++++------- + plugins/vddk/worker.c | 13 ++++++++-- + 3 files changed, 41 insertions(+), 12 deletions(-) + +diff --git a/plugins/vddk/nbdkit-vddk-plugin.pod b/plugins/vddk/nbdkit-vddk-plugin.pod +index 279da2d0..a375e152 100644 +--- a/plugins/vddk/nbdkit-vddk-plugin.pod ++++ b/plugins/vddk/nbdkit-vddk-plugin.pod +@@ -724,8 +724,7 @@ Same as above, but for writing and flushing writes. + =item C + + Same as above, but for asynchronous read and write calls introduced in +-nbdkit 1.30. Unfortunately at the moment the amount of time spent in +-these calls is not accounted for correctly. ++S. + + =item C + +diff --git a/plugins/vddk/vddk.h b/plugins/vddk/vddk.h +index 461fb528..5ff02649 100644 +--- a/plugins/vddk/vddk.h ++++ b/plugins/vddk/vddk.h +@@ -39,6 +39,7 @@ + + #include + ++#include "cleanup.h" + #include "isaligned.h" + #include "tvdiff.h" + #include "vector.h" +@@ -91,7 +92,7 @@ extern int vddk_debug_stats; + */ + #define VDDK_CALL_START(fn, fs, ...) \ + do { \ +- struct timeval start_t, end_t; \ ++ struct timeval start_t; \ + /* GCC can optimize this away at compile time: */ \ + const bool datapath = \ + strcmp (#fn, "VixDiskLib_Read") == 0 || \ +@@ -105,13 +106,13 @@ extern int vddk_debug_stats; + do + #define VDDK_CALL_END(fn, bytes_) \ + while (0); \ +- if (vddk_debug_stats) { \ +- gettimeofday (&end_t, NULL); \ +- ACQUIRE_LOCK_FOR_CURRENT_SCOPE (&stats_lock); \ +- stats_##fn.usecs += tvdiff_usec (&start_t, &end_t); \ +- stats_##fn.calls++; \ +- stats_##fn.bytes += bytes_; \ +- } \ ++ update_stats (&start_t, bytes_, &stats_##fn); \ ++ } while (0) ++/* Same as VDDK_CALL_END, but for {Read,Write}Async, where we will ++ * update the stats ourself. ++ */ ++#define VDDK_CALL_END_ASYNC() \ ++ while (0); \ + } while (0) + + /* Print VDDK errors. */ +@@ -141,6 +142,7 @@ struct command { + uint64_t id; /* serial number */ + + /* These fields are used by the internal implementation. */ ++ struct timeval start_t; /* start time */ + pthread_mutex_t mutex; /* completion mutex */ + pthread_cond_t cond; /* completion condition */ + enum { SUBMITTED, SUCCEEDED, FAILED } status; +@@ -197,6 +199,25 @@ extern pthread_mutex_t stats_lock; + #undef OPTIONAL_STUB + extern void display_stats (void); + ++static inline void ++update_stats (const struct timeval *start_t, uint64_t bytes, ++ struct vddk_stat *stat) ++{ ++ if (vddk_debug_stats) { ++ struct timeval end_t; ++ int64_t usecs; ++ ++ gettimeofday (&end_t, NULL); ++ usecs = tvdiff_usec (start_t, &end_t); ++ ++ /* Keep this critical section as small as possible. */ ++ ACQUIRE_LOCK_FOR_CURRENT_SCOPE (&stats_lock); ++ stat->usecs += usecs; ++ stat->calls++; ++ stat->bytes += bytes; ++ } ++} ++ + /* utils.c */ + extern void trim (char *str); + +diff --git a/plugins/vddk/worker.c b/plugins/vddk/worker.c +index feb8d96f..9d3a5940 100644 +--- a/plugins/vddk/worker.c ++++ b/plugins/vddk/worker.c +@@ -120,6 +120,11 @@ complete_command (void *vp, VixError result) + nbdkit_debug ("command %" PRIu64 " (%s) completed", + cmd->id, command_type_string (cmd->type)); + ++ /* Update the stats for this asynchronous call. */ ++ update_stats (&cmd->start_t, cmd->count, ++ cmd->type == READ ? &stats_VixDiskLib_ReadAsync : ++ &stats_VixDiskLib_WriteAsync); ++ + ACQUIRE_LOCK_FOR_CURRENT_SCOPE (&cmd->mutex); + + if (result == VIX_OK) { +@@ -219,13 +224,15 @@ do_read (struct command *cmd, struct vddk_handle *h) + offset /= VIXDISKLIB_SECTOR_SIZE; + count /= VIXDISKLIB_SECTOR_SIZE; + ++ gettimeofday (&cmd->start_t, NULL); ++ + VDDK_CALL_START (VixDiskLib_ReadAsync, + "handle, %" PRIu64 " sectors, " + "%" PRIu32 " sectors, buffer, callback, %" PRIu64, + offset, count, cmd->id) + err = VixDiskLib_ReadAsync (h->handle, offset, count, buf, + complete_command, cmd); +- VDDK_CALL_END (VixDiskLib_ReadAsync, count * VIXDISKLIB_SECTOR_SIZE); ++ VDDK_CALL_END_ASYNC (); + if (err != VIX_ASYNC) { + VDDK_ERROR (err, "VixDiskLib_ReadAsync"); + return -1; +@@ -256,13 +263,15 @@ do_write (struct command *cmd, struct vddk_handle *h) + offset /= VIXDISKLIB_SECTOR_SIZE; + count /= VIXDISKLIB_SECTOR_SIZE; + ++ gettimeofday (&cmd->start_t, NULL); ++ + VDDK_CALL_START (VixDiskLib_WriteAsync, + "handle, %" PRIu64 " sectors, " + "%" PRIu32 " sectors, buffer, callback, %" PRIu64, + offset, count, cmd->id) + err = VixDiskLib_WriteAsync (h->handle, offset, count, buf, + complete_command, cmd); +- VDDK_CALL_END (VixDiskLib_WriteAsync, count * VIXDISKLIB_SECTOR_SIZE); ++ VDDK_CALL_END_ASYNC (); + if (err != VIX_ASYNC) { + VDDK_ERROR (err, "VixDiskLib_WriteAsync"); + return -1; +-- +2.47.1 + diff --git a/nbdkit.spec b/nbdkit.spec index 1e694b6..f04274b 100644 --- a/nbdkit.spec +++ b/nbdkit.spec @@ -55,7 +55,7 @@ Name: nbdkit Version: 1.42.2 -Release: 6%{?dist} +Release: 7%{?dist} Summary: NBD server License: BSD-3-Clause @@ -106,6 +106,10 @@ Patch0023: 0023-vddk-Pre-cache-the-extents-for-readonly-connections.patch Patch0024: 0024-file-Save-the-filename-or-equivalent-in-the-file-han.patch Patch0025: 0025-file-Add-the-filename-or-equivalent-to-error-message.patch Patch0026: 0026-file-Add-offset-count-to-error-messages.patch +Patch0027: 0027-vddk-stats-Use-us-instead-of-Unicode-s-for-microseco.patch +Patch0028: 0028-vddk-stats-Line-up-the-columns-correctly.patch +Patch0029: 0029-vddk-stats-Record-the-byte-count-of-each-QueryAlloca.patch +Patch0030: 0030-vddk-stats-Collect-elapsed-time-for-ReadAsync-and-Wr.patch # For automatic RPM Provides generation. # See: https://rpm-software-management.github.io/rpm/manual/dependency_generators.html @@ -1548,7 +1552,7 @@ fi %changelog -* Thu Jun 05 2025 Richard W.M. Jones - 1.42.2-6 +* Sun Jun 08 2025 Richard W.M. Jones - 1.42.2-7 - Rebase to nbdkit 1.42.2 - Synch the spec file with Fedora Rawhide. - nbdkit-ondemand-plugin moves into a new subpackage. @@ -1562,6 +1566,8 @@ fi resolves: RHEL-94825 - Log filename, offset and count in nbdkit-file-plugin error messages resolves: RHEL-95364 +- vddk: Improve statistics + related: RHEL-94825 * Mon Jan 06 2025 Richard W.M. Jones - 1.40.4-3 - vddk: Avoid reading partial chunk beyond the end of the disk