From 45db64d72bf03fece8a7fb994887360954905a3b Mon Sep 17 00:00:00 2001 From: "Richard W.M. Jones" Date: Wed, 18 Aug 2021 14:47:58 +0100 Subject: [PATCH] vddk: Add stats about the amount of time spent in VDDK calls MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit If you use -D vddk.stats=1 then when the plugin is unloaded it will display the amount of time spent in each VDDK call. The output will look something like this: nbdkit: debug: VDDK function stats (-D vddk.stats=1): nbdkit: debug: µs nbdkit: debug: VixDiskLib_Exit 1001154 nbdkit: debug: VixDiskLib_InitEx 96008 nbdkit: debug: VixDiskLib_Flush 15722 nbdkit: debug: VixDiskLib_Write 12081 nbdkit: debug: VixDiskLib_Open 6029 nbdkit: debug: VixDiskLib_Read 1364 nbdkit: debug: VixDiskLib_Close 605 nbdkit: debug: VixDiskLib_QueryAllocatedBlocks 191 nbdkit: debug: VixDiskLib_ConnectEx 134 nbdkit: debug: VixDiskLib_Disconnect 76 nbdkit: debug: VixDiskLib_FreeConnectParams 57 nbdkit: debug: VixDiskLib_GetInfo 56 nbdkit: debug: VixDiskLib_GetTransportMode 43 nbdkit: debug: VixDiskLib_FreeInfo 42 nbdkit: debug: VixDiskLib_FreeBlockList 32 nbdkit: debug: VixDiskLib_AllocateConnectParams 28 VDDK APIs which are never called are not printed. (cherry picked from commit f2dfc7d74ee650bdf2cc930a07b1c5bcb509976c) --- plugins/vddk/nbdkit-vddk-plugin.pod | 5 ++ plugins/vddk/vddk.c | 107 +++++++++++++++++++++++++--- tests/test-vddk-real.sh | 2 +- 3 files changed, 103 insertions(+), 11 deletions(-) diff --git a/plugins/vddk/nbdkit-vddk-plugin.pod b/plugins/vddk/nbdkit-vddk-plugin.pod index b783f13a..2a1b17dc 100644 --- a/plugins/vddk/nbdkit-vddk-plugin.pod +++ b/plugins/vddk/nbdkit-vddk-plugin.pod @@ -510,6 +510,11 @@ Debug extents returned by C. 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. + =back =head1 FILES diff --git a/plugins/vddk/vddk.c b/plugins/vddk/vddk.c index 888009ab..fce96d9a 100644 --- a/plugins/vddk/vddk.c +++ b/plugins/vddk/vddk.c @@ -42,6 +42,7 @@ #include #include #include +#include #include @@ -52,6 +53,8 @@ #include "isaligned.h" #include "minmax.h" #include "rounding.h" +#include "tvdiff.h" +#include "vector.h" #include "vddk.h" #include "vddk-structs.h" @@ -60,6 +63,7 @@ NBDKIT_DLL_PUBLIC int vddk_debug_diskinfo; NBDKIT_DLL_PUBLIC int vddk_debug_extents; NBDKIT_DLL_PUBLIC int vddk_debug_datapath = 1; +NBDKIT_DLL_PUBLIC int vddk_debug_stats; /* For each VDDK API define a static global variable. These globals * are initialized when the plugin is loaded (by vddk_get_ready). @@ -96,22 +100,52 @@ static const char *username; /* user */ static const char *vmx_spec; /* vm */ static bool is_remote; -#define VDDK_ERROR(err, fs, ...) \ - do { \ - char *vddk_err_msg; \ - vddk_err_msg = VixDiskLib_GetErrorText ((err), NULL); \ - nbdkit_error (fs ": %s", ##__VA_ARGS__, vddk_err_msg); \ - VixDiskLib_FreeErrorText (vddk_err_msg); \ - } while (0) +/* For each VDDK API define a variable to store the time taken (used + * to implement -D vddk.stats=1). + */ +static pthread_mutex_t stats_lock = PTHREAD_MUTEX_INITIALIZER; +static void display_stats (void); +#define STUB(fn,ret,args) static int64_t stats_##fn; +#define OPTIONAL_STUB(fn,ret,args) static int64_t stats_##fn; +#include "vddk-stubs.h" +#undef STUB +#undef OPTIONAL_STUB #define VDDK_CALL_START(fn, fs, ...) \ + do { \ + struct timeval start_t, end_t; \ + if (vddk_debug_stats) \ + gettimeofday (&start_t, NULL); \ nbdkit_debug ("VDDK call: %s (" fs ")", #fn, ##__VA_ARGS__); \ do #define VDDK_CALL_START_DATAPATH(fn, fs, ...) \ + do { \ + struct timeval start_t, end_t; \ + if (vddk_debug_stats) \ + gettimeofday (&start_t, NULL); \ if (vddk_debug_datapath) \ nbdkit_debug ("VDDK call: %s (" fs ")", #fn, ##__VA_ARGS__); \ do -#define VDDK_CALL_END(fn) while (0) +#define VDDK_CALL_END(fn) \ + while (0); \ + if (vddk_debug_stats) { \ + gettimeofday (&end_t, NULL); \ + ACQUIRE_LOCK_FOR_CURRENT_SCOPE (&stats_lock); \ + stats_##fn += tvdiff_usec (&start_t, &end_t); \ + } \ + } while (0) + +#define VDDK_ERROR(err, fs, ...) \ + do { \ + char *vddk_err_msg; \ + VDDK_CALL_START (VixDiskLib_GetErrorText, "%lu", err) { \ + vddk_err_msg = VixDiskLib_GetErrorText ((err), NULL); \ + } VDDK_CALL_END (VixDiskLib_GetErrorText); \ + nbdkit_error (fs ": %s", ##__VA_ARGS__, vddk_err_msg); \ + VDDK_CALL_START (VixDiskLib_FreeErrorText, "") { \ + VixDiskLib_FreeErrorText (vddk_err_msg); \ + } VDDK_CALL_END (VixDiskLib_FreeErrorText); \ + } while (0) /* Unload the plugin. */ static void @@ -124,11 +158,61 @@ vddk_unload (void) } if (dl) dlclose (dl); + + if (vddk_debug_stats) + display_stats (); + free (config); free (libdir); free (password); } +struct vddk_stat { + const char *fn; + int64_t usecs; +}; +DEFINE_VECTOR_TYPE(statlist, struct vddk_stat) + +static int +stat_compare (const void *vp1, const void *vp2) +{ + const struct vddk_stat *st1 = vp1; + const struct vddk_stat *st2 = vp2; + + /* Note: sorts in reverse order. */ + if (st1->usecs < st2->usecs) return 1; + else if (st1->usecs > st2->usecs) return -1; + else return 0; +} + +static void +display_stats (void) +{ + statlist stats = empty_vector; + struct vddk_stat st; + size_t i; + +#define ADD_ONE_STAT(fn_, usecs_) \ + st.fn = fn_; \ + st.usecs = usecs_; \ + statlist_append (&stats, st) +#define STUB(fn,ret,args) ADD_ONE_STAT (#fn, stats_##fn); +#define OPTIONAL_STUB(fn,ret,args) ADD_ONE_STAT (#fn, stats_##fn); +#include "vddk-stubs.h" +#undef STUB +#undef OPTIONAL_STUB +#undef ADD_ONE_STAT + + 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"); + for (i = 0; i < stats.size; ++i) { + if (stats.ptr[i].usecs) + nbdkit_debug ("%-40s %9" PRIi64, stats.ptr[i].fn, stats.ptr[i].usecs); + } +} + static void trim (char *str) { @@ -557,6 +641,7 @@ vddk_open (int readonly) struct vddk_handle *h; VixError err; uint32_t flags; + const char *transport_mode; h = malloc (sizeof *h); if (h == NULL) { @@ -635,8 +720,10 @@ vddk_open (int readonly) goto err2; } - nbdkit_debug ("transport mode: %s", - VixDiskLib_GetTransportMode (h->handle)); + VDDK_CALL_START (VixDiskLib_GetTransportMode, "handle") { + transport_mode = VixDiskLib_GetTransportMode (h->handle); + } VDDK_CALL_END (VixDiskLib_GetTransportMode); + nbdkit_debug ("transport mode: %s", transport_mode); return h; diff --git a/tests/test-vddk-real.sh b/tests/test-vddk-real.sh index f848db44..3c8b4262 100755 --- a/tests/test-vddk-real.sh +++ b/tests/test-vddk-real.sh @@ -79,7 +79,7 @@ if grep 'cannot open shared object file' test-vddk-real.log; then fi # Now run nbdkit for the test. -start_nbdkit -P $pid -U $sock vddk libdir="$vddkdir" $vmdk +start_nbdkit -P $pid -U $sock -D vddk.stats=1 vddk libdir="$vddkdir" $vmdk uri="nbd+unix:///?socket=$sock" # VDDK < 6.0 did not support flush, so disable flush test there. Also -- 2.31.1