Re: [BUG] mmc: core: adjust polling interval for CMD1

[Jean Rene Dawin]

Ulf Hansson wrote on Thu  3/03/22 11:40:
> On Wed, 2 Mar 2022 at 10:40, H. Nikolaus Schaller <hns@xxxxxxxxxxxxx> wrote:
> 
> Alright, it starts to sound like we might need a revert (or at least a
> way to restore the previous behaviour) - even if that would just paper
> over the real problem. The real problem is more likely related to how
> the host driver manages restoring of the power to the card, which
> happens when runtime resuming it.
> 
> In any case, just to make sure the loop timeout itself isn't the
> problem, can you run the below debug patch please? The intent is to
> figure out how long the worst case timeout is, when it's working with
> CMD1. As soon as the timeout exceeds the worst case, there is a
> message printed to the log.
> 
> The below patch is based upon that the offending commit has been reverted.
> 
> Kind regards
> Uffe
> 
> From: Ulf Hansson <ulf.hansson@xxxxxxxxxx>
> Date: Thu, 3 Mar 2022 11:00:04 +0100
> Subject: [PATCH] mmc: core: DEBUG - Measure and log worst case CMD1 loop
> 
> Signed-off-by: Ulf Hansson <ulf.hansson@xxxxxxxxxx>
> ---
>  drivers/mmc/core/mmc_ops.c | 11 +++++++++++
>  include/linux/mmc/host.h   |  1 +
>  2 files changed, 12 insertions(+)
> 
> diff --git a/drivers/mmc/core/mmc_ops.c b/drivers/mmc/core/mmc_ops.c
> index 9946733a34c6..3f03d9e8a3a4 100644
> --- a/drivers/mmc/core/mmc_ops.c
> +++ b/drivers/mmc/core/mmc_ops.c
> @@ -177,11 +177,15 @@ int mmc_send_op_cond(struct mmc_host *host, u32
> ocr, u32 *rocr)
>  {
>         struct mmc_command cmd = {};
>         int i, err = 0;
> +       s64 cmd1_ms;
> +       ktime_t time_start;
> 
>         cmd.opcode = MMC_SEND_OP_COND;
>         cmd.arg = mmc_host_is_spi(host) ? 0 : ocr;
>         cmd.flags = MMC_RSP_SPI_R1 | MMC_RSP_R3 | MMC_CMD_BCR;
> 
> +       time_start = ktime_get();
> +
>         for (i = 100; i; i--) {
>                 err = mmc_wait_for_cmd(host, &cmd, 0);
>                 if (err)
> @@ -211,6 +215,13 @@ int mmc_send_op_cond(struct mmc_host *host, u32
> ocr, u32 *rocr)
>                         cmd.arg = cmd.resp[0] | BIT(30);
>         }
> 
> +       cmd1_ms = ktime_to_ms(ktime_sub(ktime_get(), time_start));
> +       if (!err && cmd1_ms > host->cmd1_ms) {
> +               pr_warn("%s: CMD1 timeout increased to %lld ms, loop=%d\n",
> +                       mmc_hostname(host), cmd1_ms, i);
> +               host->cmd1_ms = cmd1_ms;
> +       }
> +
>         if (rocr && !mmc_host_is_spi(host))
>                 *rocr = cmd.resp[0];
> 
> diff --git a/include/linux/mmc/host.h b/include/linux/mmc/host.h
> index 7afb57cab00b..c2ca3bb05620 100644
> --- a/include/linux/mmc/host.h
> +++ b/include/linux/mmc/host.h
> @@ -301,6 +301,7 @@ struct mmc_host {
>         unsigned int            f_min;
>         unsigned int            f_max;
>         unsigned int            f_init;
> +       s64                     cmd1_ms;
>         u32                     ocr_avail;
>         u32                     ocr_avail_sdio; /* SDIO-specific OCR */
>         u32                     ocr_avail_sd;   /* SD-specific OCR */
> -- 
> 2.25.1

Hi,

thanks. With this patch applied with reverted 76bfc7ccc2fa9d382576f6013b57a0ef93d5a722
I don't get the "stuck" errors in __mmc_poll_for_busy and only one message of

[    1.095194] mmc1: CMD1 timeout increased to 64 ms, loop=98

Regards,
Jean Rene Dawin