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
