3:42 p.m.
Previously we measured the total time and used it to calculate the rate
of different operations. This is misleading and hiding the real
throughput. Change single operation stats to use the time spent in this
operation.
To understand total system throughput, show also new "total" stats,
summing ops, bytes of other operations, and using the total time. This
works well for copying images to/from nbdkit.
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%)
total: 2299 ops, 2.190 s, 6442450944 bytes, 6.000 GiB, 2804.977 MiB/s
write: 1271 ops, 0.359 s, 1219244032 bytes, 1.136 GiB, 3237.466 MiB/s
zero: 1027 ops, 0.012 s, 5223206912 bytes, 4.864 GiB, 398658.526 MiB/s
extents: 1 ops, 0.000 s, 2147483136 bytes, 2.000 GiB, 113777750.651 MiB/s
This shows 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 | 70 ++++++++++++++++++++++++++++++++-----------
1 file changed, 52 insertions(+), 18 deletions(-)
diff --git a/filters/stats/stats.c b/filters/stats/stats.c
index 6bef65c..2c92c65 100644
--- a/filters/stats/stats.c
+++ b/filters/stats/stats.c
@@ -62,6 +62,7 @@ typedef struct {
const char *name;
uint64_t ops;
uint64_t bytes;
+ uint64_t usecs;
} stat;
/* This lock protects all the stats. */
@@ -80,28 +81,42 @@ calc_rate (uint64_t bytes, int64_t usecs)
}
static inline void
-print_stat (const stat *st, int64_t usecs)
+print_stat (const stat *st)
{
if (st->ops > 0)
- fprintf (fp, "%s: %" PRIu64 " ops, %" PRIu64 " bytes, %.3f
GiB, %.3f MiB/s\n",
+ fprintf (fp, "%s: %" PRIu64 " ops, %.3f s, %" PRIu64 "
bytes, %.3f GiB, %.3f MiB/s\n",
st->name,
st->ops,
+ st->usecs / USEC,
st->bytes,
st->bytes / GiB,
- calc_rate (st->bytes, usecs));
+ calc_rate (st->bytes, st->usecs));
}
static inline void
print_stats (int64_t usecs)
{
- fprintf (fp, "elapsed time: %.3f s\n", usecs / USEC);
-
- 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);
+ const stat total_st = {
+ .name = "total",
+ .ops = pread_st.ops
+ + pwrite_st.ops
+ + trim_st.ops
+ + zero_st.ops
+ + extents_st.ops,
+ .bytes = pread_st.bytes
+ + pwrite_st.bytes
+ + trim_st.bytes
+ + zero_st.bytes,
+ .usecs = usecs,
+ };
+
+ print_stat (&total_st);
+ print_stat (&pread_st);
+ print_stat (&pwrite_st);
+ print_stat (&trim_st);
+ print_stat (&zero_st);
+ print_stat (&extents_st);
+ print_stat (&cache_st);
fflush (fp);
}
@@ -187,11 +202,18 @@ stats_config_complete (nbdkit_next_config_complete *next, void
*nxdata)
"statsappend=<BOOL> True to append to the log (default false).\n"
static inline void
-record_stat (stat *st, uint32_t count)
+record_stat (stat *st, uint32_t count, struct timeval *start)
{
+ struct timeval end;
+ uint64_t usecs;
+
+ gettimeofday(&end, NULL);
+ usecs = tvdiff_usec(start, &end);
+
ACQUIRE_LOCK_FOR_CURRENT_SCOPE (&lock);
st->ops++;
st->bytes += count;
+ st->usecs += usecs;
}
/* Read. */
@@ -200,10 +222,12 @@ 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;
int r;
+ gettimeofday (&start, NULL);
r = next_ops->pread (nxdata, buf, count, offset, flags, err);
- if (r == 0) record_stat (&pread_st, count);
+ if (r == 0) record_stat (&pread_st, count, &start);
return r;
}
@@ -214,10 +238,12 @@ 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;
int r;
+ gettimeofday (&start, NULL);
r = next_ops->pwrite (nxdata, buf, count, offset, flags, err);
- if (r == 0) record_stat (&pwrite_st, count);
+ if (r == 0) record_stat (&pwrite_st, count, &start);
return r;
}
@@ -228,10 +254,12 @@ stats_trim (struct nbdkit_next_ops *next_ops, void *nxdata,
uint32_t count, uint64_t offset, uint32_t flags,
int *err)
{
+ struct timeval start;
int r;
+ gettimeofday (&start, NULL);
r = next_ops->trim (nxdata, count, offset, flags, err);
- if (r == 0) record_stat (&trim_st, count);
+ if (r == 0) record_stat (&trim_st, count, &start);
return r;
}
@@ -242,10 +270,12 @@ stats_zero (struct nbdkit_next_ops *next_ops, void *nxdata,
uint32_t count, uint64_t offset, uint32_t flags,
int *err)
{
+ struct timeval start;
int r;
+ gettimeofday (&start, NULL);
r = next_ops->zero (nxdata, count, offset, flags, err);
- if (r == 0) record_stat (&zero_st, count);
+ if (r == 0) record_stat (&zero_st, count, &start);
return r;
}
@@ -256,14 +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;
int r;
+ gettimeofday (&start, NULL);
r = next_ops->extents (nxdata, count, offset, flags, extents, err);
/* 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);
+ if (r == 0) record_stat (&extents_st, count, &start);
return r;
}
@@ -274,10 +306,12 @@ stats_cache (struct nbdkit_next_ops *next_ops, void *nxdata,
uint32_t count, uint64_t offset, uint32_t flags,
int *err)
{
+ struct timeval start;
int r;
+ gettimeofday (&start, NULL);
r = next_ops->cache (nxdata, count, offset, flags, err);
- if (r == 0) record_stat (&cache_st, count);
+ if (r == 0) record_stat (&cache_st, count, &start);
return r;
}
--
2.21.0