While running kselftests firmware test cases on arm64 hikey the
following kernel warning noticed after rcu_preempt detected.
metadata:
git branch: master
git repo: https://git.kernel.org/pub/scm/linux/kernel/git/next/linux-next.git
git commit: f80535b9aa10b0bbed0fb727247c03e20580db1c
git describe: next-20200810
kernel-config:
http://snapshots.linaro.org/openembedded/lkft/lkft/sumo/hikey/lkft/linux-next/836/config
Test output:
----------------
# ./fw_filesystem.sh filesystem loading works
filesystem: loading_works #
# ./fw_filesystem.sh async filesystem loading works
async: filesystem_loading #
# ./fw_filesystem.sh firmware loading platform trigger not present,
ignoring test
firmware: loading_platform #
<trim>
# Testing with the file missing...
with: the_file #
# Batched request_firmware() nofile try #1 OK
request_firmware(): nofile_try #
# Batched request_firmware() nofile try #2 OK
request_firmware(): nofile_try #
# Batched request_firmware() nofile try #3 OK
request_firmware(): nofile_try #
# Batched request_firmware() nofile try #4 OK
request_firmware(): nofile_try #
# Batched request_firmware() nofile try #5 OK
request_firmware(): nofile_try #
# Batched request_firmware_into_buf() nofile try #1 OK
request_firmware_into_buf(): nofile_try #
# Batched request_firmware_into_buf() nofile try #2 OK
request_firmware_into_buf(): nofile_try #
[ 703.458858] rcu: INFO: rcu_preempt detected expedited stalls on
CPUs/tasks: { 0-... } 6847 jiffies s: 5897 root: 0x1/.
[ 703.638281] rcu: blocking rcu_node structures:
[ 703.823398] Task dump for CPU 0:
[ 704.010337] swapper/0 R running task 0 0 0 0x0000002a
[ 704.183444] Call trace:
[ 704.350054] __switch_to+0xf8/0x148
[ 704.519735] function_trace_call+0xec/0x138
[ 704.692279] ftrace_ops_no_ops+0xd0/0x190
[ 704.857800] ftrace_graph_call+0x0/0xc
[ 705.007071] cpuidle_reflect+0x1c/0x50
[ 705.192659] do_idle+0x230/0x2c0
[ 705.367973] cpu_startup_entry+0x2c/0x70
[ 705.534699] rest_init+0x1ac/0x280
[ 705.702975] arch_call_rest_init+0x14/0x1c
[ 705.868195] start_kernel+0x4ec/0x524
[ 760.984689] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
[ 761.050531] rcu: 0-....: (3 GPs behind) idle=d36/0/0x3
softirq=30311/30311 fqs=3259
[ 761.116235] (detected by 1, t=6520 jiffies, g=69177, q=54)
[ 761.181632] Task dump for CPU 0:
[ 761.242682] swapper/0 R running task 0 0 0 0x0000002a
[ 761.308592] Call trace:
[ 761.368972] __switch_to+0xf8/0x148
[ 761.430354] function_trace_call+0xec/0x138
[ 761.492435] ftrace_ops_no_ops+0xd0/0x190
[ 761.553839] ftrace_graph_call+0x0/0xc
[ 761.614710] cpuidle_reflect+0x1c/0x50
[ 761.675523] do_idle+0x230/0x2c0
[ 761.735348] cpu_startup_entry+0x2c/0x70
[ 761.795729] rest_init+0x1ac/0x280
[ 761.855426] arch_call_rest_init+0x14/0x1c
[ 761.915590] start_kernel+0x4ec/0x524
[ 785.377148] rcu: INFO: rcu_preempt detected expedited stalls on
CPUs/tasks: { 0-... } 27327 jiffies s: 5897 root: 0x1/.
[ 785.446389] rcu: blocking rcu_node structures:
[ 785.509145] Task dump for CPU 0:
[ 785.570463] swapper/0 R running task 0 0 0 0x0000002a
[ 785.635790] Call trace:
[ 785.696364] __switch_to+0xf8/0x148
[ 785.757660] 0x0
[ 802.076559] rcu: INFO: rcu_preempt self-detected stall on CPU
[ 802.139876] rcu: 0-....: (4 GPs behind)
idle=d3a/1/0x4000000000000004 softirq=30311/30311 fqs=3258
[ 802.207058] (t=6533 jiffies g=69181 q=191)
[ 802.268659] Task dump for CPU 0:
[ 802.329629] swapper/0 R running task 0 0 0 0x0000002a
[ 802.394536] Call trace:
[ 802.454730] dump_backtrace+0x0/0x1f8
[ 802.516048] show_stack+0x2c/0x38
[ 802.576849] sched_show_task+0x1ac/0x240
[ 802.638160] dump_cpu_task+0x48/0x58
[ 802.699098] rcu_dump_cpu_stacks+0xbc/0xfc
[ 802.760519] rcu_sched_clock_irq+0x7d8/0xc60
[ 802.821943] update_process_times+0x34/0xb8
[ 802.883276] tick_sched_handle.isra.16+0x44/0x68
[ 802.944984] tick_sched_timer+0x50/0xa0
[ 803.005901] __hrtimer_run_queues+0x2c0/0x638
[ 803.067397] hrtimer_interrupt+0xd8/0x248
[ 803.128494] arch_timer_handler_phys+0x38/0x58
[ 803.189953] handle_percpu_devid_irq+0xd0/0x468
[ 803.251437] generic_handle_irq+0x3c/0x58
[ 803.312373] __handle_domain_irq+0x68/0xc0
[ 803.373219] gic_handle_irq+0x60/0xb8
[ 803.433731] el1_irq+0xbc/0x180
[ 803.493681] arch_local_irq_restore+0x4/0x8
[ 803.554618] kmem_cache_free+0xb0/0x4a0
[ 803.615231] kfree_skbmem+0xc8/0xe8
[ 803.675452] kfree_skb+0x9c/0x250
[ 803.735442] enqueue_to_backlog+0xdc/0x390
[ 803.796164] netif_rx_internal+0x98/0x2f8
[ 803.856651] netif_rx+0x60/0x318
[ 803.916259] usbnet_skb_return+0x7c/0x150
[ 803.976614] ax88179_rx_fixup+0x100/0x1e8
[ 804.036898] usbnet_bh+0x1d0/0x330
[ 804.096500] usbnet_bh_tasklet+0x20/0x30
[ 804.156685] tasklet_action_common.isra.17+0x148/0x178
[ 804.218153] tasklet_action+0x2c/0x38
[ 804.278130] __do_softirq+0x154/0x6fc
[ 804.338094] irq_exit+0x174/0x180
[ 804.397695] __handle_domain_irq+0x6c/0xc0
[ 804.458067] gic_handle_irq+0x60/0xb8
[ 804.518016] el1_irq+0xbc/0x180
[ 804.577436] tick_nohz_idle_exit+0x6c/0xd0
[ 804.637874] do_idle+0x198/0x2c0
[ 804.697323] cpu_startup_entry+0x2c/0x70
[ 804.757389] rest_init+0x1ac/0x280
[ 804.816924] arch_call_rest_init+0x14/0x1c
[ 804.877059] start_kernel+0x4ec/0x524
[ 865.249148] rcu: INFO: rcu_preempt detected expedited stalls on
CPUs/tasks: { 0-... } 47295 jiffies s: 5897 root: 0x1/.
[ 865.316312] rcu: blocking rcu_node structures:
[ 865.377050] Task dump for CPU 0:
[ 865.436479] swapper/0 R running task 0 0 0 0x0000002a
[ 865.499869] Call trace:
[ 865.558584] __switch_to+0xf8/0x148
[ 865.618377] 0x0
[ 867.936304] ax88179_178a 1-1.1:1.0 eth0: ax88179 - Link status is: 0
[ 869.373982] wlcore: down
[ 875.464663] mmc_host mmc2: Bus speed (slot 0) = 24800000Hz (slot
req 400000Hz, actual 400000HZ div = 31)
[ 884.666485] mmc_host mmc2: Bus speed (slot 0) = 24800000Hz (slot
req 25000000Hz, actual 24800000HZ div = 0)
[ 884.921791] ------------[ cut here ]------------
[ 884.971615] WARNING: CPU: 1 PID: 326 at
/usr/src/kernel/drivers/net/wireless/ti/wlcore/io.h:52
wlcore_set_partition+0x68/0x520 [wlcore]
[ 885.029490] Modules linked in: sch_fq 8021q garp mrp stp llc
iptable_filter ip_tables x_tables cls_bpf sch_ingress veth test_bpf
algif_hash wl18xx wlcore mac80211 cfg80211 snd_soc_hdmi_codec hci_uart
btqca btbcm adv7511 bluetooth wlcore_sdio snd_soc_audio_graph_card cec
crct10dif_ce snd_soc_simple_card_utils rfkill lima gpu_sched kirin_drm
dw_drm_dsi drm_kms_helper drm fuse [last unloaded: trace_printk]
[ 885.165343] CPU: 1 PID: 326 Comm: NetworkManager Tainted: G
W 5.8.0-next-20200810 #1
[ 885.220456] Hardware name: HiKey Development Board (DT)
[ 885.272459] pstate: 00000005 (nzcv daif -PAN -UAO BTYPE=--)
[ 885.334688] pc : wlcore_set_partition+0x68/0x520 [wlcore]
[ 885.396798] lr : wl12xx_set_power_on+0x90/0x188 [wlcore]
[ 885.458495] sp : ffff800013bf30e0
[ 885.517806] x29: ffff800013bf30e0 x28: ffff00006a9edb48
[ 885.579741] x27: 0000000000000003 x26: 0000000000000000
[ 885.641668] x25: ffff00006acf3120 x24: ffff00006a9edce0
[ 885.703396] x23: ffff800009837000 x22: 0000000000000000
[ 885.764913] x21: ffff800009837000 x20: ffff8000094da068
[ 885.826615] x19: ffff00006acf3120 x18: ffffffffffffffff
[ 885.888716] x17: 0000000000000000 x16: 0000000000000000
[ 885.950787] x15: 0000000000000000 x14: ffff0000772717c0
[ 886.013104] x13: ffff800065bcd000 x12: 0000000005c00ff0
[ 886.075443] x11: 0000000005c00000 x10: 0000000000000000
[ 886.137915] x9 : ffff8000126a0a88 x8 : 0000000000000001
[ 886.200375] x7 : 000000000000063c x6 : ffff800013bf2f40
[ 886.262892] x5 : 0000000000000001 x4 : ffff00006ad00000
[ 886.326075] x3 : 00c0000000000400 x2 : ffff000069831680
[ 886.390946] x1 : 0000000000700000 x0 : 0000000000000009
[ 886.454521] Call trace:
[ 886.471228] wlcore_set_partition+0x68/0x520 [wlcore]
[ 886.490669] wl12xx_set_power_on+0x90/0x188 [wlcore]
[ 886.510013] wl12xx_chip_wakeup+0x3c/0x260 [wlcore]
[ 886.529294] wl1271_op_add_interface+0x504/0xa08 [wlcore]
[ 886.549263] drv_add_interface+0xa0/0x3e0 [mac80211]
[ 886.568802] ieee80211_do_open+0x38c/0xc60 [mac80211]
[ 886.588461] ieee80211_open+0x4c/0x68 [mac80211]
[ 886.607462] __dev_open+0x118/0x1a8
[ 886.625308] __dev_change_flags+0x16c/0x1d0
[ 886.643908] dev_change_flags+0x3c/0x78
[ 886.662123] do_setlink+0x35c/0xed8
[ 886.679969] __rtnl_newlink+0x404/0x790
[ 886.698180] rtnl_newlink+0x54/0x80
[ 886.716037] rtnetlink_rcv_msg+0x29c/0x4f0
[ 886.734510] netlink_rcv_skb+0x64/0x130
[ 886.752691] rtnetlink_rcv+0x28/0x38
[ 886.770608] netlink_unicast+0x1dc/0x290
[ 886.788870] netlink_sendmsg+0x2b8/0x3f8
[ 886.807122] ____sys_sendmsg+0x288/0x2d0
[ 886.825359] ___sys_sendmsg+0x90/0xd0
[ 886.843309] __sys_sendmsg+0x78/0xd0
[ 886.861158] __arm64_sys_sendmsg+0x2c/0x38
[ 886.879529] el0_svc_common.constprop.3+0x7c/0x198
[ 886.898659] do_el0_svc+0x34/0xa0
[ 886.916260] el0_sync_handler+0x16c/0x210
[ 886.934574] el0_sync+0x140/0x180
[ 886.952129] irq event stamp: 410260
[ 886.969885] hardirqs last enabled at (410259):
[<ffff80001133808c>] _raw_spin_unlock_irqrestore+0x94/0xc0
[ 886.994216] hardirqs last disabled at (410260):
[<ffff80001132f068>] __schedule+0xf0/0x8f0
[ 887.017150] softirqs last enabled at (410218):
[<ffff800010001a94>] __do_softirq+0x674/0x6fc
[ 887.040184] softirqs last disabled at (410211):
[<ffff800010097eb4>] irq_exit+0x174/0x180
[ 887.062692] ---[ end trace 3c2f34a7bd5df45e ]---
[ 887.144763] mmc_host mmc2: Bus speed (slot 0) = 24800000Hz (slot
req 400000Hz, actual 400000HZ div = 31)
[ 887.376864] mmc_host mmc2: Bus speed (slot 0) = 24800000Hz (slot
req 25000000Hz, actual 24800000HZ div = 0)
[ 887.516634] mmc_host mmc2: Bus speed (slot 0) = 24800000Hz (slot
req 400000Hz, actual 400000HZ div = 31)
[ 887.716961] mmc_host mmc2: Bus speed (slot 0) = 24800000Hz (slot
req 25000000Hz, actual 24800000HZ div = 0)
[ 888.013264] ------------[ cut here ]------------
[ 888.074832] WARNING: CPU: 1 PID: 326 at
/usr/src/kernel/drivers/net/wireless/ti/wlcore/io.h:52
wlcore_set_partition+0x68/0x520 [wlcore]
[ 888.144754] Modules linked in: sch_fq 8021q garp mrp stp llc
iptable_filter ip_tables x_tables cls_bpf sch_ingress veth test_bpf
algif_hash wl18xx wlcore mac80211 cfg80211 snd_soc_hdmi_codec hci_uart
btqca btbcm adv7511 bluetooth wlcore_sdio snd_soc_audio_graph_card cec
crct10dif_ce snd_soc_simple_card_utils rfkill lima gpu_sched kirin_drm
dw_drm_dsi drm_kms_helper drm fuse [last unloaded: trace_printk]
[ 888.310219] CPU: 1 PID: 326 Comm: NetworkManager Tainted: G
W 5.8.0-next-20200810 #1
[ 888.377744] Hardware name: HiKey Development Board (DT)
[ 888.439538] pstate: 00000005 (nzcv daif -PAN -UAO BTYPE=--)
[ 888.500910] pc : wlcore_set_partition+0x68/0x520 [wlcore]
[ 888.561065] lr : wlcore_set_partition+0x20/0x520 [wlcore]
[ 888.620899] sp : ffff800013bf30e0
[ 888.678069] x29: ffff800013bf30e0 x28: ffff00006a9edb48
[ 888.737880] x27: 0000000000000002 x26: 0000000000000000
[ 888.798234] x25: ffff00006acf3120 x24: ffff00006a9edce0
[ 888.858216] x23: ffff800009837000 x22: 0000000000000000
[ 888.918112] x21: ffff800009837000 x20: ffff8000094da068
[ 888.978896] x19: ffff00006acf3120 x18: ffffffffffffffff
[ 889.038725] x17: 0000000000000000 x16: 0000000000000000
[ 889.098607] x15: 0000000000000000 x14: ffff0000772717c0
[ 889.158319] x13: ffff800065bcd000 x12: 0000000006700ff0
[ 889.218287] x11: 0000000006700000 x10: 0000000000000000
[ 889.278223] x9 : ffff8000126a0a88 x8 : 0000000000000001
[ 889.338189] x7 : 0000000000000754 x6 : 0000000000021c0c
[ 889.398530] x5 : ffff000062570300 x4 : 0000000000000000
[ 889.458829] x3 : 00c0000000000400 x2 : ffff000069831680
[ 889.519263] x1 : 0000000000700000 x0 : 0000000000000009
[ 889.579662] Call trace:
[ 889.636302] wlcore_set_partition+0x68/0x520 [wlcore]
[ 889.696047] wl12xx_set_power_on+0x90/0x188 [wlcore]
[ 889.755840] wl12xx_chip_wakeup+0x3c/0x260 [wlcore]
[ 889.815948] wl1271_op_add_interface+0x504/0xa08 [wlcore]
[ 889.877624] drv_add_interface+0xa0/0x3e0 [mac80211]
[ 889.937184] ieee80211_do_open+0x38c/0xc60 [mac80211]
[ 889.997542] ieee80211_open+0x4c/0x68 [mac80211]
[ 890.056701] __dev_open+0x118/0x1a8
[ 890.114776] __dev_change_flags+0x16c/0x1d0
[ 890.173336] dev_change_flags+0x3c/0x78
[ 890.231500] do_setlink+0x35c/0xed8
[ 890.288995] __rtnl_newlink+0x404/0x790
[ 890.347399] rtnl_newlink+0x54/0x80
[ 890.404950] rtnetlink_rcv_msg+0x29c/0x4f0
[ 890.463423] netlink_rcv_skb+0x64/0x130
[ 890.522076] rtnetlink_rcv+0x28/0x38
[ 890.579762] netlink_unicast+0x1dc/0x290
[ 890.638249] netlink_sendmsg+0x2b8/0x3f8
[ 890.696278] ____sys_sendmsg+0x288/0x2d0
[ 890.754574] ___sys_sendmsg+0x90/0xd0
[ 890.813095] __sys_sendmsg+0x78/0xd0
[ 890.871646] __arm64_sys_sendmsg+0x2c/0x38
[ 890.930336] el0_svc_common.constprop.3+0x7c/0x198
[ 890.989993] do_el0_svc+0x34/0xa0
[ 891.048176] el0_sync_handler+0x16c/0x210
[ 891.106626] el0_sync+0x140/0x180
[ 891.164652] irq event stamp: 410260
[ 891.222545] hardirqs last enabled at (410259):
[<ffff80001133808c>] _raw_spin_unlock_irqrestore+0x94/0xc0
[ 891.287511] hardirqs last disabled at (410260):
[<ffff80001132f068>] __schedule+0xf0/0x8f0
[ 891.350969] softirqs last enabled at (410218):
[<ffff800010001a94>] __do_softirq+0x674/0x6fc
[ 891.415147] softirqs last disabled at (410211):
[<ffff800010097eb4>] irq_exit+0x174/0x180
[ 891.478913] ---[ end trace 3c2f34a7bd5df45f ]---
[ 891.610580] mmc_host mmc2: Bus speed (slot 0) = 24800000Hz (slot
req 400000Hz, actual 400000HZ div = 31)
[ 891.866528] mmc_host mmc2: Bus speed (slot 0) = 24800000Hz (slot
req 25000000Hz, actual 24800000HZ div = 0)
[ 892.014674] mmc_host mmc2: Bus speed (slot 0) = 24800000Hz (slot
req 400000Hz, actual 400000HZ div = 31)
[ 892.282641] mmc_host mmc2: Bus speed (slot 0) = 24800000Hz (slot
req 25000000Hz, actual 24800000HZ div = 0)
full test log link,
https://qa-reports.linaro.org/lkft/linux-next-oe/build/next-20200810/testrun/3045576/suite/linux-log-parser/test/check-kernel-warning-1653950/log
--
Linaro LKFT
https://lkft.linaro.org