Re: LKFT: arm x15: mmc1: cache flush error -110

[Adrian Hunter <adrian.hunter@intel.com>]

On 24/02/20 1:16 pm, Ulf Hansson wrote:
> + Adrian
> 
> On Fri, 21 Feb 2020 at 20:44, Bitan Biswas <bbiswas@nvidia.com> wrote:
>>
>> On 2/21/20 1:48 AM, Ulf Hansson wrote:
>>> External email: Use caution opening links or attachments
>>>
>>>
>>> On Thu, 20 Feb 2020 at 18:54, Naresh Kamboju <naresh.kamboju@linaro.org> wrote:
>>>>
>>>> On Wed, 19 Feb 2020 at 21:54, Ulf Hansson <ulf.hansson@linaro.org> wrote:
>>>>>
>>>>> On Thu, 13 Feb 2020 at 16:43, Naresh Kamboju <naresh.kamboju@linaro.org> wrote:
>>>>>>
>>>>>
>>>>> Try to restore the value for the cache flush timeout, by updating the
>>>>> define MMC_CACHE_FLUSH_TIMEOUT_MS to 10 * 60 * 1000".
>>>>
>>>> I have increased the timeout to 10 minutes but it did not help.
>>>> Same error found.
>>>> [  608.679353] mmc1: Card stuck being busy! mmc_poll_for_busy
>>>> [  608.684964] mmc1: cache flush error -110
>>>> [  608.689005] blk_update_request: I/O error, dev mmcblk1, sector
>>>> 4302400 op 0x1:(WRITE) flags 0x20800 phys_seg 1 prio class 0
>>>>
>>>> OTOH, What best i could do for my own experiment to revert all three patches and
>>>> now the reported error gone and device mount successfully [1].
>>>>
>>>> List of patches reverted,
>>>>    mmc: core: Specify timeouts for BKOPS and CACHE_FLUSH for eMMC
>>>>    mmc: block: Use generic_cmd6_time when modifying
>>>>      INAND_CMD38_ARG_EXT_CSD
>>>>    mmc: core: Default to generic_cmd6_time as timeout in __mmc_switch()
>>>>
>>>> [1] https://lkft.validation.linaro.org/scheduler/job/1238275#L4346
>>>>
>>>> - Naresh
>>>
>>> Thanks for testing!
>>>
>>> This sounds a bit weird, I must say. Also, while looking into the
>>> logs, it seems like you are comparing a v5.5 kernel with v5.6-rc2, but
>>> maybe I didn't read the logs carefully enough.
>>>
>>>   In any case, I am looking into creating a debug patch so we can
>>> narrow down the problem a bit further.
>>>
>>> Kind regards
>>> Uffe
>>>
>>
>> Hi Ulf,
>>
>>   I see that Jetson-TX2 / Jetson-Xavier suspend test is aborted and
>> below error is seen due to the commit
>> 24ed3bd01d6a844fd5e8a75f48d0a3d10ed71bf9  ("mmc: core: Specify timeouts
>> for BKOPS and CACHE_FLUSH for eMMC"):
>>
>> ##
>> [  268.976197] Freezing user space processes ... (elapsed 0.001 seconds)
>> done.
>> [  268.984414] OOM killer disabled.
>> [  268.987635] Freezing remaining freezable tasks ... (elapsed 0.000
>> seconds) done.
>> [  269.217471] PM: dpm_run_callback(): mmc_bus_suspend+0x0/0x58 returns -110
>> [  269.224255] PM: Device mmc1:0001 failed to suspend: error -110
>> [  269.230080] PM: Some devices failed to suspend, or early wake event
>> detected
> 
> Is there also a print in the log about "Card stuck being busy!"?
> 
> In any case, it seems like the timeout error (-110) is happening way
> too soon. The cache flush timeout is now 30s, but the timeout seems to
> fire only a few hundred ms (at most) after the cache flush command has
> been sent.
> 
>> ##
>>
>>   I find that from the commit the changes in mmc_flush_cache below is
>> the cause.
>>
>> ##
>> @@ -961,7 +963,8 @@ int mmc_flush_cache(struct mmc_card *card)
>>                          (card->ext_csd.cache_size > 0) &&
>>                          (card->ext_csd.cache_ctrl & 1)) {
>>                  err = mmc_switch(card, EXT_CSD_CMD_SET_NORMAL,
>> -                               EXT_CSD_FLUSH_CACHE, 1, 0);
>> +                                EXT_CSD_FLUSH_CACHE, 1,
>> +                                MMC_CACHE_FLUSH_TIMEOUT_MS);
>>
>> ##
>>
>>   Do you have suggestion to try for the suspend errors ?
> 
> Just as a quick sanity test, please try the below patch, which
> restores the old cache flush timeout to 10min.
> 
> However, as I indicated above, this seems to be a problem that needs
> to be fixed at in the host driver side. For the sdhci driver, there is
> a bit of a tricky logic around how to deal with timeouts in
> sdhci_send_command(). My best guess is that's where we should look
> more closely (and I am doing that).

Could be, but hard to narrow down without more debug.  I would enable
dynamic debug and mmc messages e.g.

kernel config

	CONFIG_DYNAMIC_DEBUG=y

kernel command line option

	dyndbg="file drivers/mmc/core/* +p;file drivers/mmc/host/* +p"

But that might lead to a very large number of messages.


> 
> From: Ulf Hansson <ulf.hansson@linaro.org>
> Date: Mon, 24 Feb 2020 11:43:33 +0100
> Subject: [PATCH] mmc: core: Restore busy timeout for eMMC cache flushing
> 
> Signed-off-by: Ulf Hansson <ulf.hansson@linaro.org>
> ---
>  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 da425ee2d9bf..713e7dd6d028 100644
> --- a/drivers/mmc/core/mmc_ops.c
> +++ b/drivers/mmc/core/mmc_ops.c
> @@ -21,7 +21,7 @@
> 
>  #define MMC_OPS_TIMEOUT_MS             (10 * 60 * 1000) /* 10min*/
>  #define MMC_BKOPS_TIMEOUT_MS           (120 * 1000) /* 120s */
> -#define MMC_CACHE_FLUSH_TIMEOUT_MS     (30 * 1000) /* 30s */
> +#define MMC_CACHE_FLUSH_TIMEOUT_MS     (10 * 60 * 1000) /* 10min */
> 
>  static const u8 tuning_blk_pattern_4bit[] = {
>         0xff, 0x0f, 0xff, 0x00, 0xff, 0xcc, 0xc3, 0xcc,
>