Libguestfs - Dec 2019 - [PATCH nbdkit v3 5/5] filters: stats: Show total stats

This is the third attempt to make the stats filter better. This time I kept the
changes minimal to make it eaier to make progress.

I tried the idea of showing global stats in separate "total" section,
but it
became messy and hard to implemnt, so I tried the simpler solution of showing
both operation rate and total rate in the operation line.

Nir Soffer (5):
  filters: stats: Add maybe() helper
  filters: stats: Add humanrate() helper
  filters: stats: Show time per operation
  filters: stats: Show both operation and total rates
  filters: stats: Show total stats

 filters/stats/nbdkit-stats-filter.pod | 10 +++---
 filters/stats/stats.c                 | 46 ++++++++++++++++++++++-----
 2 files changed, 43 insertions(+), 13 deletions(-)

-- 
2.21.0

Returns non-null string or "(n/a)".
---
 filters/stats/stats.c | 9 +++++++--
 1 file changed, 7 insertions(+), 2 deletions(-)

diff --git a/filters/stats/stats.c b/filters/stats/stats.c
index 6e48017..44f3379 100644
--- a/filters/stats/stats.c
+++ b/filters/stats/stats.c
@@ -94,6 +94,12 @@ humansize (uint64_t bytes)
   return ret;
 }
 
+static inline const char *
+maybe (char *s)
+{
+  return s ? s : "(n/a)";
+}
+
 static void
 print_stat (const stat *st, int64_t usecs)
 {
@@ -104,8 +110,7 @@ print_stat (const stat *st, int64_t usecs)
       humansize (st->bytes / (usecs / 1000000.0)) : NULL;
 
     fprintf (fp, "%s: %" PRIu64 " ops, %s, %s/s\n",
-             st->name, st->ops,
-             size ? size : "(n/a)", rate ? rate : "(n/a)");
+             st->name, st->ops, maybe (size), maybe (rate));
 
     free (size);
     free (rate);
-- 
2.21.0

We want to show both operation rate based on time spent in operation,
and global rate, based on elapsed time. Add a helper to make it easier.
---
 filters/stats/stats.c | 11 ++++++++---
 1 file changed, 8 insertions(+), 3 deletions(-)

diff --git a/filters/stats/stats.c b/filters/stats/stats.c
index 44f3379..abcbff2 100644
--- a/filters/stats/stats.c
+++ b/filters/stats/stats.c
@@ -94,6 +94,13 @@ humansize (uint64_t bytes)
   return ret;
 }
 
+static char *
+humanrate (uint64_t bytes, uint64_t usecs)
+{
+  double secs = usecs / 1000000.0;
+  return secs != 0.0 ? humansize (bytes / secs) : NULL;
+}
+
 static inline const char *
 maybe (char *s)
 {
@@ -105,9 +112,7 @@ print_stat (const stat *st, int64_t usecs)
 {
   if (st->ops > 0) {
     char *size = humansize (st->bytes);
-    char *rate -      usecs / 1000000.0 != 0 ?
-      humansize (st->bytes / (usecs / 1000000.0)) : NULL;
+    char *rate = humanrate (st->bytes, usecs);
 
     fprintf (fp, "%s: %" PRIu64 " ops, %s, %s/s\n",
              st->name, st->ops, maybe (size), maybe (rate));
-- 
2.21.0

Use microseconds resolution so we get meaningful data even for rarely
called and fast operation like flush or extents. For consistency, use
same format in for elapsed time.
---
 filters/stats/nbdkit-stats-filter.pod | 10 +++++-----
 filters/stats/stats.c                 |  7 ++++---
 2 files changed, 9 insertions(+), 8 deletions(-)

diff --git a/filters/stats/nbdkit-stats-filter.pod
b/filters/stats/nbdkit-stats-filter.pod
index 28693d4..0a9f10a 100644
--- a/filters/stats/nbdkit-stats-filter.pod
+++ b/filters/stats/nbdkit-stats-filter.pod
@@ -25,11 +25,11 @@ number of read, write and trim operations involved:
                  run : \
                  mkfs ext4 /dev/sda
  '
- elapsed time: 1.33377 s
- read: 248 ops, 4.75 MiB, 3.56 MiB/s
- write: 78 ops, 32.64 MiB, 24.48 MiB/s
- trim: 33 ops, 1.00 GiB, 767.75 MiB/s
- flush: 9 ops, 0 bytes, 0 bytes/s
+ elapsed time: 1.184586 s
+ read: 253 ops, 0.000342 s, 4.77 MiB, 4.03 MiB/s
+ write: 78 ops, 0.152594 s, 32.64 MiB, 27.56 MiB/s
+ trim: 33 ops, 0.000214 s, 1.00 GiB, 864.44 MiB/s
+ flush: 9 ops, 0.000003 s, 0 bytes, 0 bytes/s
 
 =head1 PARAMETERS
 
diff --git a/filters/stats/stats.c b/filters/stats/stats.c
index abcbff2..0914248 100644
--- a/filters/stats/stats.c
+++ b/filters/stats/stats.c
@@ -114,8 +114,9 @@ print_stat (const stat *st, int64_t usecs)
     char *size = humansize (st->bytes);
     char *rate = humanrate (st->bytes, usecs);
 
-    fprintf (fp, "%s: %" PRIu64 " ops, %s, %s/s\n",
-             st->name, st->ops, maybe (size), maybe (rate));
+    fprintf (fp, "%s: %" PRIu64 " ops, %.6f s, %s, %s/s\n",
+             st->name, st->ops, st->usecs / 1000000.0, maybe (size),
+             maybe (rate));
 
     free (size);
     free (rate);
@@ -125,7 +126,7 @@ print_stat (const stat *st, int64_t usecs)
 static inline void
 print_stats (int64_t usecs)
 {
-  fprintf (fp, "elapsed time: %g s\n", usecs / 1000000.);
+  fprintf (fp, "elapsed time: %.6f s\n", usecs / 1000000.);
   print_stat (&pread_st,   usecs);
   print_stat (&pwrite_st,  usecs);
   print_stat (&trim_st,    usecs);
-- 
2.21.0

I tried to show the total rate separately, but it becomes messy. Adding
the total rate in the same line is easy, so lets start with this.

Showing both values in the same line may be confusing, so I added
labels:

    read: 254 ops, 0.000326 s, 4.78 MiB, 14.31 GiB/s op, 3.80 MiB/s total
---
 filters/stats/nbdkit-stats-filter.pod | 10 +++++-----
 filters/stats/stats.c                 | 10 ++++++----
 2 files changed, 11 insertions(+), 9 deletions(-)

diff --git a/filters/stats/nbdkit-stats-filter.pod
b/filters/stats/nbdkit-stats-filter.pod
index 0a9f10a..ac8173c 100644
--- a/filters/stats/nbdkit-stats-filter.pod
+++ b/filters/stats/nbdkit-stats-filter.pod
@@ -25,11 +25,11 @@ number of read, write and trim operations involved:
                  run : \
                  mkfs ext4 /dev/sda
  '
- elapsed time: 1.184586 s
- read: 253 ops, 0.000342 s, 4.77 MiB, 4.03 MiB/s
- write: 78 ops, 0.152594 s, 32.64 MiB, 27.56 MiB/s
- trim: 33 ops, 0.000214 s, 1.00 GiB, 864.44 MiB/s
- flush: 9 ops, 0.000003 s, 0 bytes, 0 bytes/s
+ elapsed time: 1.258933 s
+ read: 254 ops, 0.000326 s, 4.78 MiB, 14.31 GiB/s op, 3.80 MiB/s total
+ write: 78 ops, 0.167061 s, 32.64 MiB, 195.40 MiB/s op, 25.93 MiB/s total
+ trim: 33 ops, 0.000304 s, 1.00 GiB, 3289.47 GiB/s op, 813.39 MiB/s total
+ flush: 9 ops, 0.000002 s, 0 bytes, 0 bytes/s op, 0 bytes/s total
 
 =head1 PARAMETERS
 
diff --git a/filters/stats/stats.c b/filters/stats/stats.c
index 0914248..fbd6b87 100644
--- a/filters/stats/stats.c
+++ b/filters/stats/stats.c
@@ -112,14 +112,16 @@ print_stat (const stat *st, int64_t usecs)
 {
   if (st->ops > 0) {
     char *size = humansize (st->bytes);
-    char *rate = humanrate (st->bytes, usecs);
+    char *op_rate = humanrate (st->bytes, st->usecs);
+    char *total_rate = humanrate (st->bytes, usecs);
 
-    fprintf (fp, "%s: %" PRIu64 " ops, %.6f s, %s, %s/s\n",
+    fprintf (fp, "%s: %" PRIu64 " ops, %.6f s, %s, %s/s op, %s/s
total\n",
              st->name, st->ops, st->usecs / 1000000.0, maybe (size),
-             maybe (rate));
+             maybe (op_rate), maybe (total_rate));
 
     free (size);
-    free (rate);
+    free (op_rate);
+    free (total_rate);
   }
 }
 
-- 
2.21.0

Change the first line to show total ops, time, total size, and rate.
The totals are useful for understanding the total throughput of the
application.
---
 filters/stats/nbdkit-stats-filter.pod |  8 ++++----
 filters/stats/stats.c                 | 19 ++++++++++++++++++-
 2 files changed, 22 insertions(+), 5 deletions(-)

diff --git a/filters/stats/nbdkit-stats-filter.pod
b/filters/stats/nbdkit-stats-filter.pod
index ac8173c..4fda092 100644
--- a/filters/stats/nbdkit-stats-filter.pod
+++ b/filters/stats/nbdkit-stats-filter.pod
@@ -25,10 +25,10 @@ number of read, write and trim operations involved:
                  run : \
                  mkfs ext4 /dev/sda
  '
- elapsed time: 1.258933 s
- read: 254 ops, 0.000326 s, 4.78 MiB, 14.31 GiB/s op, 3.80 MiB/s total
- write: 78 ops, 0.167061 s, 32.64 MiB, 195.40 MiB/s op, 25.93 MiB/s total
- trim: 33 ops, 0.000304 s, 1.00 GiB, 3289.47 GiB/s op, 813.39 MiB/s total
+ total: 370 ops, 1.282993 s, 1.04 GiB, 827.29 MiB/s
+ read: 250 ops, 0.000364 s, 4.76 MiB, 12.78 GiB/s op, 3.71 MiB/s total
+ write: 78 ops, 0.175715 s, 32.64 MiB, 185.78 MiB/s op, 25.44 MiB/s total
+ trim: 33 ops, 0.000252 s, 1.00 GiB, 3968.25 GiB/s op, 798.13 MiB/s total
  flush: 9 ops, 0.000002 s, 0 bytes, 0 bytes/s op, 0 bytes/s total
 
 =head1 PARAMETERS
diff --git a/filters/stats/stats.c b/filters/stats/stats.c
index fbd6b87..0759ceb 100644
--- a/filters/stats/stats.c
+++ b/filters/stats/stats.c
@@ -125,10 +125,27 @@ print_stat (const stat *st, int64_t usecs)
   }
 }
 
+static void
+print_totals (uint64_t usecs)
+{
+  uint64_t ops = pread_st.ops + pwrite_st.ops + trim_st.ops + zero_st.ops +
+    extents_st.ops + flush_st.ops;
+  uint64_t bytes = pread_st.bytes + pwrite_st.bytes + trim_st.bytes +
+    zero_st.bytes;
+  char *size = humansize (bytes);
+  char *rate = humanrate (bytes, usecs);
+
+  fprintf (fp, "total: %" PRIu64 " ops, %.6f s, %s,
%s/s\n",
+           ops, usecs / 1000000.0, maybe (size), maybe (rate));
+
+  free (size);
+  free (rate);
+}
+
 static inline void
 print_stats (int64_t usecs)
 {
-  fprintf (fp, "elapsed time: %.6f s\n", usecs / 1000000.);
+  print_totals (usecs);
   print_stat (&pread_st,   usecs);
   print_stat (&pwrite_st,  usecs);
   print_stat (&trim_st,    usecs);
-- 
2.21.0

ACK series, thanks.

Rich.

-- 
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
Read my programming and virtualization blog: http://rwmj.wordpress.com
libguestfs lets you edit virtual machines.  Supports shell scripting,
bindings from many languages.  http://libguestfs.org