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