Re: SDHCI: mdelay() in hot path in esdhc_pltfm_set_clock looses CAN (!) frames

From: Fabio Estevam
Date: Tue Jul 07 2015 - 14:17:17 EST


Hi Holger,

Adding some more folks on Cc.

On Tue, Jun 30, 2015 at 10:43 AM, Holger Schurig
<holgerschurig@xxxxxxxxx> wrote:
> Hi,
>
> I noticed in a kernel 4.0.7 that I loose CAN packets when an incoming
> rsync transfer changes my eMMC or SD-Card image. I used CONFIG_FRACE
> to find why this is the case, and came to this trace:
>
> # tracer: preemptoff
> #
> # preemptoff latency trace v1.1.5 on 4.0.7
> # --------------------------------------------------------------------
> # latency: 1046 us, #756/756, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
> # -----------------
> # | task: mmcqd/0-76 (uid:0 nice:0 policy:0 rt_prio:0)
> # -----------------
> # => started at: sdhci_do_set_ios
> # => ended at: sdhci_do_set_ios
> #
> #
> # _------=> CPU#
> # / _-----=> irqs-off
> # | / _----=> need-resched
> # || / _---=> hardirq/softirq
> # ||| / _--=> preempt-depth
> # |||| / delay
> # cmd pid ||||| time | caller
> # \ / ||||| \ | /
> mmcqd/0-76 2d..1 1us : _raw_spin_lock_irq <-sdhci_do_set_ios
> mmcqd/0-76 2d..2 2us : esdhc_writeb_le <-sdhci_do_set_ios
> mmcqd/0-76 2d..2 4us : esdhc_pltfm_set_bus_width <-sdhci_do_set_ios
> mmcqd/0-76 2d..2 5us : l2c210_sync <-esdhc_pltfm_set_bus_width
> mmcqd/0-76 2d..2 7us : esdhc_writeb_le <-sdhci_do_set_ios
> mmcqd/0-76 2d..2 9us : l2c210_sync <-esdhc_writeb_le
> mmcqd/0-76 2d..2 10us : esdhc_readw_le <-sdhci_do_set_ios
> mmcqd/0-76 2d..2 12us : esdhc_writew_le <-sdhci_do_set_ios
> mmcqd/0-76 2d..2 14us : l2c210_sync <-esdhc_writew_le
> mmcqd/0-76 2d..2 16us : l2c210_sync <-esdhc_writew_le
> mmcqd/0-76 2d..2 18us : esdhc_readw_le <-sdhci_do_set_ios
> mmcqd/0-76 2d..2 19us : esdhc_writew_le <-sdhci_do_set_ios
> mmcqd/0-76 2d..2 21us : l2c210_sync <-esdhc_writew_le
> mmcqd/0-76 2d..2 22us : esdhc_set_uhs_signaling <-sdhci_do_set_ios
> mmcqd/0-76 2d..2 24us : pinctrl_select_state <-esdhc_set_uhs_signaling
> mmcqd/0-76 2d..2 26us : esdhc_readl_le <-esdhc_pltfm_set_clock
> mmcqd/0-76 2d..2 28us : esdhc_writel_le <-esdhc_pltfm_set_clock
> mmcqd/0-76 2d..2 29us : l2c210_sync <-esdhc_writel_le
> mmcqd/0-76 2d..2 31us : esdhc_readl_le <-esdhc_pltfm_set_clock
> mmcqd/0-76 2d..2 33us : esdhc_writel_le <-esdhc_pltfm_set_clock
> mmcqd/0-76 2d..2 34us : l2c210_sync <-esdhc_writel_le
> mmcqd/0-76 2d..2 36us : l2c210_sync <-esdhc_pltfm_set_clock
> mmcqd/0-76 2d..2 37us : __timer_const_udelay <-esdhc_pltfm_set_clock
> mmcqd/0-76 2d..2 39us : __timer_delay <-__timer_const_udelay
> mmcqd/0-76 2d..2 40us : read_current_timer <-__timer_delay
> mmcqd/0-76 2d..2 41us : imx_read_current_timer <-read_current_timer
> mmcqd/0-76 2d..2 43us : read_current_timer <-__timer_delay
> mmcqd/0-76 2d..2 44us : imx_read_current_timer <-read_current_timer
> mmcqd/0-76 2d..2 45us : read_current_timer <-__timer_delay
> ....
>
> So it seems that esdhc_pltfm_set_clock() somehow waits. And really
> there is an mdelay(1) there. So it waits a whopping millisecond there!
>
> What's worse: I put a printk() into this function, just before the
> mdelay(). And it get's called hundreds of times when I boot, or when I
> update via rsync. And I believe that for each call the mdelay() kills
> preemption.
>
> This is bad because in the FlexCAN driver the ISR calls
> napi_schedule(), which in turn clears the CAN RxFIFO. And if this
> scheduling is taking too long, CAN packets are dropped. With 50 bits
> per CAN packet anf 500000 bit/s this can happen quite easily (the
> RxFIFO is a hardware component that can hold only 6 CAN frames before
> data is lost).
>
> The mdelay() is also bad because it makes eMMC/SD-Card access WAY
> slower than they could be.
>
> I'm not firm with SDHCI, I only see that esdhc_pltfm_set_clock() is
> all the time called with 0 Hz and then with 20000000 Hz. Any tips on
> how to get rid of this clock-off-clock-on dance?
>
> Holger
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/