6:17 p.m.
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