On Thu, Aug 20, 2020 at 2:03 PM Kalle Valo <kvalo@xxxxxxxxxxxxxx> wrote:
>
> Wen Gong <wgong@xxxxxxxxxxxxxx> writes:
>
> > It happened "Kernel panic - not syncing: hung_task: blocked tasks" when
> > test simulate crash and ifconfig down/rmmod meanwhile.
> >
> > Test steps:
> >
> > 1.Test commands
> > echo soft > /sys/kernel/debug/ieee80211/phy0/ath10k/simulate_fw_crash;sleep 0.05;ifconfig wlan0 down
> > echo soft > /sys/kernel/debug/ieee80211/phy0/ath10k/simulate_fw_crash;rmmod ath10k_sdio
> >
> > 2. dmesg:
> > [ 5622.548630] ath10k_sdio mmc1:0001:1: simulating soft firmware crash
> > [ 5622.655995] ieee80211 phy0: Hardware restart was requested
> > [ 5776.355164] INFO: task shill:1572 blocked for more than 122 seconds.
> > [ 5776.355687] INFO: task kworker/1:2:24437 blocked for more than 122 seconds.
> > [ 5776.359812] Kernel panic - not syncing: hung_task: blocked tasks
> > [ 5776.359836] CPU: 1 PID: 55 Comm: khungtaskd Tainted: G W 4.19.86 #137
> > [ 5776.359846] Hardware name: MediaTek krane sku176 board (DT)
> > [ 5776.359855] Call trace:
> > [ 5776.359868] dump_backtrace+0x0/0x170
> > [ 5776.359881] show_stack+0x20/0x2c
> > [ 5776.359896] dump_stack+0xd4/0x10c
> > [ 5776.359916] panic+0x12c/0x29c
> > [ 5776.359937] hung_task_panic+0x0/0x50
> > [ 5776.359953] kthread+0x120/0x130
> > [ 5776.359965] ret_from_fork+0x10/0x18
> > [ 5776.359986] SMP: stopping secondary CPUs
> > [ 5776.360012] Kernel Offset: 0x141ea00000 from 0xffffff8008000000
> > [ 5776.360026] CPU features: 0x0,2188200c
> > [ 5776.360035] Memory Limit: none
> >
> > command "ifconfig wlan0 down" or "rmmod ath10k_sdio" will be blocked
> > callstack of ifconfig:
> > [<0>] __switch_to+0x120/0x13c
> > [<0>] msleep+0x28/0x38
> > [<0>] ath10k_sdio_hif_stop+0x24c/0x294 [ath10k_sdio]
> > [<0>] ath10k_core_stop+0x50/0x78 [ath10k_core]
> > [<0>] ath10k_halt+0x120/0x178 [ath10k_core]
> > [<0>] ath10k_stop+0x4c/0x8c [ath10k_core]
> > [<0>] drv_stop+0xe0/0x1e4 [mac80211]
> > [<0>] ieee80211_stop_device+0x48/0x54 [mac80211]
> > [<0>] ieee80211_do_stop+0x678/0x6f8 [mac80211]
> > [<0>] ieee80211_stop+0x20/0x30 [mac80211]
> > [<0>] __dev_close_many+0xb8/0x11c
> > [<0>] __dev_change_flags+0xe0/0x1d0
> > [<0>] dev_change_flags+0x30/0x6c
> > [<0>] devinet_ioctl+0x370/0x564
> > [<0>] inet_ioctl+0xdc/0x304
> > [<0>] sock_do_ioctl+0x50/0x288
> > [<0>] compat_sock_ioctl+0x1b4/0x1aac
> > [<0>] __se_compat_sys_ioctl+0x100/0x26fc
> > [<0>] __arm64_compat_sys_ioctl+0x20/0x2c
> > [<0>] el0_svc_common+0xa4/0x154
> > [<0>] el0_svc_compat_handler+0x2c/0x38
> > [<0>] el0_svc_compat+0x8/0x18
> > [<0>] 0xffffffffffffffff
> >
> > callstack of rmmod:
> > [<0>] __switch_to+0x120/0x13c
> > [<0>] msleep+0x28/0x38
> > [<0>] ath10k_sdio_hif_stop+0x294/0x31c [ath10k_sdio]
> > [<0>] ath10k_core_stop+0x50/0x78 [ath10k_core]
> > [<0>] ath10k_halt+0x120/0x178 [ath10k_core]
> > [<0>] ath10k_stop+0x4c/0x8c [ath10k_core]
> > [<0>] drv_stop+0xe0/0x1e4 [mac80211]
> > [<0>] ieee80211_stop_device+0x48/0x54 [mac80211]
> > [<0>] ieee80211_do_stop+0x678/0x6f8 [mac80211]
> > [<0>] ieee80211_stop+0x20/0x30 [mac80211]
> > [<0>] __dev_close_many+0xb8/0x11c
> > [<0>] dev_close_many+0x70/0x100
> > [<0>] dev_close+0x4c/0x80
> > [<0>] cfg80211_shutdown_all_interfaces+0x50/0xcc [cfg80211]
> > [<0>] ieee80211_remove_interfaces+0x58/0x1a0 [mac80211]
> > [<0>] ieee80211_unregister_hw+0x40/0x100 [mac80211]
> > [<0>] ath10k_mac_unregister+0x1c/0x44 [ath10k_core]
> > [<0>] ath10k_core_unregister+0x38/0x7c [ath10k_core]
> > [<0>] ath10k_sdio_remove+0x8c/0xd0 [ath10k_sdio]
> > [<0>] sdio_bus_remove+0x48/0x108
> > [<0>] device_release_driver_internal+0x138/0x1ec
> > [<0>] driver_detach+0x6c/0xa8
> > [<0>] bus_remove_driver+0x78/0xa8
> > [<0>] driver_unregister+0x30/0x50
> > [<0>] sdio_unregister_driver+0x28/0x34
> > [<0>] cleanup_module+0x14/0x6bc [ath10k_sdio]
> > [<0>] __arm64_sys_delete_module+0x1e0/0x22c
> > [<0>] el0_svc_common+0xa4/0x154
> > [<0>] el0_svc_compat_handler+0x2c/0x38
> > [<0>] el0_svc_compat+0x8/0x18
> > [<0>] 0xffffffffffffffff
> >
> > The test command run simulate_fw_crash firstly and it call into
> > ath10k_sdio_hif_stop from ath10k_core_restart, then napi_disable
> > is called and bit NAPI_STATE_SCHED is set. After that, function
> > ath10k_sdio_hif_stop is called again from ath10k_stop by command
> > "ifconfig wlan0 down" or "rmmod ath10k_sdio", then command blocked.
> >
> > It is blocked by napi_synchronize, napi_disable will set bit with
> > NAPI_STATE_SCHED, and then napi_synchronize will enter dead loop
> > becuase bit NAPI_STATE_SCHED is set by napi_disable.
> >
> > function of napi_synchronize
> > static inline void napi_synchronize(const struct napi_struct *n)
> > {
> > if (IS_ENABLED(CONFIG_SMP))
> > while (test_bit(NAPI_STATE_SCHED, &n->state))
> > msleep(1);
> > else
> > barrier();
> > }
> >
> > function of napi_disable
> > void napi_disable(struct napi_struct *n)
> > {
> > might_sleep();
> > set_bit(NAPI_STATE_DISABLE, &n->state);
> >
> > while (test_and_set_bit(NAPI_STATE_SCHED, &n->state))
> > msleep(1);
> > while (test_and_set_bit(NAPI_STATE_NPSVC, &n->state))
> > msleep(1);
> >
> > hrtimer_cancel(&n->timer);
> >
> > clear_bit(NAPI_STATE_DISABLE, &n->state);
> > }
> >
> > Tested with QCA6174 SDIO with firmware WLAN.RMH.4.4.1-00042.
> >
> > Signed-off-by: Wen Gong <wgong@xxxxxxxxxxxxxx>
> > ---
> > drivers/net/wireless/ath/ath10k/sdio.c | 5 ++---
> > 1 file changed, 2 insertions(+), 3 deletions(-)
> >
> > diff --git a/drivers/net/wireless/ath/ath10k/sdio.c b/drivers/net/wireless/ath/ath10k/sdio.c
> > index 7b894dcaad2e..b71499b171c6 100644
> > --- a/drivers/net/wireless/ath/ath10k/sdio.c
> > +++ b/drivers/net/wireless/ath/ath10k/sdio.c
> > @@ -1756,8 +1756,6 @@ static int ath10k_sdio_hif_start(struct ath10k *ar)
> > struct ath10k_sdio *ar_sdio = ath10k_sdio_priv(ar);
> > int ret;
> >
> > - napi_enable(&ar->napi);
> > -
> > /* Sleep 20 ms before HIF interrupts are disabled.
> > * This will give target plenty of time to process the BMI done
> > * request before interrupts are disabled.
> > @@ -1884,7 +1882,6 @@ static void ath10k_sdio_hif_stop(struct ath10k *ar)
> > spin_unlock_bh(&ar_sdio->wr_async_lock);
> >
> > napi_synchronize(&ar->napi);
> > - napi_disable(&ar->napi);
> > }
> >
> > #ifdef CONFIG_PM
> > @@ -2121,6 +2118,7 @@ static int ath10k_sdio_probe(struct sdio_func *func,
> >
> > netif_napi_add(&ar->napi_dev, &ar->napi, ath10k_sdio_napi_poll,
> > ATH10K_NAPI_BUDGET);
> > + napi_enable(&ar->napi);
> >
> > ath10k_dbg(ar, ATH10K_DBG_BOOT,
> > "sdio new func %d vendor 0x%x device 0x%x block 0x%x/0x%x\n",
> > @@ -2235,6 +2233,7 @@ static void ath10k_sdio_remove(struct sdio_func *func)
> >
> > ath10k_core_unregister(ar);
> >
> > + napi_disable(&ar->napi);
> > netif_napi_del(&ar->napi);
> >
> > ath10k_core_destroy(ar);
>
> I'm not really convinced that this is the right fix, but I'm no NAPI
> expert. Can anyone else help?
Calling napi_disable() twice can lead to hangs, but moving NAPI from
start/stop to
the probe isn't the right approach as the datapath is tied to start/stop.
Maybe check the state of NAPI before disable?
if (test_bit(NAPI_STATE_SCHED, &ar->napi.napi.state))
napi_disable(&ar->napi)
or maintain napi_state like this https://patchwork.kernel.org/patch/10249365/
Also, the most common cause for such issues (1st
napi_synchronize/napi_disable hang)
is that napi_poll is being scheduled, so, you might want to check that
napi_schedule isn't
called after stop.
cd ath10k; git log --grep=napi shows plenty of such issues. the one
that matches closest is
c2cac2f74ab4bcf0db0dcf3a612f1e5b52d145c8, so, it could just be a regression.
