From 262f7fcd22dd57ae30739703c94bc56f32a8ceec Mon Sep 17 00:00:00 2001
From: "Richard W.M. Jones" <rjones@redhat.com>
Date: Thu, 21 Oct 2021 15:10:00 +0100
Subject: [PATCH] vddk: Extend -D vddk.stats=1 to show number of calls and
bytes transferred
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit
The new output looks like this:
nbdkit: debug: VDDK function stats (-D vddk.stats=1):
nbdkit: debug: VixDiskLib_... µs calls bytes
nbdkit: debug: Exit 1000854 1
nbdkit: debug: InitEx 79304 1
nbdkit: debug: Flush 13577 1
nbdkit: debug: Write 12534 21 10485760
nbdkit: debug: Open 4753 3
nbdkit: debug: Read 966 20 5242880
nbdkit: debug: Close 574 3
nbdkit: debug: QueryAllocatedBlocks 116 4
nbdkit: debug: ConnectEx 103 3
nbdkit: debug: Disconnect 88 3
nbdkit: debug: GetTransportMode 68 3
nbdkit: debug: GetInfo 46 3
nbdkit: debug: FreeConnectParams 36 3
nbdkit: debug: FreeInfo 36 3
nbdkit: debug: FreeBlockList 22 4
nbdkit: debug: AllocateConnectParams 22 3
(cherry picked from commit 5c80f0d290db45a679d55baf37ff39bacb8ce7ec)
---
plugins/vddk/nbdkit-vddk-plugin.pod | 3 +--
plugins/vddk/vddk.c | 41 +++++++++++++++++++++++++----
2 files changed, 37 insertions(+), 7 deletions(-)
diff --git a/plugins/vddk/nbdkit-vddk-plugin.pod b/plugins/vddk/nbdkit-vddk-plugin.pod
index 078badcc..e53d3286 100644
--- a/plugins/vddk/nbdkit-vddk-plugin.pod
+++ b/plugins/vddk/nbdkit-vddk-plugin.pod
@@ -517,8 +517,7 @@ Suppress debugging of datapath calls (C<Read> and C<Write>).
=item B<-D vddk.stats=1>
-When the plugin exits print some statistics about the amount of time
-spent waiting on each VDDK call.
+When the plugin exits print some statistics about each VDDK call.
=back
diff --git a/plugins/vddk/vddk.c b/plugins/vddk/vddk.c
index 3d751544..5f1d223b 100644
--- a/plugins/vddk/vddk.c
+++ b/plugins/vddk/vddk.c
@@ -106,6 +106,8 @@ static bool is_remote;
struct vddk_stat {
const char *name; /* function name */
int64_t usecs; /* total number of usecs consumed */
+ uint64_t calls; /* number of times called */
+ uint64_t bytes; /* bytes transferred, datapath calls only */
};
static pthread_mutex_t stats_lock = PTHREAD_MUTEX_INITIALIZER;
static void display_stats (void);
@@ -141,6 +143,17 @@ static void display_stats (void);
gettimeofday (&end_t, NULL); \
ACQUIRE_LOCK_FOR_CURRENT_SCOPE (&stats_lock); \
stats_##fn.usecs += tvdiff_usec (&start_t, &end_t); \
+ stats_##fn.calls++; \
+ } \
+ } while (0)
+#define VDDK_CALL_END_DATAPATH(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_; \
} \
} while (0)
@@ -191,6 +204,12 @@ stat_compare (const void *vp1, const void *vp2)
else return 0;
}
+static const char *
+api_name_without_prefix (const char *name)
+{
+ return strncmp (name, "VixDiskLib_", 11) == 0 ? name + 11 : name;
+}
+
static void
display_stats (void)
{
@@ -206,10 +225,22 @@ display_stats (void)
qsort (stats.ptr, stats.size, sizeof stats.ptr[0], stat_compare);
nbdkit_debug ("VDDK function stats (-D vddk.stats=1):");
- nbdkit_debug ("%-40s %9s", "", "µs");
+ nbdkit_debug ("%-24s %15s %5s %15s",
+ "VixDiskLib_...", "µs", "calls", "bytes");
for (i = 0; i < stats.size; ++i) {
- if (stats.ptr[i].usecs)
- nbdkit_debug ("%-40s %9" PRIi64, stats.ptr[i].name, stats.ptr[i].usecs);
+ if (stats.ptr[i].usecs) {
+ if (stats.ptr[i].bytes > 0)
+ nbdkit_debug (" %-22s %15" PRIi64 " %5" PRIu64 " %15" PRIu64,
+ api_name_without_prefix (stats.ptr[i].name),
+ stats.ptr[i].usecs,
+ stats.ptr[i].calls,
+ stats.ptr[i].bytes);
+ else
+ nbdkit_debug (" %-22s %15" PRIi64 " %5" PRIu64,
+ api_name_without_prefix (stats.ptr[i].name),
+ stats.ptr[i].usecs,
+ stats.ptr[i].calls);
+ }
}
statlist_reset (&stats);
}
@@ -831,7 +862,7 @@ vddk_pread (void *handle, void *buf, uint32_t count, uint64_t offset,
"%" PRIu32 " sectors, buffer",
offset, count) {
err = VixDiskLib_Read (h->handle, offset, count, buf);
- } VDDK_CALL_END (VixDiskLib_Read);
+ } VDDK_CALL_END_DATAPATH (VixDiskLib_Read, count * VIXDISKLIB_SECTOR_SIZE);
if (err != VIX_OK) {
VDDK_ERROR (err, "VixDiskLib_Read");
return -1;
@@ -871,7 +902,7 @@ vddk_pwrite (void *handle, const void *buf, uint32_t count, uint64_t offset,
"%" PRIu32 " sectors, buffer",
offset, count) {
err = VixDiskLib_Write (h->handle, offset, count, buf);
- } VDDK_CALL_END (VixDiskLib_Write);
+ } VDDK_CALL_END_DATAPATH (VixDiskLib_Write, count * VIXDISKLIB_SECTOR_SIZE);
if (err != VIX_OK) {
VDDK_ERROR (err, "VixDiskLib_Write");
return -1;
--
2.31.1