WARNING: at net/wireless/ti/wlcore/io.h:52 wlcore_set_partition - wl12xx_set_power_on

WARNING: at net/wireless/ti/wlcore/io.h:52 wlcore_set_partition - wl12xx_set_power_on

[Naresh Kamboju]

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