Note: This is a beta release of Red Hat Bugzilla 5.0. The data contained within is a snapshot of the live data so any changes you make will not be reflected in the production Bugzilla. Also email is disabled so feel free to test any aspect of the site that you want. File any problems you find or give feedback here.
Bug 1516105 - [virtio-scsi] Guest hit call trace when hot plug and unplug multiple virtio-scsi devices
Summary: [virtio-scsi] Guest hit call trace when hot plug and unplug multiple virtio-s...
Keywords:
Status: NEW
Alias: None
Product: Red Hat Enterprise Linux Advanced Virtualization
Classification: Red Hat
Component: qemu-kvm
Version: ---
Hardware: All
OS: Linux
medium
medium
Target Milestone: rc
: 8.0
Assignee: John Snow
QA Contact: Xueqiang Wei
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2017-11-22 05:03 UTC by Yongxue Hong
Modified: 2019-02-27 16:56 UTC (History)
13 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:
Type: Bug


Attachments (Terms of Use)

Description Yongxue Hong 2017-11-22 05:03:50 UTC
Description of problem:
Guest hit call trace when hot plug and unplug multi virtio-scsi devices on P9 host(virt 11 on POK)

Version-Release number of selected component (if applicable):
guest : 4.14.0-2.el7a.ppc64le
host : 4.14.0-2.el7a.ppc64le
qemu : qemu-kvm-rhev-2.10.0-6.el7.ppc64le

P9 host name : c155f3-u23(virt 11)
firmware version : OPAL skiboot-v5.9-rc5-p104faa4

How reproducible:
100%

Steps to Reproduce:
1.Boot a guest.
eg:
[root@c155f3-u23 commands]# cat guest-11863-local-image.sh
/usr/libexec/qemu-kvm \
-name 'yhong-guest'  \
-sandbox off  \
-machine pseries  \
-nodefaults  \
-chardev socket,id=qmp_id_qmpmonitor1,path=./monitor-qmpmonitor-yhong,server,nowait \
-mon chardev=qmp_id_qmpmonitor1,mode=control  \
-chardev socket,id=serial_id_serial0,path=./serial-serial-yhong,server,nowait \
-device spapr-vty,reg=0x30000000,chardev=serial_id_serial0 \
-device nec-usb-xhci,id=usb1,bus=pci.0,addr=0x3 \
-device virtio-scsi-pci,id=virtio_scsi_pci0,bus=pci.0,addr=0x4,indirect_desc=off,event_idx=off \
-drive file=/home/yhong/images/Pegas-Server-7.4-ppc64le-virtio-scsi.qcow2,format=qcow2,aio=native,if=none,cache=none,media=disk,werror=stop,rerror=stop,id=drive_image1 \
-device scsi-hd,drive=drive_image1,id=image1,bus=virtio_scsi_pci0.0,channel=0,scsi-id=0,lun=0,bootindex=0 \
-device virtio-net-pci,mac=9a:e9:ea:eb:ec:ed,id=idIpjeB5,vectors=4,netdev=idRxfI4N,bus=pci.0,addr=0x5,bootindex=3  \
-netdev tap,id=idRxfI4N,vhost=on \
-m 8192  \
-smp 16,maxcpus=16,cores=16,threads=1,sockets=1 \
-drive id=drive_cd1,if=none,snapshot=off,aio=threads,cache=none,media=cdrom,file=/home/yhong/isos/RHEL-ALT-7.4-20171030.0-Server-ppc64le-dvd1.iso \
-device scsi-cd,id=cd1,drive=drive_cd1,bootindex=1 \
-device usb-tablet,id=usb-tablet1,bus=usb1.0,port=1  \
-device usb-kbd,id=usb-kbd1,bus=usb1.0,port=2  \
-rtc base=utc,clock=host  \
-boot menu=on,strict=off \
-no-shutdown \
-enable-kvm \
-qmp tcp:0:3000,server,nowait \
-monitor stdio
2. hot plug and unplug multi virtio-scsi devices
eg:
[root@c155f3-u23 commands]# cat multi-hotplug-unplug-repeated-no-sleep-local.sh
#!/bin/sh
i=0
exec 3<>/dev/tcp/localhost/$1 #note modify this to qmp port
echo -e "{ 'execute': 'qmp_capabilities' }" >&3
read response <&3
echo $response

while [ $i -lt 5 ]
do
echo hotplug virtio-scsi===== $i
echo -e "{'execute': 'device_add','arguments':{'driver':'virtio-scsi-pci','id':'scsi1','num_queues':'4'} }" >&3
echo -e "{'execute':'__com.redhat_drive_add', 'arguments': {'file':'/home/yhong/images/data0-10G.qcow2','format':'qcow2','id':'drive-data1'}}" >&3
echo -e "{'execute':'device_add','arguments':{'driver':'scsi-hd','bus':'scsi1.0','channel':'0','scsi-id':'0','lun':'0','drive':'drive-data1','id':'data1'}}" >&3
echo -e "{'execute':'__com.redhat_drive_add', 'arguments': {'file':'/home/yhong/images/data1-12G.qcow2','format':'qcow2','id':'drive-data2'}}" >&3
echo -e "{'execute':'device_add','arguments':{'driver':'scsi-hd','bus':'scsi1.0','channel':'0','scsi-id':'0','lun':'1','drive':'drive-data2','id':'data2'}}" >&3
echo -e "{'execute':'__com.redhat_drive_add', 'arguments': {'file':'/home/yhong/images/data2-14G.qcow2','format':'qcow2','id':'drive-data3'}}" >&3
echo -e "{'execute':'device_add','arguments':{'driver':'scsi-hd','bus':'scsi1.0','channel':'0','scsi-id':'1','lun':'0','drive':'drive-data3','id':'data3'}}" >&3
echo -e "{'execute':'__com.redhat_drive_add', 'arguments': {'file':'/home/yhong/images/data3-16G.qcow2','format':'qcow2','id':'drive-data4'}}" >&3
echo -e "{'execute':'device_add','arguments':{'driver':'scsi-hd','bus':'scsi1.0','channel':'0','scsi-id':'1','lun':'1','drive':'drive-data4','id':'data4'}}" >&3
echo -e "{'execute':'__com.redhat_drive_add', 'arguments': {'file':'/home/yhong/images/data4-18G.qcow2','format':'qcow2','id':'drive-data5'}}" >&3
echo -e "{'execute':'device_add','arguments':{'driver':'scsi-hd','bus':'scsi1.0','channel':'0','scsi-id':'200','lun':'11','drive':'drive-data5','id':'data5'}}" >&3
echo -e "{'execute':'__com.redhat_drive_add', 'arguments': {'file':'/home/yhong/images/data5-20G.qcow2','format':'qcow2','id':'drive-data6'}}" >&3
echo -e "{'execute':'device_add','arguments':{'driver':'scsi-hd','bus':'scsi1.0','channel':'0','scsi-id':'100','lun':'12','drive':'drive-data6','id':'data6'}}" >&3
read response <&3
echo "$response"
sleep 40

echo hotunlug virtio-scsi===== $i
echo -e "{'execute':'device_del','arguments':{'id':'data1'}}" >&3
echo -e "{'execute':'device_del','arguments':{'id':'data2'}}" >&3
echo -e "{'execute':'device_del','arguments':{'id':'data3'}}" >&3
echo -e "{'execute':'device_del','arguments':{'id':'data4'}}" >&3
echo -e "{'execute':'device_del','arguments':{'id':'data5'}}" >&3
echo -e "{'execute':'device_del','arguments':{'id':'data6'}}" >&3
echo -e "{'execute':'device_del','arguments':{'id':'scsi1'}}" >&3
read response <&3
echo "$response"
sleep 40

i=$(($i+1))
done

3.Check device info .
eg:lsscsi -s

Actual results:
Guest hit call trace:
[  103.207816] ------------[ cut here ]------------
[  103.207989] WARNING: CPU: 7 PID: 2296 at kernel/workqueue.c:617 cancel_work_sync+0x3cc/0x470
[  103.208141] Modules linked in: ip6t_rpfilter ipt_REJECT nf_reject_ipv4 ip6t_REJECT nf_reject_ipv6 xt_conntrack ip_set nfnetlink ebtable_nat ebtable_broute bridge stp llc ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 ip6table_mangle ip6table_security ip6table_raw iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack iptable_mangle iptable_security iptable_raw ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter sg ip_tables xfs libcrc32c sr_mod cdrom sd_mod virtio_net virtio_scsi scsi_transport_iscsi virtio_pci virtio_ring virtio dm_mirror dm_region_hash dm_log dm_mod
[  103.209154] CPU: 7 PID: 2296 Comm: drmgr Not tainted 4.14.0-2.el7a.ppc64le #1
[  103.209285] task: c0000001f5dc0000 task.stack: c000000006e60000
[  103.209393] NIP:  c000000000160fdc LR: c000000000160e48 CTR: c00000000018a910
[  103.209522] REGS: c000000006e63440 TRAP: 0700   Not tainted  (4.14.0-2.el7a.ppc64le)
[  103.209647] MSR:  800000000282b033 <SF,VEC,VSX,EE,FP,ME,IR,DR,RI,LE>  CR: 22088844  XER: 20040000
[  103.209811] CFAR: c000000000160d0c SOFTE: 1 
GPR00: c000000000160e48 c000000006e636c0 c0000000014ca600 0000000000000001 
GPR04: c000000006e635e8 c000000006e635e8 0000000022088842 0000000000000000 
GPR08: 0000000000000000 0000000fffffffe0 0000000000000000 000000000001b533 
GPR12: 0000000000008000 c000000007ac4980 0000000000000000 0000000000000000 
GPR16: 0000000000000000 0000000000000000 c000000006719000 0000000000000000 
GPR20: c0000001e4d110c0 c0000000013bc4c0 0000000000000000 c00000000015a590 
GPR24: 000000007fffffff 0000000000000000 c0000001ed7a3aa0 c00000000137c5a8 
GPR28: 0000000000000001 0000000000000000 c00000000137c4a0 c00000000671c8b0 
[  103.210873] NIP [c000000000160fdc] cancel_work_sync+0x3cc/0x470
[  103.210977] LR [c000000000160e48] cancel_work_sync+0x238/0x470
[  103.211078] Call Trace:
[  103.211126] [c000000006e636c0] [c000000000160e48] cancel_work_sync+0x238/0x470 (unreliable)
[  103.211259] [c000000006e63770] [c0080000020f094c] virtscsi_remove+0x12c/0x150 [virtio_scsi]
[  103.211392] [c000000006e637b0] [c008000001cc0ce4] virtio_dev_remove+0x84/0x130 [virtio]
[  103.211532] [c000000006e637f0] [c000000000800c78] device_release_driver+0x198/0x2a0
[  103.211659] [c000000006e63830] [c0000000007ffcac] bus_remove_device+0x11c/0x1c0
[  103.211790] [c000000006e638b0] [c0000000007f7f1c] device_del+0x4fc/0x6f0
[  103.211897] [c000000006e63980] [c0000000007f8140] device_unregister+0x30/0xa0
[  103.212024] [c000000006e639f0] [c008000001cc08d0] unregister_virtio_device+0x30/0x60 [virtio]
[  103.212176] [c000000006e63a20] [c008000001e61c78] virtio_pci_remove+0x48/0xe0 [virtio_pci]
[  103.212311] [c000000006e63a60] [c0000000006f58e0] pci_device_remove+0x70/0x110
[  103.212442] [c000000006e63aa0] [c000000000800c78] device_release_driver+0x198/0x2a0
[  103.212574] [c000000006e63ae0] [c0000000006df418] pci_stop_bus_device+0x678/0x700
[  103.212706] [c000000006e63be0] [c0000000006df944] pci_stop_and_remove_bus_device_locked+0x34/0x60
[  103.212855] [c000000006e63c10] [c0000000006f9450] remove_store+0xb0/0xd0
[  103.212959] [c000000006e63c60] [c0000000007f48c8] dev_attr_store+0x68/0xa0
[  103.213072] [c000000006e63ca0] [c0000000005340c0] sysfs_kf_write+0x80/0xb0
[  103.213166] [c000000006e63ce0] [c000000000532b00] kernfs_fop_write+0x180/0x260
[  103.213275] [c000000006e63d30] [c00000000043a8fc] __vfs_write+0x6c/0x230
[  103.213368] [c000000006e63dd0] [c00000000043b29c] SyS_write+0x16c/0x340
[  103.213464] [c000000006e63e30] [c00000000000b184] system_call+0x58/0x6c
[  103.213555] Instruction dump:
[  103.213613] 4804ca9d 60000000 4bfffcd4 60000000 60420000 7fe3fb78 4bffc135 4bfffea8 
[  103.213731] e8750060 3863fff8 4bffc125 4bffff18 <0fe00000> 4bfffd30 0fe00000 4bfffcf4 
[  103.213850] ---[ end trace 6709d29411cbfaa4 ]---
[  103.246842] sd 1:0:200:11: [sdg] Synchronizing SCSI cache
[  103.247237] sd 1:0:200:11: [sdg] Synchronize Cache(10) failed: Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK
[  103.316750] sd 1:0:100:12: [sdf] Synchronizing SCSI cache
[  103.317103] sd 1:0:100:12: [sdf] Synchronize Cache(10) failed: Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK
[  103.403225] iommu: Removing device 0000:00:00.0 from group 0

Expected results:
No call trace

Additional info:
It is not reproduced with virtio-blk device.

Comment 1 David Gibson 2017-11-22 05:10:41 UTC
Yongxue,

Can you try  to reproduce this with x86.  There's not much power specific code in the SCSI hot plug/unplug path, so I suspect this is a generic problem.

Comment 2 Yongxue Hong 2017-11-22 06:40:44 UTC
Hi David,

It is also reproduce on x86.
[  399.837361] Hardware name: Red Hat KVM, BIOS 1.10.2-5.el7 04/01/2014
[  399.838635] Workqueue: kacpi_hotplug acpi_hotplug_work_fn
[  399.839773] Call Trace:
[  399.840318]  [<ffffffffb12d13a4>] dump_stack+0x19/0x1b
[  399.841335]  [<ffffffffb0c8a9d8>] __warn+0xd8/0x100
[  399.842302]  [<ffffffffb0c8ab1d>] warn_slowpath_null+0x1d/0x20
[  399.843451]  [<ffffffffb0caca2c>] __cancel_work_timer+0xdc/0x120
[  399.844653]  [<ffffffffb0caca80>] cancel_work_sync+0x10/0x20
[  399.845802]  [<ffffffffc078171d>] virtscsi_remove+0x4d/0x90 [virtio_scsi]
[  399.847152]  [<ffffffffc0356169>] virtio_dev_remove+0x49/0xb0 [virtio]
[  399.848443]  [<ffffffffb105926f>] __device_release_driver+0x7f/0xf0
[  399.849692]  [<ffffffffb1059303>] device_release_driver+0x23/0x30
[  399.850903]  [<ffffffffb10589c8>] bus_remove_device+0x108/0x180
[  399.852083]  [<ffffffffb1054945>] device_del+0x135/0x210
[  399.853148]  [<ffffffffb1054a3e>] device_unregister+0x1e/0x60
[  399.854309]  [<ffffffffc03563e6>] unregister_virtio_device+0x16/0x30 [virtio]
[  399.855740]  [<ffffffffc03a3554>] virtio_pci_remove+0x34/0x70 [virtio_pci]
[  399.857099]  [<ffffffffb0f813b9>] pci_device_remove+0x39/0xc0
[  399.858244]  [<ffffffffb105926f>] __device_release_driver+0x7f/0xf0
[  399.859480]  [<ffffffffb1059303>] device_release_driver+0x23/0x30
[  399.860699]  [<ffffffffb0f79784>] pci_stop_bus_device+0x94/0xa0
[  399.861882]  [<ffffffffb0f79882>] pci_stop_and_remove_bus_device+0x12/0x20
[  399.863233]  [<ffffffffb0f97b56>] disable_slot+0x76/0xd0
[  399.864298]  [<ffffffffb0f97bcd>] acpiphp_disable_and_eject_slot+0x1d/0x80
[  399.865673]  [<ffffffffb0f986dd>] acpiphp_hotplug_notify+0x8d/0x210
[  399.866905]  [<ffffffffb0f98650>] ? acpiphp_post_dock_fixup+0xd0/0xd0
[  399.868177]  [<ffffffffb0fbde26>] acpi_device_hotplug+0x3b5/0x418
[  399.869397]  [<ffffffffb0fb7055>] acpi_hotplug_work_fn+0x1e/0x29
[  399.870584]  [<ffffffffb0cab85a>] process_one_work+0x17a/0x440
[  399.871752]  [<ffffffffb0cac526>] worker_thread+0x126/0x3c0
[  399.872872]  [<ffffffffb0cac400>] ? manage_workers.isra.24+0x2a0/0x2a0
[  399.874160]  [<ffffffffb0cb37ff>] kthread+0xcf/0xe0
[  399.875147]  [<ffffffffb0cb3730>] ? insert_kthread_work+0x40/0x40
[  399.876353]  [<ffffffffb12e2318>] ret_from_fork+0x58/0x90
[  399.877437]  [<ffffffffb0cb3730>] ? insert_kthread_work+0x40/0x40
[  399.878647] ---[ end trace a9377a742d11ee90 ]---

Comment 3 CongLi 2017-11-22 06:59:05 UTC
Hi Yongxue,

Could you please provide the test versions on x86 ?

Thanks.

Comment 4 Yongxue Hong 2017-11-22 07:14:25 UTC
(In reply to CongLi from comment #3)
> Hi Yongxue,
> 
> Could you please provide the test versions on x86 ?
> 
> Thanks.

Hi CongLi,

Host : 3.10.0-776.el7.x86_64
Guest : 3.10.0-782.el7.x86_64
Qemu-kvm : qemu-kvm-rhev-2.10.0-6.el7

Comment 5 Yongxue Hong 2017-11-22 09:26:42 UTC
    Guest didn't hit call trace if sleep some times among operations.

    The shell script:
    #!/bin/sh
    i=0
    exec 3<>/dev/tcp/localhost/$1 #note modify this to qmp port
    echo -e "{ 'execute': 'qmp_capabilities' }" >&3
    read response <&3
    echo $response

    while [ $i -lt 5 ]
    do
    echo hotplug virtio-scsi===== $i
    echo -e "{'execute': 'device_add','arguments':{'driver':'virtio-scsi-pci','id':'scsi1','num_queues':'4'} }" >&3
    echo -e "{'execute':'__com.redhat_drive_add', 'arguments': {'file':'iscsi://10.0.0.7:3260/iqn.2017-11.com.yhong:target1/0','format':'raw','id':'drive-data1'}}" >&3
    echo -e "{'execute':'device_add','arguments':{'driver':'scsi-block','bus':'scsi1.0','channel':'0','scsi-id':'0','lun':'0','drive':'drive-data1','id':'data1'}}" >&3
    sleep 3
    echo -e "{'execute':'__com.redhat_drive_add', 'arguments': {'file':'iscsi://10.0.0.7:3260/iqn.2017-11.com.yhong:target1/1','format':'raw','id':'drive-data2'}}" >&3
    echo -e "{'execute':'device_add','arguments':{'driver':'scsi-block','bus':'scsi1.0','channel':'0','scsi-id':'0','lun':'1','drive':'drive-data2','id':'data2'}}" >&3
    sleep 3
    echo -e "{'execute':'__com.redhat_drive_add', 'arguments': {'file':'iscsi://10.0.0.7:3260/iqn.2017-11.com.yhong:target1/2','format':'raw','id':'drive-data3'}}" >&3
    echo -e "{'execute':'device_add','arguments':{'driver':'scsi-block','bus':'scsi1.0','channel':'0','scsi-id':'1','lun':'0','drive':'drive-data3','id':'data3'}}" >&3
    sleep 3
    echo -e "{'execute':'__com.redhat_drive_add', 'arguments': {'file':'iscsi://10.0.0.7:3260/iqn.2017-11.com.yhong:target1/3','format':'raw','id':'drive-data4'}}" >&3
    echo -e "{'execute':'device_add','arguments':{'driver':'scsi-block','bus':'scsi1.0','channel':'0','scsi-id':'1','lun':'1','drive':'drive-data4','id':'data4'}}" >&3
    sleep 3
    echo -e "{'execute':'__com.redhat_drive_add', 'arguments': {'file':'iscsi://10.0.0.7:3260/iqn.2017-11.com.yhong:target1/4','format':'raw','id':'drive-data5'}}" >&3
    echo -e "{'execute':'device_add','arguments':{'driver':'scsi-block','bus':'scsi1.0','channel':'0','scsi-id':'199','lun':'11','drive':'drive-data5','id':'data5'}}" >&3
    sleep 3
    echo -e "{'execute':'__com.redhat_drive_add', 'arguments': {'file':'iscsi://10.0.0.7:3260/iqn.2017-11.com.yhong:target1/5','format':'raw','id':'drive-data6'}}" >&3
    echo -e "{'execute':'device_add','arguments':{'driver':'scsi-block','bus':'scsi1.0','channel':'0','scsi-id':'255','lun':'12','drive':'drive-data6','id':'data6'}}" >&3
    sleep 3
    read response <&3
    echo "$response"
    sleep 10

    echo hotunlug virtio-scsi===== $i
    echo -e "{'execute':'device_del','arguments':{'id':'data1'}}" >&3
    sleep 3
    echo -e "{'execute':'device_del','arguments':{'id':'data2'}}" >&3
    sleep 3
    echo -e "{'execute':'device_del','arguments':{'id':'data3'}}" >&3
    sleep 3
    echo -e "{'execute':'device_del','arguments':{'id':'data4'}}" >&3
    sleep 3
    echo -e "{'execute':'device_del','arguments':{'id':'data5'}}" >&3
    sleep 3
    echo -e "{'execute':'device_del','arguments':{'id':'data6'}}" >&3
    sleep 3
    echo -e "{'execute':'device_del','arguments':{'id':'scsi1'}}" >&3
    sleep 10 
    read response <&3 
    echo "$response"

    i=$(($i+1))
    done


Note You need to log in before you can comment on or make changes to this bug.