| Message ID | 20230620091113.33393-1-ulf.hansson@linaro.org (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
| Series | mmc: mmci: Add support for SW busy-end timeouts | expand |
On 6/20/23 11:11, Ulf Hansson wrote: > The ux500 variant doesn't have a HW based timeout to use for busy-end IRQs. > To avoid hanging and waiting for the card to stop signaling busy, let's > schedule a delayed work, according to the corresponding cmd->busy_timeout > for the command. If work gets to run, let's kick the IRQ handler to > completed the currently running request/command. > > Reviewed-by: Linus Walleij <linus.walleij@linaro.org> > Tested-by: Linus Walleij <linus.walleij@linaro.org> > Signed-off-by: Ulf Hansson <ulf.hansson@linaro.org> > --- > drivers/mmc/host/mmci.c | 50 ++++++++++++++++++++++++++--- > drivers/mmc/host/mmci.h | 3 +- > drivers/mmc/host/mmci_stm32_sdmmc.c | 3 +- > 3 files changed, 49 insertions(+), 7 deletions(-) > > diff --git a/drivers/mmc/host/mmci.c b/drivers/mmc/host/mmci.c > index 8a661ea1a2d1..61d761646462 100644 > --- a/drivers/mmc/host/mmci.c > +++ b/drivers/mmc/host/mmci.c > @@ -37,6 +37,7 @@ > #include <linux/pinctrl/consumer.h> > #include <linux/reset.h> > #include <linux/gpio/consumer.h> > +#include <linux/workqueue.h> > > #include <asm/div64.h> > #include <asm/io.h> > @@ -682,7 +683,8 @@ static void ux500_busy_clear_mask_done(struct mmci_host *host) > * | | > * IRQ1 IRQ2 > */ > -static bool ux500_busy_complete(struct mmci_host *host, u32 status, u32 err_msk) > +static bool ux500_busy_complete(struct mmci_host *host, struct mmc_command *cmd, > + u32 status, u32 err_msk) > { > void __iomem *base = host->base; > int retries = 10; > @@ -726,6 +728,8 @@ static bool ux500_busy_complete(struct mmci_host *host, u32 status, u32 err_msk) > host->variant->busy_detect_mask, > base + MMCIMASK0); > host->busy_state = MMCI_BUSY_WAITING_FOR_START_IRQ; > + schedule_delayed_work(&host->ux500_busy_timeout_work, > + msecs_to_jiffies(cmd->busy_timeout)); > goto out_ret_state; > } > retries--; > @@ -753,6 +757,7 @@ static bool ux500_busy_complete(struct mmci_host *host, u32 status, u32 err_msk) > } else { > dev_dbg(mmc_dev(host->mmc), > "lost busy status when waiting for busy start IRQ\n"); > + cancel_delayed_work(&host->ux500_busy_timeout_work); > ux500_busy_clear_mask_done(host); > } > break; > @@ -761,6 +766,7 @@ static bool ux500_busy_complete(struct mmci_host *host, u32 status, u32 err_msk) > if (!(status & host->variant->busy_detect_flag)) { > host->busy_status |= status & (MCI_CMDSENT | MCI_CMDRESPEND); > writel(host->variant->busy_detect_mask, base + MMCICLEAR); > + cancel_delayed_work(&host->ux500_busy_timeout_work); > ux500_busy_clear_mask_done(host); > } else { > dev_dbg(mmc_dev(host->mmc), > @@ -1277,6 +1283,7 @@ static void > mmci_start_command(struct mmci_host *host, struct mmc_command *cmd, u32 c) > { > void __iomem *base = host->base; > + bool busy_resp = cmd->flags & MMC_RSP_BUSY; > unsigned long long clks; > > dev_dbg(mmc_dev(host->mmc), "op %02x arg %08x flags %08x\n", > @@ -1304,10 +1311,11 @@ mmci_start_command(struct mmci_host *host, struct mmc_command *cmd, u32 c) > host->busy_status = 0; > host->busy_state = MMCI_BUSY_DONE; > > - if (host->variant->busy_timeout && cmd->flags & MMC_RSP_BUSY) { > - if (!cmd->busy_timeout) > - cmd->busy_timeout = 10 * MSEC_PER_SEC; > + /* Assign a default timeout if the core does not provide one */ > + if (busy_resp && !cmd->busy_timeout) > + cmd->busy_timeout = 10 * MSEC_PER_SEC; > > + if (busy_resp && host->variant->busy_timeout) { > if (cmd->busy_timeout > host->mmc->max_busy_timeout) > clks = (unsigned long long)host->mmc->max_busy_timeout * host->cclk; > else > @@ -1448,7 +1456,7 @@ mmci_cmd_irq(struct mmci_host *host, struct mmc_command *cmd, > > /* Handle busy detection on DAT0 if the variant supports it. */ > if (busy_resp && host->variant->busy_detect) > - if (!host->ops->busy_complete(host, status, err_msk)) > + if (!host->ops->busy_complete(host, cmd, status, err_msk)) > return; > > host->cmd = NULL; > @@ -1495,6 +1503,34 @@ mmci_cmd_irq(struct mmci_host *host, struct mmc_command *cmd, > } > } > > +/* > + * This busy timeout worker is used to "kick" the command IRQ if a > + * busy detect IRQ fails to appear in reasonable time. Only used on > + * variants with busy detection IRQ delivery. > + */ > +static void ux500_busy_timeout_work(struct work_struct *work) > +{ > + struct mmci_host *host = container_of(work, struct mmci_host, > + ux500_busy_timeout_work.work); > + unsigned long flags; > + u32 status; > + > + spin_lock_irqsave(&host->lock, flags); > + > + if (host->cmd) { > + dev_dbg(mmc_dev(host->mmc), "timeout waiting for busy IRQ\n"); > + > + /* If we are still busy let's tag on a cmd-timeout error. */ > + status = readl(host->base + MMCISTATUS); > + if (status & host->variant->busy_detect_flag) > + status |= MCI_CMDTIMEOUT; > + > + mmci_cmd_irq(host, host->cmd, status); > + } > + > + spin_unlock_irqrestore(&host->lock, flags); > +} > + > static int mmci_get_rx_fifocnt(struct mmci_host *host, u32 status, int remain) > { > return remain - (readl(host->base + MMCIFIFOCNT) << 2); > @@ -2309,6 +2345,10 @@ static int mmci_probe(struct amba_device *dev, > goto clk_disable; > } > > + if (host->variant->busy_detect) > + INIT_DELAYED_WORK(&host->ux500_busy_timeout_work, > + ux500_busy_timeout_work); Hi Ulf, STM32 variants also have busy_detect = true. Could that be an issue to initialize this work, which seem dedicated to ux500? I haven't tested the patch yet. Will do that soon. Yann > + > writel(MCI_IRQENABLE | variant->start_err, host->base + MMCIMASK0); > > amba_set_drvdata(dev, mmc); > diff --git a/drivers/mmc/host/mmci.h b/drivers/mmc/host/mmci.h > index 12a7bbd3ce26..69b2439842dd 100644 > --- a/drivers/mmc/host/mmci.h > +++ b/drivers/mmc/host/mmci.h > @@ -393,7 +393,7 @@ struct mmci_host_ops { > void (*dma_error)(struct mmci_host *host); > void (*set_clkreg)(struct mmci_host *host, unsigned int desired); > void (*set_pwrreg)(struct mmci_host *host, unsigned int pwr); > - bool (*busy_complete)(struct mmci_host *host, u32 status, u32 err_msk); > + bool (*busy_complete)(struct mmci_host *host, struct mmc_command *cmd, u32 status, u32 err_msk); > void (*pre_sig_volt_switch)(struct mmci_host *host); > int (*post_sig_volt_switch)(struct mmci_host *host, struct mmc_ios *ios); > }; > @@ -451,6 +451,7 @@ struct mmci_host { > void *dma_priv; > > s32 next_cookie; > + struct delayed_work ux500_busy_timeout_work; > }; > > #define dma_inprogress(host) ((host)->dma_in_progress) > diff --git a/drivers/mmc/host/mmci_stm32_sdmmc.c b/drivers/mmc/host/mmci_stm32_sdmmc.c > index 953d1be4e379..f07cfbeafe2e 100644 > --- a/drivers/mmc/host/mmci_stm32_sdmmc.c > +++ b/drivers/mmc/host/mmci_stm32_sdmmc.c > @@ -372,7 +372,8 @@ static u32 sdmmc_get_dctrl_cfg(struct mmci_host *host) > return datactrl; > } > > -static bool sdmmc_busy_complete(struct mmci_host *host, u32 status, u32 err_msk) > +static bool sdmmc_busy_complete(struct mmci_host *host, struct mmc_command *cmd, > + u32 status, u32 err_msk) > { > void __iomem *base = host->base; > u32 busy_d0, busy_d0end, mask, sdmmc_status;
On Tue, 20 Jun 2023 at 11:27, Yann Gautier <yann.gautier@foss.st.com> wrote: > > On 6/20/23 11:11, Ulf Hansson wrote: > > The ux500 variant doesn't have a HW based timeout to use for busy-end IRQs. > > To avoid hanging and waiting for the card to stop signaling busy, let's > > schedule a delayed work, according to the corresponding cmd->busy_timeout > > for the command. If work gets to run, let's kick the IRQ handler to > > completed the currently running request/command. > > > > Reviewed-by: Linus Walleij <linus.walleij@linaro.org> > > Tested-by: Linus Walleij <linus.walleij@linaro.org> > > Signed-off-by: Ulf Hansson <ulf.hansson@linaro.org> > > --- > > drivers/mmc/host/mmci.c | 50 ++++++++++++++++++++++++++--- > > drivers/mmc/host/mmci.h | 3 +- > > drivers/mmc/host/mmci_stm32_sdmmc.c | 3 +- > > 3 files changed, 49 insertions(+), 7 deletions(-) > > > > diff --git a/drivers/mmc/host/mmci.c b/drivers/mmc/host/mmci.c > > index 8a661ea1a2d1..61d761646462 100644 > > --- a/drivers/mmc/host/mmci.c > > +++ b/drivers/mmc/host/mmci.c > > @@ -37,6 +37,7 @@ > > #include <linux/pinctrl/consumer.h> > > #include <linux/reset.h> > > #include <linux/gpio/consumer.h> > > +#include <linux/workqueue.h> > > > > #include <asm/div64.h> > > #include <asm/io.h> > > @@ -682,7 +683,8 @@ static void ux500_busy_clear_mask_done(struct mmci_host *host) > > * | | > > * IRQ1 IRQ2 > > */ > > -static bool ux500_busy_complete(struct mmci_host *host, u32 status, u32 err_msk) > > +static bool ux500_busy_complete(struct mmci_host *host, struct mmc_command *cmd, > > + u32 status, u32 err_msk) > > { > > void __iomem *base = host->base; > > int retries = 10; > > @@ -726,6 +728,8 @@ static bool ux500_busy_complete(struct mmci_host *host, u32 status, u32 err_msk) > > host->variant->busy_detect_mask, > > base + MMCIMASK0); > > host->busy_state = MMCI_BUSY_WAITING_FOR_START_IRQ; > > + schedule_delayed_work(&host->ux500_busy_timeout_work, > > + msecs_to_jiffies(cmd->busy_timeout)); > > goto out_ret_state; > > } > > retries--; > > @@ -753,6 +757,7 @@ static bool ux500_busy_complete(struct mmci_host *host, u32 status, u32 err_msk) > > } else { > > dev_dbg(mmc_dev(host->mmc), > > "lost busy status when waiting for busy start IRQ\n"); > > + cancel_delayed_work(&host->ux500_busy_timeout_work); > > ux500_busy_clear_mask_done(host); > > } > > break; > > @@ -761,6 +766,7 @@ static bool ux500_busy_complete(struct mmci_host *host, u32 status, u32 err_msk) > > if (!(status & host->variant->busy_detect_flag)) { > > host->busy_status |= status & (MCI_CMDSENT | MCI_CMDRESPEND); > > writel(host->variant->busy_detect_mask, base + MMCICLEAR); > > + cancel_delayed_work(&host->ux500_busy_timeout_work); > > ux500_busy_clear_mask_done(host); > > } else { > > dev_dbg(mmc_dev(host->mmc), > > @@ -1277,6 +1283,7 @@ static void > > mmci_start_command(struct mmci_host *host, struct mmc_command *cmd, u32 c) > > { > > void __iomem *base = host->base; > > + bool busy_resp = cmd->flags & MMC_RSP_BUSY; > > unsigned long long clks; > > > > dev_dbg(mmc_dev(host->mmc), "op %02x arg %08x flags %08x\n", > > @@ -1304,10 +1311,11 @@ mmci_start_command(struct mmci_host *host, struct mmc_command *cmd, u32 c) > > host->busy_status = 0; > > host->busy_state = MMCI_BUSY_DONE; > > > > - if (host->variant->busy_timeout && cmd->flags & MMC_RSP_BUSY) { > > - if (!cmd->busy_timeout) > > - cmd->busy_timeout = 10 * MSEC_PER_SEC; > > + /* Assign a default timeout if the core does not provide one */ > > + if (busy_resp && !cmd->busy_timeout) > > + cmd->busy_timeout = 10 * MSEC_PER_SEC; > > > > + if (busy_resp && host->variant->busy_timeout) { > > if (cmd->busy_timeout > host->mmc->max_busy_timeout) > > clks = (unsigned long long)host->mmc->max_busy_timeout * host->cclk; > > else > > @@ -1448,7 +1456,7 @@ mmci_cmd_irq(struct mmci_host *host, struct mmc_command *cmd, > > > > /* Handle busy detection on DAT0 if the variant supports it. */ > > if (busy_resp && host->variant->busy_detect) > > - if (!host->ops->busy_complete(host, status, err_msk)) > > + if (!host->ops->busy_complete(host, cmd, status, err_msk)) > > return; > > > > host->cmd = NULL; > > @@ -1495,6 +1503,34 @@ mmci_cmd_irq(struct mmci_host *host, struct mmc_command *cmd, > > } > > } > > > > +/* > > + * This busy timeout worker is used to "kick" the command IRQ if a > > + * busy detect IRQ fails to appear in reasonable time. Only used on > > + * variants with busy detection IRQ delivery. > > + */ > > +static void ux500_busy_timeout_work(struct work_struct *work) > > +{ > > + struct mmci_host *host = container_of(work, struct mmci_host, > > + ux500_busy_timeout_work.work); > > + unsigned long flags; > > + u32 status; > > + > > + spin_lock_irqsave(&host->lock, flags); > > + > > + if (host->cmd) { > > + dev_dbg(mmc_dev(host->mmc), "timeout waiting for busy IRQ\n"); > > + > > + /* If we are still busy let's tag on a cmd-timeout error. */ > > + status = readl(host->base + MMCISTATUS); > > + if (status & host->variant->busy_detect_flag) > > + status |= MCI_CMDTIMEOUT; > > + > > + mmci_cmd_irq(host, host->cmd, status); > > + } > > + > > + spin_unlock_irqrestore(&host->lock, flags); > > +} > > + > > static int mmci_get_rx_fifocnt(struct mmci_host *host, u32 status, int remain) > > { > > return remain - (readl(host->base + MMCIFIFOCNT) << 2); > > @@ -2309,6 +2345,10 @@ static int mmci_probe(struct amba_device *dev, > > goto clk_disable; > > } > > > > + if (host->variant->busy_detect) > > + INIT_DELAYED_WORK(&host->ux500_busy_timeout_work, > > + ux500_busy_timeout_work); > > Hi Ulf, > > STM32 variants also have busy_detect = true. > Could that be an issue to initialize this work, which seem dedicated to > ux500? The work will not be used for the STM32 variants (sdmmc_variant_init()), so it's not a problem as it's just an initialization. > I haven't tested the patch yet. Will do that soon. Looking forward to your feedback, thanks! Kind regards Uffe > > > Yann > > > + > > writel(MCI_IRQENABLE | variant->start_err, host->base + MMCIMASK0); > > > > amba_set_drvdata(dev, mmc); > > diff --git a/drivers/mmc/host/mmci.h b/drivers/mmc/host/mmci.h > > index 12a7bbd3ce26..69b2439842dd 100644 > > --- a/drivers/mmc/host/mmci.h > > +++ b/drivers/mmc/host/mmci.h > > @@ -393,7 +393,7 @@ struct mmci_host_ops { > > void (*dma_error)(struct mmci_host *host); > > void (*set_clkreg)(struct mmci_host *host, unsigned int desired); > > void (*set_pwrreg)(struct mmci_host *host, unsigned int pwr); > > - bool (*busy_complete)(struct mmci_host *host, u32 status, u32 err_msk); > > + bool (*busy_complete)(struct mmci_host *host, struct mmc_command *cmd, u32 status, u32 err_msk); > > void (*pre_sig_volt_switch)(struct mmci_host *host); > > int (*post_sig_volt_switch)(struct mmci_host *host, struct mmc_ios *ios); > > }; > > @@ -451,6 +451,7 @@ struct mmci_host { > > void *dma_priv; > > > > s32 next_cookie; > > + struct delayed_work ux500_busy_timeout_work; > > }; > > > > #define dma_inprogress(host) ((host)->dma_in_progress) > > diff --git a/drivers/mmc/host/mmci_stm32_sdmmc.c b/drivers/mmc/host/mmci_stm32_sdmmc.c > > index 953d1be4e379..f07cfbeafe2e 100644 > > --- a/drivers/mmc/host/mmci_stm32_sdmmc.c > > +++ b/drivers/mmc/host/mmci_stm32_sdmmc.c > > @@ -372,7 +372,8 @@ static u32 sdmmc_get_dctrl_cfg(struct mmci_host *host) > > return datactrl; > > } > > > > -static bool sdmmc_busy_complete(struct mmci_host *host, u32 status, u32 err_msk) > > +static bool sdmmc_busy_complete(struct mmci_host *host, struct mmc_command *cmd, > > + u32 status, u32 err_msk) > > { > > void __iomem *base = host->base; > > u32 busy_d0, busy_d0end, mask, sdmmc_status; >
On Tue, Jun 20, 2023 at 11:27 AM Yann Gautier <yann.gautier@foss.st.com> wrote: > STM32 variants also have busy_detect = true. > Could that be an issue to initialize this work, which seem dedicated to > ux500? As Ulf says it is just initialized then it is left unused. I renamed the software timeout ux500_busy_timeout_work() from the previous name busy_timeout_work() but I actually thought it could make sense to enable it on STM32 as well. It is essentially a last resort fallback if the card does not properly report busy end or the block fails to detect it for some reason. Yours, Linus Walleij
On Tue, 20 Jun 2023 at 12:19, Linus Walleij <linus.walleij@linaro.org> wrote: > > On Tue, Jun 20, 2023 at 11:27 AM Yann Gautier <yann.gautier@foss.st.com> wrote: > > > STM32 variants also have busy_detect = true. > > Could that be an issue to initialize this work, which seem dedicated to > > ux500? > > As Ulf says it is just initialized then it is left unused. > > I renamed the software timeout ux500_busy_timeout_work() from the > previous name busy_timeout_work() but I actually thought it could > make sense to enable it on STM32 as well. It is essentially a last > resort fallback if the card does not properly report busy end or the block > fails to detect it for some reason. There is HW busy-timeout for the STM32 variant, so I don't think it's needed. However, that HW timeout does have an upper limit. If the requested timeout for the command is longer than what the HW can support, maybe a software timeout can be used in some clever way. The tricky part is, if I recall correctly from previous conversations at LKML, one can not skip to set the HW timeout. This means, this is going to be a bit more messy to support. Br Uffe
On Tue, Jun 20, 2023 at 11:11 AM Ulf Hansson <ulf.hansson@linaro.org> wrote: > The ux500 variant doesn't have a HW based timeout to use for busy-end IRQs. > To avoid hanging and waiting for the card to stop signaling busy, let's > schedule a delayed work, according to the corresponding cmd->busy_timeout > for the command. If work gets to run, let's kick the IRQ handler to > completed the currently running request/command. > > Reviewed-by: Linus Walleij <linus.walleij@linaro.org> > Tested-by: Linus Walleij <linus.walleij@linaro.org> > Signed-off-by: Ulf Hansson <ulf.hansson@linaro.org> Some experiments: I added a patch to print the offending command and dev_err() all the timing bugs. The resulting log: /home/linus # dmesg |grep '80005000\|mmcblk2' [ 2.684814] mmci-pl18x 80005000.mmc: mmc2: PL180 manf 80 rev4 at 0x80005000 irq 81,0 (pio) [ 2.695831] mmci-pl18x 80005000.mmc: DMA channels RX dma0chan4, TX dma0chan5 [ 3.410400] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) [ 3.434936] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) [ 3.451721] mmci-pl18x 80005000.mmc: lost busy status when waiting for busy start IRQ (op 06) [ 3.489379] mmcblk2: mmc2:0001 M4G1YC 3.69 GiB [ 3.569000] mmcblk2: p1 p2 p3 p4 p5 p6 p7 p8 p9 p10 p11 p12 p13 p14 p15 p16 p17 p18 p19 p20 p21 p22 p23 p24 p25 [ 3.583526] mmcblk2boot0: mmc2:0001 M4G1YC 2.00 MiB [ 3.594726] mmcblk2boot1: mmc2:0001 M4G1YC 2.00 MiB [ 3.602233] mmcblk2rpmb: mmc2:0001 M4G1YC 128 KiB, chardev (246:0) [ 4.103057] mmci-pl18x 80005000.mmc: lost busy status when waiting for busy start IRQ (op 06) [ 8.074188] mmci-pl18x 80005000.mmc: lost busy status when waiting for busy start IRQ (op 06) [ 8.084350] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) [ 8.451446] mmci-pl18x 80005000.mmc: lost busy status when waiting for busy start IRQ (op 06) [ 8.757934] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) [ 10.211883] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) [ 10.587646] mmci-pl18x 80005000.mmc: lost busy status when waiting for busy start IRQ (op 06) [ 10.913604] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) [ 10.924072] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) [ 10.931671] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) [ 12.023345] mmci-pl18x 80005000.mmc: lost busy status when waiting for busy start IRQ (op 06) [ 12.357757] mmci-pl18x 80005000.mmc: lost busy status when waiting for busy start IRQ (op 06) [ 14.087677] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) [ 14.096191] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) [ 15.124114] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) [ 15.153411] mmci-pl18x 80005000.mmc: lost busy status when waiting for busy start IRQ (op 06) [ 15.525024] mmci-pl18x 80005000.mmc: lost busy status when waiting for busy start IRQ (op 06) [ 15.850036] mmci-pl18x 80005000.mmc: timeout waiting for busy IRQ (op 06) [ 18.250122] mmci-pl18x 80005000.mmc: lost busy status when waiting for busy start IRQ (op 06) [ 18.988983] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) [ 19.302612] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) [ 19.320953] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) [ 19.333251] mmci-pl18x 80005000.mmc: lost busy status when waiting for busy start IRQ (op 06) [ 21.851715] mmci-pl18x 80005000.mmc: lost busy status when waiting for busy start IRQ (op 06) Always command 0x06, MMC_SWITCH. But this is also the *only* command that resturns MMC_RSP_BUSY so it doesn't say very much about the card in general. We have speculated that the card is maybe operating out of spec, such as holding DAT0 high for too short time (not across enough MCLK cycles) or similar when indicating busy for short timespans. I tested on the other problematic phone, Kyle, and the log is identical (it has the same eMMC card, M4G1YC.) Yours, Linus Walleij
On Tue, 20 Jun 2023 at 21:27, Linus Walleij <linus.walleij@linaro.org> wrote: > > On Tue, Jun 20, 2023 at 11:11 AM Ulf Hansson <ulf.hansson@linaro.org> wrote: > > > The ux500 variant doesn't have a HW based timeout to use for busy-end IRQs. > > To avoid hanging and waiting for the card to stop signaling busy, let's > > schedule a delayed work, according to the corresponding cmd->busy_timeout > > for the command. If work gets to run, let's kick the IRQ handler to > > completed the currently running request/command. > > > > Reviewed-by: Linus Walleij <linus.walleij@linaro.org> > > Tested-by: Linus Walleij <linus.walleij@linaro.org> > > Signed-off-by: Ulf Hansson <ulf.hansson@linaro.org> > > Some experiments: I added a patch to print the offending command and > dev_err() all the timing bugs. The resulting log: Interesting! > > /home/linus # dmesg |grep '80005000\|mmcblk2' > [ 2.684814] mmci-pl18x 80005000.mmc: mmc2: PL180 manf 80 rev4 at > 0x80005000 irq 81,0 (pio) > [ 2.695831] mmci-pl18x 80005000.mmc: DMA channels RX dma0chan4, TX dma0chan5 > [ 3.410400] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) > [ 3.434936] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) > [ 3.451721] mmci-pl18x 80005000.mmc: lost busy status when waiting > for busy start IRQ (op 06) > [ 3.489379] mmcblk2: mmc2:0001 M4G1YC 3.69 GiB > [ 3.569000] mmcblk2: p1 p2 p3 p4 p5 p6 p7 p8 p9 p10 p11 p12 p13 > p14 p15 p16 p17 p18 p19 p20 p21 p22 p23 p24 p25 > [ 3.583526] mmcblk2boot0: mmc2:0001 M4G1YC 2.00 MiB > [ 3.594726] mmcblk2boot1: mmc2:0001 M4G1YC 2.00 MiB > [ 3.602233] mmcblk2rpmb: mmc2:0001 M4G1YC 128 KiB, chardev (246:0) > [ 4.103057] mmci-pl18x 80005000.mmc: lost busy status when waiting > for busy start IRQ (op 06) > [ 8.074188] mmci-pl18x 80005000.mmc: lost busy status when waiting > for busy start IRQ (op 06) > [ 8.084350] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) > [ 8.451446] mmci-pl18x 80005000.mmc: lost busy status when waiting > for busy start IRQ (op 06) > [ 8.757934] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) > [ 10.211883] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) > [ 10.587646] mmci-pl18x 80005000.mmc: lost busy status when waiting > for busy start IRQ (op 06) > [ 10.913604] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) > [ 10.924072] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) > [ 10.931671] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) > [ 12.023345] mmci-pl18x 80005000.mmc: lost busy status when waiting > for busy start IRQ (op 06) > [ 12.357757] mmci-pl18x 80005000.mmc: lost busy status when waiting > for busy start IRQ (op 06) > [ 14.087677] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) > [ 14.096191] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) > [ 15.124114] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) > [ 15.153411] mmci-pl18x 80005000.mmc: lost busy status when waiting > for busy start IRQ (op 06) > [ 15.525024] mmci-pl18x 80005000.mmc: lost busy status when waiting > for busy start IRQ (op 06) > [ 15.850036] mmci-pl18x 80005000.mmc: timeout waiting for busy IRQ (op 06) > [ 18.250122] mmci-pl18x 80005000.mmc: lost busy status when waiting > for busy start IRQ (op 06) > [ 18.988983] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) > [ 19.302612] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) > [ 19.320953] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) > [ 19.333251] mmci-pl18x 80005000.mmc: lost busy status when waiting > for busy start IRQ (op 06) > [ 21.851715] mmci-pl18x 80005000.mmc: lost busy status when waiting > for busy start IRQ (op 06) > > Always command 0x06, MMC_SWITCH. But this is also the *only* > command that resturns MMC_RSP_BUSY so it doesn't say very > much about the card in general. We have other commands that have R1B responses. For example, open-ended I/O writes that are completed with CMD12 or the erase/discard command. Not sure which ones that are easiest for you to test with, we can chat more about this offlist. > > We have speculated that the card is maybe operating out of spec, such as > holding DAT0 high for too short time (not across enough MCLK cycles) > or similar when indicating busy for short timespans. By looking at the above log, it seems like the card does signal busy, at least occasionally. 1) The print "no busy signalling in time", isn't so worrying to me. It probably means that the card doesn't need to signal busy, as it's internal operation is completed. To be absolutely sure, we could extend the polling loop to more retries, just to test. 2) The print "lost busy status when waiting for busy start IRQ" is a bit harder to understand. However, my guess is that the mmci controller does raise an IRQ, to signal a *changed* busy signal state, which is the most important thing. When we end up reading the busy status bit to manage the IRQ, we find that the card has stopped signalling busy. That seems perfectly fine to me. So, maybe we don't get the start IRQ (as that state wasn't discovered) but only the end IRQ, so to say. More importantly, the busy timeout work never gets to run, which indicates that we are no longer hanging and waiting for an IRQ to be raised. Is that correct? > > I tested on the other problematic phone, Kyle, and the log is identical > (it has the same eMMC card, M4G1YC.) Okay! > > Yours, > Linus Walleij Kind regards Uffe
On Wed, 21 Jun 2023 at 14:28, Ulf Hansson <ulf.hansson@linaro.org> wrote: > > On Tue, 20 Jun 2023 at 21:27, Linus Walleij <linus.walleij@linaro.org> wrote: > > > > On Tue, Jun 20, 2023 at 11:11 AM Ulf Hansson <ulf.hansson@linaro.org> wrote: > > > > > The ux500 variant doesn't have a HW based timeout to use for busy-end IRQs. > > > To avoid hanging and waiting for the card to stop signaling busy, let's > > > schedule a delayed work, according to the corresponding cmd->busy_timeout > > > for the command. If work gets to run, let's kick the IRQ handler to > > > completed the currently running request/command. > > > > > > Reviewed-by: Linus Walleij <linus.walleij@linaro.org> > > > Tested-by: Linus Walleij <linus.walleij@linaro.org> > > > Signed-off-by: Ulf Hansson <ulf.hansson@linaro.org> > > > > Some experiments: I added a patch to print the offending command and > > dev_err() all the timing bugs. The resulting log: > > Interesting! > > > > > /home/linus # dmesg |grep '80005000\|mmcblk2' > > [ 2.684814] mmci-pl18x 80005000.mmc: mmc2: PL180 manf 80 rev4 at > > 0x80005000 irq 81,0 (pio) > > [ 2.695831] mmci-pl18x 80005000.mmc: DMA channels RX dma0chan4, TX dma0chan5 > > [ 3.410400] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) > > [ 3.434936] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) > > [ 3.451721] mmci-pl18x 80005000.mmc: lost busy status when waiting > > for busy start IRQ (op 06) > > [ 3.489379] mmcblk2: mmc2:0001 M4G1YC 3.69 GiB > > [ 3.569000] mmcblk2: p1 p2 p3 p4 p5 p6 p7 p8 p9 p10 p11 p12 p13 > > p14 p15 p16 p17 p18 p19 p20 p21 p22 p23 p24 p25 > > [ 3.583526] mmcblk2boot0: mmc2:0001 M4G1YC 2.00 MiB > > [ 3.594726] mmcblk2boot1: mmc2:0001 M4G1YC 2.00 MiB > > [ 3.602233] mmcblk2rpmb: mmc2:0001 M4G1YC 128 KiB, chardev (246:0) > > [ 4.103057] mmci-pl18x 80005000.mmc: lost busy status when waiting > > for busy start IRQ (op 06) > > [ 8.074188] mmci-pl18x 80005000.mmc: lost busy status when waiting > > for busy start IRQ (op 06) > > [ 8.084350] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) > > [ 8.451446] mmci-pl18x 80005000.mmc: lost busy status when waiting > > for busy start IRQ (op 06) > > [ 8.757934] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) > > [ 10.211883] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) > > [ 10.587646] mmci-pl18x 80005000.mmc: lost busy status when waiting > > for busy start IRQ (op 06) > > [ 10.913604] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) > > [ 10.924072] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) > > [ 10.931671] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) > > [ 12.023345] mmci-pl18x 80005000.mmc: lost busy status when waiting > > for busy start IRQ (op 06) > > [ 12.357757] mmci-pl18x 80005000.mmc: lost busy status when waiting > > for busy start IRQ (op 06) > > [ 14.087677] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) > > [ 14.096191] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) > > [ 15.124114] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) > > [ 15.153411] mmci-pl18x 80005000.mmc: lost busy status when waiting > > for busy start IRQ (op 06) > > [ 15.525024] mmci-pl18x 80005000.mmc: lost busy status when waiting > > for busy start IRQ (op 06) > > [ 15.850036] mmci-pl18x 80005000.mmc: timeout waiting for busy IRQ (op 06) > > [ 18.250122] mmci-pl18x 80005000.mmc: lost busy status when waiting > > for busy start IRQ (op 06) > > [ 18.988983] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) > > [ 19.302612] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) > > [ 19.320953] mmci-pl18x 80005000.mmc: no busy signalling in time (OP 06) > > [ 19.333251] mmci-pl18x 80005000.mmc: lost busy status when waiting > > for busy start IRQ (op 06) > > [ 21.851715] mmci-pl18x 80005000.mmc: lost busy status when waiting > > for busy start IRQ (op 06) > > > > Always command 0x06, MMC_SWITCH. But this is also the *only* > > command that resturns MMC_RSP_BUSY so it doesn't say very > > much about the card in general. > > We have other commands that have R1B responses. > > For example, open-ended I/O writes that are completed with CMD12 or > the erase/discard command. Not sure which ones that are easiest for > you to test with, we can chat more about this offlist. > > > > > We have speculated that the card is maybe operating out of spec, such as > > holding DAT0 high for too short time (not across enough MCLK cycles) > > or similar when indicating busy for short timespans. > > By looking at the above log, it seems like the card does signal busy, > at least occasionally. > > 1) The print "no busy signalling in time", isn't so worrying to me. It > probably means that the card doesn't need to signal busy, as it's > internal operation is completed. To be absolutely sure, we could > extend the polling loop to more retries, just to test. > > 2) The print "lost busy status when waiting for busy start IRQ" is a > bit harder to understand. However, my guess is that the mmci > controller does raise an IRQ, to signal a *changed* busy signal state, > which is the most important thing. When we end up reading the busy > status bit to manage the IRQ, we find that the card has stopped > signalling busy. That seems perfectly fine to me. So, maybe we don't > get the start IRQ (as that state wasn't discovered) but only the end > IRQ, so to say. > > More importantly, the busy timeout work never gets to run, which > indicates that we are no longer hanging and waiting for an IRQ to be > raised. Is that correct? Ehh, I should have looked more closely at the log. Indeed there is one case where the timeout work kicks in. Maybe we should log the information about the current ->busy_state at that point too, so understand under what condition we are hanging? I think we should also log the actual used timeout in this case. [...] Kind regards Uffe
On Wed, Jun 21, 2023 at 2:33 PM Ulf Hansson <ulf.hansson@linaro.org> wrote: > > More importantly, the busy timeout work never gets to run, which > > indicates that we are no longer hanging and waiting for an IRQ to be > > raised. Is that correct? > > Ehh, I should have looked more closely at the log. Indeed there is one > case where the timeout work kicks in. Yeah... It wasn't until I added the timeout that I could get the whole thing to work, both are needed: handling lost IRQs and then an occasional timeout. > Maybe we should log the information about the current ->busy_state at > that point too, so understand under what condition we are hanging? I > think we should also log the actual used timeout in this case. Sure thing, please merge this patch as-is (solves a problem!) and I try to make a debug improvement patch on top with what I have (like printing the command) and add in the busy state as well. Yours, Linus Walleij
On Wed, 21 Jun 2023 at 23:13, Linus Walleij <linus.walleij@linaro.org> wrote: > > On Wed, Jun 21, 2023 at 2:33 PM Ulf Hansson <ulf.hansson@linaro.org> wrote: > > > > More importantly, the busy timeout work never gets to run, which > > > indicates that we are no longer hanging and waiting for an IRQ to be > > > raised. Is that correct? > > > > Ehh, I should have looked more closely at the log. Indeed there is one > > case where the timeout work kicks in. > > Yeah... > > It wasn't until I added the timeout that I could get the whole > thing to work, both are needed: handling lost IRQs and then > an occasional timeout. > > > Maybe we should log the information about the current ->busy_state at > > that point too, so understand under what condition we are hanging? I > > think we should also log the actual used timeout in this case. > > Sure thing, please merge this patch as-is (solves a problem!) and I try > to make a debug improvement patch on top with what I have (like > printing the command) and add in the busy state as well. Okay, I have applied the patch for next, thanks! Yann, feel free to provide your tested-by tag too, I can amend the patch after I have applied it. Kind regards Uffe
diff --git a/drivers/mmc/host/mmci.c b/drivers/mmc/host/mmci.c index 8a661ea1a2d1..61d761646462 100644 --- a/drivers/mmc/host/mmci.c +++ b/drivers/mmc/host/mmci.c @@ -37,6 +37,7 @@ #include <linux/pinctrl/consumer.h> #include <linux/reset.h> #include <linux/gpio/consumer.h> +#include <linux/workqueue.h> #include <asm/div64.h> #include <asm/io.h> @@ -682,7 +683,8 @@ static void ux500_busy_clear_mask_done(struct mmci_host *host) * | | * IRQ1 IRQ2 */ -static bool ux500_busy_complete(struct mmci_host *host, u32 status, u32 err_msk) +static bool ux500_busy_complete(struct mmci_host *host, struct mmc_command *cmd, + u32 status, u32 err_msk) { void __iomem *base = host->base; int retries = 10; @@ -726,6 +728,8 @@ static bool ux500_busy_complete(struct mmci_host *host, u32 status, u32 err_msk) host->variant->busy_detect_mask, base + MMCIMASK0); host->busy_state = MMCI_BUSY_WAITING_FOR_START_IRQ; + schedule_delayed_work(&host->ux500_busy_timeout_work, + msecs_to_jiffies(cmd->busy_timeout)); goto out_ret_state; } retries--; @@ -753,6 +757,7 @@ static bool ux500_busy_complete(struct mmci_host *host, u32 status, u32 err_msk) } else { dev_dbg(mmc_dev(host->mmc), "lost busy status when waiting for busy start IRQ\n"); + cancel_delayed_work(&host->ux500_busy_timeout_work); ux500_busy_clear_mask_done(host); } break; @@ -761,6 +766,7 @@ static bool ux500_busy_complete(struct mmci_host *host, u32 status, u32 err_msk) if (!(status & host->variant->busy_detect_flag)) { host->busy_status |= status & (MCI_CMDSENT | MCI_CMDRESPEND); writel(host->variant->busy_detect_mask, base + MMCICLEAR); + cancel_delayed_work(&host->ux500_busy_timeout_work); ux500_busy_clear_mask_done(host); } else { dev_dbg(mmc_dev(host->mmc), @@ -1277,6 +1283,7 @@ static void mmci_start_command(struct mmci_host *host, struct mmc_command *cmd, u32 c) { void __iomem *base = host->base; + bool busy_resp = cmd->flags & MMC_RSP_BUSY; unsigned long long clks; dev_dbg(mmc_dev(host->mmc), "op %02x arg %08x flags %08x\n", @@ -1304,10 +1311,11 @@ mmci_start_command(struct mmci_host *host, struct mmc_command *cmd, u32 c) host->busy_status = 0; host->busy_state = MMCI_BUSY_DONE; - if (host->variant->busy_timeout && cmd->flags & MMC_RSP_BUSY) { - if (!cmd->busy_timeout) - cmd->busy_timeout = 10 * MSEC_PER_SEC; + /* Assign a default timeout if the core does not provide one */ + if (busy_resp && !cmd->busy_timeout) + cmd->busy_timeout = 10 * MSEC_PER_SEC; + if (busy_resp && host->variant->busy_timeout) { if (cmd->busy_timeout > host->mmc->max_busy_timeout) clks = (unsigned long long)host->mmc->max_busy_timeout * host->cclk; else @@ -1448,7 +1456,7 @@ mmci_cmd_irq(struct mmci_host *host, struct mmc_command *cmd, /* Handle busy detection on DAT0 if the variant supports it. */ if (busy_resp && host->variant->busy_detect) - if (!host->ops->busy_complete(host, status, err_msk)) + if (!host->ops->busy_complete(host, cmd, status, err_msk)) return; host->cmd = NULL; @@ -1495,6 +1503,34 @@ mmci_cmd_irq(struct mmci_host *host, struct mmc_command *cmd, } } +/* + * This busy timeout worker is used to "kick" the command IRQ if a + * busy detect IRQ fails to appear in reasonable time. Only used on + * variants with busy detection IRQ delivery. + */ +static void ux500_busy_timeout_work(struct work_struct *work) +{ + struct mmci_host *host = container_of(work, struct mmci_host, + ux500_busy_timeout_work.work); + unsigned long flags; + u32 status; + + spin_lock_irqsave(&host->lock, flags); + + if (host->cmd) { + dev_dbg(mmc_dev(host->mmc), "timeout waiting for busy IRQ\n"); + + /* If we are still busy let's tag on a cmd-timeout error. */ + status = readl(host->base + MMCISTATUS); + if (status & host->variant->busy_detect_flag) + status |= MCI_CMDTIMEOUT; + + mmci_cmd_irq(host, host->cmd, status); + } + + spin_unlock_irqrestore(&host->lock, flags); +} + static int mmci_get_rx_fifocnt(struct mmci_host *host, u32 status, int remain) { return remain - (readl(host->base + MMCIFIFOCNT) << 2); @@ -2309,6 +2345,10 @@ static int mmci_probe(struct amba_device *dev, goto clk_disable; } + if (host->variant->busy_detect) + INIT_DELAYED_WORK(&host->ux500_busy_timeout_work, + ux500_busy_timeout_work); + writel(MCI_IRQENABLE | variant->start_err, host->base + MMCIMASK0); amba_set_drvdata(dev, mmc); diff --git a/drivers/mmc/host/mmci.h b/drivers/mmc/host/mmci.h index 12a7bbd3ce26..69b2439842dd 100644 --- a/drivers/mmc/host/mmci.h +++ b/drivers/mmc/host/mmci.h @@ -393,7 +393,7 @@ struct mmci_host_ops { void (*dma_error)(struct mmci_host *host); void (*set_clkreg)(struct mmci_host *host, unsigned int desired); void (*set_pwrreg)(struct mmci_host *host, unsigned int pwr); - bool (*busy_complete)(struct mmci_host *host, u32 status, u32 err_msk); + bool (*busy_complete)(struct mmci_host *host, struct mmc_command *cmd, u32 status, u32 err_msk); void (*pre_sig_volt_switch)(struct mmci_host *host); int (*post_sig_volt_switch)(struct mmci_host *host, struct mmc_ios *ios); }; @@ -451,6 +451,7 @@ struct mmci_host { void *dma_priv; s32 next_cookie; + struct delayed_work ux500_busy_timeout_work; }; #define dma_inprogress(host) ((host)->dma_in_progress) diff --git a/drivers/mmc/host/mmci_stm32_sdmmc.c b/drivers/mmc/host/mmci_stm32_sdmmc.c index 953d1be4e379..f07cfbeafe2e 100644 --- a/drivers/mmc/host/mmci_stm32_sdmmc.c +++ b/drivers/mmc/host/mmci_stm32_sdmmc.c @@ -372,7 +372,8 @@ static u32 sdmmc_get_dctrl_cfg(struct mmci_host *host) return datactrl; } -static bool sdmmc_busy_complete(struct mmci_host *host, u32 status, u32 err_msk) +static bool sdmmc_busy_complete(struct mmci_host *host, struct mmc_command *cmd, + u32 status, u32 err_msk) { void __iomem *base = host->base; u32 busy_d0, busy_d0end, mask, sdmmc_status;