On Wed, Mar 22, 2017 at 05:17:38PM +0100, Ludovic Desroches wrote: > On Wed, Mar 22, 2017 at 12:18:00PM +0100, Ulf Hansson wrote: > > [...] > > > > >> >> > > >> >> We had other reports for similar problems. The following change fix > > >> >> those issues, have you tried this out? > > >> >> > > >> >> [PATCH] mmc: core: Restore parts of the polling policy when switch to HS/HS DDR > > >> >> https://patchwork.kernel.org/patch/9515239/ > > >> > > > >> > I did the test with next and the behavior is the same. > > >> > > > >> > mmc0: Invalid UHS-I mode selected > > >> > mmc0: switch to bus width 8 ddr failed > > >> > mmc0: error -110 whilst initialising MMC card > > >> > > > >> > It seems the root cause is to perform mmc_set_timing before mmc_switch_status. > > >> > > >> Okay, I see! This sounds a bit weird. > > >> > > >> As you know, the CMD6 has been a problematic historically, mostly > > >> because of busy detection issues. We have now tried to make the code > > >> more robust in __mmc_switch() and its friends. > > >> That said, before considering to apply your fix, I would really like > > >> us to investigate this a bit more, to make sure we find the correct > > >> solution and of course to avoid regressions for other cases. > > >> > > >> Recently reported issues [1] that was observed for sdhci-esdc-imx, > > >> which has been fixed now, can be summarized in these two issues: > > >> > > >> *) Only 3.3V I/O voltage DDR mode was supported by the SoC. Still the > > >> mmc core tried to set 1.8V, which caused errors when switching to HS > > >> DDR mode. > > >> -> To fix this, we invented MMC_CAP_3_3V_DDR [2] and a corresponding > > >> DT binding ("mmc-ddr-3_3v"). Hosts/SoCs, that supports only 3.3V DDR > > >> mode, should set this. > > >> > > >> **). Changing host's timings couldn't be done while the card was busy, > > >> because of internal limitations by the sdhci-esdhc-imx controller. The > > >> consequence was that the following CMD13 command (to get the switch > > >> status), returned the error code -110, perhaps similar to your case. > > >> ->To fix this, we decided to move the update of the host's timing, to > > >> after we verified the card isn't being busy [3]. > > >> > > >> > > >> From your description to the problem you encounter, I would recommend > > >> the following debug steps to try to understand what really goes on. > > >> 1. > > >> Check if the 3.3V DDR issue is applicable for your case as well, and > > >> fix it if it is. > > > > > > There is a regulator driven by the sdhci controller to manage 3.3V and > > > 1.8V I/O voltage. > > > > > >> > > >> 2. > > >> Both sdhci-esdhc-imx and sdhci-of-at91, don't have > > >> MMC_CAP_WAIT_WHILE_BUSY set. However, both sdhci variants are using > > >> the ->card_busy() host ops (assigned to sdhci_card_busy()), which > > >> triggers __mmc_switch() to call mmc_poll_for_busy() when it switches > > >> to HS DDR mode (CMD6). Could it be that sdhci_card_busy() isn't > > >> working properly for sdhci-of-at91? This could lead to that that > > >> mmc_poll_for_busy() believes the card isn't busy, while it actually > > >> is. > > >> > > >> To check whether theory 2 stands, I would explore these debug alternatives. > > >> *) Remove the assignment of ->card_busy() in sdhci.c, which makes > > >> mmc_poll_for_busy() to use CMD13 polling instead. If this works, it > > >> would be useful to know how many times a CMD13 is sent to find out > > >> when card moves out of busy state. > > > > > > It doesn't work. > > > > Okay. So what kind of error do you get when sending the CMD13 to poll? -110? > > No error when I poll after CMD6. Here is a log with CMD13 to perform the > polling: > > mmc0: clock 52000000Hz busmode 2 powermode 2 cs 0 Vdd 21 width 8 timing 1 > mmc0: starting CMD8 arg 00000000 flags 000000b5 > mmc0: blksz 512 blocks 1 flags 00000200 tsac 400 ms nsac 1000 > mmc0: sdhci: IRQ status 0x00000001 > mmc0: sdhci: IRQ status 0x00000002 > mmc0: req done (CMD8): 0: 00000900 00000000 00000000 00000000 > mmc0: 512 bytes transferred: 0 > === mmc_select_hs_ddr: l.1072 === > --- __mmc_switch --- > __mmc_switch: mmc_wait_for_cmd > mmc0: starting CMD6 arg 03b70601 flags 0000049d > mmc0: sdhci: IRQ status 0x00000001 > mmc0: sdhci: IRQ status 0x00000002 > mmc0: req done (CMD6): 0: 00000800 00000000 00000000 00000000 > __mmc_switch: mmc_poll_for_busy > mmc0: starting CMD13 arg 00010000 flags 00000195 > mmc0: sdhci: IRQ status 0x00000001 > mmc0: req done (CMD13): 0: 00000900 00000000 00000000 00000000 > mmc_poll_for_busy: l.512 > __mmc_switch: mmc_set_timing > mmc0: clock 52000000Hz busmode 2 powermode 2 cs 0 Vdd 21 width 8 timing 8 > __mmc_switch: mmc_switch_status > mmc0: starting CMD13 arg 00010000 flags 00000195 > mmc0: sdhci: IRQ status 0x00038000 > mmc0: req failed (CMD13): -110, retrying... > mmc0: sdhci: IRQ status 0x00038000 > mmc0: req failed (CMD13): -110, retrying... > mmc0: sdhci: IRQ status 0x00038000 > mmc0: req failed (CMD13): -110, retrying... > mmc0: sdhci: IRQ status 0x00038000 > mmc0: req done (CMD13): -110: 00000000 00000000 00000000 00000000 > mmc0: clock 52000000Hz busmode 2 powermode 2 cs 0 Vdd 21 width 8 timing 1 > mmc0: Invalid UHS-I mode selected > mmc0: switch to bus width 8 ddr failed > mmc0: error -110 whilst initialising MMC card > mmc0: clock 0Hz busmode 2 powermode 0 cs 0 Vdd 0 width 1 timing 0 > > > > > > > > > >> **) While using ->card_busy(), I would just add some simple debug > > >> prints in mmc_poll_for_busy() to prints its return values. > > > > > > No error returned. I exit the function after the while loop. > > > > If I understand correctly, the ->card_busy() callbacks immediately > > reports the eMMC card as *not* being busy, right? > > Yes, with sdhci_card_busy() this time: > > === mmc_select_hs_ddr: l.1072 === > --- __mmc_switch --- > __mmc_switch: mmc_wait_for_cmd > mmc0: starting CMD6 arg 03b70601 flags 0000049d > mmc0: sdhci: IRQ status 0x00000001 > mmc0: sdhci: IRQ status 0x00000002 > mmc0: req done (CMD6): 0: 00000800 00000000 00000000 00000000 > __mmc_switch: mmc_poll_for_busy > mmc_poll_for_busy: ops->card_busy > mmc_poll_for_busy: l.513 > __mmc_switch: mmc_set_timing > mmc0: clock 52000000Hz busmode 2 powermode 2 cs 0 Vdd 21 width 8 timing 8 > __mmc_switch: mmc_switch_status > mmc0: starting CMD13 arg 00010000 flags 00000195 > mmc0: sdhci: IRQ status 0x00038000 > mmc0: req failed (CMD13): -110, retrying... > mmc0: sdhci: IRQ status 0x00038000 > mmc0: req failed (CMD13): -110, retrying... > mmc0: sdhci: IRQ status 0x00038000 > mmc0: req failed (CMD13): -110, retrying... > mmc0: sdhci: IRQ status 0x00038000 > mmc0: req done (CMD13): -110: 00000000 00000000 00000000 00000000 > mmc0: clock 52000000Hz busmode 2 powermode 2 cs 0 Vdd 21 width 8 timing 1 > mmc0: Invalid UHS-I mode selected > mmc0: switch to bus width 8 ddr failed > mmc0: error -110 whilst initialising MMC card > > > > > > > > > > I continue the investigation to figure out why calling mmc_set_timing before > > > mmc_switch_status causes an issue. > > > > Great! > > > > Please tell if you need some further help with some more ideas. > > Ok thanks. > > To compare, if I put mmc_set_timing after mmc_switch_status: I think I have found the root cause with the help of the hardware guy but there is still some block magic. sdhci_set_uhs_signaling configures the host with SDHCI_CTRL_UHS_DDR50 when we need MMC_TIMING_MMC_DDR52 or MMC_TIMING_MMC_DDR52. In my case, I have to configure another register to indicate we want to use MMC_DDR52. It seems we are the only one to do this. I am wondering how it is managed by other controllers. It seems this was the root cause. If I configure the other register, it works but I don't understand how it could work in the past. The explanation I get from the hardware guy is that the MMC_DDR52 timings are totally different from the UHS_DDR50 ones but the MMC_HS timings may work with the MMC_DDR52 ones. Before the CMD13 was sent with MMC_HS timings, now with MMC_DDR52 ones. It should explain the CMD13 issue but why next steps passed? The next CMD13 is triggered by the mmc_switch to enable HPI and it works as we can see in these logs: > > mmc0: clock 52000000Hz busmode 2 powermode 2 cs 0 Vdd 21 width 8 timing 1 > mmc0: starting CMD8 arg 00000000 flags 000000b5 > mmc0: blksz 512 blocks 1 flags 00000200 tsac 400 ms nsac 1000 > mmc0: sdhci: IRQ status 0x00000001 > mmc0: sdhci: IRQ status 0x00000002 > mmc0: req done (CMD8): 0: 00000900 00000000 00000000 00000000 > mmc0: 512 bytes transferred: 0 > === mmc_select_hs_ddr: l.1072 === > --- __mmc_switch --- > __mmc_switch: mmc_wait_for_cmd > mmc0: starting CMD6 arg 03b70601 flags 0000049d > mmc0: sdhci: IRQ status 0x00000001 > mmc0: sdhci: IRQ status 0x00000002 > mmc0: req done (CMD6): 0: 00000800 00000000 00000000 00000000 > __mmc_switch: mmc_poll_for_busy > mmc_poll_for_busy: ops->card_busy > mmc_poll_for_busy: l.513 > __mmc_switch: mmc_switch_status > mmc0: starting CMD13 arg 00010000 flags 00000195 > mmc0: sdhci: IRQ status 0x00000001 > mmc0: req done (CMD13): 0: 00000900 00000000 00000000 00000000 > __mmc_switch: mmc_set_timing > mmc0: clock 52000000Hz busmode 2 powermode 2 cs 0 Vdd 21 width 8 timing 8 > --- __mmc_switch --- > __mmc_switch: mmc_wait_for_cmd > mmc0: starting CMD6 arg 03a10101 flags 0000049d > mmc0: sdhci: IRQ status 0x00000001 > mmc0: sdhci: IRQ status 0x00000002 > mmc0: req done (CMD6): 0: 00000800 00000000 00000000 00000000 > __mmc_switch: mmc_poll_for_busy > mmc_poll_for_busy: ops->card_busy > mmc_poll_for_busy: l.513 > __mmc_switch: mmc_switch_status > mmc0: starting CMD13 arg 00010000 flags 00000195 > mmc0: sdhci: IRQ status 0x00000001 > mmc0: req done (CMD13): 0: 00000900 00000000 00000000 00000000 > mmc0: new DDR MMC card at address 0001 Regards Ludovic -- To unsubscribe from this list: send the line "unsubscribe linux-mmc" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
