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

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <CAPDyKFrXQgtHa4gLaKUi_F0rs4FMBai3Y_+TcHZR_zpkb0B4QQ@mail.gmail.com>
Date:   Mon, 24 Feb 2020 12:16:48 +0100
From:   Ulf Hansson <ulf.hansson@...aro.org>
To:     Bitan Biswas <bbiswas@...dia.com>,
        Adrian Hunter <adrian.hunter@...el.com>
Cc:     Naresh Kamboju <naresh.kamboju@...aro.org>,
        Jens Axboe <axboe@...nel.dk>,
        Alexei Starovoitov <ast@...nel.org>,
        linux-block <linux-block@...r.kernel.org>,
        lkft-triage@...ts.linaro.org,
        open list <linux-kernel@...r.kernel.org>,
        "linux-mmc@...r.kernel.org" <linux-mmc@...r.kernel.org>,
        Arnd Bergmann <arnd@...db.de>,
        John Stultz <john.stultz@...aro.org>,
        Thierry Reding <treding@...dia.com>,
        Jon Hunter <jonathanh@...dia.com>
Subject: Re: LKFT: arm x15: mmc1: cache flush error -110

+ Adrian

On Fri, 21 Feb 2020 at 20:44, Bitan Biswas <bbiswas@...dia.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@...aro.org> wrote:
> >>
> >> On Wed, 19 Feb 2020 at 21:54, Ulf Hansson <ulf.hansson@...aro.org> wrote:
> >>>
> >>> On Thu, 13 Feb 2020 at 16:43, Naresh Kamboju <naresh.kamboju@...aro.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).

From: Ulf Hansson <ulf.hansson@...aro.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@...aro.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,
-- 

Kind regards
Uffe