[MX25][MMC] mmc esdhc failure in 3.3-rc5

[MX25][MMC] mmc esdhc failure in 3.3-rc5

[joancarles]

Hi

I have the following error when trying to access the SD-card on my MX25
device:

root@mx25-noah:~$> mount /media/card/
root@mx25-noah:~$> df -kh /media/card
Filesystem                Size      Used Available Use% Mounted on
/dev/mmcblk0p1          123.6M      2.7M    120.9M   2% /media/card
root@mx25-noah:~$> touch /media/card/file
[   82.982920] mmcblk0: error -110 transferring data, sector 559, nr 1,
cmd response 0x900, card status 0x0
[   82.993544] end_request: I/O error, dev mmcblk0, sector 559
[   82.999169] Buffer I/O error on device mmcblk0p1, logical block 497
[   83.005458] lost page write due to I/O error on mmcblk0p1
[   83.013922] mmcblk0: error -84 transferring data, sector 559, nr 1, 
cmd
response 0x900, card status 0x0
[   83.024114] end_request: I/O error, dev mmcblk0, sector 559
[   83.029965] FAT-fs (mmcblk0p1): Directory bread(block 497) failed
[   83.038051] mmcblk0: error -84 transferring data, sector 560, nr 1, 
cmd
response 0x900, card status 0x0
[   83.048579] end_request: I/O error, dev mmcblk0, sector 560
[   83.054205] Buffer I/O error on device mmcblk0p1, logical block 498
[   83.060494] lost page write due to I/O error on mmcblk0p1
touch: /media/card/file: Input/output error

I have compiled the kernel 3.3-rc5 with driver core debug support and I
get the following information:

root@mx25-noah:~$> dmesg | grep -i mmc
[    0.228098] bus: 'mmc': registered
[    0.228139] device class 'mmc_host': registering
[    1.405180] bus: 'mmc': add driver mmcblk
[    1.429969] device: 'mmc0::': device_add
[    1.430249] PM: Adding info for No Bus:mmc0::
[    1.430837] Registered led device: mmc0::
[    1.430884] device: 'mmc0': device_add
[    1.431114] PM: Adding info for No Bus:mmc0
[    1.432953] mmc0: SDHCI controller on sdhci-esdhc-imx25.0
[sdhci-esdhc-imx25.0] using DMA
[    1.771322] mmc0: host does not support reading read-only switch.
assuming write-enable.
[    1.798584] mmc0: new high speed SD card at address 0002
[    1.804018] device: 'mmc0:0002': device_add
[    1.804283] bus: 'mmc': add device mmc0:0002
[    1.804445] PM: Adding info for mmc:mmc0:0002
[    1.815198] bus: 'mmc': driver_probe_device: matched device 
mmc0:0002
with driver mmcblk
[    1.815256] bus: 'mmc': really_probe: probing driver mmcblk with 
device
mmc0:0002
[    1.825154] mmcblk0: mmc0:0002 00000 1.86 GiB
[    1.835076] device: 'mmcblk0': device_add
[    1.835680] PM: Adding info for No Bus:mmcblk0
[    1.849286]  mmcblk0: p1 p2
[    1.852252] device: 'mmcblk0p1': device_add
[    1.855232] PM: Adding info for No Bus:mmcblk0p1
[    1.855371] device: 'mmcblk0p2': device_add
[    1.855874] PM: Adding info for No Bus:mmcblk0p2
[    1.866667] driver: 'mmc0:0002': driver_bound: bound to device 
'mmcblk'
[    1.866720] bus: 'mmc': really_probe: bound device mmc0:0002 to 
driver
mmcblk
[   82.982920] mmcblk0: error -110 transferring data, sector 559, nr 1,
cmd response 0x900, card status 0x0
[   82.993544] end_request: I/O error, dev mmcblk0, sector 559
[   82.999169] Buffer I/O error on device mmcblk0p1, logical block 497
[   83.005458] lost page write due to I/O error on mmcblk0p1
[   83.013922] mmcblk0: error -84 transferring data, sector 559, nr 1, 
cmd
response 0x900, card status 0x0
[   83.024114] end_request: I/O error, dev mmcblk0, sector 559
[   83.029965] FAT-fs (mmcblk0p1): Directory bread(block 497) failed
[   83.038051] mmcblk0: error -84 transferring data, sector 560, nr 1, 
cmd
response 0x900, card status 0x0
[   83.048579] end_request: I/O error, dev mmcblk0, sector 560
[   83.054205] Buffer I/O error on device mmcblk0p1, logical block 498
[   83.060494] lost page write due to I/O error on mmcblk0p1

The same device booted into a 2.6.39.3 kernel works just fine. The
initialization of the esdhc driver in the device section is as follows:

imx25_add_sdhci_esdhc_imx(0, NULL);

Changing it to a pdata init as shown below does not change anything 
with
regard to the failure:

imx25_add_sdhci_esdhc_imx(0, &noah_esdhc_pdata);
static const struct esdhc_platform_data noah_esdhc_pdata __initconst = 
{
         .wp_gpio = -EINVAL,
         .cd_gpio = -EINVAL,
         .wp_type = ESDHC_WP_NONE,
         .cd_type = ESDHC_CD_NONE,
};

What could have changed between 2.6.39.3 and 3.3-rc5 to trigger this
behaviour? A quick look at

git diff v2.6.39 drivers/mmc/host/sdhci-esdhc-imx.c

only confuses me with regard to this issue.

Regards
-- 
Joan C. Abelaira

Re: [MX25][MMC] mmc esdhc failure in 3.3-rc5 (still present in rc7)

[joancarles]

Hi

On Tue, 06 Mar 2012 11:29:50 +0000, joancarles wrote:
> Hi
>
> I have the following error when trying to access the SD-card on my 
> MX25
> device:
>
> root@mx25-noah:~$> mount /media/card/
> root@mx25-noah:~$> df -kh /media/card
> Filesystem                Size      Used Available Use% Mounted on
> /dev/mmcblk0p1          123.6M      2.7M    120.9M   2% /media/card
> root@mx25-noah:~$> touch /media/card/file
> [   82.982920] mmcblk0: error -110 transferring data, sector 559, nr 
> 1,
> cmd response 0x900, card status 0x0
> [   82.993544] end_request: I/O error, dev mmcblk0, sector 559
> [   82.999169] Buffer I/O error on device mmcblk0p1, logical block 
> 497
> [   83.005458] lost page write due to I/O error on mmcblk0p1
> [   83.013922] mmcblk0: error -84 transferring data, sector 559, nr 
> 1, cmd
> response 0x900, card status 0x0
> [   83.024114] end_request: I/O error, dev mmcblk0, sector 559
> [   83.029965] FAT-fs (mmcblk0p1): Directory bread(block 497) failed
> [   83.038051] mmcblk0: error -84 transferring data, sector 560, nr 
> 1, cmd
> response 0x900, card status 0x0
> [   83.048579] end_request: I/O error, dev mmcblk0, sector 560
> [   83.054205] Buffer I/O error on device mmcblk0p1, logical block 
> 498
> [   83.060494] lost page write due to I/O error on mmcblk0p1
> touch: /media/card/file: Input/output error
>
> I have compiled the kernel 3.3-rc5 with driver core debug support and 
> I
> get the following information:
>
> root@mx25-noah:~$> dmesg | grep -i mmc
> [    0.228098] bus: 'mmc': registered
> [    0.228139] device class 'mmc_host': registering
> [    1.405180] bus: 'mmc': add driver mmcblk
> [    1.429969] device: 'mmc0::': device_add
> [    1.430249] PM: Adding info for No Bus:mmc0::
> [    1.430837] Registered led device: mmc0::
> [    1.430884] device: 'mmc0': device_add
> [    1.431114] PM: Adding info for No Bus:mmc0
> [    1.432953] mmc0: SDHCI controller on sdhci-esdhc-imx25.0
> [sdhci-esdhc-imx25.0] using DMA
> [    1.771322] mmc0: host does not support reading read-only switch.
> assuming write-enable.
> [    1.798584] mmc0: new high speed SD card at address 0002
> [    1.804018] device: 'mmc0:0002': device_add
> [    1.804283] bus: 'mmc': add device mmc0:0002
> [    1.804445] PM: Adding info for mmc:mmc0:0002
> [    1.815198] bus: 'mmc': driver_probe_device: matched device 
> mmc0:0002
> with driver mmcblk
> [    1.815256] bus: 'mmc': really_probe: probing driver mmcblk with 
> device
> mmc0:0002
> [    1.825154] mmcblk0: mmc0:0002 00000 1.86 GiB
> [    1.835076] device: 'mmcblk0': device_add
> [    1.835680] PM: Adding info for No Bus:mmcblk0
> [    1.849286]  mmcblk0: p1 p2
> [    1.852252] device: 'mmcblk0p1': device_add
> [    1.855232] PM: Adding info for No Bus:mmcblk0p1
> [    1.855371] device: 'mmcblk0p2': device_add
> [    1.855874] PM: Adding info for No Bus:mmcblk0p2
> [    1.866667] driver: 'mmc0:0002': driver_bound: bound to device 
> 'mmcblk'
> [    1.866720] bus: 'mmc': really_probe: bound device mmc0:0002 to 
> driver
> mmcblk
> [   82.982920] mmcblk0: error -110 transferring data, sector 559, nr 
> 1,
> cmd response 0x900, card status 0x0
> [   82.993544] end_request: I/O error, dev mmcblk0, sector 559
> [   82.999169] Buffer I/O error on device mmcblk0p1, logical block 
> 497
> [   83.005458] lost page write due to I/O error on mmcblk0p1
> [   83.013922] mmcblk0: error -84 transferring data, sector 559, nr 
> 1, cmd
> response 0x900, card status 0x0
> [   83.024114] end_request: I/O error, dev mmcblk0, sector 559
> [   83.029965] FAT-fs (mmcblk0p1): Directory bread(block 497) failed
> [   83.038051] mmcblk0: error -84 transferring data, sector 560, nr 
> 1, cmd
> response 0x900, card status 0x0
> [   83.048579] end_request: I/O error, dev mmcblk0, sector 560
> [   83.054205] Buffer I/O error on device mmcblk0p1, logical block 
> 498
> [   83.060494] lost page write due to I/O error on mmcblk0p1
>
> The same device booted into a 2.6.39.3 kernel works just fine. The
> initialization of the esdhc driver in the device section is as 
> follows:
>
> imx25_add_sdhci_esdhc_imx(0, NULL);
>
> Changing it to a pdata init as shown below does not change anything 
> with
> regard to the failure:
>
> imx25_add_sdhci_esdhc_imx(0, &noah_esdhc_pdata);
> static const struct esdhc_platform_data noah_esdhc_pdata __initconst 
> = {
>         .wp_gpio = -EINVAL,
>         .cd_gpio = -EINVAL,
>         .wp_type = ESDHC_WP_NONE,
>         .cd_type = ESDHC_CD_NONE,
> };
>
> What could have changed between 2.6.39.3 and 3.3-rc5 to trigger this
> behaviour? A quick look at
>
> git diff v2.6.39 drivers/mmc/host/sdhci-esdhc-imx.c
>
> only confuses me with regard to this issue.
>
> Regards

This is still present in 3.3-rc7. Anyone? Where could I start debugging 
this? The same device works just fine with the 2.6.39.3 kernel based 
sdhci driver (drivers/mmc/host/sdhci-esdhc-imx.c). Unfortunately, due to 
out-of-tree device support for a custom i.MX25 board that I have started 
with a fresh 3.3-rc2 git tree, I cannot bisect the tree down to 2.6.39, 
or at least I don't know how.

Best regards
-- 
Joan C. Abelaira

Re: [MX25][MMC] mmc esdhc failure in 3.3-rc5

[Wolfram Sang]

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


> What could have changed between 2.6.39.3 and 3.3-rc5 to trigger this
> behaviour? A quick look at
> 
> git diff v2.6.39 drivers/mmc/host/sdhci-esdhc-imx.c

I'd recommend:

git log v2.6.39.. drivers/mmc/host/sdhci-esdhc-imx.c

and look at those commits. You should also include the people who did
those commits in CC when writing mails, otherwise they probably won't
notice. Richard Zhu and Shawn Guo are from Freescale, and have more
knowledge about the ESDHC cores.

Wild guessing, 97e4ba6a5ea903a221d87bcabdaf01efb0a609a5 looks like the
most likely candidate, but I may be totally wrong.

Regards,

   Wolfram

-- 
Pengutronix e.K.                           | Wolfram Sang                |
Industrial Linux Solutions                 | http://www.pengutronix.de/  |

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 198 bytes --]

Re: [MX25][MMC] mmc esdhc failure in 3.3-rc5

[joancarles]

Hi

On Mon, 12 Mar 2012 14:24:23 +0100, Wolfram Sang wrote:
>> What could have changed between 2.6.39.3 and 3.3-rc5 to trigger this
>> behaviour? A quick look at
>>
>> git diff v2.6.39 drivers/mmc/host/sdhci-esdhc-imx.c
>
> I'd recommend:
>
> git log v2.6.39.. drivers/mmc/host/sdhci-esdhc-imx.c

I have been staring at those commits, however with very little domain 
knowledge it's a shot in the dark.

> and look at those commits. You should also include the people who did
> those commits in CC when writing mails, otherwise they probably won't
> notice. Richard Zhu and Shawn Guo are from Freescale, and have more
> knowledge about the ESDHC cores.

Done now, thanks. Richard, Shawn, any pointers as to where to start 
looking on this one? Since the i.MX25 eSDHC has four data lines, one 
clock and one command line hard-wired, there is really nothing from a 
hardware point of view that could influence this different behaviour 
between the 2.6.39 and the 3.3-rc7 kernels.

Again, booting the same hardware with a 2.6.39.3 kernel using the 
standard mx25 initialisation routine:

imx25_add_sdhci_esdhc_imx(0, NULL);

works as intended. I can mount the sd card and I can write/remove files 
from it, independent of the file system (VFAT, ext2 have been tested). 
Leaving the sd card inside the slot, and rebooting the device with a 
linux kernel 3.3-rc7 fails, as described earlier. On any 3.3-rc kernels, 
and probably earlier versions as well, it fails with the cited error 
messages earlier in this thread:

http://marc.info/?l=linux-mmc&m=133103397222503&w=3

Changing it to a pdata init as shown below does not change anything 
with
regard to the failure:

imx25_add_sdhci_esdhc_imx(0, &noah_esdhc_pdata);
static const struct esdhc_platform_data noah_esdhc_pdata __initconst = 
{
         .wp_gpio = -EINVAL,
         .cd_gpio = -EINVAL,
         .wp_type = ESDHC_WP_NONE,
         .cd_type = ESDHC_CD_NONE,
};

> Wild guessing, 97e4ba6a5ea903a221d87bcabdaf01efb0a609a5 looks like 
> the
> most likely candidate, but I may be totally wrong.

I extracted it as follows:

git format-patch -1 97e4ba6a5ea90
patch -R -p1 < 0001-mmc-sdhci-esdhc-imx-Enable-ADMA2.patch

compiled and booted and it has no influence on my specific misbehaviour 
of the esdhc driver. So, this can be barred as a possible candidate, I 
reckon.

Thanks and best regards
-- 
Joan C. Abelaira

Re: [MX25][MMC] mmc esdhc failure in 3.3-rc5

[Wolfram Sang]

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

On Mon, Mar 12, 2012 at 03:50:03PM +0100, joancarles wrote:

> >>What could have changed between 2.6.39.3 and 3.3-rc5 to trigger this
> >>behaviour? A quick look at
> >>
> >>git diff v2.6.39 drivers/mmc/host/sdhci-esdhc-imx.c
> >
> >I'd recommend:
> >
> >git log v2.6.39.. drivers/mmc/host/sdhci-esdhc-imx.c
> 
> I have been staring at those commits, however with very little
> domain knowledge it's a shot in the dark.

Have you tried copying sdhci-esdhc-imx.c from 2.6.39 to the current kernel
(might need some build fixes)? If that doesn't work, there might be something
wrong in the sdhci-driver itself, and not the esdhc-extension.

Regards,

   Wolfram

-- 
Pengutronix e.K.                           | Wolfram Sang                |
Industrial Linux Solutions                 | http://www.pengutronix.de/  |

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 198 bytes --]

Re: [MX25][MMC] mmc esdhc failure in 3.3-rc5

[joancarles]

>> >I'd recommend:
>> >
>> >git log v2.6.39.. drivers/mmc/host/sdhci-esdhc-imx.c
>>
>> I have been staring at those commits, however with very little
>> domain knowledge it's a shot in the dark.
>
> Have you tried copying sdhci-esdhc-imx.c from 2.6.39 to the current 
> kernel
> (might need some build fixes)? If that doesn't work, there might be 
> something
> wrong in the sdhci-driver itself, and not the esdhc-extension.

I have now, and it results in a bigger mess than I believe is worth 
pursuing for.

Therefore, I will create a stashing tree next to linux.git with our 
device specific changes (minimal setup for the PCB to boot up) that 
should theoretically apply to any kernel tree between 2.6.x and 3.3-rcX 
to subsequently bisect the biest.

Thanks for your help and best regards
-- 
Joan C. Abelaira

RE: [MX25][MMC] mmc esdhc failure in 3.3-rc5

[Zhu Richard-R65037]

Hi:
-110 is the timeout problem.
You can dump the esdhc registers if you want to debug into this issue when this timeout problem occurred.
The register dump can help to figure out what's wrong on the bus.

Best Regards
Richard Zhu


-----Original Message-----
From: joancarles [mailto:joancarles@fqingenieria.es] 
Sent: 2012年3月12日 22:50
To: Wolfram Sang
Cc: linux-mmc@vger.kernel.org; shawn.guo@linaro.org; Zhu Richard-R65037
Subject: Re: [MX25][MMC] mmc esdhc failure in 3.3-rc5

Hi

On Mon, 12 Mar 2012 14:24:23 +0100, Wolfram Sang wrote:
>> What could have changed between 2.6.39.3 and 3.3-rc5 to trigger this 
>> behaviour? A quick look at
>>
>> git diff v2.6.39 drivers/mmc/host/sdhci-esdhc-imx.c
>
> I'd recommend:
>
> git log v2.6.39.. drivers/mmc/host/sdhci-esdhc-imx.c

I have been staring at those commits, however with very little domain knowledge it's a shot in the dark.

> and look at those commits. You should also include the people who did 
> those commits in CC when writing mails, otherwise they probably won't 
> notice. Richard Zhu and Shawn Guo are from Freescale, and have more 
> knowledge about the ESDHC cores.

Done now, thanks. Richard, Shawn, any pointers as to where to start looking on this one? Since the i.MX25 eSDHC has four data lines, one clock and one command line hard-wired, there is really nothing from a hardware point of view that could influence this different behaviour between the 2.6.39 and the 3.3-rc7 kernels.

Again, booting the same hardware with a 2.6.39.3 kernel using the standard mx25 initialisation routine:

imx25_add_sdhci_esdhc_imx(0, NULL);

works as intended. I can mount the sd card and I can write/remove files from it, independent of the file system (VFAT, ext2 have been tested). 
Leaving the sd card inside the slot, and rebooting the device with a linux kernel 3.3-rc7 fails, as described earlier. On any 3.3-rc kernels, and probably earlier versions as well, it fails with the cited error messages earlier in this thread:

http://marc.info/?l=linux-mmc&m=133103397222503&w=3

Changing it to a pdata init as shown below does not change anything with regard to the failure:

imx25_add_sdhci_esdhc_imx(0, &noah_esdhc_pdata); static const struct esdhc_platform_data noah_esdhc_pdata __initconst = {
         .wp_gpio = -EINVAL,
         .cd_gpio = -EINVAL,
         .wp_type = ESDHC_WP_NONE,
         .cd_type = ESDHC_CD_NONE,
};

> Wild guessing, 97e4ba6a5ea903a221d87bcabdaf01efb0a609a5 looks like the 
> most likely candidate, but I may be totally wrong.

I extracted it as follows:

git format-patch -1 97e4ba6a5ea90
patch -R -p1 < 0001-mmc-sdhci-esdhc-imx-Enable-ADMA2.patch

compiled and booted and it has no influence on my specific misbehaviour of the esdhc driver. So, this can be barred as a possible candidate, I reckon.

Thanks and best regards
--
Joan C. Abelaira

RE: [MX25][MMC] mmc esdhc failure in 3.3-rc5

[joancarles]

Hi

Thank you for your reply. I has taken me a while to figure out what you 
meant, but I believe I have added a sdhci_dumpregs(host) to the place 
where CMD24 is issued with a -110 return error.

> Hi:
> -110 is the timeout problem.
> You can dump the esdhc registers if you want to debug into this issue
> when this timeout problem occurred.
> The register dump can help to figure out what's wrong on the bus.

I have no familiarity with the SDHC drivers, so there's nothing useful 
for me in the output as of this moment:

[ 1080.818765] sdhci: ===========================================
[ 1080.818830] mmc0: req done (CMD17): 0: 00000900 00000000 00000000 
00000000
[ 1080.818862] mmc0:     512 bytes transferred: 0
[ 1080.819395] mmc0: starting CMD24 arg 00008800 flags 000000b5
[ 1080.819444] mmc0:     blksz 512 blocks 1 flags 00000100 tsac 300 ms 
nsac 0
[ 1080.819544] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00000009
[ 1080.819595] sdhci [sdhci_data_irq()]: mmc0: DMA base 0x82547c00, 
transferred 0x038400 bytes, next 0x82580000
[ 1080.819630] sdhci: =========== REGISTER DUMP (mmc0)===========
[ 1080.819658] sdhci: Sys addr: 0x82547e00 | Version:  0x00000000
[ 1080.819683] sdhci: Blk size: 0x00000200 | Blk cnt:  0x00000000
[ 1080.819707] sdhci: Argument: 0x00008800 | Trn mode: 0x00000003
[ 1080.819732] sdhci: Present:  0xfe880006 | Host ctl: 0x00000023
[ 1080.819756] sdhci: Power:    0x00000000 | Blk gap:  0x00000000
[ 1080.819780] sdhci: Wake-up:  0x00000000 | Clock:    0x00000107
[ 1080.819804] sdhci: Timeout:  0x0000000c | Int stat: 0x00100002
[ 1080.819830] sdhci: Int enab: 0x107f000b | Sig enab: 0x107f000b
[ 1080.819854] sdhci: AC12 err: 0x00000000 | Slot int: 0x00001001
[ 1080.819879] sdhci: Caps:     0x07eb0000 | Caps_1:   0x04100410
[ 1080.819904] sdhci: Cmd:      0x0000183a | Max curr: 0x00000000
[ 1080.819926] sdhci: Host ctl2: 0x00000000
[ 1080.819942] sdhci: ===========================================
[ 1080.819985] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00100002
[ 1080.820048] mmc0: req done (CMD24): 0: 00000900 00000000 00000000 
00000000
[ 1080.820082] mmc0:     0 bytes transferred: -110
[ 1080.820134] mmc0: starting CMD13 arg 00020000 flags 00000195
[ 1080.820201] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00000001
[ 1080.820259] mmc0: req done (CMD13): 0: 00000e00 00000000 00000000 
00000000
[ 1080.820330] mmc0: starting CMD13 arg 00020000 flags 00000195
[ 1080.820391] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00000001
[ 1080.820445] mmc0: req done (CMD13): 0: 00000e00 00000000 00000000 
00000000
[ 1080.820504] mmc0: starting CMD13 arg 00020000 flags 00000195
[ 1080.820572] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00000001
[ 1080.820627] mmc0: req done (CMD13): 0: 00000e00 00000000 00000000 
00000000
[ 1080.820785] mmc0: starting CMD13 arg 00020000 flags 00000195
[ 1080.820879] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00000001
[ 1080.820946] mmc0: req done (CMD13): 0: 00000e00 00000000 00000000 
00000000
[ 1080.821021] mmc0: starting CMD13 arg 00020000 flags 00000195
[ 1080.821085] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00000001
[ 1080.821140] mmc0: req done (CMD13): 0: 00000e00 00000000 00000000 
00000000
[ 1080.821197] mmc0: starting CMD13 arg 00020000 flags 00000195
[ 1080.821255] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00000001
[ 1080.821308] mmc0: req done (CMD13): 0: 00000e00 00000000 00000000 
00000000
[ 1080.824944] mmc0: starting CMD13 arg 00020000 flags 00000195
[ 1080.825041] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00000001
[ 1080.825112] mmc0: req done (CMD13): 0: 00000e00 00000000 00000000 
00000000
[ 1080.825186] mmc0: starting CMD13 arg 00020000 flags 00000195
[ 1080.825248] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00000001
[ 1080.825302] mmc0: req done (CMD13): 0: 00000e00 00000000 00000000 
00000000
[ 1080.825364] mmc0: starting CMD13 arg 00020000 flags 00000195
[ 1080.825432] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00000001
[ 1080.825485] mmc0: req done (CMD13): 0: 00000e00 00000000 00000000 
00000000
[ 1080.825640] mmc0: starting CMD13 arg 00020000 flags 00000195
[ 1080.825736] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00000001
[ 1080.825803] mmc0: req done (CMD13): 0: 00000900 00000000 00000000 
00000000
[ 1080.825883] mmcblk0: error -110 transferring data, sector 68, nr 1, 
cmd response 0x900, card status 0x0
[ 1080.849435] mmc0: starting CMD55 arg 00020000 flags 00000095
[ 1080.849531] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00000001
[ 1080.849596] mmc0: req done (CMD55): 0: 00000920 00000000 00000000 
00000000
[ 1080.850319] mmc0: starting CMD22 arg 00000000 flags 000000b5
[ 1080.850367] mmc0:     blksz 4 blocks 1 flags 00000200 tsac 100 ms 
nsac 0
[ 1080.850468] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00000001
[ 1080.850523] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x0020000a
[ 1080.850591] mmc0: req done (CMD22): 0: 00000920 00000000 00000000 
00000000
[ 1080.850624] mmc0:     0 bytes transferred: -84
[ 1080.851339] end_request: I/O error, dev mmcblk0, sector 68
[ 1080.856881] Buffer I/O error on device mmcblk0p1, logical block 6
[ 1080.862998] lost page write due to I/O error on mmcblk0p1
[ 1080.897203] mmc0: starting CMD17 arg 00008800 flags 000000b5
[ 1080.897250] mmc0:     blksz 512 blocks 1 flags 00000200 tsac 100 ms 
nsac 0
[ 1080.897350] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00000001
[ 1080.898143] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x0020000a
[ 1080.898241] mmc0: req done (CMD17): 0: 00000900 00000000 00000000 
00000000
[ 1080.898276] mmc0:     0 bytes transferred: -84
[ 1080.898949] mmc0: starting CMD13 arg 00020000 flags 00000195
[ 1080.899134] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00000001
[ 1080.899204] mmc0: req done (CMD13): 0: 00000900 00000000 00000000 
00000000
[ 1080.899284] mmcblk0: error -84 transferring data, sector 68, nr 1, 
cmd response 0x900, card status 0x0
[ 1080.908738] end_request: I/O error, dev mmcblk0, sector 68
[ 1080.914465] FAT-fs (mmcblk0p1): FAT read failed (blocknr 6)
[ 1085.809683] mmc0: starting CMD24 arg 00045e00 flags 000000b5
[ 1085.809731] mmc0:     blksz 512 blocks 1 flags 00000100 tsac 300 ms 
nsac 0
[ 1085.809831] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00000009
[ 1085.809880] sdhci [sdhci_data_irq()]: mmc0: DMA base 0x82548200, 
transferred 0x037e00 bytes, next 0x82580000
[ 1085.809914] sdhci: =========== REGISTER DUMP (mmc0)===========
[ 1085.809941] sdhci: Sys addr: 0x82548400 | Version:  0x00000000
[ 1085.809967] sdhci: Blk size: 0x00000200 | Blk cnt:  0x00000000
[ 1085.809992] sdhci: Argument: 0x00045e00 | Trn mode: 0x00000003
[ 1085.810017] sdhci: Present:  0xff880000 | Host ctl: 0x00000021
[ 1085.810042] sdhci: Power:    0x00000000 | Blk gap:  0x00000000
[ 1085.810067] sdhci: Wake-up:  0x00000000 | Clock:    0x00000107
[ 1085.810093] sdhci: Timeout:  0x0000000c | Int stat: 0x00200002
[ 1085.810119] sdhci: Int enab: 0x107f000b | Sig enab: 0x107f000b
[ 1085.810143] sdhci: AC12 err: 0x00000000 | Slot int: 0x00001001
[ 1085.810169] sdhci: Caps:     0x07eb0000 | Caps_1:   0x04100410
[ 1085.810193] sdhci: Cmd:      0x0000183a | Max curr: 0x00000000
[ 1085.810214] sdhci: Host ctl2: 0x00000000
[ 1085.810232] sdhci: ===========================================
[ 1085.810275] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00200002
[ 1085.810340] mmc0: req done (CMD24): 0: 00000900 00000000 00000000 
00000000
[ 1085.810373] mmc0:     0 bytes transferred: -84
[ 1085.810427] mmc0: starting CMD13 arg 00020000 flags 00000195
[ 1085.810489] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00000001
[ 1085.810543] mmc0: req done (CMD13): 0: 00000900 00000000 00000000 
00000000
[ 1085.810616] mmc0: starting CMD13 arg 00020000 flags 00000195
[ 1085.810690] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00000001
[ 1085.810747] mmc0: req done (CMD13): 0: 00000900 00000000 00000000 
00000000
[ 1085.810838] mmcblk0: error -84 transferring data, sector 559, nr 1, 
cmd response 0x900, card status 0x0
[ 1085.834557] mmc0: starting CMD55 arg 00020000 flags 00000095
[ 1085.834651] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00000001
[ 1085.834722] mmc0: req done (CMD55): 0: 00000920 00000000 00000000 
00000000
[ 1085.834802] mmc0: starting CMD22 arg 00000000 flags 000000b5
[ 1085.834839] mmc0:     blksz 4 blocks 1 flags 00000200 tsac 100 ms 
nsac 0
[ 1085.834915] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00000001
[ 1085.834986] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x0020000a
[ 1085.835056] mmc0: req done (CMD22): 0: 00000920 00000000 00000000 
00000000

What else can I provide you with? The MMC/SDHC/eSDHC driver framework 
is a huge piece of software, so I don't really know where to start 
looking. Electrically, there seems nothing really wrong with the signal 
of the clock; the only thing that looks a wee bit suspicious is that the 
MX25 clock for the SDHC is currently offering a 33MHz signal (as 
gathered from the oscilloscope).

>> and look at those commits. You should also include the people who 
>> did
>> those commits in CC when writing mails, otherwise they probably 
>> won't
>> notice. Richard Zhu and Shawn Guo are from Freescale, and have more
>> knowledge about the ESDHC cores.
>
> Done now, thanks. Richard, Shawn, any pointers as to where to start
> looking on this one? Since the i.MX25 eSDHC has four data lines, one
> clock and one command line hard-wired, there is really nothing from a
> hardware point of view that could influence this different behaviour
> between the 2.6.39 and the 3.3-rc7 kernels.

-- 
Joan C. Abelaira

RE: [MX25][MMC] mmc esdhc failure in 3.3

[joancarles]

G'day

This is still present, and we have absolutely no idea where to continue 
searching for the solution of the problem. Any pointers? Any git trees 
of mmc driver changes we could try? Anybody else with a MX25 that has 
this issue?

>> Hi:
>> -110 is the timeout problem.
>> You can dump the esdhc registers if you want to debug into this 
>> issue
>> when this timeout problem occurred.
>> The register dump can help to figure out what's wrong on the bus.
>
> I have no familiarity with the SDHC drivers, so there's nothing
> useful for me in the output as of this moment:
>
> [ 1080.818765] sdhci: ===========================================
> [ 1080.818830] mmc0: req done (CMD17): 0: 00000900 00000000 00000000 
> 00000000
> [ 1080.818862] mmc0:     512 bytes transferred: 0
> [ 1080.819395] mmc0: starting CMD24 arg 00008800 flags 000000b5
> [ 1080.819444] mmc0:     blksz 512 blocks 1 flags 00000100 tsac 300 
> ms nsac 0
> [ 1080.819544] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 
> 0x00000009
> [ 1080.819595] sdhci [sdhci_data_irq()]: mmc0: DMA base 0x82547c00,
> transferred 0x038400 bytes, next 0x82580000
> [ 1080.819630] sdhci: =========== REGISTER DUMP (mmc0)===========
> [ 1080.819658] sdhci: Sys addr: 0x82547e00 | Version:  0x00000000
> [ 1080.819683] sdhci: Blk size: 0x00000200 | Blk cnt:  0x00000000
> [ 1080.819707] sdhci: Argument: 0x00008800 | Trn mode: 0x00000003
> [ 1080.819732] sdhci: Present:  0xfe880006 | Host ctl: 0x00000023
> [ 1080.819756] sdhci: Power:    0x00000000 | Blk gap:  0x00000000
> [ 1080.819780] sdhci: Wake-up:  0x00000000 | Clock:    0x00000107
> [ 1080.819804] sdhci: Timeout:  0x0000000c | Int stat: 0x00100002
> [ 1080.819830] sdhci: Int enab: 0x107f000b | Sig enab: 0x107f000b
> [ 1080.819854] sdhci: AC12 err: 0x00000000 | Slot int: 0x00001001
> [ 1080.819879] sdhci: Caps:     0x07eb0000 | Caps_1:   0x04100410
> [ 1080.819904] sdhci: Cmd:      0x0000183a | Max curr: 0x00000000
> [ 1080.819926] sdhci: Host ctl2: 0x00000000
> [ 1080.819942] sdhci: ===========================================
> [ 1080.819985] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 
> 0x00100002
> [ 1080.820048] mmc0: req done (CMD24): 0: 00000900 00000000 00000000 
> 00000000
> [ 1080.820082] mmc0:     0 bytes transferred: -110
> [ 1080.820134] mmc0: starting CMD13 arg 00020000 flags 00000195
> [ 1080.820201] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 
> 0x00000001
> [ 1080.820259] mmc0: req done (CMD13): 0: 00000e00 00000000 00000000 
> 00000000
> [ 1080.820330] mmc0: starting CMD13 arg 00020000 flags 00000195
> [ 1080.820391] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 
> 0x00000001
> [ 1080.820445] mmc0: req done (CMD13): 0: 00000e00 00000000 00000000 
> 00000000
> [ 1080.820504] mmc0: starting CMD13 arg 00020000 flags 00000195
> [ 1080.820572] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 
> 0x00000001
> [ 1080.820627] mmc0: req done (CMD13): 0: 00000e00 00000000 00000000 
> 00000000
> [ 1080.820785] mmc0: starting CMD13 arg 00020000 flags 00000195
> [ 1080.820879] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 
> 0x00000001
> [ 1080.820946] mmc0: req done (CMD13): 0: 00000e00 00000000 00000000 
> 00000000
> [ 1080.821021] mmc0: starting CMD13 arg 00020000 flags 00000195
> [ 1080.821085] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 
> 0x00000001
> [ 1080.821140] mmc0: req done (CMD13): 0: 00000e00 00000000 00000000 
> 00000000
> [ 1080.821197] mmc0: starting CMD13 arg 00020000 flags 00000195
> [ 1080.821255] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 
> 0x00000001
> [ 1080.821308] mmc0: req done (CMD13): 0: 00000e00 00000000 00000000 
> 00000000
> [ 1080.824944] mmc0: starting CMD13 arg 00020000 flags 00000195
> [ 1080.825041] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 
> 0x00000001
> [ 1080.825112] mmc0: req done (CMD13): 0: 00000e00 00000000 00000000 
> 00000000
> [ 1080.825186] mmc0: starting CMD13 arg 00020000 flags 00000195
> [ 1080.825248] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 
> 0x00000001
> [ 1080.825302] mmc0: req done (CMD13): 0: 00000e00 00000000 00000000 
> 00000000
> [ 1080.825364] mmc0: starting CMD13 arg 00020000 flags 00000195
> [ 1080.825432] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 
> 0x00000001
> [ 1080.825485] mmc0: req done (CMD13): 0: 00000e00 00000000 00000000 
> 00000000
> [ 1080.825640] mmc0: starting CMD13 arg 00020000 flags 00000195
> [ 1080.825736] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 
> 0x00000001
> [ 1080.825803] mmc0: req done (CMD13): 0: 00000900 00000000 00000000 
> 00000000
> [ 1080.825883] mmcblk0: error -110 transferring data, sector 68, nr
> 1, cmd response 0x900, card status 0x0
> [ 1080.849435] mmc0: starting CMD55 arg 00020000 flags 00000095
> [ 1080.849531] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 
> 0x00000001
> [ 1080.849596] mmc0: req done (CMD55): 0: 00000920 00000000 00000000 
> 00000000
> [ 1080.850319] mmc0: starting CMD22 arg 00000000 flags 000000b5
> [ 1080.850367] mmc0:     blksz 4 blocks 1 flags 00000200 tsac 100 ms 
> nsac 0
> [ 1080.850468] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 
> 0x00000001
> [ 1080.850523] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 
> 0x0020000a
> [ 1080.850591] mmc0: req done (CMD22): 0: 00000920 00000000 00000000 
> 00000000
> [ 1080.850624] mmc0:     0 bytes transferred: -84
> [ 1080.851339] end_request: I/O error, dev mmcblk0, sector 68
> [ 1080.856881] Buffer I/O error on device mmcblk0p1, logical block 6
> [ 1080.862998] lost page write due to I/O error on mmcblk0p1
> [ 1080.897203] mmc0: starting CMD17 arg 00008800 flags 000000b5
> [ 1080.897250] mmc0:     blksz 512 blocks 1 flags 00000200 tsac 100 
> ms nsac 0
> [ 1080.897350] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 
> 0x00000001
> [ 1080.898143] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 
> 0x0020000a
> [ 1080.898241] mmc0: req done (CMD17): 0: 00000900 00000000 00000000 
> 00000000
> [ 1080.898276] mmc0:     0 bytes transferred: -84
> [ 1080.898949] mmc0: starting CMD13 arg 00020000 flags 00000195
> [ 1080.899134] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 
> 0x00000001
> [ 1080.899204] mmc0: req done (CMD13): 0: 00000900 00000000 00000000 
> 00000000
> [ 1080.899284] mmcblk0: error -84 transferring data, sector 68, nr 1,
> cmd response 0x900, card status 0x0
> [ 1080.908738] end_request: I/O error, dev mmcblk0, sector 68
> [ 1080.914465] FAT-fs (mmcblk0p1): FAT read failed (blocknr 6)
> [ 1085.809683] mmc0: starting CMD24 arg 00045e00 flags 000000b5
> [ 1085.809731] mmc0:     blksz 512 blocks 1 flags 00000100 tsac 300 
> ms nsac 0
> [ 1085.809831] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 
> 0x00000009
> [ 1085.809880] sdhci [sdhci_data_irq()]: mmc0: DMA base 0x82548200,
> transferred 0x037e00 bytes, next 0x82580000
> [ 1085.809914] sdhci: =========== REGISTER DUMP (mmc0)===========
> [ 1085.809941] sdhci: Sys addr: 0x82548400 | Version:  0x00000000
> [ 1085.809967] sdhci: Blk size: 0x00000200 | Blk cnt:  0x00000000
> [ 1085.809992] sdhci: Argument: 0x00045e00 | Trn mode: 0x00000003
> [ 1085.810017] sdhci: Present:  0xff880000 | Host ctl: 0x00000021
> [ 1085.810042] sdhci: Power:    0x00000000 | Blk gap:  0x00000000
> [ 1085.810067] sdhci: Wake-up:  0x00000000 | Clock:    0x00000107
> [ 1085.810093] sdhci: Timeout:  0x0000000c | Int stat: 0x00200002
> [ 1085.810119] sdhci: Int enab: 0x107f000b | Sig enab: 0x107f000b
> [ 1085.810143] sdhci: AC12 err: 0x00000000 | Slot int: 0x00001001
> [ 1085.810169] sdhci: Caps:     0x07eb0000 | Caps_1:   0x04100410
> [ 1085.810193] sdhci: Cmd:      0x0000183a | Max curr: 0x00000000
> [ 1085.810214] sdhci: Host ctl2: 0x00000000
> [ 1085.810232] sdhci: ===========================================
> [ 1085.810275] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 
> 0x00200002
> [ 1085.810340] mmc0: req done (CMD24): 0: 00000900 00000000 00000000 
> 00000000
> [ 1085.810373] mmc0:     0 bytes transferred: -84
> [ 1085.810427] mmc0: starting CMD13 arg 00020000 flags 00000195
> [ 1085.810489] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 
> 0x00000001
> [ 1085.810543] mmc0: req done (CMD13): 0: 00000900 00000000 00000000 
> 00000000
> [ 1085.810616] mmc0: starting CMD13 arg 00020000 flags 00000195
> [ 1085.810690] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 
> 0x00000001
> [ 1085.810747] mmc0: req done (CMD13): 0: 00000900 00000000 00000000 
> 00000000
> [ 1085.810838] mmcblk0: error -84 transferring data, sector 559, nr
> 1, cmd response 0x900, card status 0x0
> [ 1085.834557] mmc0: starting CMD55 arg 00020000 flags 00000095
> [ 1085.834651] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 
> 0x00000001
> [ 1085.834722] mmc0: req done (CMD55): 0: 00000920 00000000 00000000 
> 00000000
> [ 1085.834802] mmc0: starting CMD22 arg 00000000 flags 000000b5
> [ 1085.834839] mmc0:     blksz 4 blocks 1 flags 00000200 tsac 100 ms 
> nsac 0
> [ 1085.834915] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 
> 0x00000001
> [ 1085.834986] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 
> 0x0020000a
> [ 1085.835056] mmc0: req done (CMD22): 0: 00000920 00000000 00000000 
> 00000000
>
> What else can I provide you with? The MMC/SDHC/eSDHC driver framework
> is a huge piece of software, so I don't really know where to start
> looking. Electrically, there seems nothing really wrong with the
> signal of the clock; the only thing that looks a wee bit suspicious 
> is
> that the MX25 clock for the SDHC is currently offering a 33MHz signal
> (as gathered from the oscilloscope).

-- 
Joan C. Abelaira

RE: [MX25][MMC] mmc esdhc failure in 3.3

[joancarles]

ADDENDUM:

On Tue, 27 Mar 2012 09:32:36 +0200, joancarles wrote:
> G'day
>
> This is still present, and we have absolutely no idea where to
> continue searching for the solution of the problem. Any pointers? Any
> git trees of mmc driver changes we could try? Anybody else with a 
> MX25
> that has this issue?

Enabling CONFIG_MMC_CLKGATE, I have managed to create an oops simply be 
trying to remove a file:

[  192.821592] mmcblk0: error -110 transferring data, sector 559, nr 1, 
cmd response 0x900, card status 0x0
[  192.846928] mmc0: starting CMD55 arg 00020000 flags 00000095
[  192.846991] mmc0: clock 50000000Hz busmode 2 powermode 2 cs 0 Vdd 17 
width 2 timing 2
[  192.847048] sdhci-esdhc-imx sdhci-esdhc-imx25.0: desired SD clock: 
50000000, actual: 33250000
[  192.848090] mmc0: ungated MCI clock
[  192.848159] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00000001
[  192.848221] mmc0: req done (CMD55): 0: 00000920 00000000 00000000 
00000000
[  192.848353] mmc0: clock 0Hz busmode 2 powermode 2 cs 0 Vdd 17 width 
2 timing 2
[  192.848400] mmc0: gated MCI clock
[  192.848458] Division by zero in kernel.
[  192.852384] [<c00141f0>] (unwind_backtrace+0x0/0x130) from 
[<c01c0bb4>] (Ldiv0+0x8/0x10)
[  192.867389] [<c01c0bb4>] (Ldiv0+0x8/0x10) from [<c029b288>] 
(mmc_sd_num_wr_blocks+0x148/0x230)
[  192.876924] [<c029b288>] (mmc_sd_num_wr_blocks+0x148/0x230) from 
[<c029c900>] (mmc_blk_issue_rw_rq+0x3fc/0x4ac)
[  192.887944] [<c029c900>] (mmc_blk_issue_rw_rq+0x3fc/0x4ac) from 
[<c029cbe8>] (mmc_blk_issue_rq+0x238/0x514)
[  192.898606] [<c029cbe8>] (mmc_blk_issue_rq+0x238/0x514) from 
[<c029d3b8>] (mmc_queue_thread+0x58/0x144)
[  192.908879] [<c029d3b8>] (mmc_queue_thread+0x58/0x144) from 
[<c0038b44>] (kthread+0x84/0x90)
[  192.918477] [<c0038b44>] (kthread+0x84/0x90) from [<c000f9a0>] 
(kernel_thread_exit+0x0/0x8)
[  192.927654] mmc0: starting CMD22 arg 00000000 flags 000000b5
[  192.927700] mmc0:     blksz 4 blocks 1 flags 00000200 tsac 100 ms 
nsac 0
[  192.927752] mmc0: clock 50000000Hz busmode 2 powermode 2 cs 0 Vdd 17 
width 2 timing 2
[  192.927810] sdhci-esdhc-imx sdhci-esdhc-imx25.0: desired SD clock: 
50000000, actual: 33250000
[  192.928852] mmc0: ungated MCI clock
[  192.928940] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00000001
[  192.928991] sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x0000000a
[  192.929031] sdhci [sdhci_data_irq()]: mmc0: DMA base 0x839a3040, 
transferred 0x05cfc0 bytes, next 0x83a00000
[  192.929094] mmc0: req done (CMD22): 0: 00000920 00000000 00000000 
00000000
[  192.929126] mmc0:     4 bytes transferred: 0
[  192.929242] mmc0: clock 0Hz busmode 2 powermode 2 cs 0 Vdd 17 width 
2 timing 2
[  192.929288] mmc0: gated MCI clock

Maybe this helps. The file, in fact, has been removed, as far as I can 
see. Also, how come, the actual clock differs so much from the desired 
clock of 50MHz? As commented before, we do actually see the 33.25MHz 
clock in the oscilloscope.

Best regards
-- 
Joan C. Abelaira

Re: [MX25][MMC] mmc esdhc failure in 3.3

[Eric Bénard]

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

Hi,

Le Tue, 27 Mar 2012 09:32:36 +0200,
joancarles <joancarles@fqingenieria.es> a écrit :

> G'day
> 
> This is still present, and we have absolutely no idea where to continue 
> searching for the solution of the problem. Any pointers? Any git trees 
> of mmc driver changes we could try? Anybody else with a MX25 that has 
> this issue?
> 
does that attached patch fix your problem ?

Eric

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: 0001-esdhc-imx-unbreak-on-i.MX25.patch --]
[-- Type: text/x-patch, Size: 1084 bytes --]

From 6b41fd664bdb4755a0c22abdbe5524a76ac74330 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Eric=20B=C3=A9nard?= <eric@eukrea.com>
Date: Mon, 12 Mar 2012 22:17:05 +0100
Subject: [PATCH] esdhc-imx: unbreak on i.MX25
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

Signed-off-by: Eric Bénard <eric@eukrea.com>
---
 drivers/mmc/host/sdhci-esdhc-imx.c |    3 +--
 1 files changed, 1 insertions(+), 2 deletions(-)

diff --git a/drivers/mmc/host/sdhci-esdhc-imx.c b/drivers/mmc/host/sdhci-esdhc-imx.c
index 4dc0028..fe0da1c 100644
--- a/drivers/mmc/host/sdhci-esdhc-imx.c
+++ b/drivers/mmc/host/sdhci-esdhc-imx.c
@@ -400,8 +400,7 @@ static int __devinit sdhci_esdhc_imx_probe(struct platform_device *pdev)
 	clk_enable(clk);
 	pltfm_host->clk = clk;
 
-	if (!is_imx25_esdhc(imx_data))
-		host->quirks |= SDHCI_QUIRK_BROKEN_TIMEOUT_VAL;
+	host->quirks |= SDHCI_QUIRK_BROKEN_TIMEOUT_VAL;
 
 	if (is_imx25_esdhc(imx_data) || is_imx35_esdhc(imx_data))
 		/* Fix errata ENGcm07207 present on i.MX25 and i.MX35 */
-- 
1.7.7.6

Re: [MX25][MMC] mmc esdhc failure in 3.3

[joancarles]

Hi Eric

>> G'day
>>
>> This is still present, and we have absolutely no idea where to 
>> continue
>> searching for the solution of the problem. Any pointers? Any git 
>> trees
>> of mmc driver changes we could try? Anybody else with a MX25 that 
>> has
>> this issue?
>>
> does that attached patch fix your problem ?

YES, indeed it does to a certain degree. The timeout errors do not 
occur anymore and I can successfully perform many fs->ops, such as READ, 
WRITE, UNLINK ... . So thank you very much for this insight through your 
patch!

The speed of the card is excruciatingly slow, however. We roughly get 
between 34KB/s and 64KB/s from a dd if=/dev/zero write to any of the 
following partitions:

root@mx25-noah:~$> grep mmc /proc/mounts
/dev/mmcblk0p2 /media/card-ext3 ext3 
rw,sync,relatime,user_xattr,barrier=1,nodelalloc,data=ordered 0 0
/dev/mmcblk0p1 /media/card vfat 
rw,sync,relatime,fmask=0022,dmask=0022,codepage=cp437,iocharset=iso8859-1,shortname=mixed,errors=remount-ro 
0 0
root@mx25-noah:~$> df -kh | grep mmc
/dev/mmcblk0p2            1.7G    133.1M      1.5G   8% 
/media/card-ext3
/dev/mmcblk0p1          123.6M      2.7M    120.9M   2% /media/card
root@mx25-noah:~$> dd if=/dev/zero of=/media/card/test-10M bs=1024K 
count=10
10+0 records in
10+0 records out
10485760 bytes (10.0MB) copied, 296.004564 seconds, 34.6KB/s
root@mx25-noah:~$> dd if=/dev/zero of=/media/card-ext3/test-10M 
bs=1024K count=10
10+0 records in
10+0 records out
10485760 bytes (10.0MB) copied, 158.207481 seconds, 64.7KB/s

What's going on here, why is it so slow?

root@mx25-noah:~$> dmesg | grep -A1 CMD24
[  635.195042] mmc0: starting CMD24 arg 0e5c1600 flags 000000b5
[  635.195081] mmc0:     blksz 512 blocks 1 flags 00000100 tsac 300 ms 
nsac 0
--
[  635.199831] mmc0: req done (CMD24): 0: 00000900 00000000 00000000 
00000000
[  635.199866] mmc0:     512 bytes transferred: 0
--
[  635.200212] mmc0: starting CMD24 arg 0e5c1800 flags 000000b5
[  635.200251] mmc0:     blksz 512 blocks 1 flags 00000100 tsac 300 ms 
nsac 0
--
[  635.206516] mmc0: req done (CMD24): 0: 00000900 00000000 00000000 
00000000
[  635.206549] mmc0:     512 bytes transferred: 0
--
[  635.206892] mmc0: starting CMD24 arg 0e5c1a00 flags 000000b5
[  635.206932] mmc0:     blksz 512 blocks 1 flags 00000100 tsac 300 ms 
nsac 0
--
[  635.211763] mmc0: req done (CMD24): 0: 00000900 00000000 00000000 
00000000
[  635.211796] mmc0:     512 bytes transferred: 0
--
[  635.212409] mmc0: starting CMD24 arg 0e5c1c00 flags 000000b5
[  635.212449] mmc0:     blksz 512 blocks 1 flags 00000100 tsac 300 ms 
nsac 0

Also, debugfs values don't make sense to me:

root@mx25-noah:/sys/kernel/debug/mmc0$> cat clock
50000000
root@mx25-noah:/sys/kernel/debug/mmc0$> cat ios
clock:		50000000 Hz
vdd:		17 (2.9 ~ 3.0 V)
bus mode:	2 (push-pull)
chip select:	0 (don't care)
power mode:	2 (on)
bus width:	2 (4 bits)
timing spec:	2 (sd high-speed)
root@mx25-noah:/sys/kernel/debug/mmc0$> cat mmc0\:0002/stat
state   status
root@mx25-noah:/sys/kernel/debug/mmc0$> cat mmc0\:0002/state
0x00000005
root@mx25-noah:/sys/kernel/debug/mmc0$> cat mmc0\:0002/status
00000900

Best regards and thank you so much for this real improvement of our 
situation here.
-- 
Joan C. Abelaira

Re: [MX25][MMC] mmc esdhc failure in 3.3

[Eric Bénard]

Hi Joan Carles,

Le Tue, 27 Mar 2012 10:46:45 +0200,
joancarles <joancarles@fqingenieria.es> a écrit :
> >> This is still present, and we have absolutely no idea where to 
> >> continue
> >> searching for the solution of the problem. Any pointers? Any git 
> >> trees
> >> of mmc driver changes we could try? Anybody else with a MX25 that 
> >> has
> >> this issue?
> >>
> > does that attached patch fix your problem ?
> 
> YES, indeed it does to a certain degree. The timeout errors do not 
> occur anymore and I can successfully perform many fs->ops, such as READ, 
> WRITE, UNLINK ... . So thank you very much for this insight through your 
> patch!
> 
> The speed of the card is excruciatingly slow, however. We roughly get 
> between 34KB/s and 64KB/s from a dd if=/dev/zero write to any of the 
> following partitions:
> 
I have the same speed problem here on i.MX25 but still haven't found
the reason.
Shawn, Richard : do you have an idea of why the eSDHC is so slow on
i.MX25 ?

Thanks,
Eric

RE: [MX25][MMC] mmc esdhc failure in 3.3

[Zhu Richard-R65037]

Hi Eric:
I'm on my business trip out of my FSL office, can't reproduce this issue on i.MX25 board now.
Sorry about that.

Best Regards
Richard Zhu

-----Original Message-----
From: Eric Bénard [mailto:eric@eukrea.com] 
Sent: 2012年3月27日 3:58
To: joancarles
Cc: Zhu Richard-R65037; shawn.guo@linaro.org; linux-mmc@vger.kernel.org; Wolfram Sang; linux-arm-kernel@lists.infradead.org
Subject: Re: [MX25][MMC] mmc esdhc failure in 3.3

Hi Joan Carles,

Le Tue, 27 Mar 2012 10:46:45 +0200,
joancarles <joancarles@fqingenieria.es> a écrit :
> >> This is still present, and we have absolutely no idea where to 
> >> continue searching for the solution of the problem. Any pointers? 
> >> Any git trees of mmc driver changes we could try? Anybody else with 
> >> a MX25 that has this issue?
> >>
> > does that attached patch fix your problem ?
> 
> YES, indeed it does to a certain degree. The timeout errors do not 
> occur anymore and I can successfully perform many fs->ops, such as 
> READ, WRITE, UNLINK ... . So thank you very much for this insight 
> through your patch!
> 
> The speed of the card is excruciatingly slow, however. We roughly get 
> between 34KB/s and 64KB/s from a dd if=/dev/zero write to any of the 
> following partitions:
> 
I have the same speed problem here on i.MX25 but still haven't found the reason.
Shawn, Richard : do you have an idea of why the eSDHC is so slow on
i.MX25 ?

Thanks,
Eric

Re: [MX25][MMC] mmc esdhc failure in 3.3

[Wolfram Sang]

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


> >does that attached patch fix your problem ?
> 
> YES, indeed it does to a certain degree. The timeout errors do not
> occur anymore and I can successfully perform many fs->ops, such as

Interesting question is now why it worked on your older kernel? The code
around BROKEN_TIMEOUT is there for much longer, I'd think.

> The speed of the card is excruciatingly slow, however. We roughly
> get between 34KB/s and 64KB/s from a dd if=/dev/zero write to any of
> the following partitions:

Check the code below what is patched. That's currently the best solution
for the errata. There might be better ones, though, but you'd need to
find out.

Regards,

   Wolfram

-- 
Pengutronix e.K.                           | Wolfram Sang                |
Industrial Linux Solutions                 | http://www.pengutronix.de/  |

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 198 bytes --]

Re: [MX25][MMC] mmc esdhc failure in 3.3

[Eric Bénard]

Hi Wolfram,

Le Tue, 27 Mar 2012 11:01:49 +0200,
Wolfram Sang <w.sang@pengutronix.de> a écrit :
> > >does that attached patch fix your problem ?
> > 
> > YES, indeed it does to a certain degree. The timeout errors do not
> > occur anymore and I can successfully perform many fs->ops, such as
> 
> Interesting question is now why it worked on your older kernel? The code
> around BROKEN_TIMEOUT is there for much longer, I'd think.
> 
not in fact it seems to have been broken from a long time and I think
I'm responsible of that in 37865fe91582582a6f6c00652f6a2b1ff71f8a78
"mmc: sdhci-esdhc-imx: fix timeout on i.MX's sdhc"
because unlike the i.MX35 it seems that the i.MX25 manages to read
properly the partition table even without the timeout quirk and it
seems that I didn't do more extensive tests for this patch.

Eric

Re: [MX25][MMC] mmc esdhc failure in 3.3

[Wolfram Sang]

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


> > Interesting question is now why it worked on your older kernel? The code
> > around BROKEN_TIMEOUT is there for much longer, I'd think.
> > 
> not in fact it seems to have been broken from a long time and I think

I know and you are saying the same, in fact :) Your patch came in around
2.6.37 and here it was said that 2.6.39 works fine. Might be random,
though.

> because unlike the i.MX35 it seems that the i.MX25 manages to read
> properly the partition table even without the timeout quirk and it
> seems that I didn't do more extensive tests for this patch.

Please do next time.

Regards,

   Wolfram

-- 
Pengutronix e.K.                           | Wolfram Sang                |
Industrial Linux Solutions                 | http://www.pengutronix.de/  |

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 198 bytes --]

Re: [MX25][MMC] mmc esdhc failure in 3.3

[Eric Bénard]

Le Tue, 27 Mar 2012 11:14:25 +0200,
Wolfram Sang <w.sang@pengutronix.de> a écrit :

> 
> > > Interesting question is now why it worked on your older kernel? The code
> > > around BROKEN_TIMEOUT is there for much longer, I'd think.
> > > 
> > not in fact it seems to have been broken from a long time and I think
> 
> I know and you are saying the same, in fact :) Your patch came in around
> 2.6.37 and here it was said that 2.6.39 works fine. Might be random,
> though.
> 
what is surprising is that no one reported this problem between 2.6.37
and 3.3

> > because unlike the i.MX35 it seems that the i.MX25 manages to read
> > properly the partition table even without the timeout quirk and it
> > seems that I didn't do more extensive tests for this patch.
> 
> Please do next time.
> 
well I should have said "enough extensive" tests as I did a lot of tests
on the 3 archs (i.MX25, i.MX35 and i.MX51). What I see here is that on
i.MX35 and i.MX51 the problem is very easy to reproduce without
extensive tests (card not detected) and that on i.MX25 it needs more
tests as the card is properly detected.

Eric

Re: [MX25][MMC] mmc esdhc failure in 3.3

[Wolfram Sang]

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


> well I should have said "enough extensive" tests as I did a lot of tests
> on the 3 archs (i.MX25, i.MX35 and i.MX51). What I see here is that on
> i.MX35 and i.MX51 the problem is very easy to reproduce without
> extensive tests (card not detected) and that on i.MX25 it needs more
> tests as the card is properly detected.

Ah, okay, thanks for the clarification! Well, since you retested now and
found it is harder to trigger that could explain why nobody reported it
and why 2.6.39 seems to work (although it maybe doesn't). Thanks for
rechecking. If you submit the patch, you can add my

Acked-by: Wolfram Sang <w.sang@pengutronix.de>

Best regards.

-- 
Pengutronix e.K.                           | Wolfram Sang                |
Industrial Linux Solutions                 | http://www.pengutronix.de/  |

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 198 bytes --]

Re: [MX25][MMC] mmc esdhc failure in 3.3

[joancarles]

Hi

>> Interesting question is now why it worked on your older kernel? The 
>> code
>> around BROKEN_TIMEOUT is there for much longer, I'd think.
>>
> not in fact it seems to have been broken from a long time and I think
> I'm responsible of that in 37865fe91582582a6f6c00652f6a2b1ff71f8a78
> "mmc: sdhci-esdhc-imx: fix timeout on i.MX's sdhc"
> because unlike the i.MX35 it seems that the i.MX25 manages to read
> properly the partition table even without the timeout quirk and it
> seems that I didn't do more extensive tests for this patch.

Might be unrelated, however I have been keeping my eyes on the fix of 
ENGcm07207 quirk introduced with 16a790bcc. According to the 
IMX25CE.pdf, to abort data transfers on the AHB, software can reset the 
eSDHC by writing 1 to SYSCTL[24] (RSTA), which currently is not done 
with SDHCI_QUIRK_NO_MULTIBLOCK. It sets the max_blk_count to 1 instead 
of 65535. Not sure if this is also limiting the speed.

I have tried putting the SD card into an ALL-in-One reader via USB and 
I get 6MB/s read and 15MB/s write performance. Since I didn't know the 
exact class of the card, this reassures me that there is nothing 
substantially wrong with the card per se.

So, how can we find a solution to this speed issue? Also, do you plan 
on submitting your patch to revert the timeout quirk for MX25?

Cheers
-- 
Joan C. Abelaira

Re: [MX25][MMC] mmc esdhc failure in 3.3

[Eric Bénard]

Hi,

Le Tue, 27 Mar 2012 11:33:57 +0200,
joancarles <joancarles@fqingenieria.es> a écrit :
> >> Interesting question is now why it worked on your older kernel? The 
> >> code
> >> around BROKEN_TIMEOUT is there for much longer, I'd think.
> >>
> > not in fact it seems to have been broken from a long time and I think
> > I'm responsible of that in 37865fe91582582a6f6c00652f6a2b1ff71f8a78
> > "mmc: sdhci-esdhc-imx: fix timeout on i.MX's sdhc"
> > because unlike the i.MX35 it seems that the i.MX25 manages to read
> > properly the partition table even without the timeout quirk and it
> > seems that I didn't do more extensive tests for this patch.
> 
> Might be unrelated, however I have been keeping my eyes on the fix of 
> ENGcm07207 quirk introduced with 16a790bcc. According to the 
> IMX25CE.pdf, to abort data transfers on the AHB, software can reset the 
> eSDHC by writing 1 to SYSCTL[24] (RSTA), which currently is not done 
> with SDHCI_QUIRK_NO_MULTIBLOCK. It sets the max_blk_count to 1 instead 
> of 65535. Not sure if this is also limiting the speed.
> 
I tried to increase max_blk_count and it breaks after a few tests.
Using an oscilloscope it seems we have a big latency between each
transfer which could explain the low throughput, I didn't have the
time to look deeper at this problem.

> I have tried putting the SD card into an ALL-in-One reader via USB and 
> I get 6MB/s read and 15MB/s write performance. Since I didn't know the 
> exact class of the card, this reassures me that there is nothing 
> substantially wrong with the card per se.
> 
> So, how can we find a solution to this speed issue? Also, do you plan 
> on submitting your patch to revert the timeout quirk for MX25?
> 
yes, I'm writing a proper commit message and will send it in a few
minutes.

Eric

Re: [MX25][MMC] mmc esdhc failure in 3.3

[joancarles]

Hi

>> Might be unrelated, however I have been keeping my eyes on the fix 
>> of
>> ENGcm07207 quirk introduced with 16a790bcc. According to the
>> IMX25CE.pdf, to abort data transfers on the AHB, software can reset 
>> the
>> eSDHC by writing 1 to SYSCTL[24] (RSTA), which currently is not done
>> with SDHCI_QUIRK_NO_MULTIBLOCK. It sets the max_blk_count to 1 
>> instead
>> of 65535. Not sure if this is also limiting the speed.
>>
> I tried to increase max_blk_count and it breaks after a few tests.

I will redo your tests in a jiffy, however the latency issues worry me 
a wee bit.

> Using an oscilloscope it seems we have a big latency between each
> transfer which could explain the low throughput, I didn't have the
> time to look deeper at this problem.

The latency we can see here in the oscilloscope is tremendous between 
two CMD24: 8ms! What is causing this? It is certainly unrelated to the 
MULTIBLOCK feature. Having a clock at 33.25MHz, our maximal read, as 
confirmed by dd is:

33.25[MHz] * 4[bits data] / 8[bits/Byte] * 30 [us write] / 8000 [us 
sleep] =~ 60KB/s

So, what's keeping the driver 8ms from sending the data??? Any pointers 
on where I could twiddle some bits in the driver? Where do I start 
looking?

Cheers
-- 
Joan C. Abelaira

Re: [MX25][MMC] mmc esdhc failure in 3.3

[joancarles]

ADDENDUM:

>> I tried to increase max_blk_count and it breaks after a few tests.
>
> I will redo your tests in a jiffy, however the latency issues worry
> me a wee bit.

Increasing max_blk_count did not help really, however I am not sure if 
setting it unconditionally to 65535 was the only change I had to make.

> So, what's keeping the driver 8ms from sending the data??? Any
> pointers on where I could twiddle some bits in the driver? Where do I
> start looking?

Using the following setup, I tried to get some more information:

diff --git a/drivers/mmc/host/sdhci-esdhc-imx.c 
b/drivers/mmc/host/sdhci-esdhc-imx.c
index 0be4e20..4896f24 100644
--- a/drivers/mmc/host/sdhci-esdhc-imx.c
+++ b/drivers/mmc/host/sdhci-esdhc-imx.c
@@ -467,8 +467,7 @@ static int __devinit sdhci_esdhc_imx_probe(struct 
platform_device *pdev)
         clk_enable(clk);
         pltfm_host->clk = clk;

-       if (!is_imx25_esdhc(imx_data))
-               host->quirks |= SDHCI_QUIRK_BROKEN_TIMEOUT_VAL;
+       host->quirks |= SDHCI_QUIRK_BROKEN_TIMEOUT_VAL;

         if (is_imx25_esdhc(imx_data) || is_imx35_esdhc(imx_data))
                 /* Fix errata ENGcm07207 present on i.MX25 and i.MX35 
*/
diff --git a/drivers/mmc/host/sdhci.c b/drivers/mmc/host/sdhci.c
index 8d66706..0b60d14 100644
--- a/drivers/mmc/host/sdhci.c
+++ b/drivers/mmc/host/sdhci.c
@@ -713,6 +713,8 @@ static void sdhci_prepare_data(struct sdhci_host 
*host, struct mmc_command *cmd)
                 sdhci_writeb(host, count, SDHCI_TIMEOUT_CONTROL);
         }

+       sdhci_dumpregs(host);
+
         if (!data)
                 return;

echo 'file core.c line 193 +p' > 
/sys/kernel/debug/dynamic_debug/control
echo 'file core.c line 158 +p' > 
/sys/kernel/debug/dynamic_debug/control
echo 'file sdhci.c line 72-115 +p' > 
/sys/kernel/debug/dynamic_debug/control
mount /media/card
dd if=/dev/urandom of=/media/card/file-4K bs=4K count=1

[  119.895460] mmc0: starting CMD24 arg 00045e00 flags 000000b5
[  119.895531] sdhci: =========== REGISTER DUMP (mmc0)===========
[  119.895570] sdhci: Sys addr: 0x82480000 | Version:  0x00000000
[  119.895602] sdhci: Blk size: 0x00000200 | Blk cnt:  0x00000000
[  119.895633] sdhci: Argument: 0x00049c00 | Trn mode: 0x00000013
[  119.895664] sdhci: Present:  0xff880000 | Host ctl: 0x00000023
[  119.895693] sdhci: Power:    0x00000000 | Blk gap:  0x00000000
[  119.895724] sdhci: Wake-up:  0x00000000 | Clock:    0x00000107
[  119.895754] sdhci: Timeout:  0x0000000e | Int stat: 0x00000000
[  119.895787] sdhci: Int enab: 0x107f000b | Sig enab: 0x107f000b
[  119.895819] sdhci: AC12 err: 0x00000000 | Slot int: 0x00001001
[  119.895852] sdhci: Caps:     0x07eb0000 | Caps_1:   0x04100410
[  119.895883] sdhci: Cmd:      0x0000113a | Max curr: 0x00000000
[  119.895911] sdhci: Host ctl2: 0x00000000
[  119.895936] sdhci: ===========================================
[  119.900527] mmc0: starting CMD13 arg 00020000 flags 00000195
[  119.900585] sdhci: =========== REGISTER DUMP (mmc0)===========
[  119.900624] sdhci: Sys addr: 0x82452400 | Version:  0x00000000
[  119.900655] sdhci: Blk size: 0x00000200 | Blk cnt:  0x00000000
[  119.900687] sdhci: Argument: 0x00045e00 | Trn mode: 0x00000003
[  119.900718] sdhci: Present:  0xff880000 | Host ctl: 0x00000023
[  119.900746] sdhci: Power:    0x00000000 | Blk gap:  0x00000000
[  119.900776] sdhci: Wake-up:  0x00000000 | Clock:    0x00000107
[  119.900807] sdhci: Timeout:  0x0000000e | Int stat: 0x00000000
[  119.900840] sdhci: Int enab: 0x107f000b | Sig enab: 0x107f000b
[  119.900869] sdhci: AC12 err: 0x00000000 | Slot int: 0x00001001
[  119.900902] sdhci: Caps:     0x07eb0000 | Caps_1:   0x04100410
[  119.900933] sdhci: Cmd:      0x0000183a | Max curr: 0x00000000
[  119.900962] sdhci: Host ctl2: 0x00000000
[  119.900985] sdhci: ===========================================
[  119.901357] mmc0: starting CMD17 arg 00009000 flags 000000b5
[  119.901419] sdhci: =========== REGISTER DUMP (mmc0)===========
[  119.901458] sdhci: Sys addr: 0x82452400 | Version:  0x00000000
[  119.901490] sdhci: Blk size: 0x00000200 | Blk cnt:  0x00000000
[  119.901520] sdhci: Argument: 0x00020000 | Trn mode: 0x00000003
[  119.901551] sdhci: Present:  0xff880000 | Host ctl: 0x00000023
[  119.901579] sdhci: Power:    0x00000000 | Blk gap:  0x00000000
[  119.901610] sdhci: Wake-up:  0x00000000 | Clock:    0x00000107
[  119.901641] sdhci: Timeout:  0x0000000e | Int stat: 0x00000000
[  119.901673] sdhci: Int enab: 0x107f000b | Sig enab: 0x107f000b
[  119.901703] sdhci: AC12 err: 0x00000000 | Slot int: 0x00001001
[  119.901735] sdhci: Caps:     0x07eb0000 | Caps_1:   0x04100410
[  119.901765] sdhci: Cmd:      0x00000d1a | Max curr: 0x00000000
[  119.901793] sdhci: Host ctl2: 0x00000000
[  119.901816] sdhci: ===========================================
[  119.908072] mmc0: starting CMD17 arg 00009200 flags 000000b5
[  119.908141] sdhci: =========== REGISTER DUMP (mmc0)===========
[  119.908179] sdhci: Sys addr: 0x82480000 | Version:  0x00000000
[  119.908212] sdhci: Blk size: 0x00000200 | Blk cnt:  0x00000000
[  119.908243] sdhci: Argument: 0x00009000 | Trn mode: 0x00000013
[  119.908274] sdhci: Present:  0xff880000 | Host ctl: 0x00000023
[  119.908304] sdhci: Power:    0x00000000 | Blk gap:  0x00000000
[  119.908335] sdhci: Wake-up:  0x00000000 | Clock:    0x00000107
[  119.908367] sdhci: Timeout:  0x0000000e | Int stat: 0x00000000
[  119.908400] sdhci: Int enab: 0x107f000b | Sig enab: 0x107f000b
[  119.908432] sdhci: AC12 err: 0x00000000 | Slot int: 0x00001001
[  119.908464] sdhci: Caps:     0x07eb0000 | Caps_1:   0x04100410
[  119.908495] sdhci: Cmd:      0x0000113a | Max curr: 0x00000000
[  119.908524] sdhci: Host ctl2: 0x00000000
[  119.908547] sdhci: ===========================================
[  119.910858] mmc0: starting CMD17 arg 00009400 flags 000000b5
[  119.910929] sdhci: =========== REGISTER DUMP (mmc0)===========
[  119.910969] sdhci: Sys addr: 0x82480000 | Version:  0x00000000
[  119.911002] sdhci: Blk size: 0x00000200 | Blk cnt:  0x00000000
[  119.911034] sdhci: Argument: 0x00009200 | Trn mode: 0x00000013
[  119.911065] sdhci: Present:  0xff880000 | Host ctl: 0x00000023
[  119.911095] sdhci: Power:    0x00000000 | Blk gap:  0x00000000
[  119.911126] sdhci: Wake-up:  0x00000000 | Clock:    0x00000107
[  119.911157] sdhci: Timeout:  0x0000000e | Int stat: 0x00000000
[  119.911191] sdhci: Int enab: 0x107f000b | Sig enab: 0x107f000b
[  119.911223] sdhci: AC12 err: 0x00000000 | Slot int: 0x00001001
[  119.911255] sdhci: Caps:     0x07eb0000 | Caps_1:   0x04100410
[  119.911286] sdhci: Cmd:      0x0000113a | Max curr: 0x00000000
[  119.911314] sdhci: Host ctl2: 0x00000000
[  119.911338] sdhci: ===========================================
[  119.913935] mmc0: starting CMD24 arg 00009000 flags 000000b5
[  119.914004] sdhci: =========== REGISTER DUMP (mmc0)===========
[  119.914042] sdhci: Sys addr: 0x82480000 | Version:  0x00000000
[  119.914073] sdhci: Blk size: 0x00000200 | Blk cnt:  0x00000000
[  119.914105] sdhci: Argument: 0x00009400 | Trn mode: 0x00000013
[  119.914135] sdhci: Present:  0xff880000 | Host ctl: 0x00000023
[  119.914164] sdhci: Power:    0x00000000 | Blk gap:  0x00000000
[  119.914194] sdhci: Wake-up:  0x00000000 | Clock:    0x00000107
[  119.914224] sdhci: Timeout:  0x0000000e | Int stat: 0x00000000
[  119.914257] sdhci: Int enab: 0x107f000b | Sig enab: 0x107f000b
[  119.914288] sdhci: AC12 err: 0x00000000 | Slot int: 0x00001001
[  119.914321] sdhci: Caps:     0x07eb0000 | Caps_1:   0x04100410
[  119.914352] sdhci: Cmd:      0x0000113a | Max curr: 0x00000000
[  119.914380] sdhci: Host ctl2: 0x00000000
[  119.914404] sdhci: ===========================================
[  119.921304] mmc0: starting CMD13 arg 00020000 flags 00000195
[  119.921368] sdhci: =========== REGISTER DUMP (mmc0)===========
[  119.921407] sdhci: Sys addr: 0x82403600 | Version:  0x00000000
[  119.921440] sdhci: Blk size: 0x00000200 | Blk cnt:  0x00000000
[  119.921472] sdhci: Argument: 0x00009000 | Trn mode: 0x00000003
[  119.921503] sdhci: Present:  0xff880000 | Host ctl: 0x00000023
[  119.921532] sdhci: Power:    0x00000000 | Blk gap:  0x00000000
[  119.921564] sdhci: Wake-up:  0x00000000 | Clock:    0x00000107
[  119.921594] sdhci: Timeout:  0x0000000e | Int stat: 0x00000000
[  119.921626] sdhci: Int enab: 0x107f000b | Sig enab: 0x107f000b
[  119.921658] sdhci: AC12 err: 0x00000000 | Slot int: 0x00001001
[  119.921689] sdhci: Caps:     0x07eb0000 | Caps_1:   0x04100410
[  119.921720] sdhci: Cmd:      0x0000183a | Max curr: 0x00000000
[  119.921747] sdhci: Host ctl2: 0x00000000
[  119.921770] sdhci: ===========================================
[  119.921889] mmc0: starting CMD24 arg 00009200 flags 000000b5
[  119.921941] sdhci: =========== REGISTER DUMP (mmc0)===========
[  119.921976] sdhci: Sys addr: 0x82403600 | Version:  0x00000000
[  119.922007] sdhci: Blk size: 0x00000200 | Blk cnt:  0x00000000
[  119.922038] sdhci: Argument: 0x00020000 | Trn mode: 0x00000003
[  119.922070] sdhci: Present:  0xff880000 | Host ctl: 0x00000023
[  119.922098] sdhci: Power:    0x00000000 | Blk gap:  0x00000000
[  119.922129] sdhci: Wake-up:  0x00000000 | Clock:    0x00000107
[  119.922161] sdhci: Timeout:  0x0000000e | Int stat: 0x00000000
[  119.922193] sdhci: Int enab: 0x107f000b | Sig enab: 0x107f000b
[  119.922223] sdhci: AC12 err: 0x00000000 | Slot int: 0x00001001
[  119.922256] sdhci: Caps:     0x07eb0000 | Caps_1:   0x04100410
[  119.922287] sdhci: Cmd:      0x00000d1a | Max curr: 0x00000000
[  119.922315] sdhci: Host ctl2: 0x00000000
[  119.922338] sdhci: ===========================================
[  119.927417] mmc0: starting CMD13 arg 00020000 flags 00000195
[  119.927481] sdhci: =========== REGISTER DUMP (mmc0)===========
[  119.927523] sdhci: Sys addr: 0x82403800 | Version:  0x00000000
[  119.927554] sdhci: Blk size: 0x00000200 | Blk cnt:  0x00000000
[  119.927586] sdhci: Argument: 0x00009200 | Trn mode: 0x00000003
[  119.927616] sdhci: Present:  0xff880000 | Host ctl: 0x00000023
[  119.927645] sdhci: Power:    0x00000000 | Blk gap:  0x00000000
[  119.927675] sdhci: Wake-up:  0x00000000 | Clock:    0x00000107
[  119.927707] sdhci: Timeout:  0x0000000e | Int stat: 0x00000000
[  119.927740] sdhci: Int enab: 0x107f000b | Sig enab: 0x107f000b
[  119.927772] sdhci: AC12 err: 0x00000000 | Slot int: 0x00001001
[  119.927804] sdhci: Caps:     0x07eb0000 | Caps_1:   0x04100410
[  119.927835] sdhci: Cmd:      0x0000183a | Max curr: 0x00000000
[  119.927864] sdhci: Host ctl2: 0x00000000

[CMD24/CMD13 changes go on like this ...]

Anybody with more insights? Why is the interval between two CMD24 more 
or less in the range of 6ms and the CMD13 follows in varying intervals 
between 1ms to 4ms? What's keeping the driver from bursting CMD24 and 
successive CMD13 requests?

Thanks and best regards
-- 
Joan C. Abelaira

Re: [MX25][MMC] mmc esdhc failure in 3.3

[joancarles]

> Anybody with more insights? Why is the interval between two CMD24
> more or less in the range of 6ms and the CMD13 follows in varying
> intervals between 1ms to 4ms? What's keeping the driver from bursting
> CMD24 and successive CMD13 requests?

A 4*128KB dd run shows the following patterns of latency between 
various CMDs issued:

http://i43.tinypic.com/2bcmsw.png

The latency distribution is plotted here:

http://i41.tinypic.com/9gvbqo.png

bin limits	freq count	pct
<0ms	0	0.0%
<1ms	922	43.6%
<6ms	491	23.2%
<10ms	411	19.4%
<20ms	113	5.3%
<100ms	163	7.7%
<300ms	9	0.4%
<1000ms	7	0.3%

It took 25 seconds to write 4*128KB to the SD-card using the current 
drivers. More than 50% of the CMD requests issued take more than 1ms 
from issuing to response between the host and the card. Anybody else 
with this issue on the i.MX25? How can I pinpoint this down to the 
culprits in the kernel source?

Regards
-- 
Joan C. Abelaira

Re: [MX25][MMC] mmc esdhc failure in 3.3

[Wolfram Sang]

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


> Might be unrelated, however I have been keeping my eyes on the fix
> of ENGcm07207 quirk introduced with 16a790bcc. According to the
> IMX25CE.pdf, to abort data transfers on the AHB, software can reset
> the eSDHC by writing 1 to SYSCTL[24] (RSTA), which currently is not
> done with SDHCI_QUIRK_NO_MULTIBLOCK. It sets the max_blk_count to 1
> instead of 65535. Not sure if this is also limiting the speed.

Oh, it is limiting speed, for sure.

SDHCI_QUIRK_NO_MULTIBLOCK is a _generic_ quirk which can be enabled by
various buggy sdhci implementations, not only esdhc (which is pretty
good at being buggy). It is not there to fix MX25 specific issues,
that would have to be done seperately in sdhci-esdhc-imx.c.

So, the above quirk is a big hammer solution. There might be more
precise ones, but those still would have to be developed. I don't know
of anyone planning to do this.

Regards,

   Wolfram

-- 
Pengutronix e.K.                           | Wolfram Sang                |
Industrial Linux Solutions                 | http://www.pengutronix.de/  |

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 198 bytes --]