Libguestfs - Nov 2019 - Re: [PATCH nbdkit 2/3] filters: stats: Measure time per operation

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

On Sat, Nov 30, 2019 at 9:13 AM Richard W.M. Jones <rjones@redhat.com>
wrote:
>
> 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?
Sure we can, but showing system throughput require more thinking.

We have 3 uses cases. Here is a possible way to show both system throughput
and fine grain per operation stats.

I'm assuming that for system throughput we like to think about the
total bytes processed
by the system in each direction:

read_rate = pread_bytes / total_time
write_rate = (pwrite_bytes + zero_bytes + trim_bytes) / total_time

1. copy image to nbdkit

total: 2300 ops, 6 GiB, 2.150 s, 2925.71 wMiB/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
flush: 1 ops, 1.200 s

2. read image from nbdkit:

total: 1272 ops, 6 GiB, 2.150 seconds, 2925.71 rMiB/s
read: 1271 ops, 1.14 GiB, 0.398 s, 2922.22 MiB/s
extents: 1 ops, 2.00 GiB, 0.000 s, 120470559.51 MiB/s

3. read/write, e.g running a vm from image served by nbdkit

total: 5998 ops, 8.50 GiB, 125.000 s, 20.48 rMiB/s, 49.15 wMiB/s
write: 1271 ops, 1.14 GiB, 0.398 s, 2922.22 MiB/s
read: 3000 ops, 2.50 GiB, 1.100 s, 2327.27 MiB/s
zero: 1027 ops, 4.86 GiB, 0.012 s, 414723.03 MiB/s
extents: 500 ops, 2.00 GiB, 0.000 s, 120470559.51 MiB/s
flush: 200 ops, 1.200 s

What do you think?
> 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?
Very nice, do you want to push it? I can include it in v2.

Nir

> > 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?
> 
> Very nice, do you want to push it? I can include it in v2.
Yes I'll push it now.

Will think about the rest of your email later!

Rich.

-- 
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
Read my programming and virtualization blog: http://rwmj.wordpress.com
virt-top is 'top' for virtual machines.  Tiny program with many
powerful monitoring features, net stats, disk stats, logging, etc.
http://people.redhat.com/~rjones/virt-top