Re: [PATCH] mmc: cqhci: Be more verbose in error irq handler

From: "Kornel Dulęba" <korneld@chromium.org>
To: Adrian Hunter <adrian.hunter@intel.com>
Cc: linux-mmc@vger.kernel.org, linux-kernel@vger.kernel.org,
	Ritesh Harjani <riteshh@codeaurora.org>,
	Asutosh Das <quic_asutoshd@quicinc.com>,
	Ulf Hansson <ulf.hansson@linaro.org>,
	Radoslaw Biernacki <biernacki@google.com>,
	Guenter Roeck <groeck@chromium.org>,
	Gwendal Grignou <gwendal@chromium.org>,
	upstream@semihalf.com
Subject: Re: [PATCH] mmc: cqhci: Be more verbose in error irq handler
Date: Fri, 20 Oct 2023 10:53:05 +0200	[thread overview]
Message-ID: <CAD=NsqybNrf-=9=5wvoj+9MT3xK3SbX7nDk3N3VLBMyA_u3KTQ@mail.gmail.com> (raw)
In-Reply-To: <613c51f0-c32e-4de5-9627-525d92fb06ed@intel.com>

On Fri, Oct 20, 2023 at 9:41 AM Adrian Hunter <adrian.hunter@intel.com> wrote:
>
> On 16/10/23 12:56, Kornel Dulęba wrote:
> > There are several reasons for controller to generate an error interrupt.
> > They include controller<->card timeout, and CRC mismatch error.
> > Right now we only get one line in the logs stating that CQE recovery was
> > triggered, but with no information about what caused it.
> > To figure out what happened be more verbose and dump the registers from
> > irq error handler logic.
> > This matches the behaviour of the software timeout logic, see
> > cqhci_timeout.
> >
> > Signed-off-by: Kornel Dulęba <korneld@chromium.org>
> > ---
> >  drivers/mmc/host/cqhci-core.c | 5 +++--
> >  1 file changed, 3 insertions(+), 2 deletions(-)
> >
> > diff --git a/drivers/mmc/host/cqhci-core.c b/drivers/mmc/host/cqhci-core.c
> > index b3d7d6d8d654..33abb4bd53b5 100644
> > --- a/drivers/mmc/host/cqhci-core.c
> > +++ b/drivers/mmc/host/cqhci-core.c
> > @@ -700,8 +700,9 @@ static void cqhci_error_irq(struct mmc_host *mmc, u32 status, int cmd_error,
> >
> >       terri = cqhci_readl(cq_host, CQHCI_TERRI);
> >
> > -     pr_debug("%s: cqhci: error IRQ status: 0x%08x cmd error %d data error %d TERRI: 0x%08x\n",
> > -              mmc_hostname(mmc), status, cmd_error, data_error, terri);
> > +     pr_warn("%s: cqhci: error IRQ status: 0x%08x cmd error %d data error %d\n",
> > +              mmc_hostname(mmc), status, cmd_error, data_error);
> > +     cqhci_dumpregs(cq_host);
>
> For debugging, isn't dynamic debug seems more appropriate?

Dynamic debug is an option, but my personal preference would be to
just log more info in the error handler.
To give you some background.
We're seeing some "running CQE recovery" lines in the logs, followed
by a dm_verity mismatch error.
The reports come from the field, with no feasible way to reproduce the
issue locally.

I'd argue that logging only the info that CQE recovery was executed is
not particularly helpful for someone looking into those logs.
Ideally we would have more data about the state the controller was in
when the error happened, or at least what caused the recovery to be
triggered.
The question here is how verbose should we be in this error scenario.
Looking at other error scenarios, in the case of a software timeout
we're dumping the controller registers. (cqhci_timeout)
Hence I thought that I'd be appropriate to match that and do the same
in CQE recovery logic.

>
> >
> >       /* Forget about errors when recovery has already been triggered */
> >       if (cq_host->recovery_halt)
>