search

open-power-host-os / linux

Linux kernel source tree
Other
3 stars 4 forks source link

Call Trace noticed in Fedora24 guest after suspend/resume. #1

Open santwana opened 8 years ago

santwana commented 8 years ago

The below Call Trace is noticed in Fedora24 guest after suspend/resume operations. [ 302.603321] INFO: rcu_sched self-detected stall on CPU [ 302.603433] 0-...: (91 GPs behind) idle=60d/1/0 softirq=2818/2818 fqs=0 [ 302.603524](t=15081 jiffies g=4573 c=4572 q=18) [ 302.603899] rcu_sched kthread starved for 15081 jiffies! g4573 c4572 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1 [ 302.604030] rcu_sched S 0000000000000000 0 7 2 0x00000800 [ 302.604179] Call Trace: [ 302.604215] [c00000009eb1b8c0] [c000000001338d08] sysctl_sched_migration_cost+0x0/0x4 (unreliable) [ 302.604375] [c00000009eb1ba90] [c000000000016274] switch_to+0x2e4/0x410 [ 302.604464] [c00000009eb1baf0] [c0000000009ae828] schedule+0x328/0x9d0 [ 302.604553] [c00000009eb1bb80] [c0000000009aef18] schedule+0x48/0xc0 [ 302.604640] [c00000009eb1bbb0] [c0000000009b313c] schedule_timeout+0x16c/0x340 [ 302.604743] [c00000009eb1bca0] [c000000000140eac] rcu_gp_kthread+0x8ec/0xc00 [ 302.604846] [c00000009eb1bd80] [c0000000000e5f90] kthread+0x110/0x130 [ 302.604993] [c00000009eb1be30] [c0000000000095b0] ret_from_kernel_thread+0x5c/0xac [ 302.605145] Task dump for CPU 0: [ 302.605191] swapper/0 R running task 0 0 0 0x00000004 [ 302.605356] Call Trace: [ 302.605429] [c0000000013075a0] [c0000000000fb720] sched_show_task+0xe0/0x180 [ 302.605472] INFO: rcu_sched self-detected stall on CPU [ 302.605475] 2-...: (1 ticks this GP) idle=909/1/0 softirq=3974/3974 fqs=0 [ 302.605475]
[ 302.605477](t=15081 jiffies g=4573 c=4572 q=18) _GP_WAIT_FQS(3) ->state=0x1 [ 302.605479] rcu_sched S [ 302.605480] 0000000000000000 [ 302.605481] 0 7 2 0x00000800 [ 302.605481] Call Trace: +0x0/0x4 302.605484 [ 302.605487] INFO: rcu_sched self-detected stall on CPU [ 302.605490] [c00000009eb1ba90] [c000000000016274] switch_to+0x2e4/0x410 [ 302.605492] [c00000009eb1baf0] [c0000000009ae828] schedule+0x328/0x9d0 [ 302.605495] [c00000009eb1bb80] [c0000000009aef18] schedule+0x48/0xc0 0 [ 302.605499] [c00000009eb1bca0] [c000000000140eac] rcu_gp_kthread+0x8ec/0xc00 [ 302.605502] [c00000009eb1bd80] [c0000000000e5f90] kthread+0x110/0x130 [ 302.605505] 7-...: (49 GPs behind) idle=e19/1/0 softirq=1338/1338 fqs=0 [ 302.605506]
/0xac [ 302.605510](t=15081 jiffies g=4573 c=4572 q=18) _GP_WAIT_FQS(3) ->state=0x1 [ 302.605514] rcu_sched S [ 302.605514] 0000000000000000 [ 302.605516] 0 7 2 0x00000800

The guest has an multifunction NIC adapter hot-plugged, and after suspend/resume, the Call Trace is noticed. Without the NIC Hot-plugged, the issue isn't noticed in the guest after suspend/resume. Apart from the Call Trace being noticed, the guest resumes fine without any further errors being noticed.

Guest Details

uname -a

Linux localhost.localdomain 4.5.5-300.fc24.ppc64le #1 SMP Tue May 24 12:23:26 UTC 2016 ppc64le ppc64le ppc64le GNU/Linux

Steps to Reproduce

  1. Hot-plug an multifunction adapter to Fedora24 guest using virsh:

    virsh attach-device fedora24-san hotadd-nic.xml --live

Device attached successfully

Inside the guest, the device is listed as:

lspci -nn

00:01.0 Ethernet controller [0200]: Red Hat, Inc Virtio network device [1af4:1000] 00:02.0 USB controller [0c03]: Apple Inc. KeyLargo/Intrepid USB [106b:003f] 00:03.0 SCSI storage controller [0100]: Red Hat, Inc Virtio block device [1af4:1001] 00:04.0 Unclassified device [00ff]: Red Hat, Inc Virtio memory balloon [1af4:1002] 00:05.0 Ethernet controller [0200]: Broadcom Corporation NetXtreme II BCM57800 1/10 Gigabit Ethernet [14e4:168a](rev 10) 00:05.1 Ethernet controller [0200]: Broadcom Corporation NetXtreme II BCM57800 1/10 Gigabit Ethernet [14e4:168a](rev 10) 00:05.2 Ethernet controller [0200]: Broadcom Corporation NetXtreme II BCM57800 1/10 Gigabit Ethernet [14e4:168a](rev 10) 00:05.3 Ethernet controller [0200]: Broadcom Corporation NetXtreme II BCM57800 1/10 Gigabit Ethernet [14e4:168a](rev 10) 00:0f.0 USB controller [0c03]: NEC Corporation uPD720200 USB 3.0 Host Controller [1033:0194](rev 03)

[00:05.0 till 00:05.3] are the hot-plugged device.

  1. Once the device is hot-plugged to the guest, suspend the guest:

    virsh suspend fedora24-san

    Domain fedora24-san suspended

  2. After resuming the guest, the Call Trace is noticed.

    virsh resume fedora24-san

    Domain fedora24-san resumed

  3. Without the NIC Hot-plugged, the CallTrace is unreproducible with suspend/resume. dmesg.txt
vipinparashar commented 8 years ago

Investigating...

vipinparashar commented 8 years ago

[root@localhost log]# lspci | grep Ethernet 00:01.0 Ethernet controller: Red Hat, Inc Virtio network device 00:05.0 Ethernet controller: Broadcom Corporation NetXtreme II BCM57800 1/10 Gigabit Ethernet (rev 10) 00:05.1 Ethernet controller: Broadcom Corporation NetXtreme II BCM57800 1/10 Gigabit Ethernet (rev 10) 00:05.2 Ethernet controller: Broadcom Corporation NetXtreme II BCM57800 1/10 Gigabit Ethernet (rev 10) 00:05.3 Ethernet controller: Broadcom Corporation NetXtreme II BCM57800 1/10 Gigabit Ethernet (rev 10) [root@localhost log]#

[root@localhost log]# lspci -k | grep -A 4 Ethernet | less 00:01.0 Ethernet controller: Red Hat, Inc Virtio network device Subsystem: Red Hat, Inc Device 0001 Kernel driver in use: virtio-pci Kernel modules: virtio_pci

00:02.0 USB controller: Apple Inc. KeyLargo/Intrepid USB

00:05.0 Ethernet controller: Broadcom Corporation NetXtreme II BCM57800 1/10 Gigabit Ethernet (rev 10) Subsystem: IBM Device 0493 Kernel driver in use: bnx2x Kernel modules: bnx2x 00:05.1 Ethernet controller: Broadcom Corporation NetXtreme II BCM57800 1/10 Gigabit Ethernet (rev 10) Subsystem: IBM Device 0493 Kernel driver in use: bnx2x Kernel modules: bnx2x 00:05.2 Ethernet controller: Broadcom Corporation NetXtreme II BCM57800 1/10 Gigabit Ethernet (rev 10) Subsystem: IBM Device 0494 Kernel driver in use: bnx2x Kernel modules: bnx2x 00:05.3 Ethernet controller: Broadcom Corporation NetXtreme II BCM57800 1/10 Gigabit Ethernet (rev 10) Subsystem: IBM Device 0494 Kernel driver in use: bnx2x Kernel modules: bnx2x 00:0f.0 USB controller: NEC Corporation uPD720200 USB 3.0 Host Controller (rev 03)

00:05.0-00:05.3 devices use bnx driver.

vipinparashar commented 8 years ago

[ 65.435969] pci 0000:00:05.3: BAR 4: assigned [mem 0x10120040000-0x1012004ffff 64bit pref] [ 65.436514] bnx2x 0000:00:05.3: msix capability found [ 65.436783] bnx2x 0000:00:05.3: enabling device (0140 -> 0142) [ 65.468366] bnx2x 0000:00:05.3: Using 64-bit direct DMA at offset 800000000000000 [ 65.468584] bnx2x 0000:00:05.3: part number 0-0-0-0 [ 65.542029] bnx2x 0000:00:05.3 enp0s5f3: renamed from eth0 [ 65.569382] IPv6: ADDRCONF(NETDEV_UP): enp0s5f3: link is not ready [ 65.684817] bnx2x 0000:00:05.1 enp0s5f1: NIC Link is Up, 10000 Mbps full duplex, Flow control: ON - receive & transmit [ 65.726679] bnx2x 0000:00:05.3 enp0s5f3: using MSI-X IRQs: sp 77 fp[0] 79 ... fp[7] 86 [ 65.992566] IPv6: ADDRCONF(NETDEV_UP): enp0s5f3: link is not ready [ 65.992695] IPv6: ADDRCONF(NETDEV_CHANGE): enp0s5f1: link becomes ready [ 67.574558] bnx2x 0000:00:05.2 enp0s5f2: NIC Link is Up, 1000 Mbps full duplex, Flow control: none [ 67.574688] IPv6: ADDRCONF(NETDEV_CHANGE): enp0s5f2: link becomes ready [ 68.304543] bnx2x 0000:00:05.3 enp0s5f3: NIC Link is Up, 1000 Mbps full duplex, Flow control: none [ 68.304675] IPv6: ADDRCONF(NETDEV_CHANGE): enp0s5f3: link becomes ready [ 302.603321] INFO: rcu_sched self-detected stall on CPU [ 302.603433] 0-...: (91 GPs behind) idle=60d/1/0 softirq=2818/2818 fqs=0 [ 302.603524](t=15081 jiffies g=4573 c=4572 q=18) [ 302.603899] rcu_sched kthread starved for 15081 jiffies! g4573 c4572 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1 [ 302.604030] rcu_sched S 0000000000000000 0 7 2 0x00000800 [ 302.604179] Call Trace: [ 302.604215] [c00000009eb1b8c0] [c000000001338d08] sysctl_sched_migration_cost+0x0/0x4 (unreliable) [ 302.604375] [c00000009eb1ba90] [c000000000016274] __switch_to+0x2e4/0x410 [ 302.604464] [c00000009eb1baf0] [c0000000009ae828] __schedule+0x328/0x9d0 [ 302.604553] [c00000009eb1bb80] [c0000000009aef18] schedule+0x48/0xc0 [ 302.604640] [c00000009eb1bbb0] [c0000000009b313c] schedule_timeout+0x16c/0x340 [ 302.604743] [c00000009eb1bca0] [c000000000140eac] rcu_gp_kthread+0x8ec/0xc00 [ 302.604846] [c00000009eb1bd80] [c0000000000e5f90] kthread+0x110/0x130 [ 302.604993] [c00000009eb1be30] [c0000000000095b0] ret_from_kernel_thread+0x5c/0xac

From attached dmesg logs, RCU sched errors are seen after eth devices hotplugged and initialised successfully

vipinparashar commented 8 years ago

virsh # list

Id Name State

7 centos72-test running 8 fedora24-san running

virsh # suspend fedora24-san Domain fedora24-san suspended

virsh # list

Id Name State

7 centos72-test running 8 fedora24-san paused

virsh # error: Disconnected from qemu:///system due to I/O error

virsh # virsh # resume fedora24-san error: Reconnected to the hypervisor Domain fedora24-san resumed

virsh # list

Id Name State

7 centos72-test running 8 fedora24-san running

virsh #

I tried suspending and resuming guest with a minute internal between. It worked fine and i didn't observe RCU sched errors. Though i daw disconnection from qemu due to I/O error but no RCU stalls on guest. I attempted thrice and got same result every time.

rmatinata-ibm commented 8 years ago

@paulusmack can you or somebody take a look into this ?

vipinparashar commented 8 years ago

Test informed that this issue is seen with delay of 3-4 mins between suspend and resume. Issue wasn't seen previously with delay of 1 mins between suspend and resume.

vipinparashar commented 8 years ago

The issue happens intermittently. I could recreate it once after trying 3 times with 5-6 mins interval between suspend and resume opeartions. RCU traces showed up after unloading bnx2xx driver as well.

vipinparashar commented 8 years ago

Currently its Fedora24 used on guest. Is this issue is being seen with other distros running on guest as well ?