From edfdfff0dae54a41bbfca30fa60f4fa6438d45b9 Mon Sep 17 00:00:00 2001 From: "Richard W.M. Jones" 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 and C). =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