Re: Inconsistent block status reply in qemu-nbd in qemu-img-6.2.0

[Nir Soffer]

On Sun, Jan 16, 2022 at 1:17 PM Nir Soffer <nsoffer@redhat.com> wrote:
>
> Some of our tests started to fail since qemu-img 6.2.0 released.
>
> Here is an example failure:
>
> $ truncate -s1g /data/scratch/empty-1g.raw
>
> $ qemu-nbd -r -t -e8 -k /tmp/nbd.sock -A -f raw /data/scratch/empty-1g.raw &

git bisect points to this commit:

$ git bisect good
0bc329fbb009f8601cec23bf2bc48ead0c5a5fa2 is the first bad commit
commit 0bc329fbb009f8601cec23bf2bc48ead0c5a5fa2
Author: Hanna Reitz <hreitz@redhat.com>
Date:   Thu Aug 12 10:41:44 2021 +0200

    block: block-status cache for data regions

The commit message says:

    (Note that only caching data regions but not zero regions means that
    returning false information from the cache is not catastrophic: Treating
    zeroes as data is fine.  While we try to invalidate the cache on zero
    writes and discards, such incongruences may still occur when there are
    other processes writing to the image.)

I don't think it is fine to report zero as data. This can cause severe
performance
issues when users copy unneeded zero extents over the network, instead of
doing no work with zero bandwidth.

Do we have a way to disable this cache, at least for nbd?

Nir




>
> $ nbdinfo --map nbd+unix:///?socket=/tmp/nbd.sock
>          0  1073741824    3  hole,zero
>
> $ python
> Python 3.10.1 (main, Dec  9 2021, 00:00:00) [GCC 11.2.1 20211203 (Red
> Hat 11.2.1-7)] on linux
> Type "help", "copyright", "credits" or "license" for more information.
>
> Enable debug logs so we can see all nbd commands and replies...
>
> >>> import logging
> >>> logging.basicConfig(level=logging.DEBUG)
>
> Connect to qemu-nbd:
>
> >>> from ovirt_imageio._internal import nbd
> >>> c = nbd.Client(nbd.UnixAddress("/tmp/nbd.sock"))
> DEBUG:nbd:Connecting address='/tmp/nbd.sock' export_name='' dirty=False
> DEBUG:nbd:Received server flags: 3
> DEBUG:nbd:Sending client flags: 1
> DEBUG:nbd:Sending option: 8 data: b''
> DEBUG:nbd:Received reply magic=3e889045565a9 option=8 type=1 len=0
> DEBUG:nbd:Structured reply enabled
> DEBUG:nbd:Sending option: 10 data:
> bytearray(b'\x00\x00\x00\x00\x00\x00\x00\x02\x00\x00\x00\x0fbase:allocation\x00\x00\x00\x15qemu:allocation-depth')
> DEBUG:nbd:Received reply magic=3e889045565a9 option=10 type=4 len=19
> DEBUG:nbd:Meta context base:allocation is available id=0
> DEBUG:nbd:Received reply magic=3e889045565a9 option=10 type=4 len=25
> DEBUG:nbd:Meta context qemu:allocation-depth is available id=1
> DEBUG:nbd:Received reply magic=3e889045565a9 option=10 type=1 len=0
> DEBUG:nbd:Sending option: 7 data: bytearray(b'\x00\x00\x00\x00\x00\x00')
> DEBUG:nbd:Received reply magic=3e889045565a9 option=7 type=3 len=14
> DEBUG:nbd:Received block size info minimum=1 preferred=4096 maximum=33554432
> DEBUG:nbd:Received reply magic=3e889045565a9 option=7 type=3 len=12
> DEBUG:nbd:Received export info size=1073741824 flags=1423
> DEBUG:nbd:Received reply magic=3e889045565a9 option=7 type=1 len=0
> DEBUG:nbd:Ready for transmission
>
> Get extents (first call):
>
> >>> c.extents(0, 1024**3)
> DEBUG:nbd:Sending NBD_CMD_BLOCK_STATUS handle=0 offset=0
> length=1073741824 flags=0
> DEBUG:nbd:Extent length=1073741824 flags=3 context=0
> DEBUG:nbd:Extent length=1073741824 flags=1 context=1
> {'base:allocation': [Extent(length=1073741824, flags=3)],
> 'qemu:allocation-depth': [Extent(length=1073741824, flags=0)]}
>
> We got the flags = 3  (NBD_STATE_HOLE | NBD_STATE_ZERO)
>
> But in the next cal...
>
> >>> c.extents(0, 1024**3)
> DEBUG:nbd:Sending NBD_CMD_BLOCK_STATUS handle=1 offset=0
> length=1073741824 flags=0
> DEBUG:nbd:Extent length=1073741824 flags=0 context=0
> DEBUG:nbd:Extent length=1073741824 flags=1 context=1
> {'base:allocation': [Extent(length=1073741824, flags=0)],
> 'qemu:allocation-depth': [Extent(length=1073741824, flags=0)]}
>
> We got flags=0 (data)
>
> Trying to the same with a real image, using this reproducer script:
>
> $ cat reporoduce.py
> import logging
> import pprint
> from ovirt_imageio._internal import nbd
>
> logging.basicConfig(level=logging.DEBUG)
>
> with nbd.Client(nbd.UnixAddress("/tmp/nbd.sock")) as c:
>     print("First call: c.extents(0, 10*1024**2) ->")
>     pprint.pprint(c.extents(0, 10*1024**2))
>
>     print("Second call: c.extents(0, 10*1024**2) ->")
>     pprint.pprint(c.extents(0, 10*1024**2))
>
>
> $ python reporoduce.py
> DEBUG:nbd:Connecting address='/tmp/nbd.sock' export_name='' dirty=False
> DEBUG:nbd:Received server flags: 3
> DEBUG:nbd:Sending client flags: 1
> DEBUG:nbd:Sending option: 8 data: b''
> DEBUG:nbd:Received reply magic=3e889045565a9 option=8 type=1 len=0
> DEBUG:nbd:Structured reply enabled
> DEBUG:nbd:Sending option: 10 data:
> bytearray(b'\x00\x00\x00\x00\x00\x00\x00\x02\x00\x00\x00\x0fbase:allocation\x00\x00\x00\x15qemu:allocation-depth')
> DEBUG:nbd:Received reply magic=3e889045565a9 option=10 type=4 len=19
> DEBUG:nbd:Meta context base:allocation is available id=0
> DEBUG:nbd:Received reply magic=3e889045565a9 option=10 type=4 len=25
> DEBUG:nbd:Meta context qemu:allocation-depth is available id=1
> DEBUG:nbd:Received reply magic=3e889045565a9 option=10 type=1 len=0
> DEBUG:nbd:Sending option: 7 data: bytearray(b'\x00\x00\x00\x00\x00\x00')
> DEBUG:nbd:Received reply magic=3e889045565a9 option=7 type=3 len=14
> DEBUG:nbd:Received block size info minimum=1 preferred=4096 maximum=33554432
> DEBUG:nbd:Received reply magic=3e889045565a9 option=7 type=3 len=12
> DEBUG:nbd:Received export info size=6442450944 flags=1423
> DEBUG:nbd:Received reply magic=3e889045565a9 option=7 type=1 len=0
> DEBUG:nbd:Ready for transmission
> First call: c.extents(0, 10*1024**2) ->
> DEBUG:nbd:Sending NBD_CMD_BLOCK_STATUS handle=0 offset=0 length=10485760 
> flags=0
> DEBUG:nbd:Extent length=4096 flags=0 context=0
> DEBUG:nbd:Extent length=1044480 flags=3 context=0
> DEBUG:nbd:Extent length=65536 flags=0 context=0
> DEBUG:nbd:Extent length=983040 flags=3 context=0
> DEBUG:nbd:Extent length=24576 flags=0 context=0
> DEBUG:nbd:Extent length=16384 flags=3 context=0
> DEBUG:nbd:Extent length=8192 flags=0 context=0
> DEBUG:nbd:Extent length=12288 flags=3 context=0
> DEBUG:nbd:Extent length=8327168 flags=0 context=0
> DEBUG:nbd:Extent length=10485760 flags=1 context=1
> {'base:allocation': [Extent(length=4096, flags=0),
>                      Extent(length=1044480, flags=3),
>                      Extent(length=65536, flags=0),
>                      Extent(length=983040, flags=3),
>                      Extent(length=24576, flags=0),
>                      Extent(length=16384, flags=3),
>                      Extent(length=8192, flags=0),
>                      Extent(length=12288, flags=3),
>                      Extent(length=8327168, flags=0)],
>  'qemu:allocation-depth': [Extent(length=10485760, flags=0)]}
> Second call: c.extents(0, 10*1024**2) ->
> DEBUG:nbd:Sending NBD_CMD_BLOCK_STATUS handle=1 offset=0 length=10485760 
> flags=0
> DEBUG:nbd:Extent length=10485760 flags=0 context=0
> DEBUG:nbd:Extent length=10485760 flags=1 context=1
> {'base:allocation': [Extent(length=10485760, flags=0)],
>  'qemu:allocation-depth': [Extent(length=10485760, flags=0)]}
> DEBUG:nbd:Initiating a soft disconnect
> DEBUG:nbd:Sending NBD_CMD_DISC handle=2 offset=0 length=0 flags=0
>
>
> All extents squashed to one data extent in the second call.
>
> Testing show that the issue is with calling block status gain for the
> same range.
> Call for new range return the expected results, calling with same range 
> returns
> always flags=0.
>
> For testing with ovirt-Imageio you can get it from copr:
> https://copr.fedorainfracloud.org/coprs/nsoffer/ovirt-imageio-preview/
>
>     dnf copr enable nsoffer/ovirt-imageio-preview
>
> But should be reproducible with libnbd.
>
> Looks like a bad bug in 6.2.0.
>
> Nir