[SOLVED] storage migration failed: block job (mirror) error: VM XXX qmp command 'query-block-jobs' failed - got wrong command id

[pschonmann]

Hello,
fresh migrated from PVE 5 > 6 > 7. Everything in upgrade process worked fine.

Now im facing problem that im moving disks back to LVM from NFS storage.

It takes too much long when copy 10G disk. And sometimes i see errors .. see below.

drive-virtio0: transferred 2.4 GiB of 10.0 GiB (23.88%) in 9m 51s
drive-virtio0: Cancelling block job
drive-virtio0: Done.
  Logical volume "vm-497-disk-0" successfully removed
TASK ERROR: storage migration failed: block job (mirror) error: VM 497 qmp command 'query-block-jobs' failed - got wrong command id '1557:2883' (expected 172539:827)

pveversion -v
proxmox-ve: 7.0-2 (running kernel: 5.11.22-4-pve)
pve-manager: 7.0-11 (running version: 7.0-11/63d82f4e)
pve-kernel-5.11: 7.0-7
pve-kernel-helper: 7.0-7
pve-kernel-5.4: 6.4-5
pve-kernel-5.11.22-4-pve: 5.11.22-8
pve-kernel-5.4.128-1-pve: 5.4.128-2
ceph-fuse: 14.2.21-1
corosync: 3.1.2-pve2
criu: 3.15-1+pve-1
glusterfs-client: 9.2-1
ifupdown: residual config
ifupdown2: 3.1.0-1+pmx3
libjs-extjs: 7.0.0-1
libknet1: 1.21-pve1
libproxmox-acme-perl: 1.3.0
libproxmox-backup-qemu0: 1.2.0-1
libpve-access-control: 7.0-4
libpve-apiclient-perl: 3.2-1
libpve-common-perl: 7.0-6
libpve-guest-common-perl: 4.0-2
libpve-http-server-perl: 4.0-2
libpve-storage-perl: 7.0-10
libspice-server1: 0.14.3-2.1
lvm2: 2.03.11-2.1
lxc-pve: 4.0.9-4
lxcfs: 4.0.8-pve2
novnc-pve: 1.2.0-3
proxmox-backup-client: 2.0.9-2
proxmox-backup-file-restore: 2.0.9-2
proxmox-mini-journalreader: 1.2-1
proxmox-widget-toolkit: 3.3-6
pve-cluster: 7.0-3
pve-container: 4.0-9
pve-docs: 7.0-5
pve-edk2-firmware: 3.20200531-1
pve-firewall: 4.2-2
pve-firmware: 3.3-1
pve-ha-manager: 3.3-1
pve-i18n: 2.4-1
pve-qemu-kvm: 6.0.0-3
pve-xtermjs: 4.12.0-1
qemu-server: 7.0-13
smartmontools: 7.2-pve2
spiceterm: 3.2-2
vncterm: 1.7-1
zfsutils-linux: 2.0.5-pve1

[CODE]
pveperf
CPU BOGOMIPS:      176041.80
REGEX/SECOND:      2655922
HD SIZE:           27.36 GB (/dev/md0)
BUFFERED READS:    519.85 MB/sec
AVERAGE SEEK TIME: 0.12 ms
FSYNCS/SECOND:     3794.72
DNS EXT:           9.11 ms
DNS INT:           3.52 ms (praguebest.cz)

iostat
Linux 5.11.22-4-pve (xeon-silver4114)     09/09/2021     _x86_64_    (40 CPU)

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           1.59    0.00    0.15    3.75    0.00   94.51

Device             tps    kB_read/s    kB_wrtn/s    kB_dscd/s    kB_read    kB_wrtn    kB_dscd
dm-0             67.43         0.08       269.45         0.00       3312   10585624          0
md0              10.88        53.93        53.37         0.00    2118605    2096764          0
md1              99.44        39.31       396.24         0.00    1544404   15567053          0
md2              57.66        57.48       228.55         0.00    2258143    8978988          0
sda              10.24        88.24       450.06         0.00    3466675   17681525          0
sdb               9.07         5.09       450.06         0.00     200114   17681525          0
sdc               0.37         0.10       228.57         0.00       4089    8979727          0
sdd               0.89        57.51       228.57         0.00    2259207    8979727          0

 

[pschonmann]

And too much activity on io_wqe_worker
-

Total DISK READ:         4.89 M/s | Total DISK WRITE:       169.61 K/s
Current DISK READ:     915.53 K/s | Current DISK WRITE:       0.00 B/s
    TID  PRIO  USER     DISK READ  DISK WRITE  SWAPIN      IO    COMMAND
 263021 be/4 root          0.00 B     15.07 M  0.00 % 99.99 % [io_wqe_worker-1]
 214889 be/4 root          0.00 B      0.00 B  0.00 % 99.99 % [io_wqe_worker-0]
 186982 be/4 root          0.00 B      0.00 B  0.00 % 99.99 % [io_wqe_worker-0]
 262698 be/4 root          0.00 B   1244.00 K  0.00 % 99.99 % [io_wqe_worker-0]
 263024 be/4 root          0.00 B   1024.00 K  0.00 % 99.75 % [io_wqe_worker-0]
 263023 be/4 root          0.00 B   1024.00 K  0.00 % 98.71 % [io_wqe_worker-1]
 255473 be/4 root          0.00 B      4.00 K  0.00 % 96.75 % [io_wqe_worker-0]
 262988 be/4 root       1408.00 K     32.00 K  0.00 % 94.68 % [io_wqe_worker-0]
 263022 be/4 root          0.00 B   1024.00 K  0.00 % 92.69 % [io_wqe_worker-0]
 263069 be/4 root       1024.00 K      8.00 K  0.00 % 91.88 % [io_wqe_worker-1]
 262933 be/4 root          0.00 B      0.00 B  0.00 % 90.08 % [io_wqe_worker-1]
 187536 be/4 root       1408.00 K      8.00 K  0.00 % 89.52 % [io_wqe_worker-0]
 263019 be/4 root          0.00 B      0.00 B  0.00 % 70.35 % [io_wqe_worker-1]
 263018 be/4 root          0.00 B      0.00 B  0.00 % 68.63 % [io_wqe_worker-0]
 178069 be/4 root          0.00 B     16.00 K  0.00 % 67.61 % [io_wqe_worker-0]
 263017 be/4 root          0.00 B      0.00 B  0.00 % 67.69 % [io_wqe_worker-1]
 263016 be/4 root          0.00 B      0.00 B  0.00 % 66.83 % [io_wqe_worker-0]
 263066 be/4 root        688.00 K     76.00 K  0.00 % 65.60 % [io_wqe_worker-0]
 263002 be/4 root          0.00 B     28.00 K  0.00 % 58.81 % [io_wqe_worker-0]
 180073 be/4 root          0.00 B    100.00 K  0.00 % 55.90 % [io_wqe_worker-0]
 180476 be/4 root          0.00 B      0.00 B  0.00 % 55.66 % [io_wqe_worker-0]
 263015 be/4 root          0.00 B      0.00 B  0.00 % 55.09 % [io_wqe_worker-1]
 262992 be/4 root          0.00 B      0.00 B  0.00 % 49.53 % [io_wqe_worker-0]
 262731 be/4 root          0.00 B      0.00 B  0.00 % 49.48 % [io_wqe_worker-0]
 262847 be/4 root        128.00 K      0.00 B  0.00 % 48.61 % [io_wqe_worker-1]
 178729 be/4 root        512.00 K    360.00 K  0.00 % 46.44 % [io_wqe_worker-0]
 263014 be/4 root          0.00 B      0.00 B  0.00 % 43.83 % [io_wqe_worker-0]
 262993 be/4 root          0.00 B      0.00 B  0.00 % 42.94 % [io_wqe_worker-1]
 263094 be/4 root          0.00 B      4.00 K  0.00 % 84.08 % [io_wqe_worker-0]
 262984 be/4 root          0.00 B     32.00 K  0.00 % 40.93 % [io_wqe_worker-1]
 262931 be/4 root          0.00 B      0.00 B  0.00 % 37.58 % [io_wqe_worker-1]
 263027 be/4 root          0.00 B    372.00 K  0.00 % 37.26 % [io_wqe_worker-1]
 262442 be/4 root        576.00 K     60.00 K  0.00 % 37.15 % [io_wqe_worker-1]
 263093 be/4 root          0.00 B      0.00 B  0.00 % 72.88 % [io_wqe_worker-1]
 263026 be/4 root          0.00 B   1024.00 K  0.00 % 35.65 % [io_wqe_worker-0]
 186357 be/4 root          0.00 B      8.00 K  0.00 % 34.54 % [io_wqe_worker-0]
 263003 be/4 root          0.00 B      0.00 B  0.00 % 34.20 % [io_wqe_worker-1]
 263083 be/4 root       1024.00 K     12.00 K  0.00 % 32.70 % [io_wqe_worker-0]
 262246 be/4 root          0.00 B     28.00 K  0.00 % 30.13 % [io_wqe_worker-1]
 263091 be/4 root          0.00 B      0.00 B  0.00 % 39.87 % [io_wqe_worker-1]
 263092 be/4 root          0.00 B      0.00 B  0.00 % 56.82 % [io_wqe_worker-0]
 186358 be/4 root          0.00 B      4.00 K  0.00 % 27.33 % [io_wqe_worker-0]
 262930 be/4 root          0.00 B      0.00 B  0.00 % 25.95 % [io_wqe_worker-0]
 262932 be/4 root          0.00 B      0.00 B  0.00 % 25.10 % [io_wqe_worker-0]
 263090 be/4 root          0.00 B      4.00 K  0.00 % 33.54 % [io_wqe_worker-0]
 263025 be/4 root          0.00 B   1024.00 K  0.00 % 24.71 % [io_wqe_worker-1]
 262777 be/4 root          0.00 B      0.00 B  0.00 % 20.03 % [io_wqe_worker-0]
 263082 be/4 root          0.00 B      4.00 K  0.00 %  7.64 % [io_wqe_worker-1]
 180074 be/4 root          0.00 B    172.00 K  0.00 %  6.12 % [io_wqe_worker-0]
 263020 be/4 root          0.00 B   1092.00 K  0.00 %  6.13 % [io_wqe_worker-0]
 262730 be/4 root          0.00 B      0.00 B  0.00 %  6.06 % [io_wqe_worker-1]

 

[fiona]

Hi,
not sure about the slow speed (is there much other load on the server?). But the issue with the wrong command id also affected other users and there might be a fix you could test now, see here. You'll need to stop+start the VM after installing the new version.

 

[pschonmann]

Thanks for reply.
The problem was caused by optical transcievers - only Rx. They have big loss - both . After change, the qmmove works like charm.

 

[fiona]

Glad you were able to figure out the root cause. You can mark the thread as [SOLVED] by editing the thread and selecting the correct prefix. It could be that the racy wrong command id part of the issue was triggered as a consequence of the lossy transfer.