From 3bc36ccfafeea14e3df60e44e36731d27ba44585 Mon Sep 17 00:00:00 2001 From: "Richard W.M. Jones" 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 e937942c..1e376140 100644 --- a/plugins/vddk/nbdkit-vddk-plugin.pod +++ b/plugins/vddk/nbdkit-vddk-plugin.pod @@ -715,8 +715,7 @@ Same as above, but for writing and flushing writes. =item C 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. =item C 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 +#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