SDHCI: timeout during data transfer

SDHCI: timeout during data transfer

[Luca Tettamanti]

Hi,
I'm seeing timeout errors when transfering "big" (over 1MB or so) files to a SD
card (small files are ok):

[  251.956666] mmcblk0: error -110 transferring data
[  251.979810] end_request: I/O error, dev mmcblk0, sector 1572758
[  251.981477] Buffer I/O error on device mmcblk0p1, logical block 1572742
[  251.983198] lost page write due to I/O error on mmcblk0p1
[  251.983788] end_request: I/O error, dev mmcblk0, sector 1572759
[  251.983788] Buffer I/O error on device mmcblk0p1, logical block 1572743
[  251.983788] lost page write due to I/O error on mmcblk0p1
[  251.983788] end_request: I/O error, dev mmcblk0, sector 1572760
[  251.983788] Buffer I/O error on device mmcblk0p1, logical block 1572744
[  251.983788] lost page write due to I/O error on mmcblk0p1
[  251.983788] end_request: I/O error, dev mmcblk0, sector 1572761
[  251.983788] Buffer I/O error on device mmcblk0p1, logical block 1572745
[  251.983788] lost page write due to I/O error on mmcblk0p1
[  253.513336] mmcblk0: error -110 transferring data
(trashed FS here)

kernel in use is 2.6.27-rc6, and this is the controller:

09:01.1 SD Host controller: Ricoh Co Ltd R5C822 SD/SDIO/MMC/MS/MSPro Host Adapter (rev 22)
09:01.2 System peripheral: Ricoh Co Ltd R5C843 MMC Host Controller (rev 12)
09:01.3 System peripheral: Ricoh Co Ltd R5C592 Memory Stick Bus Host Adapter (rev 12)
09:01.4 System peripheral: Ricoh Co Ltd xD-Picture Card Controller (rev 12)

Googling around I found a patch[1] that introduced a quirk to address an
off-by-one issue for the timeout value in certain controllers.

With this patch:

diff --git a/drivers/mmc/host/sdhci.c b/drivers/mmc/host/sdhci.c
index e3a8133..46899ee 100644
--- a/drivers/mmc/host/sdhci.c
+++ b/drivers/mmc/host/sdhci.c
@@ -575,7 +575,7 @@ static void sdhci_prepare_data(struct sdhci_host *host, struct mmc_data *data)
 	host->data = data;
 	host->data_early = 0;
 
-	count = sdhci_calc_timeout(host, data);
+	count = sdhci_calc_timeout(host, data) + 1;
 	writeb(count, host->ioaddr + SDHCI_TIMEOUT_CONTROL);
 
 	if (host->flags & SDHCI_USE_DMA)

I don't see timeouts anymore (just for reference, I'm not suggesting to apply it
as-is).

Luca
[1] http://www.gossamer-threads.com/lists/linux/kernel/937056
-- 
Dicono che  il cane sia  il miglior  amico dell'uomo. Secondo me  non e`
vero. Quanti dei vostri amici avete fatto castrare, recentemente?

Re: SDHCI: timeout during data transfer

[Pierre Ossman]

On Tue, 23 Sep 2008 23:24:59 +0200
Luca Tettamanti <kronos.it@gmail.com> wrote:

> Hi,
> I'm seeing timeout errors when transfering "big" (over 1MB or so) files to a SD
> card (small files are ok):
> 
> [  251.956666] mmcblk0: error -110 transferring data
> [  251.979810] end_request: I/O error, dev mmcblk0, sector 1572758

Looks like the card died on you there. Did you build the kernel
yourself? If so, it would be helpful if you could enable
CONFIG_MMC_DEBUG and give me a complete dmesg dump from when this
happens.

> kernel in use is 2.6.27-rc6, and this is the controller:
> 
> 09:01.1 SD Host controller: Ricoh Co Ltd R5C822 SD/SDIO/MMC/MS/MSPro Host Adapter (rev 22)
> 09:01.2 System peripheral: Ricoh Co Ltd R5C843 MMC Host Controller (rev 12)
> 09:01.3 System peripheral: Ricoh Co Ltd R5C592 Memory Stick Bus Host Adapter (rev 12)
> 09:01.4 System peripheral: Ricoh Co Ltd xD-Picture Card Controller (rev 12)
> 
> Googling around I found a patch[1] that introduced a quirk to address an
> off-by-one issue for the timeout value in certain controllers.
> 
> With this patch:
> 

The patch doubles the timeout, so something is clearly broken if that
solves the issue. I'd like to identify if it's the driver, controller
or card first though.

Are you experiencing this with just this card, or with all?

Rgds
-- 
     -- Pierre Ossman

  Linux kernel, MMC maintainer        http://www.kernel.org
  rdesktop, core developer          http://www.rdesktop.org

  WARNING: This correspondence is being monitored by the
  Swedish government. Make sure your server uses encryption
  for SMTP traffic and consider using PGP for end-to-end
  encryption.

Re: SDHCI: timeout during data transfer

[Luca Tettamanti]

On Thu, Oct 2, 2008 at 10:17 AM, Pierre Ossman <drzeus-mmc@drzeus.cx> wrote:
> On Tue, 23 Sep 2008 23:24:59 +0200
> Luca Tettamanti <kronos.it@gmail.com> wrote:
>
>> Hi,
>> I'm seeing timeout errors when transfering "big" (over 1MB or so) files to a SD
>> card (small files are ok):
>>
>> [  251.956666] mmcblk0: error -110 transferring data
>> [  251.979810] end_request: I/O error, dev mmcblk0, sector 1572758
>
> Looks like the card died on you there. Did you build the kernel
> yourself? If so, it would be helpful if you could enable
> CONFIG_MMC_DEBUG and give me a complete dmesg dump from when this
> happens.

Will do.

>> kernel in use is 2.6.27-rc6, and this is the controller:
>>
>> 09:01.1 SD Host controller: Ricoh Co Ltd R5C822 SD/SDIO/MMC/MS/MSPro Host Adapter (rev 22)
>> 09:01.2 System peripheral: Ricoh Co Ltd R5C843 MMC Host Controller (rev 12)
>> 09:01.3 System peripheral: Ricoh Co Ltd R5C592 Memory Stick Bus Host Adapter (rev 12)
>> 09:01.4 System peripheral: Ricoh Co Ltd xD-Picture Card Controller (rev 12)
>>
>> Googling around I found a patch[1] that introduced a quirk to address an
>> off-by-one issue for the timeout value in certain controllers.
>>
>> With this patch:
>
> The patch doubles the timeout, so something is clearly broken if that
> solves the issue. I'd like to identify if it's the driver, controller
> or card first though.

I was just shooting in the dark ;-) I found the patch floating around
and applied it.

> Are you experiencing this with just this card, or with all?

Actually I have only that card... I'll try to borrow another one for
testing. Btw, that card works fine under windows (on the same machine)
and my N800 is happy with it too.

Luca

Re: SDHCI: timeout during data transfer

[Luca Tettamanti]

On Thu, Oct 2, 2008 at 10:17 AM, Pierre Ossman <drzeus-mmc@drzeus.cx> wrote:
> On Tue, 23 Sep 2008 23:24:59 +0200
> Luca Tettamanti <kronos.it@gmail.com> wrote:
>
>> Hi,
>> I'm seeing timeout errors when transfering "big" (over 1MB or so) files to a SD
>> card (small files are ok):
>>
>> [  251.956666] mmcblk0: error -110 transferring data
>> [  251.979810] end_request: I/O error, dev mmcblk0, sector 1572758
>
> Looks like the card died on you there. Did you build the kernel
> yourself? If so, it would be helpful if you could enable
> CONFIG_MMC_DEBUG and give me a complete dmesg dump from when this
> happens.

Hum, cannot reproduce (but it was consistently failing when I tested
the patch... the only difference is a mkfs in between). I just got a
few retries:

[  187.158063] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00000040
[  187.656190] mmc0: clock 0Hz busmode 1 powermode 1 cs 0 Vdd 21 width
0 timing 0
[  187.658366] mmc0: clock 128906Hz busmode 1 powermode 2 cs 0 Vdd 21
width 0 timing 0
[  187.660500] mmc0: clock 128906Hz busmode 1 powermode 2 cs 1 Vdd 21
width 0 timing 0
[  187.661634] mmc0: starting CMD0 arg 00000000 flags 000000c0
[  187.662265] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00000001
[  187.662283] mmc0: req done (CMD0): 0: 00000000 00000000 00000000 00000000
[  187.663461] mmc0: clock 128906Hz busmode 1 powermode 2 cs 0 Vdd 21
width 0 timing 0
[  187.664473] mmc0: starting CMD8 arg 000001aa flags 000002f5
[  187.665423] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00000001
[  187.665439] mmc0: req done (CMD8): 0: 000001aa 00000000 00000000 00000000
[  187.665474] mmc0: starting CMD5 arg 00000000 flags 000002e1
[  187.666423] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00018000
[  187.668435] mmc0: req failed (CMD5): -110, retrying...
[  187.669423] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00018000
[  187.671424] mmc0: req failed (CMD5): -110, retrying...
[  187.672422] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00018000
[  187.674423] mmc0: req failed (CMD5): -110, retrying...
[  187.675425] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00018000
[  187.677436] mmc0: req done (CMD5): -110: 00000000 00000000 00000000 00000000
[  187.677683] mmc0: starting CMD55 arg 00000000 flags 000000f5
[  187.678754] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00000001
[  187.678770] mmc0: req done (CMD55): 0: 00000120 00000000 00000000 00000000
[  187.678808] mmc0: starting CMD41 arg 00000000 flags 000000e1
[  187.679877] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00000001
[  187.679893] mmc0: req done (CMD41): 0: 00ff8000 00000000 00000000 00000000
[  187.679995] mmc0: clock 128906Hz busmode 1 powermode 2 cs 0 Vdd 20
width 0 timing 0
[  187.680021] mmc0: clock 128906Hz busmode 1 powermode 2 cs 1 Vdd 20
width 0 timing 0
[cut 80MB of logs]

Is it possible that the error was generated by a faulty flash block?

Luca

Re: SDHCI: timeout during data transfer

[Pierre Ossman]

On Fri, 3 Oct 2008 13:27:52 +0200
"Luca Tettamanti" <kronos.it@gmail.com> wrote:

> 
> Hum, cannot reproduce (but it was consistently failing when I tested
> the patch... the only difference is a mkfs in between). I just got a
> few retries:

A silly question, but did you also try disabling the debugging? Since
this is a timing issue, the debugging output could be just enough to
make the problem go away.

> 
> Is it possible that the error was generated by a faulty flash block?
> 

Maybe. I've never gotten a bad block so I have no experience in how it
behaves.

Rgds
-- 
     -- Pierre Ossman

  Linux kernel, MMC maintainer        http://www.kernel.org
  rdesktop, core developer          http://www.rdesktop.org

  WARNING: This correspondence is being monitored by the
  Swedish government. Make sure your server uses encryption
  for SMTP traffic and consider using PGP for end-to-end
  encryption.

Re: SDHCI: timeout during data transfer

[Luca Tettamanti]

On Sun, Oct 12, 2008 at 10:52 AM, Pierre Ossman <drzeus-mmc@drzeus.cx> wrote:
> On Fri, 3 Oct 2008 13:27:52 +0200
> "Luca Tettamanti" <kronos.it@gmail.com> wrote:
>>
>> Hum, cannot reproduce (but it was consistently failing when I tested
>> the patch... the only difference is a mkfs in between). I just got a
>> few retries:
>
> A silly question, but did you also try disabling the debugging? Since
> this is a timing issue, the debugging output could be just enough to
> make the problem go away.

Ok, I managed to reproduce without the debugging, but this time it
took over a couple of GB before it started failing. Block numbers
differ from the previous failures (so maybe it's not a cluster of
broken blocks).
Will go back and test with debugging enabled.

Luca

Re: SDHCI: timeout during data transfer

[Luca Tettamanti]

On Tue, Oct 14, 2008 at 11:34 AM, Luca Tettamanti <kronos.it@gmail.com> wrote:
> On Sun, Oct 12, 2008 at 10:52 AM, Pierre Ossman <drzeus-mmc@drzeus.cx> wrote:
>> On Fri, 3 Oct 2008 13:27:52 +0200
>> "Luca Tettamanti" <kronos.it@gmail.com> wrote:
>>>
>>> Hum, cannot reproduce (but it was consistently failing when I tested
>>> the patch... the only difference is a mkfs in between). I just got a
>>> few retries:
>>
>> A silly question, but did you also try disabling the debugging? Since
>> this is a timing issue, the debugging output could be just enough to
>> make the problem go away.
>
> Ok, I managed to reproduce without the debugging, but this time it
> took over a couple of GB before it started failing. Block numbers
> differ from the previous failures (so maybe it's not a cluster of
> broken blocks).
> Will go back and test with debugging enabled.

I finally managed to capture a failure with debug enabled, I'm
attaching the log.
To recap:
- heavy write loads sometimes result in a timeout
- reads seem unaffected (I read the card multiple times without errors)
- doubling the timeout (as per my first patch) makes the timeout disappear
- windows doesn't suffer from the issue

I've tested two other cards that do not show the problem, but they are
not "high speed":

mmc0: new high speed SD card at address 0002 (troubles)
vs:
mmc0: new SD card at address e624 (OK)

Luca

Re: SDHCI: timeout during data transfer

[Luca Tettamanti]

[-- Attachment #1: Type: text/plain, Size: 198 bytes --]

On Tue, Oct 14, 2008 at 11:13 PM, Luca Tettamanti <kronos.it@gmail.com> wrote:
> I finally managed to capture a failure with debug enabled, I'm
> attaching the log.

...for real this time :-)

Luca

[-- Attachment #2: dmesg.txt.bz2 --]
[-- Type: application/x-bzip2, Size: 268512 bytes --]

Re: SDHCI: timeout during data transfer

[Pierre Ossman]

On Tue, 14 Oct 2008 23:13:39 +0200
"Luca Tettamanti" <kronos.it@gmail.com> wrote:

> 
> I finally managed to capture a failure with debug enabled, I'm
> attaching the log.

It seems to be a transfer error at least as it is in a completely
different area of the card compared to the first mail you sent.

> To recap:
> - heavy write loads sometimes result in a timeout
> - reads seem unaffected (I read the card multiple times without errors)

Looking at the dump, the controller seems to be doing the correct
thing. The timeout mandated by the SD specification is 250 ms, and that
time has passed if you look at the timestamps. If you look at some
other writes further down, the card takes around 220 ms for the writes.
IOW, it would seem that this card is cutting it a bit close and
sometimes goes over the alloted time.

> - doubling the timeout (as per my first patch) makes the timeout disappear

Since it is the card that's the problem here, not the controller, we'd
need to fix this in the core. Unfortunately the sdhci hardware is a bit
inflexible so any change I make will result in a doubling of the
timeout.

Could you try modifying line 283 of drivers/mmc/core/core.c where it
says "limit_us = 250000;" to 300000 instead?

> - windows doesn't suffer from the issue

Windows doesn't do proper handling of timeouts. It just sets the
maximum timeout and hopes for the best.

> 
> I've tested two other cards that do not show the problem, but they are
> not "high speed":
> 
> mmc0: new high speed SD card at address 0002 (troubles)
> vs:
> mmc0: new SD card at address e624 (OK)
> 

What's the vendor and model of the failing card?

-- 
     -- Pierre Ossman

  Linux kernel, MMC maintainer        http://www.kernel.org
  rdesktop, core developer          http://www.rdesktop.org

  WARNING: This correspondence is being monitored by the
  Swedish government. Make sure your server uses encryption
  for SMTP traffic and consider using PGP for end-to-end
  encryption.

Re: SDHCI: timeout during data transfer

[Luca Tettamanti]

On Sat, Oct 18, 2008 at 10:46 PM, Pierre Ossman <drzeus-mmc@drzeus.cx> wrote:
> On Tue, 14 Oct 2008 23:13:39 +0200
> "Luca Tettamanti" <kronos.it@gmail.com> wrote:
>>
>> I finally managed to capture a failure with debug enabled, I'm
>> attaching the log.
>
> It seems to be a transfer error at least as it is in a completely
> different area of the card compared to the first mail you sent.
>
>> To recap:
>> - heavy write loads sometimes result in a timeout
>> - reads seem unaffected (I read the card multiple times without errors)
>
> Looking at the dump, the controller seems to be doing the correct
> thing. The timeout mandated by the SD specification is 250 ms, and that
> time has passed if you look at the timestamps. If you look at some
> other writes further down, the card takes around 220 ms for the writes.
> IOW, it would seem that this card is cutting it a bit close and
> sometimes goes over the alloted time.
>
>> - doubling the timeout (as per my first patch) makes the timeout disappear
>
> Since it is the card that's the problem here, not the controller, we'd
> need to fix this in the core. Unfortunately the sdhci hardware is a bit
> inflexible so any change I make will result in a doubling of the
> timeout.
>
> Could you try modifying line 283 of drivers/mmc/core/core.c where it
> says "limit_us = 250000;" to 300000 instead?

300ms seems to be enough.

>> I've tested two other cards that do not show the problem, but they are
>> not "high speed":
>>
>> mmc0: new high speed SD card at address 0002 (troubles)
>> vs:
>> mmc0: new SD card at address e624 (OK)
>
> What's the vendor and model of the failing card?

The card is from S3+, and it's branded "SD Excel" (el-cheapo 4GB card)

Luca

Re: SDHCI: timeout during data transfer

[Pierre Ossman]

On Mon, 20 Oct 2008 14:20:13 +0200
"Luca Tettamanti" <kronos.it@gmail.com> wrote:

> On Sat, Oct 18, 2008 at 10:46 PM, Pierre Ossman <drzeus-mmc@drzeus.cx> wrote:
> > Could you try modifying line 283 of drivers/mmc/core/core.c where it
> > says "limit_us = 250000;" to 300000 instead?
> 
> 300ms seems to be enough.
> 

It might be. Your timeout will be in the neigbourhood of 500ms because
of the crappy resolution of the sdhci hardware.

Still, I'll queue up a patch for this...

Rgds
-- 
     -- Pierre Ossman

  Linux kernel, MMC maintainer        http://www.kernel.org
  rdesktop, core developer          http://www.rdesktop.org

  WARNING: This correspondence is being monitored by the
  Swedish government. Make sure your server uses encryption
  for SMTP traffic and consider using PGP for end-to-end
  encryption.