Re: [Qemu-devel] Quick nbdkit question

Re: [Qemu-devel] Quick nbdkit question

[Richard W.M. Jones]

On Wed, Aug 07, 2019 at 02:30:18PM -0700, ivo welch wrote:
> hi richard---please forgive us.  another quickie.  we created an nbd
> device.  just a block device...no partitions, etc.  in the guest vm, we
> wrote a short C program that writes one sector (open file, fseek, fwrite,
> close file) and then does it again.  all is working just fine.  the host
> console (filter) prints out the write requests, as it should.  (we added
> some more print code.)
> 
> but we are confused about that after the first [but not the second] write,
> we see about 30 (4096b) sector reads, starting from 4096, 12288, ... .
> (the file below has both the C code and the nbdkit messages.)

I guess it's happening because of readahead in the qemu NBD driver, or
generally in the QEMU block layer.  Eric or Kevin will probably have a
better idea.

> there is no file system layer here, just an nbdkit block device. what is
> reading sectors here?  is it the stdio.h library in the guest, something
> magic about access into an unformatted block device in the guest VM linux,
> or nbdkit itself?!     does this sound familiar?
> 
> regards,
> 
> /iaw
> --
> Ivo Welch (ivo.welch@ucla.edu)
> http://www.ivo-welch.info/

> #include<stdio.h>
> 
> int main() {
> 	FILE *fp;
> 	char str[4096] = "THIS IS A TEST";
> 	
> 	fp = fopen("/dev/sdb", "r+");
> 	fseek(fp, -4096, SEEK_END);
> 	fwrite(str, 1, sizeof(str), fp);
> 	fclose(fp);
> 
> 	fp = fopen("/dev/sdb", "r+");
> 	fseek(fp, -8192, SEEK_END);
> 	fwrite(str, 1, sizeof(str), fp);
> 	fclose(fp);
> }
> 
> 
> 
> 
> nbdkit: file.2: debug: filter: pwrite count=4096 offset=8589930496 flags=0x0
> nbdkit: file.2: debug: 
> 
> 
> WRITE [4096:8589930496:0:0]: 'THIS IS A TEST.................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................'
> 
> 
> 
> nbdkit: file.2: debug: pwrite count=4096 offset=8589930496 fua=0
> nbdkit: file.13: debug: filter: pread count=4096 offset=0 flags=0x0
> nbdkit: file.13: debug: pread count=4096 offset=0
> nbdkit: file.13: debug: filter: pread count=4096 offset=4096 flags=0x0
> nbdkit: file.13: debug: pread count=4096 offset=4096
> nbdkit: file.13: debug: filter: pread count=4096 offset=12288 flags=0x0
> nbdkit: file.13: debug: pread count=4096 offset=12288
> nbdkit: file.13: debug: filter: pread count=4096 offset=8589869056 flags=0x0
> nbdkit: file.13: debug: pread count=4096 offset=8589869056
> nbdkit: file.1: debug: filter: pread count=4096 offset=8589930496 flags=0x0
> nbdkit: file.1: debug: pread count=4096 offset=8589930496
> nbdkit: file.1: debug: filter: pread count=4096 offset=8589799424 flags=0x0
> nbdkit: file.1: debug: pread count=4096 offset=8589799424
> nbdkit: file.1: debug: filter: pread count=4096 offset=8589901824 flags=0x0
> nbdkit: file.1: debug: pread count=4096 offset=8589901824
> nbdkit: file.6: debug: filter: pread count=4096 offset=8589803520 flags=0x0
> nbdkit: file.6: debug: pread count=4096 offset=8589803520
> nbdkit: file.6: debug: filter: pread count=4096 offset=8589729792 flags=0x0
> nbdkit: file.6: debug: pread count=4096 offset=8589729792
> nbdkit: file.10: debug: filter: pread count=4096 offset=8589631488 flags=0x0
> nbdkit: file.10: debug: pread count=4096 offset=8589631488
> nbdkit: file.10: debug: filter: pread count=4096 offset=8589586432 flags=0x0
> nbdkit: file.10: debug: pread count=4096 offset=8589586432
> nbdkit: file.8: debug: filter: pread count=4096 offset=8589557760 flags=0x0
> nbdkit: file.8: debug: pread count=4096 offset=8589557760
> nbdkit: file.0: debug: filter: pread count=4096 offset=8589467648 flags=0x0
> nbdkit: file.0: debug: pread count=4096 offset=8589467648
> nbdkit: file.3: debug: filter: pread count=4096 offset=8589434880 flags=0x0
> nbdkit: file.3: debug: pread count=4096 offset=8589434880
> nbdkit: file.9: debug: filter: pread count=4096 offset=8589426688 flags=0x0
> nbdkit: file.9: debug: pread count=4096 offset=8589426688
> nbdkit: file.9: debug: filter: pread count=4096 offset=8589447168 flags=0x0
> nbdkit: file.9: debug: pread count=4096 offset=8589447168
> nbdkit: file.9: debug: filter: pread count=4096 offset=8588353536 flags=0x0
> nbdkit: file.9: debug: pread count=4096 offset=8588353536
> nbdkit: file.9: debug: filter: pread count=4096 offset=16384 flags=0x0
> nbdkit: file.9: debug: pread count=4096 offset=16384
> nbdkit: file.9: debug: filter: pread count=4096 offset=32768 flags=0x0
> nbdkit: file.9: debug: pread count=4096 offset=32768
> nbdkit: file.9: debug: filter: pread count=4096 offset=65536 flags=0x0
> nbdkit: file.9: debug: pread count=4096 offset=65536
> nbdkit: file.14: debug: filter: pread count=4096 offset=131072 flags=0x0
> nbdkit: file.14: debug: pread count=4096 offset=131072
> nbdkit: file.14: debug: filter: pread count=4096 offset=262144 flags=0x0
> nbdkit: file.14: debug: pread count=4096 offset=262144
> nbdkit: file.1: debug: filter: pread count=4096 offset=524288 flags=0x0
> nbdkit: file.1: debug: pread count=4096 offset=524288
> nbdkit: file.1: debug: filter: pread count=4096 offset=1048576 flags=0x0
> nbdkit: file.1: debug: pread count=4096 offset=1048576
> nbdkit: file.1: debug: filter: pread count=4096 offset=2097152 flags=0x0
> nbdkit: file.1: debug: pread count=4096 offset=2097152
> nbdkit: file.1: debug: filter: pread count=4096 offset=4194304 flags=0x0
> nbdkit: file.1: debug: pread count=4096 offset=4194304
> nbdkit: file.1: debug: filter: pread count=4096 offset=28672 flags=0x0
> nbdkit: file.1: debug: pread count=4096 offset=28672
> nbdkit: file.1: debug: filter: pread count=4096 offset=61440 flags=0x0
> nbdkit: file.1: debug: pread count=4096 offset=61440
> nbdkit: file.1: debug: filter: pread count=4096 offset=8192 flags=0x0
> nbdkit: file.1: debug: pread count=4096 offset=8192
> nbdkit: file.1: debug: filter: pread count=8192 offset=20480 flags=0x0
> nbdkit: file.1: debug: pread count=8192 offset=20480
> nbdkit: file.1: debug: filter: pread count=24576 offset=36864 flags=0x0
> nbdkit: file.1: debug: pread count=24576 offset=36864
> nbdkit: file.1: debug: filter: pread count=61440 offset=69632 flags=0x0
> nbdkit: file.1: debug: pread count=61440 offset=69632
> nbdkit: file.1: debug: filter: pread count=126976 offset=135168 flags=0x0
> nbdkit: file.1: debug: pread count=126976 offset=135168
> nbdkit: file.12: debug: filter: pread count=258048 offset=266240 flags=0x0
> nbdkit: file.12: debug: pread count=258048 offset=266240
> nbdkit: file.13: debug: filter: pread count=16384 offset=8589410304 flags=0x0
> nbdkit: file.13: debug: pread count=16384 offset=8589410304
> nbdkit: file.13: debug: filter: pread count=4096 offset=8589430784 flags=0x0
> nbdkit: file.13: debug: pread count=4096 offset=8589430784
> nbdkit: file.13: debug: filter: pread count=8192 offset=8589438976 flags=0x0
> nbdkit: file.13: debug: pread count=8192 offset=8589438976
> nbdkit: file.13: debug: filter: pread count=16384 offset=8589451264 flags=0x0
> nbdkit: file.13: debug: pread count=16384 offset=8589451264
> nbdkit: file.13: debug: filter: pread count=86016 offset=8589471744 flags=0x0
> nbdkit: file.13: debug: pread count=86016 offset=8589471744
> nbdkit: file.6: debug: filter: pread count=24576 offset=8589561856 flags=0x0
> nbdkit: file.6: debug: pread count=24576 offset=8589561856
> nbdkit: file.15: debug: filter: pread count=40960 offset=8589590528 flags=0x0
> nbdkit: file.15: debug: pread count=40960 offset=8589590528
> nbdkit: file.10: debug: filter: pread count=36864 offset=8589635584 flags=0x0
> nbdkit: file.10: debug: pread count=36864 offset=8589635584
> nbdkit: file.8: debug: filter: pread count=57344 offset=8589672448 flags=0x0
> nbdkit: file.8: debug: pread count=57344 offset=8589672448
> nbdkit: file.0: debug: filter: pread count=65536 offset=8589733888 flags=0x0
> nbdkit: file.0: debug: pread count=65536 offset=8589733888
> nbdkit: file.3: debug: filter: pread count=61440 offset=8589807616 flags=0x0
> nbdkit: file.3: debug: pread count=61440 offset=8589807616
> nbdkit: file.2: debug: filter: pread count=28672 offset=8589873152 flags=0x0
> nbdkit: file.2: debug: pread count=28672 offset=8589873152
> nbdkit: file.7: debug: filter: pread count=20480 offset=8589905920 flags=0x0
> nbdkit: file.7: debug: pread count=20480 offset=8589905920
> nbdkit: file.11: debug: filter: pwrite count=4096 offset=8589926400 flags=0x0
> nbdkit: file.11: debug: 
> 
> 
> WRITE [4096:8589926400:0:0]: 'THIS IS A TEST.................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................'
> 
> 
> 
> nbdkit: file.11: debug: pwrite count=4096 offset=8589926400 fua=0
> 

Rich.

-- 
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
Read my programming and virtualization blog: http://rwmj.wordpress.com
virt-df lists disk usage of guests without needing to install any
software inside the virtual machine.  Supports Linux and Windows.
http://people.redhat.com/~rjones/virt-df/

Re: [Qemu-devel] Quick nbdkit question

[Eric Blake]

[-- Attachment #1.1: Type: text/plain, Size: 2320 bytes --]

On 8/8/19 2:41 AM, Richard W.M. Jones wrote:
> On Wed, Aug 07, 2019 at 02:30:18PM -0700, ivo welch wrote:
>> hi richard---please forgive us.  another quickie.  we created an nbd
>> device.  just a block device...no partitions, etc.  in the guest vm, we
>> wrote a short C program that writes one sector (open file, fseek, fwrite,
>> close file) and then does it again.  all is working just fine.  the host
>> console (filter) prints out the write requests, as it should.  (we added
>> some more print code.)
>>
>> but we are confused about that after the first [but not the second] write,
>> we see about 30 (4096b) sector reads, starting from 4096, 12288, ... .
>> (the file below has both the C code and the nbdkit messages.)
> 
> I guess it's happening because of readahead in the qemu NBD driver, or
> generally in the QEMU block layer.  Eric or Kevin will probably have a
> better idea.

More likely, it's happening in the guest OS.  The kernel probes a lot of
sectors when first mounting block storage, to determine what lives on
that storage.  Rich even has a graphical demonstration of that probing
in his FOSDEM 2019 presentation.
https://rwmj.wordpress.com/2019/02/04/video-take-your-loop-mounts-to-the-next-level-with-nbdkit/
around the 21:20 mark.

> 
>> there is no file system layer here, just an nbdkit block device. what is
>> reading sectors here?  is it the stdio.h library in the guest, something
>> magic about access into an unformatted block device in the guest VM linux,
>> or nbdkit itself?!     does this sound familiar?

In order to determine if storage is formatted or not, the guest VM Linux
kernel reads a lot of sectors.  Qemu is not doing readahead, so much as
faithfully reproducing the read requests from the guest.  There are
places where qemu tries to consolidate consecutive actions from the
guest into one larger action to the storage, and we also have ideas
about adding a caching filter which can perform readahead and such for
performance, but I don't think they can be universally enabled in qemu
without penalizing some users, so it should be obvious when you are
opting in to those sorts of qemu features.

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3226
Virtualization:  qemu.org | libvirt.org


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 488 bytes --]