Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

kvdo 6.2.7.17 storage read/write issue with kernel 6.0 from KVM VMs #61

Closed
andreamtp opened this issue Nov 14, 2022 · 2 comments
Closed

Comments

@andreamtp
Copy link

andreamtp commented Nov 14, 2022

OS Fedora36
Arch x86_64

components from https://copr.fedorainfracloud.org/coprs/rhawalsh/dm-vdo/

vdo-6.2.7.17-3.fc36.x86_64
kmod-kvdo-6.2.7.17-4.fc36.x86_64

modules releases:

uds: modprobe: loaded version 8.0.5.1
kvdo: modprobe: loaded version 6.2.7.17

After upgrading to kernel 6.0.5-200 or 6.0.7-200, the volume kvm created on top of a partition is recognized, but the logical volumes built ontop, that are used as disk for VMs, have some problems.

Existing VMs do not boot, fails to proceed to bootloader and if uefi remain stuck at uefi shell.
Trying to create install RHEL7 from scratch in a new VM, it fails at the beginning of the installation, during partitioning/fs creation with:
mkfs.xfs: pwrite64 failed: Input/output error

I checked in the logs from the live iso of the installer and this error from the kernel:

INFO kernel:sd 2:0:0:0: [sda] FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE cmd_age=0s
INFO kernel:sd 2:0:0:0: [sda] Sense Key: Illegal Request [current]
INFO kernel:sd 2:0:0:0: [sda] Add. Sense: Invalid field in cdb
INFO kernel:sd 2:0:0:0: [sda] CDB: Read (10) 28 00 00 06 48 00 00 00 01 00
ERR kernel:blk_update_request: critical target error, dev sda, sector 411648
INFO kernel:sd 2:0:0:0 [sda] FAILED Results: hostbyte=DID_OK driverbyte=DRIVER_SENSE cmd_age=0s
INFO kernel:sd 2:0:0:0: [sda] Sense Key: Illegal Request [current]
INFO kernel:sd 2:0:0:0: [sda] Add. Sense: Invalid field in cdb
INFO kernel:sd 2:0:0:0: [sda] CDB: Write(10) 2a 00 00 06 48 00 00 01 00 00
ERR kernel:blk_update_request: critical target error, dev sda, sector 411648

from console I've tried also to delete an lvm - the disk I was installing rhel to was not clean - and if failed:

# lvremove /dev/r7vg/swap_lv
Error writing device /dev/sda3 at 4096 length 512.
Failed to write mda header to /dev/sda3 fd -1
Failed to write metadata area header
Error writing device /dev/sda3 at 4096 length 512.
Failed to write mda header to /dev/sda3 fd -1
Failed to write metadata area header

and the kernel logs:

INFO kernel: sd 2:0:0:0: [sda] FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE cmd_age=0s
INFO kernel: sd 2:0:0:0: [sda] Sense Key: Illegal Request [current]
INFO kernel: sd 2:0:0:0: [sda] Add. Sense: Invalid field in cdb
INFO kernel: sd 2:0:0:0: [sda] CDB: Write(10) 2a 00 00 15 e8 00 00 00 09 00
ERR kernel:blk_update_request: critical target error, dev sda, sector 1435648
INFO kernel: sd 2:0:0:0: [sda] FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE cmd_age=0s
INFO kernel: sd 2:0:0:0: [sdal Sense Key: Illegal Request [current]
INFO kernel:sd 2:0:0:0: [sda] Add. Sense: Invalid field in cdb
INFO kernel:sd 2:0:0:0: [sda] CDB: Write(18) 2a 00 00 15 e8 00 00 00 09 08
ERR kernel:blk_update_request: critical target error, dev sda, sector 1435648

If I try to create an ext4 filesystem, the command complete successfully (but I haven't tried to do a full installation on a blank disk).

On the physical host/hypervisor, there's no significant message during the guest setup.

Below the kvdo kernel messages at boot:

kernel 6.0.5 boot

[ 1379.210211] uds: loading out-of-tree module taints kernel.
[ 1379.211553] uds: module verification failed: signature and/or required key missing - tainting kernel
[ 1379.220773] uds: modprobe: loaded version 8.0.5.1
[ 1379.610724] kvdo: modprobe: loaded version 6.2.7.17
[ 1399.530936] kvdo0:dmsetup: underlying device, REQ_FLUSH: not supported, REQ_FUA: not supported
[ 1399.531096] kvdo0:dmsetup: Using write policy sync automatically.
[ 1399.531230] kvdo0:dmsetup: loading device 'kvm'
[ 1399.532133] kvdo0:dmsetup: zones: 1 logical, 1 physical, 1 hash; base threads: 5
[ 1399.581444] kvdo0:dmsetup: starting device 'kvm'
[ 1399.931355] kvdo0:dmsetup: Setting UDS index target state to online
[ 1399.931363] uds: kvdo0:dedupeQ: loading or rebuilding index: dev=/dev/disk/by-id/scsi-3600304801dbd470629c27088136423a7-part4 offset=4096 size=2781704192
[ 1399.932088] kvdo0:dmsetup: device 'kvm' started
[ 1399.932323] kvdo0:dmsetup: resuming device 'kvm'
[ 1399.932542] kvdo0:dmsetup: device 'kvm' resumed
[ 1399.933237] uds: kvdo0:dedupeQ: Using 16 indexing zones for concurrency.
[ 1400.486498] uds: kvdo0:dedupeQ: loaded index from chapter 0 through chapter 414
[ 1400.506134] uds: kvdo0:dedupeQ: Replaying volume from chapter 5246 through chapter 6269
[ 1400.507931] uds: kvdo0:dedupeQ: unexpected index page map update, jumping from 414 to 5246
[ 1400.541009] kvdo0:journalQ: VDO commencing normal operation
[ 1463.801354] uds: kvdo0:dedupeQ: replay changed index page map update from 414 to 6268

If I boot with a 5.19 kernel, everything works fine:

kernel 5.19 boot

Nov 14 15:52:11 kernel: uds: loading out-of-tree module taints kernel.
Nov 14 15:52:11 kernel: uds: module verification failed: signature and/or required key missing - tainting kernel
Nov 14 15:52:11 kernel: uds: modprobe: loaded version 8.0.5.1
Nov 14 15:52:11 kernel: kvdo: modprobe: loaded version 6.2.7.17
Nov 14 15:52:11 kernel: kvdo0:dmsetup: underlying device, REQ_FLUSH: not supported, REQ_FUA: not supported
Nov 14 15:52:11 kernel: kvdo0:dmsetup: Using write policy sync automatically.
Nov 14 15:52:11 kernel: kvdo0:dmsetup: loading device 'kvm'
Nov 14 15:52:11 kernel: kvdo0:dmsetup: zones: 1 logical, 1 physical, 1 hash; base threads: 5
Nov 14 15:52:11 kernel: kvdo0:dmsetup: starting device 'kvm'
Nov 14 15:52:12 kernel: kvdo0:dmsetup: Setting UDS index target state to online
Nov 14 15:52:12 kernel: uds: kvdo0:dedupeQ: loading or rebuilding index: dev=/dev/disk/by-id/scsi-3600304801dbd470129c27088136423a7-part4 offset=4096 size=2781704192
Nov 14 15:52:12 kernel: kvdo0:dmsetup: device 'kvm' started
Nov 14 15:52:12 kernel: kvdo0:dmsetup: resuming device 'kvm'
Nov 14 15:52:12 kernel: kvdo0:dmsetup: device 'kvm' resumed
Nov 14 15:52:12 kernel: uds: kvdo0:dedupeQ: Using 16 indexing zones for concurrency.
Nov 14 15:52:12 kernel: kvdo0:journalQ: VDO commencing normal operation
Nov 14 15:52:12 UDS/vdodmeventd[1148]: INFO   (vdodmeventd/1148) VDO device kvm is now registered with dmeventd for monitoring
Nov 14 15:52:12 vdo-by-dev[1034]: Starting VDO kvm
Nov 14 15:52:12 vdo-by-dev[1034]: VDO instance 0 volume is ready at /dev/mapper/kvm
Nov 14 15:52:12 systemd[1]: Finished vdo-start-by-dev@sda4.service - Start VDO volume backed by sda4.
Nov 14 15:52:12 audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=vdo-start-by-dev@sda4 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 14 15:52:13 kernel: uds: kvdo0:dedupeQ: loaded index from chapter 0 through chapter 414
Nov 14 15:52:13 kernel: uds: kvdo0:dedupeQ: Replaying volume from chapter 5246 through chapter 6269
Nov 14 15:52:13 kernel: uds: kvdo0:dedupeQ: unexpected index page map update, jumping from 414 to 5246
Nov 14 15:52:13 systemd[1]: Starting vdo.service - VDO volume services...
Nov 14 15:52:13 vdo[1312]: vdo: WARNING - VDO service kvm already started; no changes made
Nov 14 15:52:13 vdo[1312]: WARNING - VDO service kvm already started; no changes made
Nov 14 15:52:13 vdo[1312]: Starting VDO kvm
Nov 14 15:52:13 vdo[1312]: VDO instance 0 volume is ready at /dev/mapper/kvm
Nov 14 15:52:13 systemd[1]: Finished vdo.service - VDO volume services.
Nov 14 15:53:16 kernel: uds: kvdo0:dedupeQ: replay changed index page map update from 414 to 6268

And some infos on the VDO volume:

# vdo status 

VDO status:
  Date: '2022-11-14 18:31:08+01:00'
  Node: red.act.ed
Kernel module:
  Loaded: true
  Name: kvdo
  Version information:
    kvdo version: 6.2.7.17
Configuration:
  File: /etc/vdoconf.yml
  Last modified: '2022-03-28 13:32:07'
VDOs:
  kvm:
    Acknowledgement threads: 1
    Activate: enabled
    Bio rotation interval: 64
    Bio submission threads: 4
    Block map cache size: 128M
    Block map period: 16380
    Block size: 4096
    CPU-work threads: 2
    Compression: disabled
    Configured write policy: auto
    Deduplication: enabled
    Device mapper status: 0 15032385536 vdo /dev/sda4 normal - online offline 9540440 188610043
    Emulate 512 byte: disabled
    Hash zone threads: 1
    Index checkpoint frequency: 0
    Index memory setting: 0.25
    Index parallel factor: 0
    Index sparse: disabled
    Index status: online
    Logical size: 7T
    Logical threads: 1
    Max discard size: 4K
    Physical size: 754440172K
    Physical threads: 1
    Slab size: 2G
    Storage device: /dev/disk/by-id/scsi-3600304801dbd470629c27088136423a7-part4
    UUID: VDO-9bdd0d4a-41ed-4a72-aca1-7ebfc4cd5bdc
    VDO statistics:
      /dev/mapper/kvm:
        1K-blocks: 754440172
        1K-blocks available: 716278412
        1K-blocks used: 38161760
        512 byte emulation: false
        KVDO module bytes used: 620487208
        KVDO module peak bytes used: 620631016
        bios acknowledged discard: 0
        bios acknowledged flush: 0
        bios acknowledged fua: 0
        bios acknowledged partial discard: 0
        bios acknowledged partial flush: 0
        bios acknowledged partial fua: 0
        bios acknowledged partial read: 0
        bios acknowledged partial write: 0
        bios acknowledged read: 1433851
        bios acknowledged write: 5297
        bios in discard: 0
        bios in flush: 0
        bios in fua: 0
        bios in partial discard: 0
        bios in partial flush: 0
        bios in partial fua: 0
        bios in partial read: 0
        bios in partial write: 0
        bios in progress discard: 0
        bios in progress flush: 0
        bios in progress fua: 0
        bios in progress read: 0
        bios in progress write: 0
        bios in read: 1433851
        bios in write: 5297
        bios journal completed discard: 0
        bios journal completed flush: 0
        bios journal completed fua: 0
        bios journal completed read: 0
        bios journal completed write: 543
        bios journal discard: 0
        bios journal flush: 543
        bios journal fua: 543
        bios journal read: 0
        bios journal write: 543
        bios meta completed discard: 0
        bios meta completed flush: 0
        bios meta completed fua: 0
        bios meta completed read: 26952
        bios meta completed write: 616
        bios meta discard: 0
        bios meta flush: 548
        bios meta fua: 544
        bios meta read: 26952
        bios meta write: 616
        bios out completed discard: 0
        bios out completed flush: 0
        bios out completed fua: 0
        bios out completed read: 94273
        bios out completed write: 2738
        bios out discard: 0
        bios out flush: 0
        bios out fua: 0
        bios out read: 94273
        bios out write: 2738
        bios page cache completed discard: 0
        bios page cache completed flush: 0
        bios page cache completed fua: 0
        bios page cache completed read: 78
        bios page cache completed write: 0
        bios page cache discard: 0
        bios page cache flush: 0
        bios page cache fua: 0
        bios page cache read: 78
        bios page cache write: 0
        block map cache pressure: 0
        block map cache size: 134217728
        block map clean pages: 70
        block map dirty pages: 8
        block map discard required: 0
        block map failed pages: 0
        block map failed reads: 0
        block map failed writes: 0
        block map fetch required: 78
        block map flush count: 0
        block map found in cache: 1443444
        block map free pages: 32690
        block map incoming pages: 0
        block map outgoing pages: 0
        block map pages loaded: 78
        block map pages saved: 0
        block map read count: 1438980
        block map read outgoing: 0
        block map reclaimed: 0
        block map wait for page: 2164
        block map write count: 6706
        block size: 4096
        completed recovery count: 4
        compressed blocks written: 0
        compressed fragments in packer: 0
        compressed fragments written: 0
        concurrent data matches: 8
        concurrent hash collisions: 0
        current VDO IO requests in progress: 0
        current dedupe queries: 0
        data blocks used: 8334462
        dedupe advice stale: 0
        dedupe advice timeouts: 0
        dedupe advice valid: 1401
        entries indexed: 63306270
        flush out: 0
        instance: 0
        invalid advice PBN count: 0
        journal blocks batching: 0
        journal blocks committed: 543
        journal blocks started: 543
        journal blocks writing: 0
        journal blocks written: 543
        journal commits requested count: 0
        journal disk full count: 0
        journal entries batching: 0
        journal entries committed: 13416
        journal entries started: 13416
        journal entries writing: 0
        journal entries written: 13416
        logical blocks: 1879048192
        logical blocks used: 24278017
        maximum VDO IO requests in progress: 2000
        maximum dedupe queries: 269
        no space error count: 0
        operating mode: normal
        overhead blocks used: 1205978
        physical blocks: 188610043
        posts found: 1401
        posts not found: 1329
        queries found: 0
        queries not found: 0
        read only error count: 0
        read-only recovery count: 0
        recovery progress (%): N/A
        reference blocks written: 0
        release version: 133524
        saving percent: 65
        slab count: 358
        slab journal blocked count: 0
        slab journal blocks written: 4
        slab journal disk full count: 0
        slab journal flush count: 0
        slab journal tail busy count: 0
        slab summary blocks written: 4
        slabs opened: 186
        slabs reopened: 1
        updates found: 0
        updates not found: 0
        used percent: 5
        version: 31
        write amplification ratio: 0.0
        write policy: sync

vdoconf.yml

# cat /etc/vdoconf.yml 

####################################################################
# THIS FILE IS MACHINE GENERATED. DO NOT EDIT THIS FILE BY HAND.
####################################################################
config: !Configuration
  vdos:
    kvm: !VDOService
      _operationState: finished
      ackThreads: 1
      activated: enabled
      bioRotationInterval: 64
      bioThreads: 4
      blockMapCacheSize: 128M
      blockMapPeriod: 16380
      compression: disabled
      cpuThreads: 2
      deduplication: enabled
      device: /dev/disk/by-id/scsi-3600304801dbd470629c27088136423a7-part4
      hashZoneThreads: 1
      indexCfreq: 0
      indexMemory: 0.25
      indexSparse: disabled
      indexThreads: 0
      logicalBlockSize: 4096
      logicalSize: 7T
      logicalThreads: 1
      maxDiscardSize: 4K
      name: kvm
      physicalSize: 754440172K
      physicalThreads: 1
      slabSize: 2G
      uuid: null
      writePolicy: auto
  version: 538380551

Is this setup supported (kvdo 6.2 on kernel 6.0.x)?
Is it a known bug/limit?
Are data on the volume safe?

@raeburn
Copy link
Member

raeburn commented Dec 14, 2022

Hi, Andrea. I apologize for the delay in getting back to you.

Our Fedora testing has started using the 6.0.12 kernel at this point, but that’s testing the newer 8.x branch; the 6.2 code is mainly tested on RHEL 8 and its 4.18-based kernels. So I wouldn’t suggest mixing them like this. Also, our testing tends to use file systems or direct I/O and not running VMs atop VDO.

All that said, I don’t recall seeing any problems that would likely result in what you’re seeing. If VDO was returning an error in the hypervisor environment, it should’ve logged something to that effect, and you said there were “no significant message[s]” from the hypervisor. So I suspect the SCSI errors are coming from some other source.

That doesn’t mean it couldn’t be related to the VDO configuration. I note that the “emulate 512 byte” option is disabled in your VDO device, yet lvremove (at least) was trying to do I/O of 512 bytes. Depending on the flags set in various places, I imagine it might be possible that this size difference could cause an error instead of a read-modify-write sequence.

There are a couple of things you could try to see what’s going on:
(1) use “losetup” with a big backing file and “--sector-size=4096” as storage for a VM to see if the I/O size is the problem
(2) recreate the VDO device with --emulate512=enabled

Depending what you’ve got stored in your VDO device, the losetup approach might be the easier way to figure out if the 4k block size is the actual issue. Unfortunately I don’t think the emulate512 option can be modified for an already-created device, at least in the version of the vdo script I looked at.

If it’s just a test system and you don’t mind hacking config files directly, you could try changing “logicalBlockSize” in /etc/vdoconf.yml from 4096 to 512, instead of recreating the VDO device. But getting that edit wrong could stop VDO from starting at all...

Any of these might give us some insights as to what’s going on with the SCSI errors reported from the guests. Where VDO is reported no problems at all, I doubt it’s anything internal to VDO, and I expect the data is still safe on the volume.

@andreamtp
Copy link
Author

If it’s just a test system and you don’t mind hacking config files directly, you could try changing “logicalBlockSize” in /etc/vdoconf.yml from 4096 to 512, instead of recreating the VDO device. But getting that edit wrong could stop VDO from starting at all...

Hi, just to let you know that probably vdo is not the origin of my problem: I've uninstalled (kmod + vdo) from the system, but problems persist, so it should be something else.

Thanks for the feedback and ideas.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants