Revert "mmc: core: do not retry CMD6 in __mmc_switch()"

Message ID	20190820114229.11948-1-ja.kaisrlik@gmail.com (mailing list archive)
State	New, archived
Headers	show Return-Path: <SRS0=Ymbj=WQ=vger.kernel.org=linux-mmc-owner@kernel.org> From: ja.kaisrlik@gmail.com To: linux-mmc@vger.kernel.org Cc: ulf.hansson@linaro.org, Jan Kaisrlik <ja.kaisrlik@gmail.com> Subject: [PATCH] Revert "mmc: core: do not retry CMD6 in __mmc_switch()" Date: Tue, 20 Aug 2019 13:42:29 +0200 Message-Id: <20190820114229.11948-1-ja.kaisrlik@gmail.com> MIME-Version: 1.0 Content-Transfer-Encoding: 8bit Sender: linux-mmc-owner@vger.kernel.org Precedence: bulk
Series	Revert "mmc: core: do not retry CMD6 in __mmc_switch()" \| expand Revert "mmc: core: do not retry CMD6 in __mmc_switch()"

Jan Kaisrlik Aug. 20, 2019, 11:42 a.m. UTC

From: Jan Kaisrlik <ja.kaisrlik@gmail.com>

This reverts commit 3a0681c7448b174e5dcfd19e9079cdd281c35f1a.

Turns out the patch breaks initialization of Toshiba THGBMNG5.
[    1.648951] mmc0: mmc_select_hs200 failed, error -84
[    1.648988] mmc0: error -84 whilst initialising MMC card

Signed-off-by: Jan Kaisrlik <ja.kaisrlik@gmail.com>
---
 drivers/mmc/core/mmc_ops.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

Ulf Hansson Aug. 21, 2019, 3:11 p.m. UTC | #1

+ Chaotian Jing

On Tue, 20 Aug 2019 at 13:42, <ja.kaisrlik@gmail.com> wrote:
>
> From: Jan Kaisrlik <ja.kaisrlik@gmail.com>
>
> This reverts commit 3a0681c7448b174e5dcfd19e9079cdd281c35f1a.
>
> Turns out the patch breaks initialization of Toshiba THGBMNG5.
> [    1.648951] mmc0: mmc_select_hs200 failed, error -84
> [    1.648988] mmc0: error -84 whilst initialising MMC card

For exactly this reason, when getting CRC errors on the first attempt,
doing a retry makes little sense.

I have looped in Chaotian who has some more details about the problem.

In any case, Jan, what HW and mmc controller are you using?

>
> Signed-off-by: Jan Kaisrlik <ja.kaisrlik@gmail.com>
> ---
>  drivers/mmc/core/mmc_ops.c | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
>
> diff --git a/drivers/mmc/core/mmc_ops.c b/drivers/mmc/core/mmc_ops.c
> index 74e4364bc9fb..09113b9ad679 100644
> --- a/drivers/mmc/core/mmc_ops.c
> +++ b/drivers/mmc/core/mmc_ops.c
> @@ -564,7 +564,7 @@ int __mmc_switch(struct mmc_card *card, u8 set, u8 index, u8 value,
>         if (index == EXT_CSD_SANITIZE_START)
>                 cmd.sanitize_busy = true;
>
> -       err = mmc_wait_for_cmd(host, &cmd, 0);
> +       err = mmc_wait_for_cmd(host, &cmd, MMC_CMD_RETRIES);
>         if (err)
>                 goto out;
>
> --
> 2.20.1
>

Kind regards
Uffe

Jan Kaisrlik Aug. 22, 2019, 8:27 a.m. UTC | #2

st 21. 8. 2019 v 17:12 odesílatel Ulf Hansson <ulf.hansson@linaro.org> napsal:
>
> + Chaotian Jing
>
> On Tue, 20 Aug 2019 at 13:42, <ja.kaisrlik@gmail.com> wrote:
> >
> > From: Jan Kaisrlik <ja.kaisrlik@gmail.com>
> >
> > This reverts commit 3a0681c7448b174e5dcfd19e9079cdd281c35f1a.
> >
> > Turns out the patch breaks initialization of Toshiba THGBMNG5.
> > [    1.648951] mmc0: mmc_select_hs200 failed, error -84
> > [    1.648988] mmc0: error -84 whilst initialising MMC card
>
> For exactly this reason, when getting CRC errors on the first attempt,
> doing a retry makes little sense.
>
> I have looped in Chaotian who has some more details about the problem.
>
> In any case, Jan, what HW and mmc controller are you using?

It's a custom board based on Amlogic A113D. The compatibility in dts
is set to "alogic,meson-axg-mmc".

In the different revision of HW we are using Kingston EMMC04G. The
card has no such problem and is working fine without this patch.
We observed it only on mention Toshiba card.

Best regards,
Jan

>
> >
> > Signed-off-by: Jan Kaisrlik <ja.kaisrlik@gmail.com>
> > ---
> >  drivers/mmc/core/mmc_ops.c | 2 +-
> >  1 file changed, 1 insertion(+), 1 deletion(-)
> >
> > diff --git a/drivers/mmc/core/mmc_ops.c b/drivers/mmc/core/mmc_ops.c
> > index 74e4364bc9fb..09113b9ad679 100644
> > --- a/drivers/mmc/core/mmc_ops.c
> > +++ b/drivers/mmc/core/mmc_ops.c
> > @@ -564,7 +564,7 @@ int __mmc_switch(struct mmc_card *card, u8 set, u8 index, u8 value,
> >         if (index == EXT_CSD_SANITIZE_START)
> >                 cmd.sanitize_busy = true;
> >
> > -       err = mmc_wait_for_cmd(host, &cmd, 0);
> > +       err = mmc_wait_for_cmd(host, &cmd, MMC_CMD_RETRIES);
> >         if (err)
> >                 goto out;
> >
> > --
> > 2.20.1
> >
>
> Kind regards
> Uffe

Ulf Hansson Aug. 22, 2019, 1:59 p.m. UTC | #3

+ some meson driver folkz

On Thu, 22 Aug 2019 at 10:27, Jan Kaisrlik <ja.kaisrlik@gmail.com> wrote:
>
> st 21. 8. 2019 v 17:12 odesílatel Ulf Hansson <ulf.hansson@linaro.org> napsal:
> >
> > + Chaotian Jing
> >
> > On Tue, 20 Aug 2019 at 13:42, <ja.kaisrlik@gmail.com> wrote:
> > >
> > > From: Jan Kaisrlik <ja.kaisrlik@gmail.com>
> > >
> > > This reverts commit 3a0681c7448b174e5dcfd19e9079cdd281c35f1a.
> > >
> > > Turns out the patch breaks initialization of Toshiba THGBMNG5.
> > > [    1.648951] mmc0: mmc_select_hs200 failed, error -84
> > > [    1.648988] mmc0: error -84 whilst initialising MMC card
> >
> > For exactly this reason, when getting CRC errors on the first attempt,
> > doing a retry makes little sense.
> >
> > I have looped in Chaotian who has some more details about the problem.
> >
> > In any case, Jan, what HW and mmc controller are you using?
>
> It's a custom board based on Amlogic A113D. The compatibility in dts
> is set to "alogic,meson-axg-mmc".

Good. I have looped in some of the relevant developers/maintainers.

>
> In the different revision of HW we are using Kingston EMMC04G. The
> card has no such problem and is working fine without this patch.
> We observed it only on mention Toshiba card.

I see. Of course it would also be interesting to see what CMD6 command
that is that fails. Would you mind adding some debug/trace to find out
what command it is that fails?

[...]

Kind regards
Uffe

Jan Kaisrlik Aug. 23, 2019, 9:36 a.m. UTC | #4

čt 22. 8. 2019 v 15:59 odesílatel Ulf Hansson <ulf.hansson@linaro.org> napsal:
>
> + some meson driver folkz
>
> On Thu, 22 Aug 2019 at 10:27, Jan Kaisrlik <ja.kaisrlik@gmail.com> wrote:
> >
> > st 21. 8. 2019 v 17:12 odesílatel Ulf Hansson <ulf.hansson@linaro.org> napsal:
> > >
> > > + Chaotian Jing
> > >
> > > On Tue, 20 Aug 2019 at 13:42, <ja.kaisrlik@gmail.com> wrote:
> > > >
> > > > From: Jan Kaisrlik <ja.kaisrlik@gmail.com>
> > > >
> > > > This reverts commit 3a0681c7448b174e5dcfd19e9079cdd281c35f1a.
> > > >
> > > > Turns out the patch breaks initialization of Toshiba THGBMNG5.
> > > > [    1.648951] mmc0: mmc_select_hs200 failed, error -84
> > > > [    1.648988] mmc0: error -84 whilst initialising MMC card
> > >
> > > For exactly this reason, when getting CRC errors on the first attempt,
> > > doing a retry makes little sense.
> > >
> > > I have looped in Chaotian who has some more details about the problem.
> > >
> > > In any case, Jan, what HW and mmc controller are you using?
> >
> > It's a custom board based on Amlogic A113D. The compatibility in dts
> > is set to "alogic,meson-axg-mmc".
>
> Good. I have looped in some of the relevant developers/maintainers.
>
> >
> > In the different revision of HW we are using Kingston EMMC04G. The
> > card has no such problem and is working fine without this patch.
> > We observed it only on mention Toshiba card.
>
> I see. Of course it would also be interesting to see what CMD6 command
> that is that fails. Would you mind adding some debug/trace to find out
> what command it is that fails?

Providing a log with following debug option  `dyndbg="func mmc_mrq_pr_debug +p`

# dmesg | grep mmc0
[    1.557984] mmc0: starting CMD52 arg 00000c00 flags 00000195
[    1.563989] mmc0: starting CMD52 arg 80000c08 flags 00000195
[    1.575219] mmc0: starting CMD0 arg 00000000 flags 000000c0
[    1.593142] mmc0: starting CMD8 arg 000001aa flags 000002f5
[    1.604439] mmc0: starting CMD5 arg 00000000 flags 000002e1
[    1.623875] mmc0: starting CMD55 arg 00000000 flags 000000f5
[    1.631024] mmc0: starting CMD55 arg 00000000 flags 000000f5
[    1.640221] mmc0: starting CMD55 arg 00000000 flags 000000f5
[    1.646802] mmc0: starting CMD55 arg 00000000 flags 000000f5
[    1.652397] mmc0: starting CMD1 arg 00000000 flags 000000e1
[    1.669894] mmc0: starting CMD1 arg 40ff8080 flags 000000e1
[    1.682925] mmc0: starting CMD1 arg 40ff8080 flags 000000e1
[    1.697073] mmc0: starting CMD1 arg 40ff8080 flags 000000e1
[    1.704327] mmc0: starting CMD0 arg 00000000 flags 000000c0
[    1.722251] mmc0: starting CMD1 arg 40200000 flags 000000e1
[    1.745317] mmc0: starting CMD1 arg 40200000 flags 000000e1
[    1.752813] mmc0: starting CMD2 arg 00000000 flags 00000007
[    1.771731] mmc0: starting CMD3 arg 00010000 flags 00000015
[    1.784771] mmc0: starting CMD9 arg 00010000 flags 00000007
[    1.790433] mmc0: starting CMD7 arg 00010000 flags 00000015
[    1.795691] mmc0: starting CMD8 arg 00000000 flags 000000b5
[    1.800800] mmc0:     blksz 512 blocks 1 flags 00000200 tsac 50 ms nsac 0
[    1.818402] mmc0: starting CMD6 arg 03af0101 flags 0000049d
[    1.818845] mmc0: starting CMD13 arg 00010000 flags 00000195
[    1.824349] mmc0: starting CMD6 arg 03220101 flags 0000049d
[    1.829992] mmc0: starting CMD13 arg 00010000 flags 00000195
[    1.835493] mmc0: starting CMD6 arg 03b70201 flags 0000049d
[    1.841119] mmc0: starting CMD13 arg 00010000 flags 00000195
[    1.846628] mmc0: starting CMD8 arg 00000000 flags 000000b5
[    1.851719] mmc0:     blksz 512 blocks 1 flags 00000200 tsac 50 ms nsac 0
[    1.860347] mmc0: starting CMD6 arg 03b90201 flags 0000049d
[    1.864421] mmc0: mmc_select_hs200 failed, error -84
[    1.868892] mmc0: error -84 whilst initialising MMC card

I cannot provide more verbose logs. When I enable more it (f.e. file
core.c) the initialization of card was successful.
If you want to see any another logs fell free to ask.

Best regards,
Jan

>
> [...]
>
> Kind regards
> Uffe

Ulf Hansson Aug. 27, 2019, 1:13 p.m. UTC | #5

On Fri, 23 Aug 2019 at 11:36, Jan Kaisrlik <ja.kaisrlik@gmail.com> wrote:
>
> čt 22. 8. 2019 v 15:59 odesílatel Ulf Hansson <ulf.hansson@linaro.org> napsal:
> >
> > + some meson driver folkz
> >
> > On Thu, 22 Aug 2019 at 10:27, Jan Kaisrlik <ja.kaisrlik@gmail.com> wrote:
> > >
> > > st 21. 8. 2019 v 17:12 odesílatel Ulf Hansson <ulf.hansson@linaro.org> napsal:
> > > >
> > > > + Chaotian Jing
> > > >
> > > > On Tue, 20 Aug 2019 at 13:42, <ja.kaisrlik@gmail.com> wrote:
> > > > >
> > > > > From: Jan Kaisrlik <ja.kaisrlik@gmail.com>
> > > > >
> > > > > This reverts commit 3a0681c7448b174e5dcfd19e9079cdd281c35f1a.
> > > > >
> > > > > Turns out the patch breaks initialization of Toshiba THGBMNG5.
> > > > > [    1.648951] mmc0: mmc_select_hs200 failed, error -84
> > > > > [    1.648988] mmc0: error -84 whilst initialising MMC card
> > > >
> > > > For exactly this reason, when getting CRC errors on the first attempt,
> > > > doing a retry makes little sense.
> > > >
> > > > I have looped in Chaotian who has some more details about the problem.
> > > >
> > > > In any case, Jan, what HW and mmc controller are you using?
> > >
> > > It's a custom board based on Amlogic A113D. The compatibility in dts
> > > is set to "alogic,meson-axg-mmc".
> >
> > Good. I have looped in some of the relevant developers/maintainers.
> >
> > >
> > > In the different revision of HW we are using Kingston EMMC04G. The
> > > card has no such problem and is working fine without this patch.
> > > We observed it only on mention Toshiba card.
> >
> > I see. Of course it would also be interesting to see what CMD6 command
> > that is that fails. Would you mind adding some debug/trace to find out
> > what command it is that fails?
>
> Providing a log with following debug option  `dyndbg="func mmc_mrq_pr_debug +p`

Thanks!

>
> # dmesg | grep mmc0
> [    1.557984] mmc0: starting CMD52 arg 00000c00 flags 00000195
> [    1.563989] mmc0: starting CMD52 arg 80000c08 flags 00000195
> [    1.575219] mmc0: starting CMD0 arg 00000000 flags 000000c0
> [    1.593142] mmc0: starting CMD8 arg 000001aa flags 000002f5
> [    1.604439] mmc0: starting CMD5 arg 00000000 flags 000002e1
> [    1.623875] mmc0: starting CMD55 arg 00000000 flags 000000f5
> [    1.631024] mmc0: starting CMD55 arg 00000000 flags 000000f5
> [    1.640221] mmc0: starting CMD55 arg 00000000 flags 000000f5
> [    1.646802] mmc0: starting CMD55 arg 00000000 flags 000000f5
> [    1.652397] mmc0: starting CMD1 arg 00000000 flags 000000e1
> [    1.669894] mmc0: starting CMD1 arg 40ff8080 flags 000000e1
> [    1.682925] mmc0: starting CMD1 arg 40ff8080 flags 000000e1
> [    1.697073] mmc0: starting CMD1 arg 40ff8080 flags 000000e1
> [    1.704327] mmc0: starting CMD0 arg 00000000 flags 000000c0
> [    1.722251] mmc0: starting CMD1 arg 40200000 flags 000000e1
> [    1.745317] mmc0: starting CMD1 arg 40200000 flags 000000e1
> [    1.752813] mmc0: starting CMD2 arg 00000000 flags 00000007
> [    1.771731] mmc0: starting CMD3 arg 00010000 flags 00000015
> [    1.784771] mmc0: starting CMD9 arg 00010000 flags 00000007
> [    1.790433] mmc0: starting CMD7 arg 00010000 flags 00000015
> [    1.795691] mmc0: starting CMD8 arg 00000000 flags 000000b5
> [    1.800800] mmc0:     blksz 512 blocks 1 flags 00000200 tsac 50 ms nsac 0
> [    1.818402] mmc0: starting CMD6 arg 03af0101 flags 0000049d
> [    1.818845] mmc0: starting CMD13 arg 00010000 flags 00000195
> [    1.824349] mmc0: starting CMD6 arg 03220101 flags 0000049d
> [    1.829992] mmc0: starting CMD13 arg 00010000 flags 00000195
> [    1.835493] mmc0: starting CMD6 arg 03b70201 flags 0000049d
> [    1.841119] mmc0: starting CMD13 arg 00010000 flags 00000195
> [    1.846628] mmc0: starting CMD8 arg 00000000 flags 000000b5
> [    1.851719] mmc0:     blksz 512 blocks 1 flags 00000200 tsac 50 ms nsac 0
> [    1.860347] mmc0: starting CMD6 arg 03b90201 flags 0000049d
> [    1.864421] mmc0: mmc_select_hs200 failed, error -84
> [    1.868892] mmc0: error -84 whilst initialising MMC card

Alright, so the CMD6 command that tries to switch the card into HS200
mode is the one that fails.

>
> I cannot provide more verbose logs. When I enable more it (f.e. file
> core.c) the initialization of card was successful.

That's an interesting observation!

Perhaps the card is still in some kind of busy state, after the CMD8
has been sent to read the EXT_CSD, when verifying the earlier bus
width switch (mmc_compare_ext_csds()).

> If you want to see any another logs fell free to ask.

Would you mind trying one thing, in a way to narrow down the problem?

Add a delay (msleep() or usleep_range() with some different values up
to 50 ms) somewhere after mmc_compare_ext_csds() has been executed,
but also before having mmc_select_bus_width() to return the error
code?

Kind regards
Uffe

Jan Kaisrlik Aug. 27, 2019, 3:55 p.m. UTC | #6

On Tue, Aug 27, 2019 at 3:14 PM Ulf Hansson <ulf.hansson@linaro.org> wrote:
>
> On Fri, 23 Aug 2019 at 11:36, Jan Kaisrlik <ja.kaisrlik@gmail.com> wrote:
> >
> > čt 22. 8. 2019 v 15:59 odesílatel Ulf Hansson <ulf.hansson@linaro.org> napsal:
> > >
> > > + some meson driver folkz
> > >
> > > On Thu, 22 Aug 2019 at 10:27, Jan Kaisrlik <ja.kaisrlik@gmail.com> wrote:
> > > >
> > > > st 21. 8. 2019 v 17:12 odesílatel Ulf Hansson <ulf.hansson@linaro.org> napsal:
> > > > >
> > > > > + Chaotian Jing
> > > > >
> > > > > On Tue, 20 Aug 2019 at 13:42, <ja.kaisrlik@gmail.com> wrote:
> > > > > >
> > > > > > From: Jan Kaisrlik <ja.kaisrlik@gmail.com>
> > > > > >
> > > > > > This reverts commit 3a0681c7448b174e5dcfd19e9079cdd281c35f1a.
> > > > > >
> > > > > > Turns out the patch breaks initialization of Toshiba THGBMNG5.
> > > > > > [    1.648951] mmc0: mmc_select_hs200 failed, error -84
> > > > > > [    1.648988] mmc0: error -84 whilst initialising MMC card
> > > > >
> > > > > For exactly this reason, when getting CRC errors on the first attempt,
> > > > > doing a retry makes little sense.
> > > > >
> > > > > I have looped in Chaotian who has some more details about the problem.
> > > > >
> > > > > In any case, Jan, what HW and mmc controller are you using?
> > > >
> > > > It's a custom board based on Amlogic A113D. The compatibility in dts
> > > > is set to "alogic,meson-axg-mmc".
> > >
> > > Good. I have looped in some of the relevant developers/maintainers.
> > >
> > > >
> > > > In the different revision of HW we are using Kingston EMMC04G. The
> > > > card has no such problem and is working fine without this patch.
> > > > We observed it only on mention Toshiba card.
> > >
> > > I see. Of course it would also be interesting to see what CMD6 command
> > > that is that fails. Would you mind adding some debug/trace to find out
> > > what command it is that fails?
> >
> > Providing a log with following debug option  `dyndbg="func mmc_mrq_pr_debug +p`
>
> Thanks!
>
> >
> > # dmesg | grep mmc0
> > [    1.557984] mmc0: starting CMD52 arg 00000c00 flags 00000195
> > [    1.563989] mmc0: starting CMD52 arg 80000c08 flags 00000195
> > [    1.575219] mmc0: starting CMD0 arg 00000000 flags 000000c0
> > [    1.593142] mmc0: starting CMD8 arg 000001aa flags 000002f5
> > [    1.604439] mmc0: starting CMD5 arg 00000000 flags 000002e1
> > [    1.623875] mmc0: starting CMD55 arg 00000000 flags 000000f5
> > [    1.631024] mmc0: starting CMD55 arg 00000000 flags 000000f5
> > [    1.640221] mmc0: starting CMD55 arg 00000000 flags 000000f5
> > [    1.646802] mmc0: starting CMD55 arg 00000000 flags 000000f5
> > [    1.652397] mmc0: starting CMD1 arg 00000000 flags 000000e1
> > [    1.669894] mmc0: starting CMD1 arg 40ff8080 flags 000000e1
> > [    1.682925] mmc0: starting CMD1 arg 40ff8080 flags 000000e1
> > [    1.697073] mmc0: starting CMD1 arg 40ff8080 flags 000000e1
> > [    1.704327] mmc0: starting CMD0 arg 00000000 flags 000000c0
> > [    1.722251] mmc0: starting CMD1 arg 40200000 flags 000000e1
> > [    1.745317] mmc0: starting CMD1 arg 40200000 flags 000000e1
> > [    1.752813] mmc0: starting CMD2 arg 00000000 flags 00000007
> > [    1.771731] mmc0: starting CMD3 arg 00010000 flags 00000015
> > [    1.784771] mmc0: starting CMD9 arg 00010000 flags 00000007
> > [    1.790433] mmc0: starting CMD7 arg 00010000 flags 00000015
> > [    1.795691] mmc0: starting CMD8 arg 00000000 flags 000000b5
> > [    1.800800] mmc0:     blksz 512 blocks 1 flags 00000200 tsac 50 ms nsac 0
> > [    1.818402] mmc0: starting CMD6 arg 03af0101 flags 0000049d
> > [    1.818845] mmc0: starting CMD13 arg 00010000 flags 00000195
> > [    1.824349] mmc0: starting CMD6 arg 03220101 flags 0000049d
> > [    1.829992] mmc0: starting CMD13 arg 00010000 flags 00000195
> > [    1.835493] mmc0: starting CMD6 arg 03b70201 flags 0000049d
> > [    1.841119] mmc0: starting CMD13 arg 00010000 flags 00000195
> > [    1.846628] mmc0: starting CMD8 arg 00000000 flags 000000b5
> > [    1.851719] mmc0:     blksz 512 blocks 1 flags 00000200 tsac 50 ms nsac 0
> > [    1.860347] mmc0: starting CMD6 arg 03b90201 flags 0000049d
> > [    1.864421] mmc0: mmc_select_hs200 failed, error -84
> > [    1.868892] mmc0: error -84 whilst initialising MMC card
>
> Alright, so the CMD6 command that tries to switch the card into HS200
> mode is the one that fails.
>
> >
> > I cannot provide more verbose logs. When I enable more it (f.e. file
> > core.c) the initialization of card was successful.
>
> That's an interesting observation!
>
> Perhaps the card is still in some kind of busy state, after the CMD8
> has been sent to read the EXT_CSD, when verifying the earlier bus
> width switch (mmc_compare_ext_csds()).

I'm curious, do you know if there is a command that says if the card
is busy/ready?

>
> > If you want to see any another logs fell free to ask.
>
> Would you mind trying one thing, in a way to narrow down the problem?
>
> Add a delay (msleep() or usleep_range() with some different values up
> to 50 ms) somewhere after mmc_compare_ext_csds() has been executed,
> but also before having mmc_select_bus_width() to return the error
> code?

I've added msleep just before exit point of mmc_select_bus_width() and
observation is following
* 1ms or 2 ms - failing (time to time it was successfully initialized)
* 5 ms - success in all attempts

Best regards,
Jan

>
> Kind regards
> Uffe

Ulf Hansson Aug. 28, 2019, 10:44 a.m. UTC | #7

On Tue, 27 Aug 2019 at 17:55, Jan Kaisrlik <ja.kaisrlik@gmail.com> wrote:
>
> On Tue, Aug 27, 2019 at 3:14 PM Ulf Hansson <ulf.hansson@linaro.org> wrote:
> >
> > On Fri, 23 Aug 2019 at 11:36, Jan Kaisrlik <ja.kaisrlik@gmail.com> wrote:
> > >
> > > čt 22. 8. 2019 v 15:59 odesílatel Ulf Hansson <ulf.hansson@linaro.org> napsal:
> > > >
> > > > + some meson driver folkz
> > > >
> > > > On Thu, 22 Aug 2019 at 10:27, Jan Kaisrlik <ja.kaisrlik@gmail.com> wrote:
> > > > >
> > > > > st 21. 8. 2019 v 17:12 odesílatel Ulf Hansson <ulf.hansson@linaro.org> napsal:
> > > > > >
> > > > > > + Chaotian Jing
> > > > > >
> > > > > > On Tue, 20 Aug 2019 at 13:42, <ja.kaisrlik@gmail.com> wrote:
> > > > > > >
> > > > > > > From: Jan Kaisrlik <ja.kaisrlik@gmail.com>
> > > > > > >
> > > > > > > This reverts commit 3a0681c7448b174e5dcfd19e9079cdd281c35f1a.
> > > > > > >
> > > > > > > Turns out the patch breaks initialization of Toshiba THGBMNG5.
> > > > > > > [    1.648951] mmc0: mmc_select_hs200 failed, error -84
> > > > > > > [    1.648988] mmc0: error -84 whilst initialising MMC card
> > > > > >
> > > > > > For exactly this reason, when getting CRC errors on the first attempt,
> > > > > > doing a retry makes little sense.
> > > > > >
> > > > > > I have looped in Chaotian who has some more details about the problem.
> > > > > >
> > > > > > In any case, Jan, what HW and mmc controller are you using?
> > > > >
> > > > > It's a custom board based on Amlogic A113D. The compatibility in dts
> > > > > is set to "alogic,meson-axg-mmc".
> > > >
> > > > Good. I have looped in some of the relevant developers/maintainers.
> > > >
> > > > >
> > > > > In the different revision of HW we are using Kingston EMMC04G. The
> > > > > card has no such problem and is working fine without this patch.
> > > > > We observed it only on mention Toshiba card.
> > > >
> > > > I see. Of course it would also be interesting to see what CMD6 command
> > > > that is that fails. Would you mind adding some debug/trace to find out
> > > > what command it is that fails?
> > >
> > > Providing a log with following debug option  `dyndbg="func mmc_mrq_pr_debug +p`
> >
> > Thanks!
> >
> > >
> > > # dmesg | grep mmc0
> > > [    1.557984] mmc0: starting CMD52 arg 00000c00 flags 00000195
> > > [    1.563989] mmc0: starting CMD52 arg 80000c08 flags 00000195
> > > [    1.575219] mmc0: starting CMD0 arg 00000000 flags 000000c0
> > > [    1.593142] mmc0: starting CMD8 arg 000001aa flags 000002f5
> > > [    1.604439] mmc0: starting CMD5 arg 00000000 flags 000002e1
> > > [    1.623875] mmc0: starting CMD55 arg 00000000 flags 000000f5
> > > [    1.631024] mmc0: starting CMD55 arg 00000000 flags 000000f5
> > > [    1.640221] mmc0: starting CMD55 arg 00000000 flags 000000f5
> > > [    1.646802] mmc0: starting CMD55 arg 00000000 flags 000000f5
> > > [    1.652397] mmc0: starting CMD1 arg 00000000 flags 000000e1
> > > [    1.669894] mmc0: starting CMD1 arg 40ff8080 flags 000000e1
> > > [    1.682925] mmc0: starting CMD1 arg 40ff8080 flags 000000e1
> > > [    1.697073] mmc0: starting CMD1 arg 40ff8080 flags 000000e1
> > > [    1.704327] mmc0: starting CMD0 arg 00000000 flags 000000c0
> > > [    1.722251] mmc0: starting CMD1 arg 40200000 flags 000000e1
> > > [    1.745317] mmc0: starting CMD1 arg 40200000 flags 000000e1
> > > [    1.752813] mmc0: starting CMD2 arg 00000000 flags 00000007
> > > [    1.771731] mmc0: starting CMD3 arg 00010000 flags 00000015
> > > [    1.784771] mmc0: starting CMD9 arg 00010000 flags 00000007
> > > [    1.790433] mmc0: starting CMD7 arg 00010000 flags 00000015
> > > [    1.795691] mmc0: starting CMD8 arg 00000000 flags 000000b5
> > > [    1.800800] mmc0:     blksz 512 blocks 1 flags 00000200 tsac 50 ms nsac 0
> > > [    1.818402] mmc0: starting CMD6 arg 03af0101 flags 0000049d
> > > [    1.818845] mmc0: starting CMD13 arg 00010000 flags 00000195
> > > [    1.824349] mmc0: starting CMD6 arg 03220101 flags 0000049d
> > > [    1.829992] mmc0: starting CMD13 arg 00010000 flags 00000195
> > > [    1.835493] mmc0: starting CMD6 arg 03b70201 flags 0000049d
> > > [    1.841119] mmc0: starting CMD13 arg 00010000 flags 00000195
> > > [    1.846628] mmc0: starting CMD8 arg 00000000 flags 000000b5
> > > [    1.851719] mmc0:     blksz 512 blocks 1 flags 00000200 tsac 50 ms nsac 0
> > > [    1.860347] mmc0: starting CMD6 arg 03b90201 flags 0000049d
> > > [    1.864421] mmc0: mmc_select_hs200 failed, error -84
> > > [    1.868892] mmc0: error -84 whilst initialising MMC card
> >
> > Alright, so the CMD6 command that tries to switch the card into HS200
> > mode is the one that fails.
> >
> > >
> > > I cannot provide more verbose logs. When I enable more it (f.e. file
> > > core.c) the initialization of card was successful.
> >
> > That's an interesting observation!
> >
> > Perhaps the card is still in some kind of busy state, after the CMD8
> > has been sent to read the EXT_CSD, when verifying the earlier bus
> > width switch (mmc_compare_ext_csds()).
>
> I'm curious, do you know if there is a command that says if the card
> is busy/ready?

Yes, the CMD13.

However, CMD13 is not allowed to be sent for some command sequences.
For example sending CMD6 to switch to HS200 mode, is one case where we
must avoid it.

For these scenarios, either we rely on the host HW to detect when the
card stop signals busy or we simply insert a delay (according to spec)
after sending the CMD6 command.

>
> >
> > > If you want to see any another logs fell free to ask.
> >
> > Would you mind trying one thing, in a way to narrow down the problem?
> >
> > Add a delay (msleep() or usleep_range() with some different values up
> > to 50 ms) somewhere after mmc_compare_ext_csds() has been executed,
> > but also before having mmc_select_bus_width() to return the error
> > code?
>
> I've added msleep just before exit point of mmc_select_bus_width() and
> observation is following
> * 1ms or 2 ms - failing (time to time it was successfully initialized)
> * 5 ms - success in all attempts

Very good!

Let me post a debug patch in short while, that can try to verify if
the card is busy during this period.

Kind regards
Uffe

Ulf Hansson Aug. 29, 2019, 7:50 a.m. UTC | #8

On Wed, 28 Aug 2019 at 12:44, Ulf Hansson <ulf.hansson@linaro.org> wrote:
>
> On Tue, 27 Aug 2019 at 17:55, Jan Kaisrlik <ja.kaisrlik@gmail.com> wrote:
> >
> > On Tue, Aug 27, 2019 at 3:14 PM Ulf Hansson <ulf.hansson@linaro.org> wrote:
> > >
> > > On Fri, 23 Aug 2019 at 11:36, Jan Kaisrlik <ja.kaisrlik@gmail.com> wrote:
> > > >
> > > > čt 22. 8. 2019 v 15:59 odesílatel Ulf Hansson <ulf.hansson@linaro.org> napsal:
> > > > >
> > > > > + some meson driver folkz
> > > > >
> > > > > On Thu, 22 Aug 2019 at 10:27, Jan Kaisrlik <ja.kaisrlik@gmail.com> wrote:
> > > > > >
> > > > > > st 21. 8. 2019 v 17:12 odesílatel Ulf Hansson <ulf.hansson@linaro.org> napsal:
> > > > > > >
> > > > > > > + Chaotian Jing
> > > > > > >
> > > > > > > On Tue, 20 Aug 2019 at 13:42, <ja.kaisrlik@gmail.com> wrote:
> > > > > > > >
> > > > > > > > From: Jan Kaisrlik <ja.kaisrlik@gmail.com>
> > > > > > > >
> > > > > > > > This reverts commit 3a0681c7448b174e5dcfd19e9079cdd281c35f1a.
> > > > > > > >
> > > > > > > > Turns out the patch breaks initialization of Toshiba THGBMNG5.
> > > > > > > > [    1.648951] mmc0: mmc_select_hs200 failed, error -84
> > > > > > > > [    1.648988] mmc0: error -84 whilst initialising MMC card
> > > > > > >
> > > > > > > For exactly this reason, when getting CRC errors on the first attempt,
> > > > > > > doing a retry makes little sense.
> > > > > > >
> > > > > > > I have looped in Chaotian who has some more details about the problem.
> > > > > > >
> > > > > > > In any case, Jan, what HW and mmc controller are you using?
> > > > > >
> > > > > > It's a custom board based on Amlogic A113D. The compatibility in dts
> > > > > > is set to "alogic,meson-axg-mmc".
> > > > >
> > > > > Good. I have looped in some of the relevant developers/maintainers.
> > > > >
> > > > > >
> > > > > > In the different revision of HW we are using Kingston EMMC04G. The
> > > > > > card has no such problem and is working fine without this patch.
> > > > > > We observed it only on mention Toshiba card.
> > > > >
> > > > > I see. Of course it would also be interesting to see what CMD6 command
> > > > > that is that fails. Would you mind adding some debug/trace to find out
> > > > > what command it is that fails?
> > > >
> > > > Providing a log with following debug option  `dyndbg="func mmc_mrq_pr_debug +p`
> > >
> > > Thanks!
> > >
> > > >
> > > > # dmesg | grep mmc0
> > > > [    1.557984] mmc0: starting CMD52 arg 00000c00 flags 00000195
> > > > [    1.563989] mmc0: starting CMD52 arg 80000c08 flags 00000195
> > > > [    1.575219] mmc0: starting CMD0 arg 00000000 flags 000000c0
> > > > [    1.593142] mmc0: starting CMD8 arg 000001aa flags 000002f5
> > > > [    1.604439] mmc0: starting CMD5 arg 00000000 flags 000002e1
> > > > [    1.623875] mmc0: starting CMD55 arg 00000000 flags 000000f5
> > > > [    1.631024] mmc0: starting CMD55 arg 00000000 flags 000000f5
> > > > [    1.640221] mmc0: starting CMD55 arg 00000000 flags 000000f5
> > > > [    1.646802] mmc0: starting CMD55 arg 00000000 flags 000000f5
> > > > [    1.652397] mmc0: starting CMD1 arg 00000000 flags 000000e1
> > > > [    1.669894] mmc0: starting CMD1 arg 40ff8080 flags 000000e1
> > > > [    1.682925] mmc0: starting CMD1 arg 40ff8080 flags 000000e1
> > > > [    1.697073] mmc0: starting CMD1 arg 40ff8080 flags 000000e1
> > > > [    1.704327] mmc0: starting CMD0 arg 00000000 flags 000000c0
> > > > [    1.722251] mmc0: starting CMD1 arg 40200000 flags 000000e1
> > > > [    1.745317] mmc0: starting CMD1 arg 40200000 flags 000000e1
> > > > [    1.752813] mmc0: starting CMD2 arg 00000000 flags 00000007
> > > > [    1.771731] mmc0: starting CMD3 arg 00010000 flags 00000015
> > > > [    1.784771] mmc0: starting CMD9 arg 00010000 flags 00000007
> > > > [    1.790433] mmc0: starting CMD7 arg 00010000 flags 00000015
> > > > [    1.795691] mmc0: starting CMD8 arg 00000000 flags 000000b5
> > > > [    1.800800] mmc0:     blksz 512 blocks 1 flags 00000200 tsac 50 ms nsac 0
> > > > [    1.818402] mmc0: starting CMD6 arg 03af0101 flags 0000049d
> > > > [    1.818845] mmc0: starting CMD13 arg 00010000 flags 00000195
> > > > [    1.824349] mmc0: starting CMD6 arg 03220101 flags 0000049d
> > > > [    1.829992] mmc0: starting CMD13 arg 00010000 flags 00000195
> > > > [    1.835493] mmc0: starting CMD6 arg 03b70201 flags 0000049d
> > > > [    1.841119] mmc0: starting CMD13 arg 00010000 flags 00000195
> > > > [    1.846628] mmc0: starting CMD8 arg 00000000 flags 000000b5
> > > > [    1.851719] mmc0:     blksz 512 blocks 1 flags 00000200 tsac 50 ms nsac 0
> > > > [    1.860347] mmc0: starting CMD6 arg 03b90201 flags 0000049d
> > > > [    1.864421] mmc0: mmc_select_hs200 failed, error -84
> > > > [    1.868892] mmc0: error -84 whilst initialising MMC card
> > >
> > > Alright, so the CMD6 command that tries to switch the card into HS200
> > > mode is the one that fails.
> > >
> > > >
> > > > I cannot provide more verbose logs. When I enable more it (f.e. file
> > > > core.c) the initialization of card was successful.
> > >
> > > That's an interesting observation!
> > >
> > > Perhaps the card is still in some kind of busy state, after the CMD8
> > > has been sent to read the EXT_CSD, when verifying the earlier bus
> > > width switch (mmc_compare_ext_csds()).
> >
> > I'm curious, do you know if there is a command that says if the card
> > is busy/ready?
>
> Yes, the CMD13.
>
> However, CMD13 is not allowed to be sent for some command sequences.
> For example sending CMD6 to switch to HS200 mode, is one case where we
> must avoid it.
>
> For these scenarios, either we rely on the host HW to detect when the
> card stop signals busy or we simply insert a delay (according to spec)
> after sending the CMD6 command.
>
> >
> > >
> > > > If you want to see any another logs fell free to ask.
> > >
> > > Would you mind trying one thing, in a way to narrow down the problem?
> > >
> > > Add a delay (msleep() or usleep_range() with some different values up
> > > to 50 ms) somewhere after mmc_compare_ext_csds() has been executed,
> > > but also before having mmc_select_bus_width() to return the error
> > > code?
> >
> > I've added msleep just before exit point of mmc_select_bus_width() and
> > observation is following
> > * 1ms or 2 ms - failing (time to time it was successfully initialized)
> > * 5 ms - success in all attempts
>
> Very good!
>
> Let me post a debug patch in short while, that can try to verify if
> the card is busy during this period.

Here it is, please give it a try and see what happens.

You may also want to run a second test, changing the second parameter
to false when calling poll_for_busy(), as that switches from CMD13 to
use of the host driver's ->card_busy() callback, when checking for
busy.

Kind regards
Uffe

From: Ulf Hansson <ulf.hansson@linaro.org>
Date: Thu, 29 Aug 2019 09:42:11 +0200
Subject: [PATCH] mmc: core: DEBUG for mmc_select_bus_width()

Signed-off-by: Ulf Hansson <ulf.hansson@linaro.org>
---
 drivers/mmc/core/mmc.c | 47 ++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 47 insertions(+)

diff --git a/drivers/mmc/core/mmc.c b/drivers/mmc/core/mmc.c
index c8804895595f..ff3a4c166f20 100644
--- a/drivers/mmc/core/mmc.c
+++ b/drivers/mmc/core/mmc.c
@@ -975,6 +975,52 @@ static void mmc_set_bus_speed(struct mmc_card *card)
        mmc_set_clock(card->host, max_dtr);
 }

+static void poll_for_busy(struct mmc_card *card, bool send_status)
+{
+       struct mmc_host *host = card->host;
+       int err;
+       unsigned long timeout;
+       unsigned int timeout_ms = 5000;
+       u32 status = 0;
+       bool expired = false;
+       bool busy = false;
+
+       if (!send_status && !host->ops->card_busy) {
+               mmc_delay(timeout_ms);
+               return;
+       }
+
+       timeout = jiffies + msecs_to_jiffies(timeout_ms) + 1;
+       do {
+               expired = time_after(jiffies, timeout);
+               if (send_status) {
+                       err = __mmc_send_status(card, &status, 0);
+                       if (err) {
+                               busy = true;
+                               pr_err("%s: failed to get card status
err=%d! %s\n",
+                                       mmc_hostname(host), err, __func__);
+                               continue;
+                       }
+                       busy = R1_CURRENT_STATE(status) == R1_STATE_PRG;
+               } else {
+                       busy = host->ops->card_busy(host);
+               }
+
+               if (expired && busy) {
+                       pr_err("%s: Card stuck being busy! %s\n",
+                               mmc_hostname(host), __func__);
+                       return;
+               }
+
+               if (busy)
+                       pr_err("%s: card temporary busy! %s\n",
+                               mmc_hostname(host), __func__);
+
+       } while (busy);
+
+       return;
+}
+
 /*
  * Select the bus width amoung 4-bit and 8-bit(SDR).
  * If the bus width is changed successfully, return the selected width value.
@@ -1036,6 +1082,7 @@ static int mmc_select_bus_width(struct mmc_card *card)

                if (!err) {
                        err = bus_width;
+                       poll_for_busy(card, true);
                        break;
                } else {
                        pr_warn("%s: switch to bus width %d failed\n",

Jan Kaisrlik Aug. 30, 2019, 10:01 a.m. UTC | #9

On Thu, Aug 29, 2019 at 9:50 AM Ulf Hansson <ulf.hansson@linaro.org> wrote:
>
> On Wed, 28 Aug 2019 at 12:44, Ulf Hansson <ulf.hansson@linaro.org> wrote:
> >
> > On Tue, 27 Aug 2019 at 17:55, Jan Kaisrlik <ja.kaisrlik@gmail.com> wrote:
> > >
> > > On Tue, Aug 27, 2019 at 3:14 PM Ulf Hansson <ulf.hansson@linaro.org> wrote:
> > > >
> > > > On Fri, 23 Aug 2019 at 11:36, Jan Kaisrlik <ja.kaisrlik@gmail.com> wrote:
> > > > >
> > > > > čt 22. 8. 2019 v 15:59 odesílatel Ulf Hansson <ulf.hansson@linaro.org> napsal:
> > > > > >
> > > > > > + some meson driver folkz
> > > > > >
> > > > > > On Thu, 22 Aug 2019 at 10:27, Jan Kaisrlik <ja.kaisrlik@gmail.com> wrote:
> > > > > > >
> > > > > > > st 21. 8. 2019 v 17:12 odesílatel Ulf Hansson <ulf.hansson@linaro.org> napsal:
> > > > > > > >
> > > > > > > > + Chaotian Jing
> > > > > > > >
> > > > > > > > On Tue, 20 Aug 2019 at 13:42, <ja.kaisrlik@gmail.com> wrote:
> > > > > > > > >
> > > > > > > > > From: Jan Kaisrlik <ja.kaisrlik@gmail.com>
> > > > > > > > >
> > > > > > > > > This reverts commit 3a0681c7448b174e5dcfd19e9079cdd281c35f1a.
> > > > > > > > >
> > > > > > > > > Turns out the patch breaks initialization of Toshiba THGBMNG5.
> > > > > > > > > [    1.648951] mmc0: mmc_select_hs200 failed, error -84
> > > > > > > > > [    1.648988] mmc0: error -84 whilst initialising MMC card
> > > > > > > >
> > > > > > > > For exactly this reason, when getting CRC errors on the first attempt,
> > > > > > > > doing a retry makes little sense.
> > > > > > > >
> > > > > > > > I have looped in Chaotian who has some more details about the problem.
> > > > > > > >
> > > > > > > > In any case, Jan, what HW and mmc controller are you using?
> > > > > > >
> > > > > > > It's a custom board based on Amlogic A113D. The compatibility in dts
> > > > > > > is set to "alogic,meson-axg-mmc".
> > > > > >
> > > > > > Good. I have looped in some of the relevant developers/maintainers.
> > > > > >
> > > > > > >
> > > > > > > In the different revision of HW we are using Kingston EMMC04G. The
> > > > > > > card has no such problem and is working fine without this patch.
> > > > > > > We observed it only on mention Toshiba card.
> > > > > >
> > > > > > I see. Of course it would also be interesting to see what CMD6 command
> > > > > > that is that fails. Would you mind adding some debug/trace to find out
> > > > > > what command it is that fails?
> > > > >
> > > > > Providing a log with following debug option  `dyndbg="func mmc_mrq_pr_debug +p`
> > > >
> > > > Thanks!
> > > >
> > > > >
> > > > > # dmesg | grep mmc0
> > > > > [    1.557984] mmc0: starting CMD52 arg 00000c00 flags 00000195
> > > > > [    1.563989] mmc0: starting CMD52 arg 80000c08 flags 00000195
> > > > > [    1.575219] mmc0: starting CMD0 arg 00000000 flags 000000c0
> > > > > [    1.593142] mmc0: starting CMD8 arg 000001aa flags 000002f5
> > > > > [    1.604439] mmc0: starting CMD5 arg 00000000 flags 000002e1
> > > > > [    1.623875] mmc0: starting CMD55 arg 00000000 flags 000000f5
> > > > > [    1.631024] mmc0: starting CMD55 arg 00000000 flags 000000f5
> > > > > [    1.640221] mmc0: starting CMD55 arg 00000000 flags 000000f5
> > > > > [    1.646802] mmc0: starting CMD55 arg 00000000 flags 000000f5
> > > > > [    1.652397] mmc0: starting CMD1 arg 00000000 flags 000000e1
> > > > > [    1.669894] mmc0: starting CMD1 arg 40ff8080 flags 000000e1
> > > > > [    1.682925] mmc0: starting CMD1 arg 40ff8080 flags 000000e1
> > > > > [    1.697073] mmc0: starting CMD1 arg 40ff8080 flags 000000e1
> > > > > [    1.704327] mmc0: starting CMD0 arg 00000000 flags 000000c0
> > > > > [    1.722251] mmc0: starting CMD1 arg 40200000 flags 000000e1
> > > > > [    1.745317] mmc0: starting CMD1 arg 40200000 flags 000000e1
> > > > > [    1.752813] mmc0: starting CMD2 arg 00000000 flags 00000007
> > > > > [    1.771731] mmc0: starting CMD3 arg 00010000 flags 00000015
> > > > > [    1.784771] mmc0: starting CMD9 arg 00010000 flags 00000007
> > > > > [    1.790433] mmc0: starting CMD7 arg 00010000 flags 00000015
> > > > > [    1.795691] mmc0: starting CMD8 arg 00000000 flags 000000b5
> > > > > [    1.800800] mmc0:     blksz 512 blocks 1 flags 00000200 tsac 50 ms nsac 0
> > > > > [    1.818402] mmc0: starting CMD6 arg 03af0101 flags 0000049d
> > > > > [    1.818845] mmc0: starting CMD13 arg 00010000 flags 00000195
> > > > > [    1.824349] mmc0: starting CMD6 arg 03220101 flags 0000049d
> > > > > [    1.829992] mmc0: starting CMD13 arg 00010000 flags 00000195
> > > > > [    1.835493] mmc0: starting CMD6 arg 03b70201 flags 0000049d
> > > > > [    1.841119] mmc0: starting CMD13 arg 00010000 flags 00000195
> > > > > [    1.846628] mmc0: starting CMD8 arg 00000000 flags 000000b5
> > > > > [    1.851719] mmc0:     blksz 512 blocks 1 flags 00000200 tsac 50 ms nsac 0
> > > > > [    1.860347] mmc0: starting CMD6 arg 03b90201 flags 0000049d
> > > > > [    1.864421] mmc0: mmc_select_hs200 failed, error -84
> > > > > [    1.868892] mmc0: error -84 whilst initialising MMC card
> > > >
> > > > Alright, so the CMD6 command that tries to switch the card into HS200
> > > > mode is the one that fails.
> > > >
> > > > >
> > > > > I cannot provide more verbose logs. When I enable more it (f.e. file
> > > > > core.c) the initialization of card was successful.
> > > >
> > > > That's an interesting observation!
> > > >
> > > > Perhaps the card is still in some kind of busy state, after the CMD8
> > > > has been sent to read the EXT_CSD, when verifying the earlier bus
> > > > width switch (mmc_compare_ext_csds()).
> > >
> > > I'm curious, do you know if there is a command that says if the card
> > > is busy/ready?
> >
> > Yes, the CMD13.
> >
> > However, CMD13 is not allowed to be sent for some command sequences.
> > For example sending CMD6 to switch to HS200 mode, is one case where we
> > must avoid it.
> >
> > For these scenarios, either we rely on the host HW to detect when the
> > card stop signals busy or we simply insert a delay (according to spec)
> > after sending the CMD6 command.
> >
> > >
> > > >
> > > > > If you want to see any another logs fell free to ask.
> > > >
> > > > Would you mind trying one thing, in a way to narrow down the problem?
> > > >
> > > > Add a delay (msleep() or usleep_range() with some different values up
> > > > to 50 ms) somewhere after mmc_compare_ext_csds() has been executed,
> > > > but also before having mmc_select_bus_width() to return the error
> > > > code?
> > >
> > > I've added msleep just before exit point of mmc_select_bus_width() and
> > > observation is following
> > > * 1ms or 2 ms - failing (time to time it was successfully initialized)
> > > * 5 ms - success in all attempts
> >
> > Very good!
> >
> > Let me post a debug patch in short while, that can try to verify if
> > the card is busy during this period.
>
> Here it is, please give it a try and see what happens.
>
> You may also want to run a second test, changing the second parameter
> to false when calling poll_for_busy(), as that switches from CMD13 to
> use of the host driver's ->card_busy() callback, when checking for
> busy.

I've applied the patch and test poll_for_busy() with different
send_status parameter as you recommend (true/false).
The outputs are the same
[    1.526554] meson-gx-mmc ffe07000.mmc: allocated mmc-pwrseq
[    1.682886] mmc0: mmc_select_hs200 failed, error -84
[    1.693081] mmc0: error -84 whilst initialising MMC card

>
> Kind regards
> Uffe
>
> From: Ulf Hansson <ulf.hansson@linaro.org>
> Date: Thu, 29 Aug 2019 09:42:11 +0200
> Subject: [PATCH] mmc: core: DEBUG for mmc_select_bus_width()
>
> Signed-off-by: Ulf Hansson <ulf.hansson@linaro.org>
> ---
>  drivers/mmc/core/mmc.c | 47 ++++++++++++++++++++++++++++++++++++++++++
>  1 file changed, 47 insertions(+)
>
> diff --git a/drivers/mmc/core/mmc.c b/drivers/mmc/core/mmc.c
> index c8804895595f..ff3a4c166f20 100644
> --- a/drivers/mmc/core/mmc.c
> +++ b/drivers/mmc/core/mmc.c
> @@ -975,6 +975,52 @@ static void mmc_set_bus_speed(struct mmc_card *card)
>         mmc_set_clock(card->host, max_dtr);
>  }
>
> +static void poll_for_busy(struct mmc_card *card, bool send_status)
> +{
> +       struct mmc_host *host = card->host;
> +       int err;
> +       unsigned long timeout;
> +       unsigned int timeout_ms = 5000;
> +       u32 status = 0;
> +       bool expired = false;
> +       bool busy = false;
> +
> +       if (!send_status && !host->ops->card_busy) {
> +               mmc_delay(timeout_ms);

fyi this code hasn't been executed.

> +               return;
> +       }
> +
> +       timeout = jiffies + msecs_to_jiffies(timeout_ms) + 1;
> +       do {
> +               expired = time_after(jiffies, timeout);
> +               if (send_status) {
> +                       err = __mmc_send_status(card, &status, 0);

I've added some print here as well to see whats the value of the status

+                       printk("%s: %s status=0x%x
R1_CURRENT_STATE(status)=0x%x \n",
+                               mmc_hostname(host),__func__, status,
R1_CURRENT_STATE(status));

[    1.676970] mmc0: poll_for_busy status=0x900 R1_CURRENT_STATE(status)=0x4
[    1.685821] mmc0: mmc_select_hs200 failed, error -84
[    1.698029] mmc0: error -84 whilst initialising MMC card

best regards,
Jan


> +                       if (err) {
> +                               busy = true;
> +                               pr_err("%s: failed to get card status
> err=%d! %s\n",
> +                                       mmc_hostname(host), err, __func__);
> +                               continue;
> +                       }
> +                       busy = R1_CURRENT_STATE(status) == R1_STATE_PRG;
> +               } else {
> +                       busy = host->ops->card_busy(host);
> +               }
> +
> +               if (expired && busy) {
> +                       pr_err("%s: Card stuck being busy! %s\n",
> +                               mmc_hostname(host), __func__);
> +                       return;
> +               }
> +
> +               if (busy)
> +                       pr_err("%s: card temporary busy! %s\n",
> +                               mmc_hostname(host), __func__);
> +
> +       } while (busy);
> +
> +       return;
> +}
> +
>  /*
>   * Select the bus width amoung 4-bit and 8-bit(SDR).
>   * If the bus width is changed successfully, return the selected width value.
> @@ -1036,6 +1082,7 @@ static int mmc_select_bus_width(struct mmc_card *card)
>
>                 if (!err) {
>                         err = bus_width;
> +                       poll_for_busy(card, true);
>                         break;
>                 } else {
>                         pr_warn("%s: switch to bus width %d failed\n",
> --
> 2.17.1

Ulf Hansson Aug. 30, 2019, 11:07 a.m. UTC | #10

On Fri, 30 Aug 2019 at 12:01, Jan Kaisrlik <ja.kaisrlik@gmail.com> wrote:
>
> On Thu, Aug 29, 2019 at 9:50 AM Ulf Hansson <ulf.hansson@linaro.org> wrote:
> >
> > On Wed, 28 Aug 2019 at 12:44, Ulf Hansson <ulf.hansson@linaro.org> wrote:
> > >
> > > On Tue, 27 Aug 2019 at 17:55, Jan Kaisrlik <ja.kaisrlik@gmail.com> wrote:
> > > >
> > > > On Tue, Aug 27, 2019 at 3:14 PM Ulf Hansson <ulf.hansson@linaro.org> wrote:
> > > > >
> > > > > On Fri, 23 Aug 2019 at 11:36, Jan Kaisrlik <ja.kaisrlik@gmail.com> wrote:
> > > > > >
> > > > > > čt 22. 8. 2019 v 15:59 odesílatel Ulf Hansson <ulf.hansson@linaro.org> napsal:
> > > > > > >
> > > > > > > + some meson driver folkz
> > > > > > >
> > > > > > > On Thu, 22 Aug 2019 at 10:27, Jan Kaisrlik <ja.kaisrlik@gmail.com> wrote:
> > > > > > > >
> > > > > > > > st 21. 8. 2019 v 17:12 odesílatel Ulf Hansson <ulf.hansson@linaro.org> napsal:
> > > > > > > > >
> > > > > > > > > + Chaotian Jing
> > > > > > > > >
> > > > > > > > > On Tue, 20 Aug 2019 at 13:42, <ja.kaisrlik@gmail.com> wrote:
> > > > > > > > > >
> > > > > > > > > > From: Jan Kaisrlik <ja.kaisrlik@gmail.com>
> > > > > > > > > >
> > > > > > > > > > This reverts commit 3a0681c7448b174e5dcfd19e9079cdd281c35f1a.
> > > > > > > > > >
> > > > > > > > > > Turns out the patch breaks initialization of Toshiba THGBMNG5.
> > > > > > > > > > [    1.648951] mmc0: mmc_select_hs200 failed, error -84
> > > > > > > > > > [    1.648988] mmc0: error -84 whilst initialising MMC card
> > > > > > > > >
> > > > > > > > > For exactly this reason, when getting CRC errors on the first attempt,
> > > > > > > > > doing a retry makes little sense.
> > > > > > > > >
> > > > > > > > > I have looped in Chaotian who has some more details about the problem.
> > > > > > > > >
> > > > > > > > > In any case, Jan, what HW and mmc controller are you using?
> > > > > > > >
> > > > > > > > It's a custom board based on Amlogic A113D. The compatibility in dts
> > > > > > > > is set to "alogic,meson-axg-mmc".
> > > > > > >
> > > > > > > Good. I have looped in some of the relevant developers/maintainers.
> > > > > > >
> > > > > > > >
> > > > > > > > In the different revision of HW we are using Kingston EMMC04G. The
> > > > > > > > card has no such problem and is working fine without this patch.
> > > > > > > > We observed it only on mention Toshiba card.
> > > > > > >
> > > > > > > I see. Of course it would also be interesting to see what CMD6 command
> > > > > > > that is that fails. Would you mind adding some debug/trace to find out
> > > > > > > what command it is that fails?
> > > > > >
> > > > > > Providing a log with following debug option  `dyndbg="func mmc_mrq_pr_debug +p`
> > > > >
> > > > > Thanks!
> > > > >
> > > > > >
> > > > > > # dmesg | grep mmc0
> > > > > > [    1.557984] mmc0: starting CMD52 arg 00000c00 flags 00000195
> > > > > > [    1.563989] mmc0: starting CMD52 arg 80000c08 flags 00000195
> > > > > > [    1.575219] mmc0: starting CMD0 arg 00000000 flags 000000c0
> > > > > > [    1.593142] mmc0: starting CMD8 arg 000001aa flags 000002f5
> > > > > > [    1.604439] mmc0: starting CMD5 arg 00000000 flags 000002e1
> > > > > > [    1.623875] mmc0: starting CMD55 arg 00000000 flags 000000f5
> > > > > > [    1.631024] mmc0: starting CMD55 arg 00000000 flags 000000f5
> > > > > > [    1.640221] mmc0: starting CMD55 arg 00000000 flags 000000f5
> > > > > > [    1.646802] mmc0: starting CMD55 arg 00000000 flags 000000f5
> > > > > > [    1.652397] mmc0: starting CMD1 arg 00000000 flags 000000e1
> > > > > > [    1.669894] mmc0: starting CMD1 arg 40ff8080 flags 000000e1
> > > > > > [    1.682925] mmc0: starting CMD1 arg 40ff8080 flags 000000e1
> > > > > > [    1.697073] mmc0: starting CMD1 arg 40ff8080 flags 000000e1
> > > > > > [    1.704327] mmc0: starting CMD0 arg 00000000 flags 000000c0
> > > > > > [    1.722251] mmc0: starting CMD1 arg 40200000 flags 000000e1
> > > > > > [    1.745317] mmc0: starting CMD1 arg 40200000 flags 000000e1
> > > > > > [    1.752813] mmc0: starting CMD2 arg 00000000 flags 00000007
> > > > > > [    1.771731] mmc0: starting CMD3 arg 00010000 flags 00000015
> > > > > > [    1.784771] mmc0: starting CMD9 arg 00010000 flags 00000007
> > > > > > [    1.790433] mmc0: starting CMD7 arg 00010000 flags 00000015
> > > > > > [    1.795691] mmc0: starting CMD8 arg 00000000 flags 000000b5
> > > > > > [    1.800800] mmc0:     blksz 512 blocks 1 flags 00000200 tsac 50 ms nsac 0
> > > > > > [    1.818402] mmc0: starting CMD6 arg 03af0101 flags 0000049d
> > > > > > [    1.818845] mmc0: starting CMD13 arg 00010000 flags 00000195
> > > > > > [    1.824349] mmc0: starting CMD6 arg 03220101 flags 0000049d
> > > > > > [    1.829992] mmc0: starting CMD13 arg 00010000 flags 00000195
> > > > > > [    1.835493] mmc0: starting CMD6 arg 03b70201 flags 0000049d
> > > > > > [    1.841119] mmc0: starting CMD13 arg 00010000 flags 00000195
> > > > > > [    1.846628] mmc0: starting CMD8 arg 00000000 flags 000000b5
> > > > > > [    1.851719] mmc0:     blksz 512 blocks 1 flags 00000200 tsac 50 ms nsac 0
> > > > > > [    1.860347] mmc0: starting CMD6 arg 03b90201 flags 0000049d
> > > > > > [    1.864421] mmc0: mmc_select_hs200 failed, error -84
> > > > > > [    1.868892] mmc0: error -84 whilst initialising MMC card
> > > > >
> > > > > Alright, so the CMD6 command that tries to switch the card into HS200
> > > > > mode is the one that fails.
> > > > >
> > > > > >
> > > > > > I cannot provide more verbose logs. When I enable more it (f.e. file
> > > > > > core.c) the initialization of card was successful.
> > > > >
> > > > > That's an interesting observation!
> > > > >
> > > > > Perhaps the card is still in some kind of busy state, after the CMD8
> > > > > has been sent to read the EXT_CSD, when verifying the earlier bus
> > > > > width switch (mmc_compare_ext_csds()).
> > > >
> > > > I'm curious, do you know if there is a command that says if the card
> > > > is busy/ready?
> > >
> > > Yes, the CMD13.
> > >
> > > However, CMD13 is not allowed to be sent for some command sequences.
> > > For example sending CMD6 to switch to HS200 mode, is one case where we
> > > must avoid it.
> > >
> > > For these scenarios, either we rely on the host HW to detect when the
> > > card stop signals busy or we simply insert a delay (according to spec)
> > > after sending the CMD6 command.
> > >
> > > >
> > > > >
> > > > > > If you want to see any another logs fell free to ask.
> > > > >
> > > > > Would you mind trying one thing, in a way to narrow down the problem?
> > > > >
> > > > > Add a delay (msleep() or usleep_range() with some different values up
> > > > > to 50 ms) somewhere after mmc_compare_ext_csds() has been executed,
> > > > > but also before having mmc_select_bus_width() to return the error
> > > > > code?
> > > >
> > > > I've added msleep just before exit point of mmc_select_bus_width() and
> > > > observation is following
> > > > * 1ms or 2 ms - failing (time to time it was successfully initialized)
> > > > * 5 ms - success in all attempts
> > >
> > > Very good!
> > >
> > > Let me post a debug patch in short while, that can try to verify if
> > > the card is busy during this period.
> >
> > Here it is, please give it a try and see what happens.
> >
> > You may also want to run a second test, changing the second parameter
> > to false when calling poll_for_busy(), as that switches from CMD13 to
> > use of the host driver's ->card_busy() callback, when checking for
> > busy.
>
> I've applied the patch and test poll_for_busy() with different
> send_status parameter as you recommend (true/false).
> The outputs are the same
> [    1.526554] meson-gx-mmc ffe07000.mmc: allocated mmc-pwrseq
> [    1.682886] mmc0: mmc_select_hs200 failed, error -84
> [    1.693081] mmc0: error -84 whilst initialising MMC card

Alright, my guess that the card was busy was solely incorrect.

>
> >
> > Kind regards
> > Uffe
> >
> > From: Ulf Hansson <ulf.hansson@linaro.org>
> > Date: Thu, 29 Aug 2019 09:42:11 +0200
> > Subject: [PATCH] mmc: core: DEBUG for mmc_select_bus_width()
> >
> > Signed-off-by: Ulf Hansson <ulf.hansson@linaro.org>
> > ---
> >  drivers/mmc/core/mmc.c | 47 ++++++++++++++++++++++++++++++++++++++++++
> >  1 file changed, 47 insertions(+)
> >
> > diff --git a/drivers/mmc/core/mmc.c b/drivers/mmc/core/mmc.c
> > index c8804895595f..ff3a4c166f20 100644
> > --- a/drivers/mmc/core/mmc.c
> > +++ b/drivers/mmc/core/mmc.c
> > @@ -975,6 +975,52 @@ static void mmc_set_bus_speed(struct mmc_card *card)
> >         mmc_set_clock(card->host, max_dtr);
> >  }
> >
> > +static void poll_for_busy(struct mmc_card *card, bool send_status)
> > +{
> > +       struct mmc_host *host = card->host;
> > +       int err;
> > +       unsigned long timeout;
> > +       unsigned int timeout_ms = 5000;
> > +       u32 status = 0;
> > +       bool expired = false;
> > +       bool busy = false;
> > +
> > +       if (!send_status && !host->ops->card_busy) {
> > +               mmc_delay(timeout_ms);
>
> fyi this code hasn't been executed.

Yeah, thanks, expected.

>
> > +               return;
> > +       }
> > +
> > +       timeout = jiffies + msecs_to_jiffies(timeout_ms) + 1;
> > +       do {
> > +               expired = time_after(jiffies, timeout);
> > +               if (send_status) {
> > +                       err = __mmc_send_status(card, &status, 0);
>
> I've added some print here as well to see whats the value of the status
>
> +                       printk("%s: %s status=0x%x
> R1_CURRENT_STATE(status)=0x%x \n",
> +                               mmc_hostname(host),__func__, status,
> R1_CURRENT_STATE(status));

Great!

>
> [    1.676970] mmc0: poll_for_busy status=0x900 R1_CURRENT_STATE(status)=0x4

This means the card reports that it's "READY_FOR_DATA" and the current
state is the transfer state.

Nothing weird is going on at card side, it seems.

> [    1.685821] mmc0: mmc_select_hs200 failed, error -84
> [    1.698029] mmc0: error -84 whilst initialising MMC card

I am out of ideas. :-(

Perhaps the meson developers can think of something? Could it be that
the driver isn't behaving as it should when switching bus width? Maybe
something happens on pinctrl level?

Anyway, if no progress is made the next few days, let's do the revert.
And thanks a lot for helping out with the tests, etc!

Kind regards
Uffe

Jerome Brunet Aug. 30, 2019, 1:54 p.m. UTC | #11

On Fri 30 Aug 2019 at 13:07, Ulf Hansson <ulf.hansson@linaro.org> wrote:

> On Fri, 30 Aug 2019 at 12:01, Jan Kaisrlik <ja.kaisrlik@gmail.com> wrote:
>>
>> On Thu, Aug 29, 2019 at 9:50 AM Ulf Hansson <ulf.hansson@linaro.org> wrote:
>> >
>> > On Wed, 28 Aug 2019 at 12:44, Ulf Hansson <ulf.hansson@linaro.org> wrote:
>> > >
>> > > On Tue, 27 Aug 2019 at 17:55, Jan Kaisrlik <ja.kaisrlik@gmail.com> wrote:
>> > > >
>> > > > On Tue, Aug 27, 2019 at 3:14 PM Ulf Hansson <ulf.hansson@linaro.org> wrote:
>> > > > >
>> > > > > On Fri, 23 Aug 2019 at 11:36, Jan Kaisrlik <ja.kaisrlik@gmail.com> wrote:
>> > > > > >
>> > > > > > čt 22. 8. 2019 v 15:59 odesílatel Ulf Hansson <ulf.hansson@linaro.org> napsal:
>> > > > > > >
>> > > > > > > + some meson driver folkz
>> > > > > > >
>> > > > > > > On Thu, 22 Aug 2019 at 10:27, Jan Kaisrlik <ja.kaisrlik@gmail.com> wrote:
>> > > > > > > >
>> > > > > > > > st 21. 8. 2019 v 17:12 odesílatel Ulf Hansson <ulf.hansson@linaro.org> napsal:
>> > > > > > > > >
>> > > > > > > > > + Chaotian Jing
>> > > > > > > > >
>> > > > > > > > > On Tue, 20 Aug 2019 at 13:42, <ja.kaisrlik@gmail.com> wrote:
>> > > > > > > > > >
>> > > > > > > > > > From: Jan Kaisrlik <ja.kaisrlik@gmail.com>
>> > > > > > > > > >
>> > > > > > > > > > This reverts commit 3a0681c7448b174e5dcfd19e9079cdd281c35f1a.
>> > > > > > > > > >
>> > > > > > > > > > Turns out the patch breaks initialization of Toshiba THGBMNG5.
>> > > > > > > > > > [    1.648951] mmc0: mmc_select_hs200 failed, error -84
>> > > > > > > > > > [    1.648988] mmc0: error -84 whilst initialising MMC card
>> > > > > > > > >
>> > > > > > > > > For exactly this reason, when getting CRC errors on the first attempt,
>> > > > > > > > > doing a retry makes little sense.
>> > > > > > > > >
>> > > > > > > > > I have looped in Chaotian who has some more details about the problem.
>> > > > > > > > >
>> > > > > > > > > In any case, Jan, what HW and mmc controller are you using?
>> > > > > > > >
>> > > > > > > > It's a custom board based on Amlogic A113D. The compatibility in dts
>> > > > > > > > is set to "alogic,meson-axg-mmc".
>> > > > > > >
>> > > > > > > Good. I have looped in some of the relevant developers/maintainers.
>> > > > > > >
>> > > > > > > >
>> > > > > > > > In the different revision of HW we are using Kingston EMMC04G. The
>> > > > > > > > card has no such problem and is working fine without this patch.
>> > > > > > > > We observed it only on mention Toshiba card.
>> > > > > > >
>> > > > > > > I see. Of course it would also be interesting to see what CMD6 command
>> > > > > > > that is that fails. Would you mind adding some debug/trace to find out
>> > > > > > > what command it is that fails?
>> > > > > >
>> > > > > > Providing a log with following debug option  `dyndbg="func mmc_mrq_pr_debug +p`
>> > > > >
>> > > > > Thanks!
>> > > > >
>> > > > > >
>> > > > > > # dmesg | grep mmc0
>> > > > > > [    1.557984] mmc0: starting CMD52 arg 00000c00 flags 00000195
>> > > > > > [    1.563989] mmc0: starting CMD52 arg 80000c08 flags 00000195
>> > > > > > [    1.575219] mmc0: starting CMD0 arg 00000000 flags 000000c0
>> > > > > > [    1.593142] mmc0: starting CMD8 arg 000001aa flags 000002f5
>> > > > > > [    1.604439] mmc0: starting CMD5 arg 00000000 flags 000002e1
>> > > > > > [    1.623875] mmc0: starting CMD55 arg 00000000 flags 000000f5
>> > > > > > [    1.631024] mmc0: starting CMD55 arg 00000000 flags 000000f5
>> > > > > > [    1.640221] mmc0: starting CMD55 arg 00000000 flags 000000f5
>> > > > > > [    1.646802] mmc0: starting CMD55 arg 00000000 flags 000000f5
>> > > > > > [    1.652397] mmc0: starting CMD1 arg 00000000 flags 000000e1
>> > > > > > [    1.669894] mmc0: starting CMD1 arg 40ff8080 flags 000000e1
>> > > > > > [    1.682925] mmc0: starting CMD1 arg 40ff8080 flags 000000e1
>> > > > > > [    1.697073] mmc0: starting CMD1 arg 40ff8080 flags 000000e1
>> > > > > > [    1.704327] mmc0: starting CMD0 arg 00000000 flags 000000c0
>> > > > > > [    1.722251] mmc0: starting CMD1 arg 40200000 flags 000000e1
>> > > > > > [    1.745317] mmc0: starting CMD1 arg 40200000 flags 000000e1
>> > > > > > [    1.752813] mmc0: starting CMD2 arg 00000000 flags 00000007
>> > > > > > [    1.771731] mmc0: starting CMD3 arg 00010000 flags 00000015
>> > > > > > [    1.784771] mmc0: starting CMD9 arg 00010000 flags 00000007
>> > > > > > [    1.790433] mmc0: starting CMD7 arg 00010000 flags 00000015
>> > > > > > [    1.795691] mmc0: starting CMD8 arg 00000000 flags 000000b5
>> > > > > > [    1.800800] mmc0:     blksz 512 blocks 1 flags 00000200 tsac 50 ms nsac 0
>> > > > > > [    1.818402] mmc0: starting CMD6 arg 03af0101 flags 0000049d
>> > > > > > [    1.818845] mmc0: starting CMD13 arg 00010000 flags 00000195
>> > > > > > [    1.824349] mmc0: starting CMD6 arg 03220101 flags 0000049d
>> > > > > > [    1.829992] mmc0: starting CMD13 arg 00010000 flags 00000195
>> > > > > > [    1.835493] mmc0: starting CMD6 arg 03b70201 flags 0000049d
>> > > > > > [    1.841119] mmc0: starting CMD13 arg 00010000 flags 00000195
>> > > > > > [    1.846628] mmc0: starting CMD8 arg 00000000 flags 000000b5
>> > > > > > [    1.851719] mmc0:     blksz 512 blocks 1 flags 00000200 tsac 50 ms nsac 0
>> > > > > > [    1.860347] mmc0: starting CMD6 arg 03b90201 flags 0000049d
>> > > > > > [    1.864421] mmc0: mmc_select_hs200 failed, error -84
>> > > > > > [    1.868892] mmc0: error -84 whilst initialising MMC card
>> > > > >
>> > > > > Alright, so the CMD6 command that tries to switch the card into HS200
>> > > > > mode is the one that fails.
>> > > > >
>> > > > > >
>> > > > > > I cannot provide more verbose logs. When I enable more it (f.e. file
>> > > > > > core.c) the initialization of card was successful.
>> > > > >
>> > > > > That's an interesting observation!
>> > > > >
>> > > > > Perhaps the card is still in some kind of busy state, after the CMD8
>> > > > > has been sent to read the EXT_CSD, when verifying the earlier bus
>> > > > > width switch (mmc_compare_ext_csds()).
>> > > >
>> > > > I'm curious, do you know if there is a command that says if the card
>> > > > is busy/ready?
>> > >
>> > > Yes, the CMD13.
>> > >
>> > > However, CMD13 is not allowed to be sent for some command sequences.
>> > > For example sending CMD6 to switch to HS200 mode, is one case where we
>> > > must avoid it.
>> > >
>> > > For these scenarios, either we rely on the host HW to detect when the
>> > > card stop signals busy or we simply insert a delay (according to spec)
>> > > after sending the CMD6 command.
>> > >
>> > > >
>> > > > >
>> > > > > > If you want to see any another logs fell free to ask.
>> > > > >
>> > > > > Would you mind trying one thing, in a way to narrow down the problem?
>> > > > >
>> > > > > Add a delay (msleep() or usleep_range() with some different values up
>> > > > > to 50 ms) somewhere after mmc_compare_ext_csds() has been executed,
>> > > > > but also before having mmc_select_bus_width() to return the error
>> > > > > code?
>> > > >
>> > > > I've added msleep just before exit point of mmc_select_bus_width() and
>> > > > observation is following
>> > > > * 1ms or 2 ms - failing (time to time it was successfully initialized)
>> > > > * 5 ms - success in all attempts
>> > >
>> > > Very good!
>> > >
>> > > Let me post a debug patch in short while, that can try to verify if
>> > > the card is busy during this period.
>> >
>> > Here it is, please give it a try and see what happens.
>> >
>> > You may also want to run a second test, changing the second parameter
>> > to false when calling poll_for_busy(), as that switches from CMD13 to
>> > use of the host driver's ->card_busy() callback, when checking for
>> > busy.
>>
>> I've applied the patch and test poll_for_busy() with different
>> send_status parameter as you recommend (true/false).
>> The outputs are the same
>> [    1.526554] meson-gx-mmc ffe07000.mmc: allocated mmc-pwrseq
>> [    1.682886] mmc0: mmc_select_hs200 failed, error -84
>> [    1.693081] mmc0: error -84 whilst initialising MMC card
>
> Alright, my guess that the card was busy was solely incorrect.
>
>>
>> >
>> > Kind regards
>> > Uffe
>> >
>> > From: Ulf Hansson <ulf.hansson@linaro.org>
>> > Date: Thu, 29 Aug 2019 09:42:11 +0200
>> > Subject: [PATCH] mmc: core: DEBUG for mmc_select_bus_width()
>> >
>> > Signed-off-by: Ulf Hansson <ulf.hansson@linaro.org>
>> > ---
>> >  drivers/mmc/core/mmc.c | 47 ++++++++++++++++++++++++++++++++++++++++++
>> >  1 file changed, 47 insertions(+)
>> >
>> > diff --git a/drivers/mmc/core/mmc.c b/drivers/mmc/core/mmc.c
>> > index c8804895595f..ff3a4c166f20 100644
>> > --- a/drivers/mmc/core/mmc.c
>> > +++ b/drivers/mmc/core/mmc.c
>> > @@ -975,6 +975,52 @@ static void mmc_set_bus_speed(struct mmc_card *card)
>> >         mmc_set_clock(card->host, max_dtr);
>> >  }
>> >
>> > +static void poll_for_busy(struct mmc_card *card, bool send_status)
>> > +{
>> > +       struct mmc_host *host = card->host;
>> > +       int err;
>> > +       unsigned long timeout;
>> > +       unsigned int timeout_ms = 5000;
>> > +       u32 status = 0;
>> > +       bool expired = false;
>> > +       bool busy = false;
>> > +
>> > +       if (!send_status && !host->ops->card_busy) {
>> > +               mmc_delay(timeout_ms);
>>
>> fyi this code hasn't been executed.
>
> Yeah, thanks, expected.
>
>>
>> > +               return;
>> > +       }
>> > +
>> > +       timeout = jiffies + msecs_to_jiffies(timeout_ms) + 1;
>> > +       do {
>> > +               expired = time_after(jiffies, timeout);
>> > +               if (send_status) {
>> > +                       err = __mmc_send_status(card, &status, 0);
>>
>> I've added some print here as well to see whats the value of the status
>>
>> +                       printk("%s: %s status=0x%x
>> R1_CURRENT_STATE(status)=0x%x \n",
>> +                               mmc_hostname(host),__func__, status,
>> R1_CURRENT_STATE(status));
>
> Great!
>
>>
>> [    1.676970] mmc0: poll_for_busy status=0x900 R1_CURRENT_STATE(status)=0x4
>
> This means the card reports that it's "READY_FOR_DATA" and the current
> state is the transfer state.
>
> Nothing weird is going on at card side, it seems.
>
>> [    1.685821] mmc0: mmc_select_hs200 failed, error -84
>> [    1.698029] mmc0: error -84 whilst initialising MMC card
>
> I am out of ideas. :-(
>
> Perhaps the meson developers can think of something? Could it be that
> the driver isn't behaving as it should when switching bus width? Maybe
> something happens on pinctrl level?

I have not seen this particular issue myself. Since the last round of
updates we did a few month ago, things have been quite stable

We get our information only from the datasheet and vendor code. These
are publicly available and it has proved quite insufficient judging by
the number of issue we had in the past years.

IOW, we would love to know more about this controller too ;)

So, to answer your question, AFAIK, there is nothing special regarding
bus width switch ...

Regarding pinctrl, I think there a bias-pull-up on data line set in DT.
Maybe it's worth trying to disable that a see how it goes ?

OTOH, it this was the problem, I wonder how it could have got this far
and why a delay would help ?

>
> Anyway, if no progress is made the next few days, let's do the revert.
> And thanks a lot for helping out with the tests, etc!
>
> Kind regards
> Uffe

Jan Kaisrlik Sept. 2, 2019, 8:28 a.m. UTC | #12

On Fri, Aug 30, 2019 at 3:54 PM Jerome Brunet <jbrunet@baylibre.com> wrote:
>
> On Fri 30 Aug 2019 at 13:07, Ulf Hansson <ulf.hansson@linaro.org> wrote:
>
> > On Fri, 30 Aug 2019 at 12:01, Jan Kaisrlik <ja.kaisrlik@gmail.com> wrote:
> >>
> >> On Thu, Aug 29, 2019 at 9:50 AM Ulf Hansson <ulf.hansson@linaro.org> wrote:
> >> >
> >> > On Wed, 28 Aug 2019 at 12:44, Ulf Hansson <ulf.hansson@linaro.org> wrote:
> >> > >
> >> > > On Tue, 27 Aug 2019 at 17:55, Jan Kaisrlik <ja.kaisrlik@gmail.com> wrote:
> >> > > >
> >> > > > On Tue, Aug 27, 2019 at 3:14 PM Ulf Hansson <ulf.hansson@linaro.org> wrote:
> >> > > > >
> >> > > > > On Fri, 23 Aug 2019 at 11:36, Jan Kaisrlik <ja.kaisrlik@gmail.com> wrote:
> >> > > > > >
> >> > > > > > čt 22. 8. 2019 v 15:59 odesílatel Ulf Hansson <ulf.hansson@linaro.org> napsal:
> >> > > > > > >
> >> > > > > > > + some meson driver folkz
> >> > > > > > >
> >> > > > > > > On Thu, 22 Aug 2019 at 10:27, Jan Kaisrlik <ja.kaisrlik@gmail.com> wrote:
> >> > > > > > > >
> >> > > > > > > > st 21. 8. 2019 v 17:12 odesílatel Ulf Hansson <ulf.hansson@linaro.org> napsal:
> >> > > > > > > > >
> >> > > > > > > > > + Chaotian Jing
> >> > > > > > > > >
> >> > > > > > > > > On Tue, 20 Aug 2019 at 13:42, <ja.kaisrlik@gmail.com> wrote:
> >> > > > > > > > > >
> >> > > > > > > > > > From: Jan Kaisrlik <ja.kaisrlik@gmail.com>
> >> > > > > > > > > >
> >> > > > > > > > > > This reverts commit 3a0681c7448b174e5dcfd19e9079cdd281c35f1a.
> >> > > > > > > > > >
> >> > > > > > > > > > Turns out the patch breaks initialization of Toshiba THGBMNG5.
> >> > > > > > > > > > [    1.648951] mmc0: mmc_select_hs200 failed, error -84
> >> > > > > > > > > > [    1.648988] mmc0: error -84 whilst initialising MMC card
> >> > > > > > > > >
> >> > > > > > > > > For exactly this reason, when getting CRC errors on the first attempt,
> >> > > > > > > > > doing a retry makes little sense.
> >> > > > > > > > >
> >> > > > > > > > > I have looped in Chaotian who has some more details about the problem.
> >> > > > > > > > >
> >> > > > > > > > > In any case, Jan, what HW and mmc controller are you using?
> >> > > > > > > >
> >> > > > > > > > It's a custom board based on Amlogic A113D. The compatibility in dts
> >> > > > > > > > is set to "alogic,meson-axg-mmc".
> >> > > > > > >
> >> > > > > > > Good. I have looped in some of the relevant developers/maintainers.
> >> > > > > > >
> >> > > > > > > >
> >> > > > > > > > In the different revision of HW we are using Kingston EMMC04G. The
> >> > > > > > > > card has no such problem and is working fine without this patch.
> >> > > > > > > > We observed it only on mention Toshiba card.
> >> > > > > > >
> >> > > > > > > I see. Of course it would also be interesting to see what CMD6 command
> >> > > > > > > that is that fails. Would you mind adding some debug/trace to find out
> >> > > > > > > what command it is that fails?
> >> > > > > >
> >> > > > > > Providing a log with following debug option  `dyndbg="func mmc_mrq_pr_debug +p`
> >> > > > >
> >> > > > > Thanks!
> >> > > > >
> >> > > > > >
> >> > > > > > # dmesg | grep mmc0
> >> > > > > > [    1.557984] mmc0: starting CMD52 arg 00000c00 flags 00000195
> >> > > > > > [    1.563989] mmc0: starting CMD52 arg 80000c08 flags 00000195
> >> > > > > > [    1.575219] mmc0: starting CMD0 arg 00000000 flags 000000c0
> >> > > > > > [    1.593142] mmc0: starting CMD8 arg 000001aa flags 000002f5
> >> > > > > > [    1.604439] mmc0: starting CMD5 arg 00000000 flags 000002e1
> >> > > > > > [    1.623875] mmc0: starting CMD55 arg 00000000 flags 000000f5
> >> > > > > > [    1.631024] mmc0: starting CMD55 arg 00000000 flags 000000f5
> >> > > > > > [    1.640221] mmc0: starting CMD55 arg 00000000 flags 000000f5
> >> > > > > > [    1.646802] mmc0: starting CMD55 arg 00000000 flags 000000f5
> >> > > > > > [    1.652397] mmc0: starting CMD1 arg 00000000 flags 000000e1
> >> > > > > > [    1.669894] mmc0: starting CMD1 arg 40ff8080 flags 000000e1
> >> > > > > > [    1.682925] mmc0: starting CMD1 arg 40ff8080 flags 000000e1
> >> > > > > > [    1.697073] mmc0: starting CMD1 arg 40ff8080 flags 000000e1
> >> > > > > > [    1.704327] mmc0: starting CMD0 arg 00000000 flags 000000c0
> >> > > > > > [    1.722251] mmc0: starting CMD1 arg 40200000 flags 000000e1
> >> > > > > > [    1.745317] mmc0: starting CMD1 arg 40200000 flags 000000e1
> >> > > > > > [    1.752813] mmc0: starting CMD2 arg 00000000 flags 00000007
> >> > > > > > [    1.771731] mmc0: starting CMD3 arg 00010000 flags 00000015
> >> > > > > > [    1.784771] mmc0: starting CMD9 arg 00010000 flags 00000007
> >> > > > > > [    1.790433] mmc0: starting CMD7 arg 00010000 flags 00000015
> >> > > > > > [    1.795691] mmc0: starting CMD8 arg 00000000 flags 000000b5
> >> > > > > > [    1.800800] mmc0:     blksz 512 blocks 1 flags 00000200 tsac 50 ms nsac 0
> >> > > > > > [    1.818402] mmc0: starting CMD6 arg 03af0101 flags 0000049d
> >> > > > > > [    1.818845] mmc0: starting CMD13 arg 00010000 flags 00000195
> >> > > > > > [    1.824349] mmc0: starting CMD6 arg 03220101 flags 0000049d
> >> > > > > > [    1.829992] mmc0: starting CMD13 arg 00010000 flags 00000195
> >> > > > > > [    1.835493] mmc0: starting CMD6 arg 03b70201 flags 0000049d
> >> > > > > > [    1.841119] mmc0: starting CMD13 arg 00010000 flags 00000195
> >> > > > > > [    1.846628] mmc0: starting CMD8 arg 00000000 flags 000000b5
> >> > > > > > [    1.851719] mmc0:     blksz 512 blocks 1 flags 00000200 tsac 50 ms nsac 0
> >> > > > > > [    1.860347] mmc0: starting CMD6 arg 03b90201 flags 0000049d
> >> > > > > > [    1.864421] mmc0: mmc_select_hs200 failed, error -84
> >> > > > > > [    1.868892] mmc0: error -84 whilst initialising MMC card
> >> > > > >
> >> > > > > Alright, so the CMD6 command that tries to switch the card into HS200
> >> > > > > mode is the one that fails.
> >> > > > >
> >> > > > > >
> >> > > > > > I cannot provide more verbose logs. When I enable more it (f.e. file
> >> > > > > > core.c) the initialization of card was successful.
> >> > > > >
> >> > > > > That's an interesting observation!
> >> > > > >
> >> > > > > Perhaps the card is still in some kind of busy state, after the CMD8
> >> > > > > has been sent to read the EXT_CSD, when verifying the earlier bus
> >> > > > > width switch (mmc_compare_ext_csds()).
> >> > > >
> >> > > > I'm curious, do you know if there is a command that says if the card
> >> > > > is busy/ready?
> >> > >
> >> > > Yes, the CMD13.
> >> > >
> >> > > However, CMD13 is not allowed to be sent for some command sequences.
> >> > > For example sending CMD6 to switch to HS200 mode, is one case where we
> >> > > must avoid it.
> >> > >
> >> > > For these scenarios, either we rely on the host HW to detect when the
> >> > > card stop signals busy or we simply insert a delay (according to spec)
> >> > > after sending the CMD6 command.
> >> > >
> >> > > >
> >> > > > >
> >> > > > > > If you want to see any another logs fell free to ask.
> >> > > > >
> >> > > > > Would you mind trying one thing, in a way to narrow down the problem?
> >> > > > >
> >> > > > > Add a delay (msleep() or usleep_range() with some different values up
> >> > > > > to 50 ms) somewhere after mmc_compare_ext_csds() has been executed,
> >> > > > > but also before having mmc_select_bus_width() to return the error
> >> > > > > code?
> >> > > >
> >> > > > I've added msleep just before exit point of mmc_select_bus_width() and
> >> > > > observation is following
> >> > > > * 1ms or 2 ms - failing (time to time it was successfully initialized)
> >> > > > * 5 ms - success in all attempts
> >> > >
> >> > > Very good!
> >> > >
> >> > > Let me post a debug patch in short while, that can try to verify if
> >> > > the card is busy during this period.
> >> >
> >> > Here it is, please give it a try and see what happens.
> >> >
> >> > You may also want to run a second test, changing the second parameter
> >> > to false when calling poll_for_busy(), as that switches from CMD13 to
> >> > use of the host driver's ->card_busy() callback, when checking for
> >> > busy.
> >>
> >> I've applied the patch and test poll_for_busy() with different
> >> send_status parameter as you recommend (true/false).
> >> The outputs are the same
> >> [    1.526554] meson-gx-mmc ffe07000.mmc: allocated mmc-pwrseq
> >> [    1.682886] mmc0: mmc_select_hs200 failed, error -84
> >> [    1.693081] mmc0: error -84 whilst initialising MMC card
> >
> > Alright, my guess that the card was busy was solely incorrect.
> >
> >>
> >> >
> >> > Kind regards
> >> > Uffe
> >> >
> >> > From: Ulf Hansson <ulf.hansson@linaro.org>
> >> > Date: Thu, 29 Aug 2019 09:42:11 +0200
> >> > Subject: [PATCH] mmc: core: DEBUG for mmc_select_bus_width()
> >> >
> >> > Signed-off-by: Ulf Hansson <ulf.hansson@linaro.org>
> >> > ---
> >> >  drivers/mmc/core/mmc.c | 47 ++++++++++++++++++++++++++++++++++++++++++
> >> >  1 file changed, 47 insertions(+)
> >> >
> >> > diff --git a/drivers/mmc/core/mmc.c b/drivers/mmc/core/mmc.c
> >> > index c8804895595f..ff3a4c166f20 100644
> >> > --- a/drivers/mmc/core/mmc.c
> >> > +++ b/drivers/mmc/core/mmc.c
> >> > @@ -975,6 +975,52 @@ static void mmc_set_bus_speed(struct mmc_card *card)
> >> >         mmc_set_clock(card->host, max_dtr);
> >> >  }
> >> >
> >> > +static void poll_for_busy(struct mmc_card *card, bool send_status)
> >> > +{
> >> > +       struct mmc_host *host = card->host;
> >> > +       int err;
> >> > +       unsigned long timeout;
> >> > +       unsigned int timeout_ms = 5000;
> >> > +       u32 status = 0;
> >> > +       bool expired = false;
> >> > +       bool busy = false;
> >> > +
> >> > +       if (!send_status && !host->ops->card_busy) {
> >> > +               mmc_delay(timeout_ms);
> >>
> >> fyi this code hasn't been executed.
> >
> > Yeah, thanks, expected.
> >
> >>
> >> > +               return;
> >> > +       }
> >> > +
> >> > +       timeout = jiffies + msecs_to_jiffies(timeout_ms) + 1;
> >> > +       do {
> >> > +               expired = time_after(jiffies, timeout);
> >> > +               if (send_status) {
> >> > +                       err = __mmc_send_status(card, &status, 0);
> >>
> >> I've added some print here as well to see whats the value of the status
> >>
> >> +                       printk("%s: %s status=0x%x
> >> R1_CURRENT_STATE(status)=0x%x \n",
> >> +                               mmc_hostname(host),__func__, status,
> >> R1_CURRENT_STATE(status));
> >
> > Great!
> >
> >>
> >> [    1.676970] mmc0: poll_for_busy status=0x900 R1_CURRENT_STATE(status)=0x4
> >
> > This means the card reports that it's "READY_FOR_DATA" and the current
> > state is the transfer state.
> >
> > Nothing weird is going on at card side, it seems.
> >
> >> [    1.685821] mmc0: mmc_select_hs200 failed, error -84
> >> [    1.698029] mmc0: error -84 whilst initialising MMC card
> >
> > I am out of ideas. :-(
> >
> > Perhaps the meson developers can think of something? Could it be that
> > the driver isn't behaving as it should when switching bus width? Maybe
> > something happens on pinctrl level?
>
> I have not seen this particular issue myself. Since the last round of
> updates we did a few month ago, things have been quite stable
>
> We get our information only from the datasheet and vendor code. These
> are publicly available and it has proved quite insufficient judging by
> the number of issue we had in the past years.
>
> IOW, we would love to know more about this controller too ;)

Amlogic A113D, Avast Omni - I think you are familiar with this
particular device :]

>
> So, to answer your question, AFAIK, there is nothing special regarding
> bus width switch ...
>
> Regarding pinctrl, I think there a bias-pull-up on data line set in DT.
> Maybe it's worth trying to disable that a see how it goes ?

It did not help.

Best regards,
Jan

>
> OTOH, it this was the problem, I wonder how it could have got this far
> and why a delay would help ?
>
> >
> > Anyway, if no progress is made the next few days, let's do the revert.
> > And thanks a lot for helping out with the tests, etc!
> >
> > Kind regards
> > Uffe

Jerome Brunet Sept. 2, 2019, 8:44 a.m. UTC | #13

On Mon 02 Sep 2019 at 10:28, Jan Kaisrlik <ja.kaisrlik@gmail.com> wrote:

> On Fri, Aug 30, 2019 at 3:54 PM Jerome Brunet <jbrunet@baylibre.com> wrote:
>>
>> On Fri 30 Aug 2019 at 13:07, Ulf Hansson <ulf.hansson@linaro.org> wrote:
>>
>> > On Fri, 30 Aug 2019 at 12:01, Jan Kaisrlik <ja.kaisrlik@gmail.com> wrote:
>> >>
>> >> On Thu, Aug 29, 2019 at 9:50 AM Ulf Hansson <ulf.hansson@linaro.org> wrote:
>> >> >
>> >> > On Wed, 28 Aug 2019 at 12:44, Ulf Hansson <ulf.hansson@linaro.org> wrote:
>> >> > >
>> >> > > On Tue, 27 Aug 2019 at 17:55, Jan Kaisrlik <ja.kaisrlik@gmail.com> wrote:
>> >> > > >
>> >> > > > On Tue, Aug 27, 2019 at 3:14 PM Ulf Hansson <ulf.hansson@linaro.org> wrote:
>> >> > > > >
>> >> > > > > On Fri, 23 Aug 2019 at 11:36, Jan Kaisrlik <ja.kaisrlik@gmail.com> wrote:
>> >> > > > > >
>> >> > > > > > čt 22. 8. 2019 v 15:59 odesílatel Ulf Hansson <ulf.hansson@linaro.org> napsal:
>> >> > > > > > >
>> >> > > > > > > + some meson driver folkz
>> >> > > > > > >
>> >> > > > > > > On Thu, 22 Aug 2019 at 10:27, Jan Kaisrlik <ja.kaisrlik@gmail.com> wrote:
>> >> > > > > > > >
>> >> > > > > > > > st 21. 8. 2019 v 17:12 odesílatel Ulf Hansson <ulf.hansson@linaro.org> napsal:
>> >> > > > > > > > >
>> >> > > > > > > > > + Chaotian Jing
>> >> > > > > > > > >
>> >> > > > > > > > > On Tue, 20 Aug 2019 at 13:42, <ja.kaisrlik@gmail.com> wrote:
>> >> > > > > > > > > >
>> >> > > > > > > > > > From: Jan Kaisrlik <ja.kaisrlik@gmail.com>
>> >> > > > > > > > > >
>> >> > > > > > > > > > This reverts commit 3a0681c7448b174e5dcfd19e9079cdd281c35f1a.
>> >> > > > > > > > > >
>> >> > > > > > > > > > Turns out the patch breaks initialization of Toshiba THGBMNG5.
>> >> > > > > > > > > > [    1.648951] mmc0: mmc_select_hs200 failed, error -84
>> >> > > > > > > > > > [    1.648988] mmc0: error -84 whilst initialising MMC card
>> >> > > > > > > > >
>> >> > > > > > > > > For exactly this reason, when getting CRC errors on the first attempt,
>> >> > > > > > > > > doing a retry makes little sense.
>> >> > > > > > > > >
>> >> > > > > > > > > I have looped in Chaotian who has some more details about the problem.
>> >> > > > > > > > >
>> >> > > > > > > > > In any case, Jan, what HW and mmc controller are you using?
>> >> > > > > > > >
>> >> > > > > > > > It's a custom board based on Amlogic A113D. The compatibility in dts
>> >> > > > > > > > is set to "alogic,meson-axg-mmc".
>> >> > > > > > >
>> >> > > > > > > Good. I have looped in some of the relevant developers/maintainers.
>> >> > > > > > >
>> >> > > > > > > >
>> >> > > > > > > > In the different revision of HW we are using Kingston EMMC04G. The
>> >> > > > > > > > card has no such problem and is working fine without this patch.
>> >> > > > > > > > We observed it only on mention Toshiba card.
>> >> > > > > > >
>> >> > > > > > > I see. Of course it would also be interesting to see what CMD6 command
>> >> > > > > > > that is that fails. Would you mind adding some debug/trace to find out
>> >> > > > > > > what command it is that fails?
>> >> > > > > >
>> >> > > > > > Providing a log with following debug option  `dyndbg="func mmc_mrq_pr_debug +p`
>> >> > > > >
>> >> > > > > Thanks!
>> >> > > > >
>> >> > > > > >
>> >> > > > > > # dmesg | grep mmc0
>> >> > > > > > [    1.557984] mmc0: starting CMD52 arg 00000c00 flags 00000195
>> >> > > > > > [    1.563989] mmc0: starting CMD52 arg 80000c08 flags 00000195
>> >> > > > > > [    1.575219] mmc0: starting CMD0 arg 00000000 flags 000000c0
>> >> > > > > > [    1.593142] mmc0: starting CMD8 arg 000001aa flags 000002f5
>> >> > > > > > [    1.604439] mmc0: starting CMD5 arg 00000000 flags 000002e1
>> >> > > > > > [    1.623875] mmc0: starting CMD55 arg 00000000 flags 000000f5
>> >> > > > > > [    1.631024] mmc0: starting CMD55 arg 00000000 flags 000000f5
>> >> > > > > > [    1.640221] mmc0: starting CMD55 arg 00000000 flags 000000f5
>> >> > > > > > [    1.646802] mmc0: starting CMD55 arg 00000000 flags 000000f5
>> >> > > > > > [    1.652397] mmc0: starting CMD1 arg 00000000 flags 000000e1
>> >> > > > > > [    1.669894] mmc0: starting CMD1 arg 40ff8080 flags 000000e1
>> >> > > > > > [    1.682925] mmc0: starting CMD1 arg 40ff8080 flags 000000e1
>> >> > > > > > [    1.697073] mmc0: starting CMD1 arg 40ff8080 flags 000000e1
>> >> > > > > > [    1.704327] mmc0: starting CMD0 arg 00000000 flags 000000c0
>> >> > > > > > [    1.722251] mmc0: starting CMD1 arg 40200000 flags 000000e1
>> >> > > > > > [    1.745317] mmc0: starting CMD1 arg 40200000 flags 000000e1
>> >> > > > > > [    1.752813] mmc0: starting CMD2 arg 00000000 flags 00000007
>> >> > > > > > [    1.771731] mmc0: starting CMD3 arg 00010000 flags 00000015
>> >> > > > > > [    1.784771] mmc0: starting CMD9 arg 00010000 flags 00000007
>> >> > > > > > [    1.790433] mmc0: starting CMD7 arg 00010000 flags 00000015
>> >> > > > > > [    1.795691] mmc0: starting CMD8 arg 00000000 flags 000000b5
>> >> > > > > > [    1.800800] mmc0:     blksz 512 blocks 1 flags 00000200 tsac 50 ms nsac 0
>> >> > > > > > [    1.818402] mmc0: starting CMD6 arg 03af0101 flags 0000049d
>> >> > > > > > [    1.818845] mmc0: starting CMD13 arg 00010000 flags 00000195
>> >> > > > > > [    1.824349] mmc0: starting CMD6 arg 03220101 flags 0000049d
>> >> > > > > > [    1.829992] mmc0: starting CMD13 arg 00010000 flags 00000195
>> >> > > > > > [    1.835493] mmc0: starting CMD6 arg 03b70201 flags 0000049d
>> >> > > > > > [    1.841119] mmc0: starting CMD13 arg 00010000 flags 00000195
>> >> > > > > > [    1.846628] mmc0: starting CMD8 arg 00000000 flags 000000b5
>> >> > > > > > [    1.851719] mmc0:     blksz 512 blocks 1 flags 00000200 tsac 50 ms nsac 0
>> >> > > > > > [    1.860347] mmc0: starting CMD6 arg 03b90201 flags 0000049d
>> >> > > > > > [    1.864421] mmc0: mmc_select_hs200 failed, error -84
>> >> > > > > > [    1.868892] mmc0: error -84 whilst initialising MMC card
>> >> > > > >
>> >> > > > > Alright, so the CMD6 command that tries to switch the card into HS200
>> >> > > > > mode is the one that fails.
>> >> > > > >
>> >> > > > > >
>> >> > > > > > I cannot provide more verbose logs. When I enable more it (f.e. file
>> >> > > > > > core.c) the initialization of card was successful.
>> >> > > > >
>> >> > > > > That's an interesting observation!
>> >> > > > >
>> >> > > > > Perhaps the card is still in some kind of busy state, after the CMD8
>> >> > > > > has been sent to read the EXT_CSD, when verifying the earlier bus
>> >> > > > > width switch (mmc_compare_ext_csds()).
>> >> > > >
>> >> > > > I'm curious, do you know if there is a command that says if the card
>> >> > > > is busy/ready?
>> >> > >
>> >> > > Yes, the CMD13.
>> >> > >
>> >> > > However, CMD13 is not allowed to be sent for some command sequences.
>> >> > > For example sending CMD6 to switch to HS200 mode, is one case where we
>> >> > > must avoid it.
>> >> > >
>> >> > > For these scenarios, either we rely on the host HW to detect when the
>> >> > > card stop signals busy or we simply insert a delay (according to spec)
>> >> > > after sending the CMD6 command.
>> >> > >
>> >> > > >
>> >> > > > >
>> >> > > > > > If you want to see any another logs fell free to ask.
>> >> > > > >
>> >> > > > > Would you mind trying one thing, in a way to narrow down the problem?
>> >> > > > >
>> >> > > > > Add a delay (msleep() or usleep_range() with some different values up
>> >> > > > > to 50 ms) somewhere after mmc_compare_ext_csds() has been executed,
>> >> > > > > but also before having mmc_select_bus_width() to return the error
>> >> > > > > code?
>> >> > > >
>> >> > > > I've added msleep just before exit point of mmc_select_bus_width() and
>> >> > > > observation is following
>> >> > > > * 1ms or 2 ms - failing (time to time it was successfully initialized)
>> >> > > > * 5 ms - success in all attempts
>> >> > >
>> >> > > Very good!
>> >> > >
>> >> > > Let me post a debug patch in short while, that can try to verify if
>> >> > > the card is busy during this period.
>> >> >
>> >> > Here it is, please give it a try and see what happens.
>> >> >
>> >> > You may also want to run a second test, changing the second parameter
>> >> > to false when calling poll_for_busy(), as that switches from CMD13 to
>> >> > use of the host driver's ->card_busy() callback, when checking for
>> >> > busy.
>> >>
>> >> I've applied the patch and test poll_for_busy() with different
>> >> send_status parameter as you recommend (true/false).
>> >> The outputs are the same
>> >> [    1.526554] meson-gx-mmc ffe07000.mmc: allocated mmc-pwrseq
>> >> [    1.682886] mmc0: mmc_select_hs200 failed, error -84
>> >> [    1.693081] mmc0: error -84 whilst initialising MMC card
>> >
>> > Alright, my guess that the card was busy was solely incorrect.
>> >
>> >>
>> >> >
>> >> > Kind regards
>> >> > Uffe
>> >> >
>> >> > From: Ulf Hansson <ulf.hansson@linaro.org>
>> >> > Date: Thu, 29 Aug 2019 09:42:11 +0200
>> >> > Subject: [PATCH] mmc: core: DEBUG for mmc_select_bus_width()
>> >> >
>> >> > Signed-off-by: Ulf Hansson <ulf.hansson@linaro.org>
>> >> > ---
>> >> >  drivers/mmc/core/mmc.c | 47 ++++++++++++++++++++++++++++++++++++++++++
>> >> >  1 file changed, 47 insertions(+)
>> >> >
>> >> > diff --git a/drivers/mmc/core/mmc.c b/drivers/mmc/core/mmc.c
>> >> > index c8804895595f..ff3a4c166f20 100644
>> >> > --- a/drivers/mmc/core/mmc.c
>> >> > +++ b/drivers/mmc/core/mmc.c
>> >> > @@ -975,6 +975,52 @@ static void mmc_set_bus_speed(struct mmc_card *card)
>> >> >         mmc_set_clock(card->host, max_dtr);
>> >> >  }
>> >> >
>> >> > +static void poll_for_busy(struct mmc_card *card, bool send_status)
>> >> > +{
>> >> > +       struct mmc_host *host = card->host;
>> >> > +       int err;
>> >> > +       unsigned long timeout;
>> >> > +       unsigned int timeout_ms = 5000;
>> >> > +       u32 status = 0;
>> >> > +       bool expired = false;
>> >> > +       bool busy = false;
>> >> > +
>> >> > +       if (!send_status && !host->ops->card_busy) {
>> >> > +               mmc_delay(timeout_ms);
>> >>
>> >> fyi this code hasn't been executed.
>> >
>> > Yeah, thanks, expected.
>> >
>> >>
>> >> > +               return;
>> >> > +       }
>> >> > +
>> >> > +       timeout = jiffies + msecs_to_jiffies(timeout_ms) + 1;
>> >> > +       do {
>> >> > +               expired = time_after(jiffies, timeout);
>> >> > +               if (send_status) {
>> >> > +                       err = __mmc_send_status(card, &status, 0);
>> >>
>> >> I've added some print here as well to see whats the value of the status
>> >>
>> >> +                       printk("%s: %s status=0x%x
>> >> R1_CURRENT_STATE(status)=0x%x \n",
>> >> +                               mmc_hostname(host),__func__, status,
>> >> R1_CURRENT_STATE(status));
>> >
>> > Great!
>> >
>> >>
>> >> [    1.676970] mmc0: poll_for_busy status=0x900 R1_CURRENT_STATE(status)=0x4
>> >
>> > This means the card reports that it's "READY_FOR_DATA" and the current
>> > state is the transfer state.
>> >
>> > Nothing weird is going on at card side, it seems.
>> >
>> >> [    1.685821] mmc0: mmc_select_hs200 failed, error -84
>> >> [    1.698029] mmc0: error -84 whilst initialising MMC card
>> >
>> > I am out of ideas. :-(
>> >
>> > Perhaps the meson developers can think of something? Could it be that
>> > the driver isn't behaving as it should when switching bus width? Maybe
>> > something happens on pinctrl level?
>>
>> I have not seen this particular issue myself. Since the last round of
>> updates we did a few month ago, things have been quite stable
>>
>> We get our information only from the datasheet and vendor code. These
>> are publicly available and it has proved quite insufficient judging by
>> the number of issue we had in the past years.
>>
>> IOW, we would love to know more about this controller too ;)
>
> Amlogic A113D, Avast Omni - I think you are familiar with this
> particular device :]

The board yes, however I have not seen this error on the samples I have

The controller embedded in the SoC is something else. As mentionned
above, we have the datasheet and the vendor code, That does not tell
us everything, unfortunately.

Most of the time, the SoC erratas, if any, have to be found "the hard
way" ...


>
>>
>> So, to answer your question, AFAIK, there is nothing special regarding
>> bus width switch ...
>>
>> Regarding pinctrl, I think there a bias-pull-up on data line set in DT.
>> Maybe it's worth trying to disable that a see how it goes ?
>
> It did not help.

Not really surprised. Thanks for trying anyway.

>
> Best regards,
> Jan
>
>>
>> OTOH, it this was the problem, I wonder how it could have got this far
>> and why a delay would help ?
>>
>> >
>> > Anyway, if no progress is made the next few days, let's do the revert.
>> > And thanks a lot for helping out with the tests, etc!
>> >
>> > Kind regards
>> > Uffe

Ulf Hansson Sept. 3, 2019, 3:10 p.m. UTC | #14

On Tue, 20 Aug 2019 at 13:42, <ja.kaisrlik@gmail.com> wrote:
>
> From: Jan Kaisrlik <ja.kaisrlik@gmail.com>
>
> This reverts commit 3a0681c7448b174e5dcfd19e9079cdd281c35f1a.
>
> Turns out the patch breaks initialization of Toshiba THGBMNG5.
> [    1.648951] mmc0: mmc_select_hs200 failed, error -84
> [    1.648988] mmc0: error -84 whilst initialising MMC card
>
> Signed-off-by: Jan Kaisrlik <ja.kaisrlik@gmail.com>

Applied for fixes and by adding some more information to the
changelog, according to our additional findings.

Thanks and kind regards
Uffe


> ---
>  drivers/mmc/core/mmc_ops.c | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
>
> diff --git a/drivers/mmc/core/mmc_ops.c b/drivers/mmc/core/mmc_ops.c
> index 74e4364bc9fb..09113b9ad679 100644
> --- a/drivers/mmc/core/mmc_ops.c
> +++ b/drivers/mmc/core/mmc_ops.c
> @@ -564,7 +564,7 @@ int __mmc_switch(struct mmc_card *card, u8 set, u8 index, u8 value,
>         if (index == EXT_CSD_SANITIZE_START)
>                 cmd.sanitize_busy = true;
>
> -       err = mmc_wait_for_cmd(host, &cmd, 0);
> +       err = mmc_wait_for_cmd(host, &cmd, MMC_CMD_RETRIES);
>         if (err)
>                 goto out;
>
> --
> 2.20.1
>

Revert "mmc: core: do not retry CMD6 in __mmc_switch()"

Commit Message

Comments

Patch