Non-working mwifiex_sdio with SD8897

[Takashi Iwai <tiwai@suse.de>]

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.


thanks,

Takashi