rpms/nbdkit
6
0
Fork 0
Code Issues Pull Requests Releases Activity

vddk: Improve statistics

Browse Source 
related: RHEL-94825
This commit is contained in:
Richard W.M. Jones 2025-06-08 13:20:57 +01:00
parent 06e4722074
commit 8dd1d50752
5 changed files with 307 additions and 2 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

34
0027-vddk-stats-Use-us-instead-of-Unicode-s-for-microseco.patch Normal file
View File

@ -0,0 +1,34 @@
From 72d9a049af483990d446de740e6da9f0420f723a Mon Sep 17 00:00:00 2001
From: "Richard W.M. Jones" <rjones@redhat.com>
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

26
0028-vddk-stats-Line-up-the-columns-correctly.patch Normal file
View File

@ -0,0 +1,26 @@
From a36ec14b115a84c9aa8a1341e5f0a8a4576c7e02 Mon Sep 17 00:00:00 2001
From: "Richard W.M. Jones" <rjones@redhat.com>
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

61
0029-vddk-stats-Record-the-byte-count-of-each-QueryAlloca.patch Normal file
View File

@ -0,0 +1,61 @@
From 3cbde587c10dbe4da016eaf6a2d45dc09fac1858 Mon Sep 17 00:00:00 2001
From: "Richard W.M. Jones" <rjones@redhat.com>
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

178
0030-vddk-stats-Collect-elapsed-time-for-ReadAsync-and-Wr.patch Normal file
View File

@ -0,0 +1,178 @@
From 9de0cd7c25acb8eaa47cb128fa15053235eb433f Mon Sep 17 00:00:00 2001
From: "Richard W.M. Jones" <rjones@redhat.com>
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<WriteAsync>
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<nbdkit 1.30>.
=item C<QueryAllocatedBlocks>
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 <pthread.h>
+#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

10
nbdkit.spec
View File

@ -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 <rjones@redhat.com> - 1.42.2-6
* Sun Jun 08 2025 Richard W.M. Jones <rjones@redhat.com> - 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 <rjones@redhat.com> - 1.40.4-3
- vddk: Avoid reading partial chunk beyond the end of the disk