On Sat, Nov 30, 2019 at 02:17:06AM +0200, Nir Soffer wrote: > 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.
I think opinions differ here. Some people will want to know the throughput being achieved by the system, and some people will want to know how well the plugin/backend is performing single operations. I know that you're interested in benchmarking imageio and that's completely valid, but I'm interested in measuring the total throughput. IOW: Can't we show both? The rest of the code is screaming out to be refactored so we aren't repeating the same change over and over. How about using something like the attached patch as an initial refactoring? Rich. -- Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones Read my programming and virtualization blog: http://rwmj.wordpress.com virt-p2v converts physical machines to virtual machines. Boot with a live CD or over the network (PXE) and turn machines into KVM guests. http://libguestfs.org/virt-v2v
>From 45c5f0b086e71aaf813159537525c0dc89da403a Mon Sep 17 00:00:00 2001 From: "Richard W.M. Jones" <[email protected]> Date: Sat, 30 Nov 2019 07:11:52 +0000 Subject: [PATCH] stats: Refactor stats recording and printing. Use a single struct to record and print stats, reducing the amount of duplicate code. --- filters/stats/stats.c | 104 ++++++++++++++++++------------------------ 1 file changed, 44 insertions(+), 60 deletions(-) diff --git a/filters/stats/stats.c b/filters/stats/stats.c index 98282e2..ffc367c 100644 --- a/filters/stats/stats.c +++ b/filters/stats/stats.c @@ -54,14 +54,20 @@ static bool append; static FILE *fp; static struct timeval start_t; +typedef struct { + const char *name; + uint64_t ops; + uint64_t bytes; +} stat; + /* 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 stat pread_st = { "read" }; +static stat pwrite_st = { "write" }; +static stat trim_st = { "trim" }; +static stat zero_st = { "zero" }; +static stat extents_st = { "extents" }; +static stat cache_st = { "cache" }; static inline double calc_bps (uint64_t bytes, int64_t usecs) @@ -69,30 +75,24 @@ calc_bps (uint64_t bytes, int64_t usecs) return 8.0 * bytes / usecs * 1000000.; } +static inline void +print_stat (const stat *st, int64_t usecs) +{ + if (st->ops > 0) + fprintf (fp, "%s: %" PRIu64 " ops, %" PRIu64 " bytes, %g bits/s\n", + st->name, st->ops, st->bytes, calc_bps (st->bytes, usecs)); +} + static inline void print_stats (int64_t usecs) { fprintf (fp, "elapsed time: %g s\n", usecs / 1000000.); - - if (pread_ops > 0) - fprintf (fp, "read: %" PRIu64 " ops, %" PRIu64 " bytes, %g bits/s\n", - pread_ops, pread_bytes, calc_bps (pread_bytes, usecs)); - if (pwrite_ops > 0) - fprintf (fp, "write: %" PRIu64 " ops, %" PRIu64 " bytes, %g bits/s\n", - pwrite_ops, pwrite_bytes, calc_bps (pwrite_bytes, usecs)); - if (trim_ops > 0) - fprintf (fp, "trim: %" PRIu64 " ops, %" PRIu64 " bytes, %g bits/s\n", - trim_ops, trim_bytes, calc_bps (trim_bytes, usecs)); - if (zero_ops > 0) - fprintf (fp, "zero: %" PRIu64 " ops, %" PRIu64 " bytes, %g bits/s\n", - zero_ops, zero_bytes, calc_bps (zero_bytes, usecs)); - if (extents_ops > 0) - fprintf (fp, "extents: %" PRIu64 " ops, %" PRIu64 " bytes, %g bits/s\n", - extents_ops, extents_bytes, calc_bps (extents_bytes, usecs)); - if (cache_ops > 0) - fprintf (fp, "cache: %" PRIu64 " ops, %" PRIu64 " bytes, %g bits/s\n", - cache_ops, cache_bytes, calc_bps (cache_bytes, usecs)); - + print_stat (&pread_st, usecs); + print_stat (&pwrite_st, usecs); + print_stat (&trim_st, usecs); + print_stat (&zero_st, usecs); + print_stat (&extents_st, usecs); + print_stat (&cache_st, usecs); fflush (fp); } @@ -176,6 +176,14 @@ stats_config_complete (nbdkit_next_config_complete *next, void *nxdata) "statsfile=<FILE> (required) The file to place the log in.\n" \ "statsappend=<BOOL> True to append to the log (default false).\n" +static inline void +record_stat (stat *st, uint32_t count) +{ + ACQUIRE_LOCK_FOR_CURRENT_SCOPE (&lock); + st->ops++; + st->bytes += count; +} + /* Read. */ static int stats_pread (struct nbdkit_next_ops *next_ops, void *nxdata, @@ -185,11 +193,7 @@ stats_pread (struct nbdkit_next_ops *next_ops, void *nxdata, int r; r = next_ops->pread (nxdata, buf, count, offset, flags, err); - if (r == 0) { - ACQUIRE_LOCK_FOR_CURRENT_SCOPE (&lock); - pread_ops++; - pread_bytes += count; - } + if (r == 0) record_stat (&pread_st, count); return r; } @@ -203,11 +207,7 @@ stats_pwrite (struct nbdkit_next_ops *next_ops, void *nxdata, int r; r = next_ops->pwrite (nxdata, buf, count, offset, flags, err); - if (r == 0) { - ACQUIRE_LOCK_FOR_CURRENT_SCOPE (&lock); - pwrite_ops++; - pwrite_bytes += count; - } + if (r == 0) record_stat (&pwrite_st, count); return r; } @@ -221,11 +221,7 @@ stats_trim (struct nbdkit_next_ops *next_ops, void *nxdata, int r; r = next_ops->trim (nxdata, count, offset, flags, err); - if (r == 0) { - ACQUIRE_LOCK_FOR_CURRENT_SCOPE (&lock); - trim_ops++; - trim_bytes += count; - } + if (r == 0) record_stat (&trim_st, count); return r; } @@ -239,11 +235,7 @@ stats_zero (struct nbdkit_next_ops *next_ops, void *nxdata, int r; r = next_ops->zero (nxdata, count, offset, flags, err); - if (r == 0) { - ACQUIRE_LOCK_FOR_CURRENT_SCOPE (&lock); - zero_ops++; - zero_bytes += count; - } + if (r == 0) record_stat (&zero_st, count); return r; } @@ -257,15 +249,11 @@ stats_extents (struct nbdkit_next_ops *next_ops, void *nxdata, int r; r = next_ops->extents (nxdata, count, offset, flags, extents, err); - if (r == 0) { - ACQUIRE_LOCK_FOR_CURRENT_SCOPE (&lock); - extents_ops++; - /* XXX There's a case for trying to determine how long the extents - * will be that are returned to the client, given the flags and - * the complex rules in the protocol. - */ - extents_bytes += count; - } + /* XXX There's a case for trying to determine how long the extents + * will be that are returned to the client (instead of simply using + * count), given the flags and the complex rules in the protocol. + */ + if (r == 0) record_stat (&extents_st, count); return r; } @@ -279,11 +267,7 @@ stats_cache (struct nbdkit_next_ops *next_ops, void *nxdata, int r; r = next_ops->cache (nxdata, count, offset, flags, err); - if (r == 0) { - ACQUIRE_LOCK_FOR_CURRENT_SCOPE (&lock); - cache_ops++; - cache_bytes += count; - } + if (r == 0) record_stat (&cache_st, count); return r; } -- 2.23.0
_______________________________________________ Libguestfs mailing list [email protected] https://www.redhat.com/mailman/listinfo/libguestfs
