Re: Non-working mwifiex_sdio with SD8897

[Takashi Iwai <tiwai@suse.de>]

On Fri, 02 Dec 2016 17:49:13 +0100,
Takashi Iwai wrote:
> 
> Hi,
> 
> we've got an Intel Cherry Trail-based system with Marvell SD8897 chip
> over MMC (sdhci), and WiFi / BT always fails at starting (or better to
> say, it never worked properly).
> 
> For avoiding the race between WiFi and BT, I blacklisted btmrvl_sdio,
> so let's concentrate only on mwifiex_sdio now.
> 
> At the beginning of the driver loading, it looks fine:
> 
>  mwifiex_sdio mmc1:0001:1: info: FW download over, size 802164 bytes
>  mwifiex_sdio mmc1:0001:1: WLAN FW is active
>  mwifiex_sdio mmc1:0001:1: info: MWIFIEX VERSION: mwifiex 1.0 (15.68.7.p77) 
>  mwifiex_sdio mmc1:0001:1: driver_version = mwifiex 1.0 (15.68.7.p77) 
>  cfg80211: Regulatory domain changed to country: US
>  .....
> 
> Then it gets a timeout
> 
>  mwifiex_sdio mmc1:0001:1: mwifiex_cmd_timeout_func: Timeout cmd id = 0x107, act = 0x0
>  mwifiex_sdio mmc1:0001:1: num_data_h2c_failure = 0
>  mwifiex_sdio mmc1:0001:1: num_cmd_h2c_failure = 0
>  mwifiex_sdio mmc1:0001:1: is_cmd_timedout = 1
>  mwifiex_sdio mmc1:0001:1: num_tx_timeout = 0
>  mwifiex_sdio mmc1:0001:1: last_cmd_index = 4
>  mwifiex_sdio mmc1:0001:1: last_cmd_id: 1e 00 0c 01 1e 00 20 00 07 01
>  mwifiex_sdio mmc1:0001:1: last_cmd_act: 00 00 01 00 00 00 08 00 00 00
>  mwifiex_sdio mmc1:0001:1: last_cmd_resp_index = 3
>  mwifiex_sdio mmc1:0001:1: last_cmd_resp_id: 1e 80 0c 81 1e 80 20 80 20 80
>  mwifiex_sdio mmc1:0001:1: last_event_index = 1
>  mwifiex_sdio mmc1:0001:1: last_event: 00 00 0b 00 00 00 00 00 00 00
>  mwifiex_sdio mmc1:0001:1: data_sent=0 cmd_sent=0
>  mwifiex_sdio mmc1:0001:1: ps_mode=1 ps_state=1
>  mwifiex_sdio mmc1:0001:1: ===mwifiex driverinfo dump start===
>  mwifiex_sdio mmc1:0001:1: info: MWIFIEX VERSION: mwifiex 1.0 (15.68.7.p77) 
>  mwifiex_sdio mmc1:0001:1: SDIO register dump start
>  mwifiex_sdio mmc1:0001:1: SDIO Func0 (0x0-0x9): 43 03 02 02 03 02 00 02 03 00 
>  mwifiex_sdio mmc1:0001:1: SDIO Func1 (0x0-0xb): 02 ff c3 40 00 00 00 00 ff ff ff ff 
>  mwifiex_sdio mmc1:0001:1: SDIO Func1: (0x4c) 00 (0x50) 08 (0x54) 07 (0x55) 0c (0x58) 10 (0x59) 00 (0x5c) 00 (0x5d) 00 
>  mwifiex_sdio mmc1:0001:1: SDIO Func1 (0xc0-0xca): dc fe 6c 00 10 00 3f 36 36 02 20 
>  mwifiex_sdio mmc1:0001:1: SDIO Func1 (0xc0-0xca): dc fe 76 00 1a 00 3f 36 36 02 20 
>  mwifiex_sdio mmc1:0001:1: SDIO register dump end
>  mwifiex_sdio mmc1:0001:1: ===mwifiex driverinfo dump end===
>  mwifiex_sdio mmc1:0001:1: == mwifiex firmware dump start ==
>  mwifiex_sdio mmc1:0001:1: Ignore scan. Card removed or firmware in bad state
>  mwifiex_sdio mmc1:0001:1: scan failed: -14
>  mwifiex_sdio mmc1:0001:1: == mwifiex firmware dump end ==
>  mwifiex_sdio mmc1:0001:1: == mwifiex dump information to /sys/class/devcoredump start
>  mwifiex_sdio mmc1:0001:1: == mwifiex dump information to /sys/class/devcoredump end
> 
> And the reset fails as well:
> 
>  mwifiex_sdio mmc1:0001:1: info: shutdown mwifiex...
>  mwifiex_sdio mmc1:0001:1: PREP_CMD: card is removed
>  mmc1: tried to reset card
>  mwifiex_sdio mmc1:0001:1: failed to enable function
> 
> 
> I can give the output with CONFIG_MMC_DEBUG and dyndbg for mwifiex*,
> but the full log is way too big to post, as the system is eMMC and it
> contains lots of noises.  In case it helps, the log snippet before the
> timeout is like:
> 
>  [   42.367403] mwifiex_sdio mmc1:0001:1: bgscan already stopped!
>  [   42.398871] mmc1: starting CMD53 arg 93000100 flags 000001b5
>  [   42.398880] mmc1:     blksz 256 blocks 1 flags 00000100 tsac 1000 ms nsac 0
>  [   42.399136] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000020
>  [   42.400415] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000020
>  [   42.401787] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000020
>  [   42.403044] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000020
>  [   42.404498] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000020
>  [   42.405874] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000020
>  [   42.407192] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000020
>  [   42.408703] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000020
>  [   42.410229] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000020
>  [   42.411464] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000020
>  [   42.412754] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000020
>  [   42.414211] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000020
>  [   42.415365] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000020
>  [   42.416635] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000020
>  [   42.417968] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000020
>  [   42.419163] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000020
>  [   42.420439] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000020
>  [   42.421891] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000020
>  [   42.423206] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000020
>  [   42.424531] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000020
>  [   42.425974] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000020
>  [   42.427268] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000020
>  [   42.428575] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000020
>  [   42.429959] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000020
>  [   42.431153] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000020
>  [   42.432436] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000020
>  [   42.433793] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000020
>  [   42.435034] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000020
>  [   42.436447] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000020
>  [   42.437957] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000020
>  [   42.439244] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000020
>  [   42.440559] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000020
>  [   42.441993] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000103
>  [   42.442061] mmc1: req done (CMD53): 0: 00002000 00000000 00000000 00000000
>  [   42.442067] mmc1:     256 bytes transferred: 0
>  [   42.442183] mmc1: starting CMD53 arg 100000b8 flags 000001b5
>  [   42.442189] mmc1:     blksz 184 blocks 1 flags 00000200 tsac 1000 ms nsac 0
>  [   42.442217] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000003
>  [   42.442228] mmc1: req done (CMD53): 0: 00002000 00000000 00000000 00000000
>  [   42.442229] mmc1:     184 bytes transferred: 0
>  [   42.442368] mmc1: starting CMD53 arg 13000100 flags 000001b5
>  [   42.442374] mmc1:     blksz 256 blocks 1 flags 00000200 tsac 1000 ms nsac 0
>  [   42.442472] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000003
>  [   42.442483] mmc1: req done (CMD53): 0: 00002000 00000000 00000000 00000000
>  [   42.442484] mmc1:     256 bytes transferred: 0
>  [   42.442645] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000100
>  [   42.442675] mmc1: starting CMD53 arg 100000b8 flags 000001b5
>  [   42.442681] mmc1:     blksz 184 blocks 1 flags 00000200 tsac 1000 ms nsac 0
>  [   42.442804] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000003
>  [   42.442814] mmc1: req done (CMD53): 0: 00002000 00000000 00000000 00000000
>  [   42.442816] mmc1:     184 bytes transferred: 0
>  [   52.447746] mwifiex_sdio mmc1:0001:1: mwifiex_cmd_timeout_func: Timeout cmd id = 0x6, act = 0x3
> 
> So there seems really no ack before the timeout.
> 
> 
> Looking through the web, some earlier bug reports (in year 2014)
> showed the similar problem,
> 
>   https://bugzilla.kernel.org/show_bug.cgi?id=76111
> 
> The bug entry remains opened, so I'm not sure about the situation of
> that bug.  Also there are some other hits, but not quite sure whether
> it's the same issue.
> 
> 
> A few more things to be noted:
> 
> - The timeout isn't always 0x107.  Sometimes it gets 0xa9.
> - I already tried to set can_ext_scan=false, but it didn't help.
> - The symptom appears on all kernel version from 4.4 to 4.9.
> - Backporting the stuff in mwifiex from linux-next as of today didn't
>   help, either.
> 
> 
> Does anyone have a hint for further debugging?
> Any suggestions appreciated.

Does anyone have an idea how to debug further?


thanks,

Takashi