Bug 1320114

Summary: qemu prompt "main-loop: WARNING: I/O thread spun for 1000 iterations" when block mirror from format qcow2 to raw
Product: Red Hat Enterprise Linux 7 Reporter: Qianqian Zhu <qizhu>
Component: qemu-kvm-rhevAssignee: John Snow <jsnow>
Status: CLOSED ERRATA QA Contact: Qianqian Zhu <qizhu>
Severity: medium Docs Contact:
Priority: unspecified    
Version: 7.4CC: chayang, juzhang, knoel, michen, mrezanin, qizhu, virt-maint, xfu, yuhuang
Target Milestone: rc   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2018-04-11 00:09:32 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Qianqian Zhu 2016-03-22 10:40:14 UTC
Description of problem:
qemu prompt "main-loop: WARNING: I/O thread spun for 1000 iterations" when block mirror from format raw to raw

Version-Release number of selected component (if applicable):
kernel-3.10.0-365.el7.x86_64
qemu-kvm-rhev-2.5.0-2.el7.x86_64

guest: 
rhel7.2: kernel-3.10.0-327.el7.x86_64

How reproducible:
3/3

Steps to Reproduce:
1.launch guest with qcow2 format image:
qemu-kvm -cpu host -m 1024 -device virtio-serial-pci,id=virtio-serial0,bus=pci.0,addr=0x6 -drive file=/home/RHEL-Server-7.2-64-virtio.qcow2,format=qcow2,if=none,id=drive-virtio-blk0,werror=stop,rerror=stop -device virtio-blk-pci,drive=drive-virtio-blk0,id=virtio-disk0 -vnc :1 -monitor stdio -netdev tap,id=hostnet0,vhost=on -device virtio-net-pci,netdev=hostnet0,id=net0,mac=3C:D9:2B:09:AB:44,bus=pci.0,addr=0x4 -qmp tcp:0:5555,server,nowait
2.block mirror from qcow2 to raw:
{ "execute": "drive-mirror", "arguments": { "device": "drive-virtio-blk0", "target": "/home/mirror1.qcow2", "format": "qcow2", "mode": "absolute-paths", "sync": "full", "on-source-error": "stop", "on-target-error": "stop", "granularity": 65536, "buf-size": 655360 } }
3.{"execute": "block-job-complete", "arguments": { "device": "drive-virtio-blk0"} }
4. block mirror from raw to raw:
{ "execute": "drive-mirror", "arguments": { "device": "drive-virtio-blk0", "target": "/home/mirror2.raw", "format": "raw", "mode": "absolute-paths", "sync": "full", "on-source-error": "stop", "on-target-error": "stop", "granularity": 65536, "buf-size": 655360 } }

Actual results:
after step 4:
(qemu) Formatting '/home/mirror2.raw', fmt=raw size=21474836480
main-loop: WARNING: I/O thread spun for 1000 iterations

Expected results:
no warning prompt

Additional info:
Can't reproduce this issue if launch a raw format guest and block mirror to raw image directly.

Comment 2 Yumei Huang 2017-05-18 02:32:24 UTC
Hit same issue when do live commit. 

Details:
1. Boot guest 
#  /usr/libexec/qemu-kvm -m 4G \

-drive file=rhel74.qcow2,if=none,format=qcow2,id=drive0 -device virtio-blk-pci,id=blk0,drive=drive0 \

-monitor stdio -vnc :1  \

-netdev tap,id=tap0 -device virtio-net-pci,netdev=tap0,id=net0 \

-numa node -sandbox on   -qmp tcp:0:4444,server,nowait

2. Create 4 snapshots
{ "execute": "blockdev-snapshot-sync", "arguments": { "device": "drive0", "snapshot-file": "/root/sn1", "format": "qcow2"} }
{"return": {}}

{ "execute": "blockdev-snapshot-sync", "arguments": { "device": "drive0", "snapshot-file": "/root/sn2", "format": "qcow2"} }
{"return": {}}

{ "execute": "blockdev-snapshot-sync", "arguments": { "device": "drive0", "snapshot-file": "/root/sn3", "format": "qcow2"} }
{"return": {}}

{ "execute": "blockdev-snapshot-sync", "arguments": { "device": "drive0", "snapshot-file": "/root/sn4", "format": "qcow2"} }
{"return": {}}

3. Do live commit
{ "execute": "block-commit", "arguments": { "device": "drive0", "base": "/root/sn1", "top": "/root/sn3", "speed": 1000000000 } }
{"return": {}}


HMP shows the warning:
(qemu) Formatting '/root/sn1', fmt=qcow2 size=42949672960 backing_file=rhel74.qcow2 backing_fmt=qcow2 encryption=off cluster_size=65536 lazy_refcounts=off refcount_bits=16

(qemu) Formatting '/root/sn2', fmt=qcow2 size=42949672960 backing_file=/root/sn1 backing_fmt=qcow2 encryption=off cluster_size=65536 lazy_refcounts=off refcount_bits=16
 
(qemu) Formatting '/root/sn3', fmt=qcow2 size=42949672960 backing_file=/root/sn2 backing_fmt=qcow2 encryption=off cluster_size=65536 lazy_refcounts=off refcount_bits=16

(qemu) Formatting '/root/sn4', fmt=qcow2 size=42949672960 backing_file=/root/sn3 backing_fmt=qcow2 encryption=off cluster_size=65536 lazy_refcounts=off refcount_bits=16

(qemu) main-loop: WARNING: I/O thread spun for 1000 iterations

Comment 3 Yumei Huang 2017-05-18 02:34:40 UTC
Add qemu and kernel version to comment 2:

qemu-kvm-rhev-2.9.0-5.el7
kernel-3.10.0-666.el7.x86_64

Comment 4 John Snow 2017-12-18 20:44:53 UTC
(In reply to Qianqian Zhu from comment #0)
> Description of problem:
> qemu prompt "main-loop: WARNING: I/O thread spun for 1000 iterations" when
> block mirror from format raw to raw
> 
> Version-Release number of selected component (if applicable):
> kernel-3.10.0-365.el7.x86_64
> qemu-kvm-rhev-2.5.0-2.el7.x86_64
> 
> guest: 
> rhel7.2: kernel-3.10.0-327.el7.x86_64
> 
> How reproducible:
> 3/3
> 
> Steps to Reproduce:
> 1.launch guest with qcow2 format image:
> qemu-kvm -cpu host -m 1024 -device
> virtio-serial-pci,id=virtio-serial0,bus=pci.0,addr=0x6 -drive
> file=/home/RHEL-Server-7.2-64-virtio.qcow2,format=qcow2,if=none,id=drive-
> virtio-blk0,werror=stop,rerror=stop -device
> virtio-blk-pci,drive=drive-virtio-blk0,id=virtio-disk0 -vnc :1 -monitor
> stdio -netdev tap,id=hostnet0,vhost=on -device
> virtio-net-pci,netdev=hostnet0,id=net0,mac=3C:D9:2B:09:AB:44,bus=pci.0,
> addr=0x4 -qmp tcp:0:5555,server,nowait
> 2.block mirror from qcow2 to raw:
> { "execute": "drive-mirror", "arguments": { "device": "drive-virtio-blk0",
> "target": "/home/mirror1.qcow2", "format": "qcow2", "mode":
> "absolute-paths", "sync": "full", "on-source-error": "stop",
> "on-target-error": "stop", "granularity": 65536, "buf-size": 655360 } }

(A) From the instructions given, this mirrors from qcow2 to qcow2.
(B) Is the buf-size here intentional? 655360 looks like a typo.

> 3.{"execute": "block-job-complete", "arguments": { "device":
> "drive-virtio-blk0"} }

> 4. block mirror from raw to raw:
> { "execute": "drive-mirror", "arguments": { "device": "drive-virtio-blk0",
> "target": "/home/mirror2.raw", "format": "raw", "mode": "absolute-paths",
> "sync": "full", "on-source-error": "stop", "on-target-error": "stop",
> "granularity": 65536, "buf-size": 655360 } }
> 

(C) Given the above, this looks like qcow2-to-raw.

> Actual results:
> after step 4:
> (qemu) Formatting '/home/mirror2.raw', fmt=raw size=21474836480
> main-loop: WARNING: I/O thread spun for 1000 iterations
> 
> Expected results:
> no warning prompt
> 
> Additional info:
> Can't reproduce this issue if launch a raw format guest and block mirror to
> raw image directly.



My attempt:

Step 2:

(QEMU) drive-mirror device=drive0 target=/media/ext/img/mirror1.qcow2 format=qcow2 mode=absolute-paths sync=full on-source-error=stop on-target-error=stop granularity=65536 buf-size=655360
{"return": {}}

(QEMU) 
{u'timestamp': {u'seconds': 1513629294, u'microseconds': 846094}, u'data': {u'device': u'drive0', u'type': u'mirror', u'speed': 0, u'len': 1588396032, u'offset': 1588396032}, u'event': u'BLOCK_JOB_READY'}

Step 3:

(QEMU) block-job-complete device=drive0
{"return": {}}

(QEMU) 
{u'timestamp': {u'seconds': 1513629339, u'microseconds': 922111}, u'data': {u'device': u'drive0', u'type': u'mirror', u'speed': 0, u'len': 1588396032, u'offset': 1588396032}, u'event': u'BLOCK_JOB_COMPLETED'}

Step 4:

(QEMU) drive-mirror device=drive0 target=/media/ext/img/mirror2.raw format=raw mode=absolute-paths sync=full on-source-error=stop on-target-error=stop granularity=65536 buf-size=655360
{"return": {}}

(QEMU) 
{u'timestamp': {u'seconds': 1513629560, u'microseconds': 408998}, u'data': {u'device': u'drive0', u'type': u'mirror', u'speed': 0, u'len': 1588396032, u'offset': 1588396032}, u'event': u'BLOCK_JOB_READY'}


step 5:

(QEMU) drive-mirror device=drive0 target=/media/ext/img/mirror2.raw format=raw mode=absolute-paths sync=full on-source-error=stop on-target-error=stop granularity=65536 buf-size=655360
{"return": {}}




Couldn't reproduce on latest upstream; this may have been fixed there. Is this still reproducible downstream? the reproduction instructions don't match the bug title, so I am worried I am not attempting this correctly.

Comment 5 Qianqian Zhu 2017-12-19 07:26:49 UTC
(In reply to John Snow from comment #4)
> (In reply to Qianqian Zhu from comment #0)
> > Description of problem:
> > qemu prompt "main-loop: WARNING: I/O thread spun for 1000 iterations" when
> > block mirror from format raw to raw
> > 
> > Version-Release number of selected component (if applicable):
> > kernel-3.10.0-365.el7.x86_64
> > qemu-kvm-rhev-2.5.0-2.el7.x86_64
> > 
> > guest: 
> > rhel7.2: kernel-3.10.0-327.el7.x86_64
> > 
> > How reproducible:
> > 3/3
> > 
> > Steps to Reproduce:
> > 1.launch guest with qcow2 format image:
> > qemu-kvm -cpu host -m 1024 -device
> > virtio-serial-pci,id=virtio-serial0,bus=pci.0,addr=0x6 -drive
> > file=/home/RHEL-Server-7.2-64-virtio.qcow2,format=qcow2,if=none,id=drive-
> > virtio-blk0,werror=stop,rerror=stop -device
> > virtio-blk-pci,drive=drive-virtio-blk0,id=virtio-disk0 -vnc :1 -monitor
> > stdio -netdev tap,id=hostnet0,vhost=on -device
> > virtio-net-pci,netdev=hostnet0,id=net0,mac=3C:D9:2B:09:AB:44,bus=pci.0,
> > addr=0x4 -qmp tcp:0:5555,server,nowait
> > 2.block mirror from qcow2 to raw:
> > { "execute": "drive-mirror", "arguments": { "device": "drive-virtio-blk0",
> > "target": "/home/mirror1.qcow2", "format": "qcow2", "mode":
> > "absolute-paths", "sync": "full", "on-source-error": "stop",
> > "on-target-error": "stop", "granularity": 65536, "buf-size": 655360 } }
> 
> (A) From the instructions given, this mirrors from qcow2 to qcow2.
> (B) Is the buf-size here intentional? 655360 looks like a typo.

Yes, the buf-size is intentional, it tries to be 10 times granularity.

> 
> > 3.{"execute": "block-job-complete", "arguments": { "device":
> > "drive-virtio-blk0"} }
> 
> > 4. block mirror from raw to raw:
> > { "execute": "drive-mirror", "arguments": { "device": "drive-virtio-blk0",
> > "target": "/home/mirror2.raw", "format": "raw", "mode": "absolute-paths",
> > "sync": "full", "on-source-error": "stop", "on-target-error": "stop",
> > "granularity": 65536, "buf-size": 655360 } }
> > 
> 
> (C) Given the above, this looks like qcow2-to-raw.

That's right, it should be qcow2 to raw, I wrongly described in the title, sorry for that.

> 
> > Actual results:
> > after step 4:
> > (qemu) Formatting '/home/mirror2.raw', fmt=raw size=21474836480
> > main-loop: WARNING: I/O thread spun for 1000 iterations
> > 
> > Expected results:
> > no warning prompt
> > 
> > Additional info:
> > Can't reproduce this issue if launch a raw format guest and block mirror to
> > raw image directly.
> 
> 
> 
> My attempt:
> 
> Step 2:
> 
> (QEMU) drive-mirror device=drive0 target=/media/ext/img/mirror1.qcow2
> format=qcow2 mode=absolute-paths sync=full on-source-error=stop
> on-target-error=stop granularity=65536 buf-size=655360
> {"return": {}}
> 
> (QEMU) 
> {u'timestamp': {u'seconds': 1513629294, u'microseconds': 846094}, u'data':
> {u'device': u'drive0', u'type': u'mirror', u'speed': 0, u'len': 1588396032,
> u'offset': 1588396032}, u'event': u'BLOCK_JOB_READY'}
> 
> Step 3:
> 
> (QEMU) block-job-complete device=drive0
> {"return": {}}
> 
> (QEMU) 
> {u'timestamp': {u'seconds': 1513629339, u'microseconds': 922111}, u'data':
> {u'device': u'drive0', u'type': u'mirror', u'speed': 0, u'len': 1588396032,
> u'offset': 1588396032}, u'event': u'BLOCK_JOB_COMPLETED'}
> 
> Step 4:
> 
> (QEMU) drive-mirror device=drive0 target=/media/ext/img/mirror2.raw
> format=raw mode=absolute-paths sync=full on-source-error=stop
> on-target-error=stop granularity=65536 buf-size=655360
> {"return": {}}
> 
> (QEMU) 
> {u'timestamp': {u'seconds': 1513629560, u'microseconds': 408998}, u'data':
> {u'device': u'drive0', u'type': u'mirror', u'speed': 0, u'len': 1588396032,
> u'offset': 1588396032}, u'event': u'BLOCK_JOB_READY'}
> 
> 
> step 5:
> 
> (QEMU) drive-mirror device=drive0 target=/media/ext/img/mirror2.raw
> format=raw mode=absolute-paths sync=full on-source-error=stop
> on-target-error=stop granularity=65536 buf-size=655360
> {"return": {}}
> 
> 
> 
> 
> Couldn't reproduce on latest upstream; this may have been fixed there. Is
> this still reproducible downstream? the reproduction instructions don't
> match the bug title, so I am worried I am not attempting this correctly.

I have tested this scenario with qemu-kvm-rhev-2.10.0-12.el7.x86_64, the issue does not exist anymore. I think it is already fixed in latest qemu.

Comment 6 John Snow 2017-12-19 15:27:12 UTC
Excellent, thank you for verifying. Marking this as MODIFIED, I'm not 100% sure what the correct end-state ought to be.

(CLOSED CURRENTRELEASE?)

Comment 8 Qianqian Zhu 2018-01-03 05:31:18 UTC
Move to VERIFIED per comment 5

Comment 10 errata-xmlrpc 2018-04-11 00:09:32 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHSA-2018:1104