bug: queue_depth > 1 stalls i/o when open-iscsi is used within KVM guest
78 views
Skip to first unread message
goo...@pierre-beck.de
Apr 30, 2012, 3:32:33 PM4/30/12
to open-...@googlegroups.com
Hi,
this is a fairly grave bug for me. I imagine it's specific to my setup, otherwise more people would complain. KVM or open-iscsi, or both involved. Posting bug report here.
The setup is:
Dual socket Host with 2x Intel Xeon L5520
2x Ethernet controller: Intel Corporation 82576 Gigabit Network Connection (rev 01)
Debian Squeeze / Unstable mix on Host and Guest
Kernel 3.2 on Host and Guest
Qemu-KVM 1.0 (current Debian package = 1.01)
(the bug was encountered with earlier kernel / qemu versions on same hardware)
Guest with -smp 2 or higher and bridged networking (br0, tap, etc.)
Logical block size for target is 4096 bytes. Another target uses 512 bytes, same problem.
After --login, target is represented as /dev/sdc.
# cat /dev/sdc > /dev/null;
dstat shows a bit of traffic, then silence, 100% wait on 1 vcpu. Occasionally, data flows.
Failed workarounds:
- disabling all offloading functions of guest and host ethernet NIC
- changing -cpu to kvm64
- changing virtual network card from virtio-net to e1000, rtl8139
- without vhost_net module
- forcing host NIC to 100 MBit/s
- tweaking coalesce, ring buffer size of host NIC
"Working" workarounds:
- queue_depth. default 32, reducing to 1 prevents bug, 2 and higher triggers bug
- read_ahead_kb. default is 128, reducing to 64 prevents bug, 65 and higher triggers bug.
- reducing guest cpu count to 1.
- using host instead of guest for iscsi yields ~70 MiB/s throughput.
Oddities:
- limiting rate does not prevent bug: # echo 1 > /proc/sys/vm/drop_caches; pv -L1000k /dev/sdc > /dev/null
- writing data does not trigger bug: # cat /dev/zero > /dev/sdc
- reading while writing, triggering bug, will cause both to interrupt
- booting VM without hardware assisted virtualization, things got worse. even queue_depth = 1 and read_ahead_kb = 64 did not help.
Any ideas?
Greetings,
Pierre Beck
this is a fairly grave bug for me. I imagine it's specific to my setup, otherwise more people would complain. KVM or open-iscsi, or both involved. Posting bug report here.
The setup is:
Dual socket Host with 2x Intel Xeon L5520
2x Ethernet controller: Intel Corporation 82576 Gigabit Network Connection (rev 01)
Debian Squeeze / Unstable mix on Host and Guest
Kernel 3.2 on Host and Guest
Qemu-KVM 1.0 (current Debian package = 1.01)
(the bug was encountered with earlier kernel / qemu versions on same hardware)
Guest with -smp 2 or higher and bridged networking (br0, tap, etc.)
Logical block size for target is 4096 bytes. Another target uses 512 bytes, same problem.
After --login, target is represented as /dev/sdc.
# cat /dev/sdc > /dev/null;
dstat shows a bit of traffic, then silence, 100% wait on 1 vcpu. Occasionally, data flows.
Failed workarounds:
- disabling all offloading functions of guest and host ethernet NIC
- changing -cpu to kvm64
- changing virtual network card from virtio-net to e1000, rtl8139
- without vhost_net module
- forcing host NIC to 100 MBit/s
- tweaking coalesce, ring buffer size of host NIC
"Working" workarounds:
- queue_depth. default 32, reducing to 1 prevents bug, 2 and higher triggers bug
- read_ahead_kb. default is 128, reducing to 64 prevents bug, 65 and higher triggers bug.
- reducing guest cpu count to 1.
- using host instead of guest for iscsi yields ~70 MiB/s throughput.
Oddities:
- limiting rate does not prevent bug: # echo 1 > /proc/sys/vm/drop_caches; pv -L1000k /dev/sdc > /dev/null
- writing data does not trigger bug: # cat /dev/zero > /dev/sdc
- reading while writing, triggering bug, will cause both to interrupt
- booting VM without hardware assisted virtualization, things got worse. even queue_depth = 1 and read_ahead_kb = 64 did not help.
Any ideas?
Greetings,
Pierre Beck
Mike Christie
Apr 30, 2012, 5:39:22 PM4/30/12
to open-...@googlegroups.com, goo...@pierre-beck.de
On 04/30/2012 02:32 PM, goo...@pierre-beck.de wrote:
> Hi,
>
> this is a fairly grave bug for me. I imagine it's specific to my setup,
> otherwise more people would complain. KVM or open-iscsi, or both
> involved. Posting bug report here.
>
> The setup is:
>
> Dual socket Host with 2x Intel Xeon L5520
> 2x Ethernet controller: Intel Corporation 82576 Gigabit Network
> Connection (rev 01)
>
> Debian Squeeze / Unstable mix on Host and Guest
> Kernel 3.2 on Host and Guest
> Qemu-KVM 1.0 (current Debian package = 1.01)
> (the bug was encountered with earlier kernel / qemu versions on same
> hardware)
I ran with kernel 3.3 on host and guest and it is working for me. I beat
> Hi,
>
> this is a fairly grave bug for me. I imagine it's specific to my setup,
> otherwise more people would complain. KVM or open-iscsi, or both
> involved. Posting bug report here.
>
> The setup is:
>
> Dual socket Host with 2x Intel Xeon L5520
> 2x Ethernet controller: Intel Corporation 82576 Gigabit Network
> Connection (rev 01)
>
> Debian Squeeze / Unstable mix on Host and Guest
> Kernel 3.2 on Host and Guest
> Qemu-KVM 1.0 (current Debian package = 1.01)
> (the bug was encountered with earlier kernel / qemu versions on same
> hardware)
up on it pretty hard, because I have been testing vm/memory + iscsi issues.
> Oddities:
> - limiting rate does not prevent bug: # echo 1 >
> /proc/sys/vm/drop_caches; pv -L1000k /dev/sdc > /dev/null
> - writing data does not trigger bug: # cat /dev/zero > /dev/sdc
> - reading while writing, triggering bug, will cause both to interrupt
> - booting VM without hardware assisted virtualization, things got
> worse. even queue_depth = 1 and read_ahead_kb = 64 did not help.
>
What is in /var/log/messages when you hit problems?
Could you try with some debugging on?
echo 1 > /sys/module/libiscsi/parameters/debug_libiscsi_session
echo 1 > /sys/module/libiscsi/parameters/debug_libiscsi_eh
goo...@pierre-beck.de
May 1, 2012, 5:59:20 PM5/1/12
to open-...@googlegroups.com, goo...@pierre-beck.de
Does just reading work?
Quite the opposite. Just writing works, reading fails.
What is in /var/log/messages when you hit problems?
Nothing without debugging. Since a few kb make it in occasionally, not even hung task messages.
Could you try with some debugging on?
echo 1 > /sys/module/libiscsi/parameters/debug_libiscsi_session
echo 1 > /sys/module/libiscsi/parameters/debug_libiscsi_eh
OK. Attached output.
Regards,
Pierre Beck
goo...@pierre-beck.de
May 2, 2012, 12:16:07 PM5/2/12
to open-...@googlegroups.com, goo...@pierre-beck.de
Does just reading work?
Quite the opposite: Just writing works.
What is in /var/log/messages when you hit problems?
No messages. Since some kb get through every few seconds, not even hung task oops.
Could you try with some debugging on?
echo 1 > /sys/module/libiscsi/parameters/debug_libiscsi_session
echo 1 > /sys/module/libiscsi/parameters/debug_libiscsi_eh
OK. This is the output:
May 1 22:59:39 backups103 kernel: [93381.056156] session3: iscsi_prep_mgmt_task mgmtpdu [op 0x0 hdr->itt 0x30 datalen 0]
May 1 22:59:39 backups103 kernel: [93381.056616] session3: __iscsi_complete_pdu [op 0x20 cid 0 itt 0x30 len 0]
May 1 22:59:39 backups103 kernel: [93381.056625] session3: iscsi_complete_task complete task itt 0x30 state 3 sc (null)
May 1 22:59:39 backups103 kernel: [93381.056629] session3: iscsi_free_task freeing task itt 0x30 state 1 sc (null)
May 1 22:59:44 backups103 kernel: [93386.064137] session3: iscsi_prep_mgmt_task mgmtpdu [op 0x0 hdr->itt 0x31 datalen 0]
May 1 22:59:44 backups103 kernel: [93386.066710] session3: __iscsi_complete_pdu [op 0x20 cid 0 itt 0x31 len 0]
May 1 22:59:44 backups103 kernel: [93386.066720] session3: iscsi_complete_task complete task itt 0x31 state 3 sc (null)
May 1 22:59:44 backups103 kernel: [93386.066727] session3: iscsi_free_task freeing task itt 0x31 state 1 sc (null)
May 1 22:59:49 backups103 kernel: [93391.072116] session3: iscsi_prep_mgmt_task mgmtpdu [op 0x0 hdr->itt 0x32 datalen 0]
May 1 22:59:49 backups103 kernel: [93391.072326] session3: __iscsi_complete_pdu [op 0x20 cid 0 itt 0x32 len 0]
May 1 22:59:49 backups103 kernel: [93391.072326] session3: iscsi_complete_task complete task itt 0x32 state 3 sc (null)
May 1 22:59:49 backups103 kernel: [93391.072326] session3: iscsi_free_task freeing task itt 0x32 state 1 sc (null)
May 1 22:59:54 backups103 kernel: [93396.080506] session3: iscsi_prep_mgmt_task mgmtpdu [op 0x0 hdr->itt 0x33 datalen 0]
May 1 22:59:54 backups103 kernel: [93396.080725] session3: __iscsi_complete_pdu [op 0x20 cid 0 itt 0x33 len 0]
May 1 22:59:54 backups103 kernel: [93396.080733] session3: iscsi_complete_task complete task itt 0x33 state 3 sc (null)
May 1 22:59:54 backups103 kernel: [93396.080736] session3: iscsi_free_task freeing task itt 0x33 state 1 sc (null)
May 1 22:59:59 backups103 kernel: [93401.088416] session3: iscsi_prep_mgmt_task mgmtpdu [op 0x0 hdr->itt 0x34 datalen 0]
May 1 22:59:59 backups103 kernel: [93401.088798] session3: __iscsi_complete_pdu [op 0x20 cid 0 itt 0x34 len 0]
May 1 22:59:59 backups103 kernel: [93401.088807] session3: iscsi_complete_task complete task itt 0x34 state 3 sc (null)
May 1 22:59:59 backups103 kernel: [93401.088811] session3: iscsi_free_task freeing task itt 0x34 state 1 sc (null)
May 1 23:00:02 backups103 kernel: [93403.297715] session3: iscsi_prep_scsi_cmd_pdu iscsi prep [read cid 0 sc ffff88002f94b580 cdb 0x0 itt 0x35 len 0 bidi_len 0 cmdsn 408 win 128]
May 1 23:00:02 backups103 kernel: [93403.297900] session3: __iscsi_complete_pdu [op 0x21 cid 0 itt 0x35 len 0]
May 1 23:00:02 backups103 kernel: [93403.297904] session3: iscsi_scsi_cmd_rsp cmd rsp done [sc ffff88002f94b580 res 0 itt 0x35]
May 1 23:00:02 backups103 kernel: [93403.297908] session3: iscsi_complete_task complete task itt 0x35 state 3 sc ffff88002f94b580
May 1 23:00:02 backups103 kernel: [93403.297911] session3: iscsi_free_task freeing task itt 0x35 state 1 sc ffff88002f94b580
May 1 23:00:02 backups103 kernel: [93403.300510] session3: iscsi_prep_scsi_cmd_pdu iscsi prep [read cid 0 sc ffff88002f94b480 cdb 0x28 itt 0x36 len 262144 bidi_len 0 cmdsn 409 win 127]
May 1 23:00:02 backups103 kernel: [93403.328884] session3: __iscsi_complete_pdu [op 0x25 cid 0 itt 0x36 len 0]
May 1 23:00:02 backups103 kernel: [93403.328889] session3: iscsi_data_in_rsp data in with status done [sc ffff88002f94b480 res 0 itt 0x36]
May 1 23:00:02 backups103 kernel: [93403.328893] session3: iscsi_complete_task complete task itt 0x36 state 3 sc ffff88002f94b480
May 1 23:00:02 backups103 kernel: [93403.328896] session3: iscsi_free_task freeing task itt 0x36 state 1 sc ffff88002f94b480
May 1 23:00:02 backups103 kernel: [93403.329625] session3: iscsi_prep_scsi_cmd_pdu iscsi prep [read cid 0 sc ffff88002f94b480 cdb 0x28 itt 0x37 len 131072 bidi_len 0 cmdsn 410 win 127]
May 1 23:00:02 backups103 kernel: [93403.329723] session3: iscsi_prep_scsi_cmd_pdu iscsi prep [read cid 0 sc ffff88002f94bc80 cdb 0x28 itt 0x38 len 131072 bidi_len 0 cmdsn 411 win 127]
May 1 23:00:02 backups103 kernel: [93403.333179] session3: __iscsi_complete_pdu [op 0x25 cid 0 itt 0x37 len 0]
May 1 23:00:02 backups103 kernel: [93403.333184] session3: iscsi_data_in_rsp data in with status done [sc ffff88002f94b480 res 0 itt 0x37]
May 1 23:00:02 backups103 kernel: [93403.333188] session3: iscsi_complete_task complete task itt 0x37 state 3 sc ffff88002f94b480
May 1 23:00:02 backups103 kernel: [93403.333191] session3: iscsi_free_task freeing task itt 0x37 state 1 sc ffff88002f94b480
May 1 23:00:02 backups103 kernel: [93403.333462] session3: iscsi_prep_scsi_cmd_pdu iscsi prep [read cid 0 sc ffff88002f94b480 cdb 0x28 itt 0x39 len 131072 bidi_len 0 cmdsn 412 win 126]
May 1 23:00:02 backups103 kernel: [93403.335062] session3: __iscsi_complete_pdu [op 0x25 cid 0 itt 0x38 len 0]
May 1 23:00:02 backups103 kernel: [93403.335066] session3: iscsi_data_in_rsp data in with status done [sc ffff88002f94bc80 res 0 itt 0x38]
May 1 23:00:02 backups103 kernel: [93403.335079] session3: iscsi_complete_task complete task itt 0x38 state 3 sc ffff88002f94bc80
May 1 23:00:02 backups103 kernel: [93403.335082] session3: iscsi_free_task freeing task itt 0x38 state 1 sc ffff88002f94bc80
May 1 23:00:02 backups103 kernel: [93403.335313] session3: iscsi_prep_scsi_cmd_pdu iscsi prep [read cid 0 sc ffff88002f94bc80 cdb 0x28 itt 0x3a len 131072 bidi_len 0 cmdsn 413 win 126]
May 1 23:00:02 backups103 kernel: [93403.341561] session3: __iscsi_complete_pdu [op 0x25 cid 0 itt 0x39 len 0]
May 1 23:00:02 backups103 kernel: [93403.341565] session3: iscsi_data_in_rsp data in with status done [sc ffff88002f94b480 res 0 itt 0x39]
May 1 23:00:02 backups103 kernel: [93403.341569] session3: iscsi_complete_task complete task itt 0x39 state 3 sc ffff88002f94b480
May 1 23:00:02 backups103 kernel: [93403.341572] session3: iscsi_free_task freeing task itt 0x39 state 1 sc ffff88002f94b480
May 1 23:00:02 backups103 kernel: [93403.342061] session3: iscsi_prep_scsi_cmd_pdu iscsi prep [read cid 0 sc ffff88002f94b480 cdb 0x28 itt 0x3b len 131072 bidi_len 0 cmdsn 414 win 126]
May 1 23:00:08 backups103 kernel: [93409.375570] session3: __iscsi_complete_pdu [op 0x25 cid 0 itt 0x3a len 0]
May 1 23:00:08 backups103 kernel: [93409.375577] session3: iscsi_data_in_rsp data in with status done [sc ffff88002f94bc80 res 0 itt 0x3a]
May 1 23:00:08 backups103 kernel: [93409.375581] session3: iscsi_complete_task complete task itt 0x3a state 3 sc ffff88002f94bc80
May 1 23:00:08 backups103 kernel: [93409.375584] session3: iscsi_free_task freeing task itt 0x3a state 1 sc ffff88002f94bc80
May 1 23:00:08 backups103 kernel: [93409.377154] session3: __iscsi_complete_pdu [op 0x25 cid 0 itt 0x3b len 0]
May 1 23:00:08 backups103 kernel: [93409.377158] session3: iscsi_data_in_rsp data in with status done [sc ffff88002f94b480 res 0 itt 0x3b]
May 1 23:00:08 backups103 kernel: [93409.377162] session3: iscsi_complete_task complete task itt 0x3b state 3 sc ffff88002f94b480
May 1 23:00:08 backups103 kernel: [93409.377170] session3: iscsi_free_task freeing task itt 0x3b state 1 sc ffff88002f94b480
May 1 23:00:08 backups103 kernel: [93409.415717] session3: iscsi_prep_scsi_cmd_pdu iscsi prep [read cid 0 sc ffff88002f94b780 cdb 0x0 itt 0x3c len 0 bidi_len 0 cmdsn 415 win 126]
May 1 23:00:08 backups103 kernel: [93409.416025] session3: __iscsi_complete_pdu [op 0x21 cid 0 itt 0x3c len 0]
May 1 23:00:08 backups103 kernel: [93409.416028] session3: iscsi_scsi_cmd_rsp cmd rsp done [sc ffff88002f94b780 res 0 itt 0x3c]
May 1 23:00:08 backups103 kernel: [93409.416028] session3: iscsi_complete_task complete task itt 0x3c state 3 sc ffff88002f94b780
May 1 23:00:08 backups103 kernel: [93409.416028] session3: iscsi_free_task freeing task itt 0x3c state 1 sc ffff88002f94b780
May 1 23:00:13 backups103 kernel: [93414.424071] session3: iscsi_prep_mgmt_task mgmtpdu [op 0x0 hdr->itt 0x3d datalen 0]
May 1 23:00:13 backups103 kernel: [93414.424561] session3: __iscsi_complete_pdu [op 0x20 cid 0 itt 0x3d len 0]
May 1 23:00:13 backups103 kernel: [93414.424568] session3: iscsi_complete_task complete task itt 0x3d state 3 sc (null)
May 1 23:00:13 backups103 kernel: [93414.424571] session3: iscsi_free_task freeing task itt 0x3d state 1 sc (null)
May 1 23:00:18 backups103 kernel: [93419.440111] session3: iscsi_prep_mgmt_task mgmtpdu [op 0x0 hdr->itt 0x3e datalen 0]
May 1 23:00:18 backups103 kernel: [93419.440490] session3: __iscsi_complete_pdu [op 0x20 cid 0 itt 0x3e len 0]
May 1 23:00:18 backups103 kernel: [93419.440498] session3: iscsi_complete_task complete task itt 0x3e state 3 sc (null)
May 1 23:00:18 backups103 kernel: [93419.440501] session3: iscsi_free_task freeing task itt 0x3e state 1 sc (null)
May 1 23:00:23 backups103 kernel: [93424.448156] session3: iscsi_prep_mgmt_task mgmtpdu [op 0x0 hdr->itt 0x3f datalen 0]
May 1 23:00:23 backups103 kernel: [93424.448721] session3: __iscsi_complete_pdu [op 0x20 cid 0 itt 0x3f len 0]
May 1 23:00:23 backups103 kernel: [93424.448729] session3: iscsi_complete_task complete task itt 0x3f state 3 sc (null)
May 1 23:00:23 backups103 kernel: [93424.448733] session3: iscsi_free_task freeing task itt 0x3f state 1 sc (null)
May 1 23:00:28 backups103 kernel: [93429.456167] session3: iscsi_prep_mgmt_task mgmtpdu [op 0x0 hdr->itt 0x40 datalen 0]
May 1 23:00:28 backups103 kernel: [93429.456601] session3: __iscsi_complete_pdu [op 0x20 cid 0 itt 0x40 len 0]
May 1 23:00:28 backups103 kernel: [93429.456609] session3: iscsi_complete_task complete task itt 0x40 state 3 sc (null)
May 1 23:00:28 backups103 kernel: [93429.456612] session3: iscsi_free_task freeing task itt 0x40 state 1 sc (null)
May 1 23:00:33 backups103 kernel: [93434.464228] session3: iscsi_prep_mgmt_task mgmtpdu [op 0x0 hdr->itt 0x41 datalen 0]
May 1 23:00:33 backups103 kernel: [93434.464881] session3: __iscsi_complete_pdu [op 0x20 cid 0 itt 0x41 len 0]
May 1 23:00:33 backups103 kernel: [93434.464889] session3: iscsi_complete_task complete task itt 0x41 state 3 sc (null)
May 1 23:00:33 backups103 kernel: [93434.464892] session3: iscsi_free_task freeing task itt 0x41 state 1 sc (null)
May 1 23:00:38 backups103 kernel: [93439.472315] session3: iscsi_prep_mgmt_task mgmtpdu [op 0x0 hdr->itt 0x42 datalen 0]
May 1 23:00:38 backups103 kernel: [93439.472725] session3: __iscsi_complete_pdu [op 0x20 cid 0 itt 0x42 len 0]
May 1 23:00:38 backups103 kernel: [93439.472733] session3: iscsi_complete_task complete task itt 0x42 state 3 sc (null)
May 1 23:00:38 backups103 kernel: [93439.472736] session3: iscsi_free_task freeing task itt 0x42 state 1 sc (null)
May 1 23:00:43 backups103 kernel: [93444.480165] session3: iscsi_prep_mgmt_task mgmtpdu [op 0x0 hdr->itt 0x43 datalen 0]
May 1 23:00:43 backups103 kernel: [93444.480931] session3: __iscsi_complete_pdu [op 0x20 cid 0 itt 0x43 len 0]
May 1 23:00:43 backups103 kernel: [93444.480937] session3: iscsi_complete_task complete task itt 0x43 state 3 sc (null)
May 1 23:00:43 backups103 kernel: [93444.480941] session3: iscsi_free_task freeing task itt 0x43 state 1 sc (null)
I get the feeling something is very wrong with the virtualized network. This night, the VM lost all connectivity. I logged in via vnc console, saw ping timeout from iscsi and couldn't bring the interface up again. Since I varied guest drivers, and bridge works OK for host, the tap interface usage by qemu seems to be the source of my troubles. Will dig into that. open-iscsi is likely not the issue here.
Thanks for helping anyways,
Pierre Beck
goo...@pierre-beck.de
May 2, 2012, 3:30:04 PM5/2/12
to open-...@googlegroups.com
Hi,
it seems my messages get deleted by the group. Is that true or just some display glitch? I guess the bug is more KVM related than open-iscsi, so I will file the bug there.
Regards,
Pierre Beck
it seems my messages get deleted by the group. Is that true or just some display glitch? I guess the bug is more KVM related than open-iscsi, so I will file the bug there.
Regards,
Pierre Beck
Reply all
Reply to author
Forward
0 new messages