dw_mmc: failures on Rockchip rk3288 veyron boards

Hi all,

I haven't managed to get as far as a bugfix for this, but I've bisected some issues seen on v4.10+ with a Chromebook of the Veyron family (Jaq, in particular). v4.9 works fine.

Issue #1 - eMMC complains periodically:

[    4.358135] mmc_host mmc2: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[    4.461466] mmc_host mmc2: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[    5.291450] mmc_host mmc2: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[    5.381471] mmc_host mmc2: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[   11.243337] mmc_host mmc2: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[   17.371628] mmc_host mmc2: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)

and if I stress it out at all (e.g., dd if=/dev/mmcblk2 bs=1M > /dev/null), it will eventually croak:

[  359.916315] mmc_host mmc2: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[  360.071378] dwmmc_rockchip ff0f0000.dwmmc: Successfully tuned phase to 153
[  360.211351] mmcblk2: error -110 transferring data, sector 8644608, nr 2048, cmd response 0x900, card status 0x0
[  360.221936] mmcblk2: retrying using single block read
[  363.491362] mmcblk2: error -110 transferring data, sector 8646656, nr 2048, cmd response 0x900, card status 0x0
[  363.531569] mmc_host mmc2: Bus speed (slot 0) = 400000Hz (slot req 400000Hz, actual 400000HZ div = 0)
[  363.596326] mmc_host mmc2: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[  363.612712] dwmmc_rockchip ff0f0000.dwmmc: Successfully tuned phase to 152
[  363.751351] mmcblk2: error -110 transferring data, sector 8646656, nr 2048, cmd response 0x900, card status 0x0
[  363.761938] mmcblk2: retrying using single block read
[  366.611356] INFO: task mmcqd/2boot1:92 blocked for more than 120 seconds.
[  366.618134]       Not tainted 4.10.0 #284
[  366.622146] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  366.629960] mmcqd/2boot1    D    0    92      2 0x00000000
[  366.635454] [<c07dc21c>] (__schedule) from [<c07dc4e0>] (schedule+0x90/0xa0)
[  366.642497] [<c07dc4e0>] (schedule) from [<c066e8b4>] (__mmc_claim_host+0xd4/0x19c)
[  366.650142] [<c066e8b4>] (__mmc_claim_host) from [<c066e9ac>] (mmc_get_card+0x30/0x34)
[  366.658056] [<c066e9ac>] (mmc_get_card) from [<c067fc8c>] (mmc_blk_issue_rq+0x64/0x48c)
[  366.666052] [<c067fc8c>] (mmc_blk_issue_rq) from [<c0680230>] (mmc_queue_thread+0x114/0x1b4)
[  366.674484] [<c0680230>] (mmc_queue_thread) from [<c023d1b0>] (kthread+0x128/0x144)
[  366.682134] [<c023d1b0>] (kthread) from [<c02076e8>] (ret_from_fork+0x14/0x2c)

...

Issue #2 - Wifi (via SDIO, mmc1) is completely dead:

[    1.444125] mmc_host mmc1: card is non-removable.
[    1.471368] mmc_host mmc1: Bus speed (slot 0) = 400000Hz (slot req 400000Hz, actual 400000HZ div = 0)
[    1.619553] mmc_host mmc1: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[    1.881699] mmc1: new ultra high speed SDR104 SDIO card at address 0001
[   25.681172] mmc_host mmc1: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[   25.691666] mwifiex: rx work enabled, cpus 4
[   26.827000] mwifiex_sdio mmc1:0001:1: info: FW download over, size 800344 bytes
[   27.561352] mwifiex_sdio mmc1:0001:1: WLAN FW is active
[   33.585165] mmc_host mmc1: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[   37.651344] mwifiex_sdio mmc1:0001:1: mwifiex_cmd_timeout_func: Timeout cmd id = 0xa9, act = 0x0
[   37.660122] mwifiex_sdio mmc1:0001:1: num_data_h2c_failure = 0
[   37.665951] mwifiex_sdio mmc1:0001:1: num_cmd_h2c_failure = 0
[   37.671688] mwifiex_sdio mmc1:0001:1: is_cmd_timedout = 1
[   37.677076] mwifiex_sdio mmc1:0001:1: num_tx_timeout = 0
[   37.682380] mwifiex_sdio mmc1:0001:1: last_cmd_index = 1
[   37.687681] mwifiex_sdio mmc1:0001:1: last_cmd_id: 00 00 a9 00 00 00 00 00 00 00
[   37.695066] mwifiex_sdio mmc1:0001:1: last_cmd_act: 00 00 00 00 00 00 00 00 00 00
[   37.702536] mwifiex_sdio mmc1:0001:1: last_cmd_resp_index = 0
[   37.708269] mwifiex_sdio mmc1:0001:1: last_cmd_resp_id: 00 00 00 00 00 00 00 00 00 00
[   37.716087] mwifiex_sdio mmc1:0001:1: last_event_index = 0
[   37.721564] mwifiex_sdio mmc1:0001:1: last_event: 00 00 00 00 00 00 00 00 00 00
[   37.728857] mwifiex_sdio mmc1:0001:1: data_sent=1 cmd_sent=0
[   37.734508] mwifiex_sdio mmc1:0001:1: ps_mode=0 ps_state=0
[   37.740016] mmc_host mmc1: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[   37.750268] mwifiex_sdio mmc1:0001:1: info: mwifiex_fw_dpc: unregister device

For either of these issues, if I simply revert the dw_mmc driver back to its v4.9 version (but keep everything else at v4.10), things seem to work fine.

At this point, I'm pretty sure that it's the runtime PM support added to dw_mmc that cause the regression.

Any thoughts? I don't exactly plan on trying to debug a solution myself here, but I thought I'd report it in case somebody else has ideas.

Brian

Hi Brian,

Quoted 5 lines · Brian Norris

Hi all,

I haven't managed to get as far as a bugfix for this, but I've bisected some issues seen on v4.10+ with a Chromebook of the Veyron family (Jaq, in particular). v4.9 works fine.

Does your v4.10+ kernel have these commits?

commit e9748e0364fe82dc037d22900ff13a62d04518bf

Author: Ziyuan Xu <[email protected]>
Date:   Tue Jan 17 09:22:56 2017 +0800

mmc: dw_mmc: force setup bus if active slots exist

commit df9bcc2bc0a1f8d2963bd916698268fb2470713b

Author: Joonyoung Shim <[email protected]>
Date:   Fri Nov 25 12:47:15 2016 +0900

mmc: dw_mmc: add missing codes for runtime resume

commit ce69e2fea093b7fa3991c87849c4955cd47796c9

Author: Shawn Lin <[email protected]>
Date:   Tue Jan 17 09:22:55 2017 +0800

mmc: dw_mmc: silent verbose log when calling from PM context

Quoted 10 lines

Hi Brian,

Quoted 5 lines · Brian Norris

Hi all,

I haven't managed to get as far as a bugfix for this, but I've bisected some issues seen on v4.10+ with a Chromebook of the Veyron family (Jaq, in particular). v4.9 works fine.

Does your v4.10+ kernel have these commits?

By "4.10+", I meant that pure 4.10 is broken, as are all subsequent versions (e.g., 4.11-rc1).

Quoted 4 lines

commit e9748e0364fe82dc037d22900ff13a62d04518bf

Author: Ziyuan Xu <[email protected]>
Date:   Tue Jan 17 09:22:56 2017 +0800

Quoted 8 lines

mmc: dw_mmc: force setup bus if active slots exist

commit df9bcc2bc0a1f8d2963bd916698268fb2470713b

Author: Joonyoung Shim <[email protected]>
Date:   Fri Nov 25 12:47:15 2016 +0900

mmc: dw_mmc: add missing codes for runtime resume

'git describe' tells me these are in 4.10-rc1 and -rc6. So yes.

Quoted 5 lines

commit ce69e2fea093b7fa3991c87849c4955cd47796c9

Author: Shawn Lin <[email protected]>
Date:   Tue Jan 17 09:22:55 2017 +0800

mmc: dw_mmc: silent verbose log when calling from PM context

'git describe' tells me this is in 4.11-rc1, so no.

Brian

_______________________________________________
Linux-rockchip mailing list
[email protected]
http://lists.infradead.org/mailman/listinfo/linux-rockchip

I test on rk3288 firefly reload with 4.11-rc4. It work fine.

Quoted 9 lines · Shawn Lin

Quoted 8 lines

Hi Brian,

Quoted 5 lines · Brian Norris

Hi all,

I haven't managed to get as far as a bugfix for this, but I've bisected some issues seen on v4.10+ with a Chromebook of the Veyron family (Jaq, in particular). v4.9 works fine.

Hi Eddie,

Quoted 1 line · Eddie Cai

I test on rk3288 firefly reload with 4.11-rc4. It work fine.

OK, thanks for checking.

Quoted 9 lines

Quoted 9 lines · Shawn Lin

Quoted 8 lines

Hi Brian,

Quoted 5 lines · Brian Norris

Hi all,

I haven't managed to get as far as a bugfix for this, but I've bisected some issues seen on v4.10+ with a Chromebook of the Veyron family (Jaq, in particular). v4.9 works fine.

[...]

By the way, Kevin (CC'd) says he noticed similiar Wifi issues on an Exynos 5800 Peach chromebook, but not on an Exynos 5250 Snow chromebook. I haven't picked these apart yet to see what the differences and similarities are, but presumably it's not actually a Rockchip-specific bug. Maybe related to the way power sequencing is plumbed for these, for example?

Brian

Quoted 17 lines · Brian Norris

Quoted 1 line · Eddie Cai

I test on rk3288 firefly reload with 4.11-rc4. It work fine.

OK, thanks for checking.

Quoted 9 lines

Quoted 9 lines · Shawn Lin

Quoted 8 lines

Hi Brian,

Quoted 5 lines · Brian Norris

Hi all,

I haven't managed to get as far as a bugfix for this, but I've bisected some issues seen on v4.10+ with a Chromebook of the Veyron family (Jaq, in particular). v4.9 works fine.

[...]

Quoted 6 lines

By the way, Kevin (CC'd) says he noticed similiar Wifi issues on an Exynos 5800 Peach chromebook, but not on an Exynos 5250 Snow chromebook. I haven't picked these apart yet to see what the differences and similarities are, but presumably it's not actually a Rockchip-specific bug. Maybe related to the way power sequencing is plumbed for these, for example?

I'm not sure but if card-detecting is polling, the timing issue could be occurred.

Hi,

Quoted 25 lines · Jaehoon Chung

Quoted 23 lines · Brian Norris

Quoted 1 line · Eddie Cai

I test on rk3288 firefly reload with 4.11-rc4. It work fine.

OK, thanks for checking.

Quoted 9 lines

Quoted 9 lines · Shawn Lin

Quoted 8 lines

Hi Brian,

Quoted 5 lines · Brian Norris

Hi all,

I haven't managed to get as far as a bugfix for this, but I've bisected some issues seen on v4.10+ with a Chromebook of the Veyron family (Jaq, in particular). v4.9 works fine.

[...]

By the way, Kevin (CC'd) says he noticed similiar Wifi issues on an Exynos 5800 Peach chromebook, but not on an Exynos 5250 Snow chromebook. I haven't picked these apart yet to see what the differences and similarities are, but presumably it's not actually a Rockchip-specific bug. Maybe related to the way power sequencing is plumbed for these, for example?

Quoted 1 line

I'm not sure but if card-detecting is polling, the timing issue could be occurred.

I don't know much about MMC in general, nor about this driver. Any chance you'd accept reverts of the patches in question though? This is a huge regression, and there were only a few relevant changes that seem to have triggered this. I can try to come up with something targeted, but I'm not going to even try if that'd get rejected up front.

Brian

Hi,

Quoted 25 lines · Jaehoon Chung

Quoted 23 lines · Brian Norris

Quoted 1 line · Eddie Cai

I test on rk3288 firefly reload with 4.11-rc4. It work fine.

OK, thanks for checking.

Quoted 9 lines

Quoted 9 lines · Shawn Lin

Quoted 8 lines

Hi Brian,

Quoted 5 lines · Brian Norris

Hi all,

I haven't managed to get as far as a bugfix for this, but I've bisected some issues seen on v4.10+ with a Chromebook of the Veyron family (Jaq, in particular). v4.9 works fine.

[...]

By the way, Kevin (CC'd) says he noticed similiar Wifi issues on an Exynos 5800 Peach chromebook, but not on an Exynos 5250 Snow chromebook. I haven't picked these apart yet to see what the differences and similarities are, but presumably it's not actually a Rockchip-specific bug. Maybe related to the way power sequencing is plumbed for these, for example?

Quoted 1 line

I'm not sure but if card-detecting is polling, the timing issue could be occurred.

I don't know much about MMC in general, nor about this driver. Any chance you'd accept reverts of the patches in question though? This is a huge regression, and there were only a few relevant changes that seem to have triggered this. I can try to come up with something targeted, but I'm not going to even try if that'd get rejected up front.

Brian

Hi Brian,

Quoted 28 lines · Brian Norris

Hi,

Quoted 25 lines · Jaehoon Chung

Quoted 23 lines · Brian Norris

Quoted 1 line · Eddie Cai

I test on rk3288 firefly reload with 4.11-rc4. It work fine.

OK, thanks for checking.

Quoted 9 lines

Quoted 9 lines · Shawn Lin

Quoted 8 lines

Hi Brian,

Quoted 5 lines · Brian Norris

Hi all,

I haven't managed to get as far as a bugfix for this, but I've bisected some issues seen on v4.10+ with a Chromebook of the Veyron family (Jaq, in particular). v4.9 works fine.

[...]

By the way, Kevin (CC'd) says he noticed similiar Wifi issues on an Exynos 5800 Peach chromebook, but not on an Exynos 5250 Snow chromebook. I haven't picked these apart yet to see what the differences and similarities are, but presumably it's not actually a Rockchip-specific bug. Maybe related to the way power sequencing is plumbed for these, for example?

Quoted 7 lines

Quoted 1 line

I'm not sure but if card-detecting is polling, the timing issue could be occurred.

I don't know much about MMC in general, nor about this driver. Any chance you'd accept reverts of the patches in question though? This is a huge regression, and there were only a few relevant changes that seem to have triggered this. I can try to come up with something targeted, but I'm not going to even try if that'd get rejected up front.

Untile now, none of my(and my colleagues') rockchip platforms are able to reproduce this issue, so I can't tell what exactly the problem is. However, I noticed you mentioned that the Exynos platforms are also affected by rpm of dwmmc. I don't see dw_mmc-exynos enable this feature, so it looks quite odd to me!

Can I or Eddie get a Veyron board to help you debug it?

Quoted 5 lines

Brian

Signature · 3 lines

To unsubscribe from this list: send the line "unsubscribe linux-mmc" in
the body of a message to [email protected]
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Hi all,

I haven't managed to get as far as a bugfix for this, but I've bisected some issues seen on v4.10+ with a Chromebook of the Veyron family (Jaq, in particular). v4.9 works fine.

Issue #1 - eMMC complains periodically:

[    4.358135] mmc_host mmc2: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[    4.461466] mmc_host mmc2: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[    5.291450] mmc_host mmc2: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[    5.381471] mmc_host mmc2: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[   11.243337] mmc_host mmc2: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[   17.371628] mmc_host mmc2: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)

and if I stress it out at all (e.g., dd if=/dev/mmcblk2 bs=1M > /dev/null), it will eventually croak:

[  359.916315] mmc_host mmc2: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[  360.071378] dwmmc_rockchip ff0f0000.dwmmc: Successfully tuned phase to 153
[  360.211351] mmcblk2: error -110 transferring data, sector 8644608, nr 2048, cmd response 0x900, card status 0x0
[  360.221936] mmcblk2: retrying using single block read
[  363.491362] mmcblk2: error -110 transferring data, sector 8646656, nr 2048, cmd response 0x900, card status 0x0
[  363.531569] mmc_host mmc2: Bus speed (slot 0) = 400000Hz (slot req 400000Hz, actual 400000HZ div = 0)
[  363.596326] mmc_host mmc2: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[  363.612712] dwmmc_rockchip ff0f0000.dwmmc: Successfully tuned phase to 152
[  363.751351] mmcblk2: error -110 transferring data, sector 8646656, nr 2048, cmd response 0x900, card status 0x0
[  363.761938] mmcblk2: retrying using single block read
[  366.611356] INFO: task mmcqd/2boot1:92 blocked for more than 120 seconds.
[  366.618134]       Not tainted 4.10.0 #284
[  366.622146] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

[  366.629960] mmcqd/2boot1    D    0    92      2 0x00000000
[  366.635454] [<c07dc21c>] (__schedule) from [<c07dc4e0>] (schedule+0x90/0xa0)
[  366.642497] [<c07dc4e0>] (schedule) from [<c066e8b4>] (__mmc_claim_host+0xd4/0x19c)
[  366.650142] [<c066e8b4>] (__mmc_claim_host) from [<c066e9ac>] (mmc_get_card+0x30/0x34)
[  366.658056] [<c066e9ac>] (mmc_get_card) from [<c067fc8c>] (mmc_blk_issue_rq+0x64/0x48c)
[  366.666052] [<c067fc8c>] (mmc_blk_issue_rq) from [<c0680230>] (mmc_queue_thread+0x114/0x1b4)
[  366.674484] [<c0680230>] (mmc_queue_thread) from [<c023d1b0>] (kthread+0x128/0x144)
[  366.682134] [<c023d1b0>] (kthread) from [<c02076e8>] (ret_from_fork+0x14/0x2c)

Issue #2 - Wifi (via SDIO, mmc1) is completely dead:

[    1.444125] mmc_host mmc1: card is non-removable.
[    1.471368] mmc_host mmc1: Bus speed (slot 0) = 400000Hz (slot req 400000Hz, actual 400000HZ div = 0)
[    1.619553] mmc_host mmc1: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[    1.881699] mmc1: new ultra high speed SDR104 SDIO card at address 0001
[   25.681172] mmc_host mmc1: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[   25.691666] mwifiex: rx work enabled, cpus 4
[   26.827000] mwifiex_sdio mmc1:0001:1: info: FW download over, size 800344 bytes
[   27.561352] mwifiex_sdio mmc1:0001:1: WLAN FW is active
[   33.585165] mmc_host mmc1: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[   37.651344] mwifiex_sdio mmc1:0001:1: mwifiex_cmd_timeout_func: Timeout cmd id = 0xa9, act = 0x0
[   37.660122] mwifiex_sdio mmc1:0001:1: num_data_h2c_failure = 0
[   37.665951] mwifiex_sdio mmc1:0001:1: num_cmd_h2c_failure = 0
[   37.671688] mwifiex_sdio mmc1:0001:1: is_cmd_timedout = 1
[   37.677076] mwifiex_sdio mmc1:0001:1: num_tx_timeout = 0
[   37.682380] mwifiex_sdio mmc1:0001:1: last_cmd_index = 1
[   37.687681] mwifiex_sdio mmc1:0001:1: last_cmd_id: 00 00 a9 00 00 00 00 00 00 00
[   37.695066] mwifiex_sdio mmc1:0001:1: last_cmd_act: 00 00 00 00 00 00 00 00 00 00

[   37.702536] mwifiex_sdio mmc1:0001:1: last_cmd_resp_index = 0
[   37.708269] mwifiex_sdio mmc1:0001:1: last_cmd_resp_id: 00 00 00 00 00 00 00 00 00 00
[   37.716087] mwifiex_sdio mmc1:0001:1: last_event_index = 0
[   37.721564] mwifiex_sdio mmc1:0001:1: last_event: 00 00 00 00 00 00 00 00 00 00
[   37.728857] mwifiex_sdio mmc1:0001:1: data_sent=1 cmd_sent=0
[   37.734508] mwifiex_sdio mmc1:0001:1: ps_mode=0 ps_state=0
[   37.740016] mmc_host mmc1: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[   37.750268] mwifiex_sdio mmc1:0001:1: info: mwifiex_fw_dpc: unregister device

Quoted 20 lines

Issue #2 - Wifi (via SDIO, mmc1) is completely dead:

[    1.444125] mmc_host mmc1: card is non-removable.
[    1.471368] mmc_host mmc1: Bus speed (slot 0) = 400000Hz (slot req 400000Hz, actual 400000HZ div = 0)
[    1.619553] mmc_host mmc1: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[    1.881699] mmc1: new ultra high speed SDR104 SDIO card at address 0001
[   25.681172] mmc_host mmc1: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[   25.691666] mwifiex: rx work enabled, cpus 4
[   26.827000] mwifiex_sdio mmc1:0001:1: info: FW download over, size 800344 bytes
[   27.561352] mwifiex_sdio mmc1:0001:1: WLAN FW is active
[   33.585165] mmc_host mmc1: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[   37.651344] mwifiex_sdio mmc1:0001:1: mwifiex_cmd_timeout_func: Timeout cmd id = 0xa9, act = 0x0
[   37.660122] mwifiex_sdio mmc1:0001:1: num_data_h2c_failure = 0
[   37.665951] mwifiex_sdio mmc1:0001:1: num_cmd_h2c_failure = 0
[   37.671688] mwifiex_sdio mmc1:0001:1: is_cmd_timedout = 1
[   37.677076] mwifiex_sdio mmc1:0001:1: num_tx_timeout = 0
[   37.682380] mwifiex_sdio mmc1:0001:1: last_cmd_index = 1
[   37.687681] mwifiex_sdio mmc1:0001:1: last_cmd_id: 00 00 a9 00 00 00 00 00 00 00
[   37.695066] mwifiex_sdio mmc1:0001:1: last_cmd_act: 00 00 00 00 00 00 00 00 00 00

Quoted 8 lines

[   37.702536] mwifiex_sdio mmc1:0001:1: last_cmd_resp_index = 0
[   37.708269] mwifiex_sdio mmc1:0001:1: last_cmd_resp_id: 00 00 00 00 00 00 00 00 00 00
[   37.716087] mwifiex_sdio mmc1:0001:1: last_event_index = 0
[   37.721564] mwifiex_sdio mmc1:0001:1: last_event: 00 00 00 00 00 00 00 00 00 00
[   37.728857] mwifiex_sdio mmc1:0001:1: data_sent=1 cmd_sent=0
[   37.734508] mwifiex_sdio mmc1:0001:1: ps_mode=0 ps_state=0
[   37.740016] mmc_host mmc1: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[   37.750268] mwifiex_sdio mmc1:0001:1: info: mwifiex_fw_dpc: unregister device

This doesn't surprise me at all. What surprises me, though, is that nobody else seems to be able to reproduce this.

On veyron, WiFi is connected via SDIO. For good speed, it uses SDIO Interrupts. See this bit in the device tree:

cap-sdio-irq;

SDIO interrupts (in 4-bit mode) specifically need the card clock to be running all the time to work. I can reproduce your regression (on veryron-jerry, which also has Marvell WiFi) and I can also find that the regression is "gone' if I take out the "cap-sdio-irq" in the veyron device tree. Ah, interestingly enough, turning off SDIO interrupts has the side effect of sending enough (polling) traffic that we never seem to runtime suspend, either. ;-P

In general I'd question whether dw_mmc actually gets much power benefit from Runtime PM in Linux. The dw_mmc IP blocks already have a feature in them to automatically stop and restart the card clock. See SDMMC_CLKEN_LOW_PWR. Maybe you're getting the benefit of turning off VMMC or VQMMC? Is that really a lot of power? Presumably those power savings would be for eMMC or normal SD cards (not SDIO).

Maybe someone else on this thread knows how Runtime PM is supposed to work in general for SDIO? I notice that in sdio.c the mmc_sdio_runtime_suspend() unconditionally calls mmc_power_off(). That seems odd since the main mmc_sdio_suspend() _doesn't_ call it if mmc_card_keep_power(). Hrmmm...

OK, so I just tried this on veyron-minnie. On minnie we have Broadcom WiFi. That actually works (!). Presumably this is because brcmf_sdiod_host_fixup() calls pm_runtime_forbid(). Commenting that out breaks things.

OK, and I can make Marvell work by adding "pm_runtime_forbid(func->card->host->parent);" to the end of mwifiex_sdio_probe().

--

So where does that leave us?

A) Technically we can fix Marvell's driver to work like Broadcom's. One could possibly assert that this is the wrong fix because technically we could make Runtime PM work with SDIO with enough work. We could theoretically move into 1-bit mode and there (I think) you can get interrupts with the clock off. ...or we could have a dedicated SDIO Interrupt pin (for the embedded case), which is talked about in the SDIO spec.

B) Technically we could hack this in the dw_mmc code to disable Runtime PM if we see that an SDIO interrupt is used. One advantage of doing it here is that if we ever add support in dw_mmc for the external SDIO interrupt we could allow Runtime PM in that case. In theory the dw_mmc IP block has some basic support for a dedicated SDIO interrupt pin, but there's no code to support it.

C) Technically we could add this into the MMC core.

D) Technically we could remove Runtime PM support from dw_mmc for now until someone can address all these issues (and ideally show a real power savings).

I'd tend to vote for D, but I've been pretty absent from dw_mmc for a long time, so probably my vote isn't worth that much...

Shawn: I think you actually enabled runtime PM. Did you really see power savings, or did it just seem like enabling Runtime PM would be a neat thing to do?

-Doug

[...]

Quoted 29 lines

Quoted 20 lines

Issue #2 - Wifi (via SDIO, mmc1) is completely dead:

[    1.444125] mmc_host mmc1: card is non-removable.
[    1.471368] mmc_host mmc1: Bus speed (slot 0) = 400000Hz (slot req 400000Hz, actual 400000HZ div = 0)
[    1.619553] mmc_host mmc1: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[    1.881699] mmc1: new ultra high speed SDR104 SDIO card at address 0001
[   25.681172] mmc_host mmc1: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[   25.691666] mwifiex: rx work enabled, cpus 4
[   26.827000] mwifiex_sdio mmc1:0001:1: info: FW download over, size 800344 bytes
[   27.561352] mwifiex_sdio mmc1:0001:1: WLAN FW is active
[   33.585165] mmc_host mmc1: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[   37.651344] mwifiex_sdio mmc1:0001:1: mwifiex_cmd_timeout_func: Timeout cmd id = 0xa9, act = 0x0
[   37.660122] mwifiex_sdio mmc1:0001:1: num_data_h2c_failure = 0
[   37.665951] mwifiex_sdio mmc1:0001:1: num_cmd_h2c_failure = 0
[   37.671688] mwifiex_sdio mmc1:0001:1: is_cmd_timedout = 1
[   37.677076] mwifiex_sdio mmc1:0001:1: num_tx_timeout = 0
[   37.682380] mwifiex_sdio mmc1:0001:1: last_cmd_index = 1
[   37.687681] mwifiex_sdio mmc1:0001:1: last_cmd_id: 00 00 a9 00 00 00 00 00 00 00
[   37.695066] mwifiex_sdio mmc1:0001:1: last_cmd_act: 00 00 00 00 00 00 00 00 00 00

Quoted 8 lines

[   37.702536] mwifiex_sdio mmc1:0001:1: last_cmd_resp_index = 0
[   37.708269] mwifiex_sdio mmc1:0001:1: last_cmd_resp_id: 00 00 00 00 00 00 00 00 00 00
[   37.716087] mwifiex_sdio mmc1:0001:1: last_event_index = 0
[   37.721564] mwifiex_sdio mmc1:0001:1: last_event: 00 00 00 00 00 00 00 00 00 00
[   37.728857] mwifiex_sdio mmc1:0001:1: data_sent=1 cmd_sent=0
[   37.734508] mwifiex_sdio mmc1:0001:1: ps_mode=0 ps_state=0
[   37.740016] mmc_host mmc1: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[   37.750268] mwifiex_sdio mmc1:0001:1: info: mwifiex_fw_dpc: unregister device

Quoted 2 lines

This doesn't surprise me at all. What surprises me, though, is that nobody else seems to be able to reproduce this.

Me too.

As I have stated several times, the PM code for SDIO is fragile/broken for many scenarios. This is just one case.

Quoted 6 lines

On veyron, WiFi is connected via SDIO. For good speed, it uses SDIO Interrupts. See this bit in the device tree:

cap-sdio-irq;

Quoted 7 lines

SDIO interrupts (in 4-bit mode) specifically need the card clock to be running all the time to work. I can reproduce your regression (on veryron-jerry, which also has Marvell WiFi) and I can also find that the regression is "gone' if I take out the "cap-sdio-irq" in the veyron device tree. Ah, interestingly enough, turning off SDIO interrupts has the side effect of sending enough (polling) traffic that we never seem to runtime suspend, either. ;-P

We did a similar fix for sdhci recently. Simply, in cases when sdio IRQ is turned on, we call pm_runtime_get_noresume() to prevent the device from being runtime suspended.

Quoted 6 lines

In general I'd question whether dw_mmc actually gets much power benefit from Runtime PM in Linux. The dw_mmc IP blocks already have a feature in them to automatically stop and restart the card clock. See SDMMC_CLKEN_LOW_PWR. Maybe you're getting the benefit of turning off VMMC or VQMMC? Is that really a lot of power? Presumably those power savings would be for eMMC or normal SD cards (not SDIO).

I think that depends on the PM topology of the SoC. Perhaps the dw_mmc devices are in PM domains sharing power rails etc, and preventing runtime PM could be very costly as it then prevent those shared resources to be put into low power state.

Hi,

Quoted 5 lines · Brian Norris

Hi all,

I haven't managed to get as far as a bugfix for this, but I've bisected some issues seen on v4.10+ with a Chromebook of the Veyron family (Jaq, in particular). v4.9 works fine.

OK, I finally got everything up and running to test this too...

Quoted 8 lines

Issue #1 - eMMC complains periodically:

[    4.358135] mmc_host mmc2: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[    4.461466] mmc_host mmc2: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[    5.291450] mmc_host mmc2: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[    5.381471] mmc_host mmc2: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[   11.243337] mmc_host mmc2: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[   17.371628] mmc_host mmc2: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)

I don't believe that this is an error, actually. Really we just need to quiet this message or (since I've always found it useful) move it to a different place. I believe that with runtime PM we're effectively turning the clock off whenever the MMC device isn't in use. On dw_mmc we have a "helpful" printout every time the clock is changed, and that's what you're seeing here.

You can see with:

while true; do
dd if=/dev/mmcblk2 of=/dev/null bs=512 count=1 iflag=direct; sleep .1;
done

...that you'll get a printout every 100ms.

Ah, looks like this is in:

ce69e2fea093 mmc: dw_mmc: silent verbose log when calling from PM context

...as pointed out by Shawn Lin. So I think in 4.10 we can just ignore those messages and they're good on 4.11.

Quoted 16 lines

and if I stress it out at all (e.g., dd if=/dev/mmcblk2 bs=1M > /dev/null), it will eventually croak:

[  359.916315] mmc_host mmc2: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[  360.071378] dwmmc_rockchip ff0f0000.dwmmc: Successfully tuned phase to 153
[  360.211351] mmcblk2: error -110 transferring data, sector 8644608, nr 2048, cmd response 0x900, card status 0x0
[  360.221936] mmcblk2: retrying using single block read
[  363.491362] mmcblk2: error -110 transferring data, sector 8646656, nr 2048, cmd response 0x900, card status 0x0
[  363.531569] mmc_host mmc2: Bus speed (slot 0) = 400000Hz (slot req 400000Hz, actual 400000HZ div = 0)
[  363.596326] mmc_host mmc2: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[  363.612712] dwmmc_rockchip ff0f0000.dwmmc: Successfully tuned phase to 152
[  363.751351] mmcblk2: error -110 transferring data, sector 8646656, nr 2048, cmd response 0x900, card status 0x0
[  363.761938] mmcblk2: retrying using single block read
[  366.611356] INFO: task mmcqd/2boot1:92 blocked for more than 120 seconds.
[  366.618134]       Not tainted 4.10.0 #284
[  366.622146] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

Quoted 8 lines

[  366.629960] mmcqd/2boot1    D    0    92      2 0x00000000
[  366.635454] [<c07dc21c>] (__schedule) from [<c07dc4e0>] (schedule+0x90/0xa0)
[  366.642497] [<c07dc4e0>] (schedule) from [<c066e8b4>] (__mmc_claim_host+0xd4/0x19c)
[  366.650142] [<c066e8b4>] (__mmc_claim_host) from [<c066e9ac>] (mmc_get_card+0x30/0x34)
[  366.658056] [<c066e9ac>] (mmc_get_card) from [<c067fc8c>] (mmc_blk_issue_rq+0x64/0x48c)
[  366.666052] [<c067fc8c>] (mmc_blk_issue_rq) from [<c0680230>] (mmc_queue_thread+0x114/0x1b4)
[  366.674484] [<c0680230>] (mmc_queue_thread) from [<c023d1b0>] (kthread+0x128/0x144)
[  366.682134] [<c023d1b0>] (kthread) from [<c02076e8>] (ret_from_fork+0x14/0x2c)

I'm not convinced this is a regression.

I remember Heiko saying that he's heard reports that on some boards eMMC doesn't work with high speed, and I'be believe that's what you're seeing here. It would be interesting to try to debug this. I can't personally reproduce, though.

I think veyron_minnie already has UHS turned off for eMMC upstream. I guess we could do it for other veyron boards too until someone can debug?

Quoted 19 lines

Issue #2 - Wifi (via SDIO, mmc1) is completely dead:

[    1.444125] mmc_host mmc1: card is non-removable.
[    1.471368] mmc_host mmc1: Bus speed (slot 0) = 400000Hz (slot req 400000Hz, actual 400000HZ div = 0)
[    1.619553] mmc_host mmc1: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[    1.881699] mmc1: new ultra high speed SDR104 SDIO card at address 0001
[   25.681172] mmc_host mmc1: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[   25.691666] mwifiex: rx work enabled, cpus 4
[   26.827000] mwifiex_sdio mmc1:0001:1: info: FW download over, size 800344 bytes
[   27.561352] mwifiex_sdio mmc1:0001:1: WLAN FW is active
[   33.585165] mmc_host mmc1: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[   37.651344] mwifiex_sdio mmc1:0001:1: mwifiex_cmd_timeout_func: Timeout cmd id = 0xa9, act = 0x0
[   37.660122] mwifiex_sdio mmc1:0001:1: num_data_h2c_failure = 0
[   37.665951] mwifiex_sdio mmc1:0001:1: num_cmd_h2c_failure = 0
[   37.671688] mwifiex_sdio mmc1:0001:1: is_cmd_timedout = 1
[   37.677076] mwifiex_sdio mmc1:0001:1: num_tx_timeout = 0
[   37.682380] mwifiex_sdio mmc1:0001:1: last_cmd_index = 1
[   37.687681] mwifiex_sdio mmc1:0001:1: last_cmd_id: 00 00 a9 00 00 00 00 00 00 00
[   37.695066] mwifiex_sdio mmc1:0001:1: last_cmd_act: 00 00 00 00 00 00 00 00 00 00

Quoted 8 lines

[   37.702536] mwifiex_sdio mmc1:0001:1: last_cmd_resp_index = 0
[   37.708269] mwifiex_sdio mmc1:0001:1: last_cmd_resp_id: 00 00 00 00 00 00 00 00 00 00
[   37.716087] mwifiex_sdio mmc1:0001:1: last_event_index = 0
[   37.721564] mwifiex_sdio mmc1:0001:1: last_event: 00 00 00 00 00 00 00 00 00 00
[   37.728857] mwifiex_sdio mmc1:0001:1: data_sent=1 cmd_sent=0
[   37.734508] mwifiex_sdio mmc1:0001:1: ps_mode=0 ps_state=0
[   37.740016] mmc_host mmc1: Bus speed (slot 0) = 148500000Hz (slot req 150000000Hz, actual 148500000HZ div = 0)
[   37.750268] mwifiex_sdio mmc1:0001:1: info: mwifiex_fw_dpc: unregister device

This doesn't surprise me at all. What surprises me, though, is that nobody else seems to be able to reproduce this.

On veyron, WiFi is connected via SDIO. For good speed, it uses SDIO Interrupts. See this bit in the device tree:

cap-sdio-irq;

SDIO interrupts (in 4-bit mode) specifically need the card clock to be running all the time to work. I can reproduce your regression (on veryron-jerry, which also has Marvell WiFi) and I can also find that the regression is "gone' if I take out the "cap-sdio-irq" in the veyron device tree. Ah, interestingly enough, turning off SDIO interrupts has the side effect of sending enough (polling) traffic that we never seem to runtime suspend, either. ;-P

In general I'd question whether dw_mmc actually gets much power benefit from Runtime PM in Linux. The dw_mmc IP blocks already have a feature in them to automatically stop and restart the card clock. See SDMMC_CLKEN_LOW_PWR. Maybe you're getting the benefit of turning off VMMC or VQMMC? Is that really a lot of power? Presumably those power savings would be for eMMC or normal SD cards (not SDIO).

Maybe someone else on this thread knows how Runtime PM is supposed to work in general for SDIO? I notice that in sdio.c the mmc_sdio_runtime_suspend() unconditionally calls mmc_power_off(). That seems odd since the main mmc_sdio_suspend() _doesn't_ call it if mmc_card_keep_power(). Hrmmm...

OK, so I just tried this on veyron-minnie. On minnie we have Broadcom WiFi. That actually works (!). Presumably this is because brcmf_sdiod_host_fixup() calls pm_runtime_forbid(). Commenting that out breaks things.

OK, and I can make Marvell work by adding "pm_runtime_forbid(func->card->host->parent);" to the end of mwifiex_sdio_probe().

--

So where does that leave us?

A) Technically we can fix Marvell's driver to work like Broadcom's. One could possibly assert that this is the wrong fix because technically we could make Runtime PM work with SDIO with enough work. We could theoretically move into 1-bit mode and there (I think) you can get interrupts with the clock off. ...or we could have a dedicated SDIO Interrupt pin (for the embedded case), which is talked about in the SDIO spec.

B) Technically we could hack this in the dw_mmc code to disable Runtime PM if we see that an SDIO interrupt is used. One advantage of doing it here is that if we ever add support in dw_mmc for the external SDIO interrupt we could allow Runtime PM in that case. In theory the dw_mmc IP block has some basic support for a dedicated SDIO interrupt pin, but there's no code to support it.

C) Technically we could add this into the MMC core.

D) Technically we could remove Runtime PM support from dw_mmc for now until someone can address all these issues (and ideally show a real power savings).

I'd tend to vote for D, but I've been pretty absent from dw_mmc for a long time, so probably my vote isn't worth that much...

Shawn: I think you actually enabled runtime PM. Did you really see power savings, or did it just seem like enabling Runtime PM would be a neat thing to do?

-Doug

Quoted 8 lines

This doesn't surprise me at all. What surprises me, though, is that nobody else seems to be able to reproduce this.

On veyron, WiFi is connected via SDIO. For good speed, it uses SDIO Interrupts. See this bit in the device tree:

cap-sdio-irq;

all of *my* boards are using side-band interrupt, so there are no "cap-sdio-irq".

Shawn

Quoted 11 lines · Shawn Lin

Quoted 8 lines

This doesn't surprise me at all. What surprises me, though, is that nobody else seems to be able to reproduce this.

On veyron, WiFi is connected via SDIO. For good speed, it uses SDIO Interrupts. See this bit in the device tree:

cap-sdio-irq;

all of *my* boards are using side-band interrupt, so there are no "cap-sdio-irq".

They are all using side-band interrupt? What WiFi device do you have connected?

If you're truly using a side-band interrupt using the dedicated SDIO interrupt pin on your SoC, I'm pretty sure you still need to define cap-sdio-irq in order for things to work properly. If you don't do that, you'll get "polling mode" for SDIO Interrupts. See sdio_irq_thread() where you can see that the kernel will poll your device every 10 ms if MMC_CAP_SDIO_IRQ isn't set.

Maybe you should try defining cap-sdio-irq and see if you get a big performance boost?

Quoted 15 lines · Doug Anderson

Shawn

Quoted 11 lines · Shawn Lin

Quoted 8 lines

This doesn't surprise me at all. What surprises me, though, is that nobody else seems to be able to reproduce this.

On veyron, WiFi is connected via SDIO. For good speed, it uses SDIO Interrupts. See this bit in the device tree:

cap-sdio-irq;

all of *my* boards are using side-band interrupt, so there are no "cap-sdio-irq".

Quoted 8 lines

They are all using side-band interrupt? What WiFi device do you have connected?

If you're truly using a side-band interrupt using the dedicated SDIO interrupt pin on your SoC, I'm pretty sure you still need to define cap-sdio-irq in order for things to work properly. If you don't do that, you'll get "polling mode" for SDIO Interrupts. See sdio_irq_thread() where you can see that the kernel will poll your device every 10 ms if MMC_CAP_SDIO_IRQ isn't set.

In these cases I would expect the WIFI driver to deal with the SDIO IRQ itself and not requesting it via calling sdio_claim_irq(). Because of this, there should be no polling performed by the sdio_irq_thread.

Quoted 2 lines

Maybe you should try defining cap-sdio-irq and see if you get a big performance boost?

No, that seems like a bad idea. I think it would rather add overhead - decreasing performance. Likely it will also make us wake up the mmc host from its low power state, when when it actually isn't needed.

Shawn

Quoted 6 lines · Shawn Lin

Quoted 6 lines

This doesn't surprise me at all. What surprises me, though, is that nobody else seems to be able to reproduce this.

On veyron, WiFi is connected via SDIO. For good speed, it uses SDIO Interrupts. See this bit in the device tree:

Quoted 5 lines

Quoted 2 lines

cap-sdio-irq;

all of *my* boards are using side-band interrupt, so there are no "cap-sdio-irq".

They are all using side-band interrupt? What WiFi device do you have connected?

If you're truly using a side-band interrupt using the dedicated SDIO interrupt pin on your SoC, I'm pretty sure you still need to define

cap-sdio-irq in order for things to work properly. If you don't do that, you'll get "polling mode" for SDIO Interrupts. See sdio_irq_thread() where you can see that the kernel will poll your device every 10 ms if MMC_CAP_SDIO_IRQ isn't set.

Maybe you should try defining cap-sdio-irq and see if you get a big performance boost?