Previously we measured the total time and used it to calculate the rate of different operations. This is incorrect and hides the real throughput. A more useful way is to measure the time we spent in each operation. Here is an example run with this change: $ ./nbdkit --foreground \ --unix /tmp/nbd.sock \ --exportname '' \ --filter stats \ file file=/var/tmp/dst.img \ statsfile=/dev/stderr \ --run 'qemu-img convert -p -n -f raw -O raw -T none /var/tmp/fedora-30.img nbd:unix:/tmp/nbd.sock' (100.00/100%) elapsed time: 2.150 s write: 1271 ops, 1.14 GiB, 0.398 s, 2922.22 MiB/s zero: 1027 ops, 4.86 GiB, 0.012 s, 414723.03 MiB/s extents: 1 ops, 2.00 GiB, 0.000 s, 120470559.51 MiB/s This show that the actual time waiting for storage was only 0.4 seconds, but elapsed time was 2.1 seconds. I think the missing time is in flush() which we do not measure yet. --- filters/stats/stats.c | 78 +++++++++++++++++++++++++++++++++---------- 1 file changed, 60 insertions(+), 18 deletions(-) diff --git a/filters/stats/stats.c b/filters/stats/stats.c index 45bedae..86439e7 100644 --- a/filters/stats/stats.c +++ b/filters/stats/stats.c @@ -60,12 +60,12 @@ static struct timeval start_t; /* This lock protects all the stats. */ static pthread_mutex_t lock = PTHREAD_MUTEX_INITIALIZER; -static uint64_t pread_ops, pread_bytes; -static uint64_t pwrite_ops, pwrite_bytes; -static uint64_t trim_ops, trim_bytes; -static uint64_t zero_ops, zero_bytes; -static uint64_t extents_ops, extents_bytes; -static uint64_t cache_ops, cache_bytes; +static uint64_t pread_ops, pread_bytes, pread_usecs; +static uint64_t pwrite_ops, pwrite_bytes, pwrite_usecs; +static uint64_t trim_ops, trim_bytes, trim_usecs; +static uint64_t zero_ops, zero_bytes, zero_usecs; +static uint64_t extents_ops, extents_bytes, extents_usecs; +static uint64_t cache_ops, cache_bytes, cache_usecs; static inline double calc_mibps (uint64_t bytes, int64_t usecs) @@ -79,23 +79,23 @@ print_stats (int64_t usecs) fprintf (fp, "elapsed time: %.3f s\n", usecs / USEC); if (pread_ops > 0) - fprintf (fp, "read: %" PRIu64 " ops, %.2f GiB, %.2f MiB/s\n", - pread_ops, pread_bytes / GiB, calc_mibps (pread_bytes, usecs)); + fprintf (fp, "read: %" PRIu64 " ops, %.2f GiB, %.3f s, %.2f MiB/s\n", + pread_ops, pread_bytes / GiB, pread_usecs / USEC, calc_mibps (pread_bytes, pread_usecs)); if (pwrite_ops > 0) - fprintf (fp, "write: %" PRIu64 " ops, %.2f GiB, %.2f MiB/s\n", - pwrite_ops, pwrite_bytes / GiB, calc_mibps (pwrite_bytes, usecs)); + fprintf (fp, "write: %" PRIu64 " ops, %.2f GiB, %.3f s, %.2f MiB/s\n", + pwrite_ops, pwrite_bytes / GiB, pwrite_usecs / USEC, calc_mibps (pwrite_bytes, pwrite_usecs)); if (trim_ops > 0) - fprintf (fp, "trim: %" PRIu64 " ops, %.2f GiB, %.2f MiB/s\n", - trim_ops, trim_bytes / GiB, calc_mibps (trim_bytes, usecs)); + fprintf (fp, "trim: %" PRIu64 " ops, %.2f GiB, %.3f s, %.2f MiB/s\n", + trim_ops, trim_bytes / GiB, trim_usecs / USEC, calc_mibps (trim_bytes, trim_usecs)); if (zero_ops > 0) - fprintf (fp, "zero: %" PRIu64 " ops, %.2f GiB, %.2f MiB/s\n", - zero_ops, zero_bytes / GiB, calc_mibps (zero_bytes, usecs)); + fprintf (fp, "zero: %" PRIu64 " ops, %.2f GiB, %.3f s, %.2f MiB/s\n", + zero_ops, zero_bytes / GiB, zero_usecs / USEC, calc_mibps (zero_bytes, zero_usecs)); if (extents_ops > 0) - fprintf (fp, "extents: %" PRIu64 " ops, %.2f GiB, %.2f MiB/s\n", - extents_ops, extents_bytes / GiB, calc_mibps (extents_bytes, usecs)); + fprintf (fp, "extents: %" PRIu64 " ops, %.2f GiB, %.3f s, %.2f MiB/s\n", + extents_ops, extents_bytes / GiB, extents_usecs / USEC, calc_mibps (extents_bytes, extents_usecs)); if (cache_ops > 0) - fprintf (fp, "cache: %" PRIu64 " ops, %.2f GiB, %.2f MiB/s\n", - cache_ops, cache_bytes / GiB, calc_mibps (cache_bytes, usecs)); + fprintf (fp, "cache: %" PRIu64 " ops, %.2f GiB, %.3f s, %.2f MiB/s\n", + cache_ops, cache_bytes / GiB, cache_usecs / USEC, calc_mibps (cache_bytes, cache_usecs)); fflush (fp); } @@ -186,13 +186,20 @@ stats_pread (struct nbdkit_next_ops *next_ops, void *nxdata, void *handle, void *buf, uint32_t count, uint64_t offset, uint32_t flags, int *err) { + struct timeval start, end; + int64_t usecs; int r; + gettimeofday (&start, NULL); r = next_ops->pread (nxdata, buf, count, offset, flags, err); if (r == 0) { + gettimeofday (&end, NULL); + usecs = tvdiff_usec(&start, &end); + ACQUIRE_LOCK_FOR_CURRENT_SCOPE (&lock); pread_ops++; pread_bytes += count; + pread_usecs += usecs; } return r; } @@ -204,13 +211,20 @@ stats_pwrite (struct nbdkit_next_ops *next_ops, void *nxdata, const void *buf, uint32_t count, uint64_t offset, uint32_t flags, int *err) { + struct timeval start, end; + int64_t usecs; int r; + gettimeofday (&start, NULL); r = next_ops->pwrite (nxdata, buf, count, offset, flags, err); if (r == 0) { + gettimeofday (&end, NULL); + usecs = tvdiff_usec(&start, &end); + ACQUIRE_LOCK_FOR_CURRENT_SCOPE (&lock); pwrite_ops++; pwrite_bytes += count; + pwrite_usecs += usecs; } return r; } @@ -222,13 +236,20 @@ stats_trim (struct nbdkit_next_ops *next_ops, void *nxdata, uint32_t count, uint64_t offset, uint32_t flags, int *err) { + struct timeval start, end; + int64_t usecs; int r; + gettimeofday (&start, NULL); r = next_ops->trim (nxdata, count, offset, flags, err); if (r == 0) { + gettimeofday (&end, NULL); + usecs = tvdiff_usec(&start, &end); + ACQUIRE_LOCK_FOR_CURRENT_SCOPE (&lock); trim_ops++; trim_bytes += count; + trim_usecs += usecs; } return r; } @@ -240,13 +261,20 @@ stats_zero (struct nbdkit_next_ops *next_ops, void *nxdata, uint32_t count, uint64_t offset, uint32_t flags, int *err) { + struct timeval start, end; + int64_t usecs; int r; + gettimeofday (&start, NULL); r = next_ops->zero (nxdata, count, offset, flags, err); if (r == 0) { + gettimeofday (&end, NULL); + usecs = tvdiff_usec(&start, &end); + ACQUIRE_LOCK_FOR_CURRENT_SCOPE (&lock); zero_ops++; zero_bytes += count; + zero_usecs += usecs; } return r; } @@ -258,10 +286,16 @@ stats_extents (struct nbdkit_next_ops *next_ops, void *nxdata, uint32_t count, uint64_t offset, uint32_t flags, struct nbdkit_extents *extents, int *err) { + struct timeval start, end; + int64_t usecs; int r; + gettimeofday (&start, NULL); r = next_ops->extents (nxdata, count, offset, flags, extents, err); if (r == 0) { + gettimeofday (&end, NULL); + usecs = tvdiff_usec(&start, &end); + ACQUIRE_LOCK_FOR_CURRENT_SCOPE (&lock); extents_ops++; /* XXX There's a case for trying to determine how long the extents @@ -269,6 +303,7 @@ stats_extents (struct nbdkit_next_ops *next_ops, void *nxdata, * the complex rules in the protocol. */ extents_bytes += count; + extents_usecs += usecs; } return r; } @@ -280,13 +315,20 @@ stats_cache (struct nbdkit_next_ops *next_ops, void *nxdata, uint32_t count, uint64_t offset, uint32_t flags, int *err) { + struct timeval start, end; + int64_t usecs; int r; + gettimeofday (&start, NULL); r = next_ops->cache (nxdata, count, offset, flags, err); if (r == 0) { + gettimeofday (&end, NULL); + usecs = tvdiff_usec(&start, &end); + ACQUIRE_LOCK_FOR_CURRENT_SCOPE (&lock); cache_ops++; cache_bytes += count; + cache_usecs += usecs; } return r; } -- 2.21.0