Hynix eMMC RPMB: Access timeouts, broken?

DISCUSSION Dirk Behme 3 participants 3 messages Jun 4, 2013 – Oct 31, 2013 MMC, SD and SDIO

Share & tools

Dirk Behme

author

2013-06-04 11:41 UTC #0 lore raw

Using some recent Hynix eMMC devices [1] on our Freescale i.MX6 boards we get harmless (?), but annoying access timeouts accessing the RPMB partition:

mmcblk1rpmb: error -110 transferring data, sector 0, nr 32, cmd response 0x900, card status 0xb00
mmcblk1rpmb: retrying using single block read
...

The output with MMC debug enabled below [2].

This seems to be harmless because it stops, but is annoying due to some auto mounter trying to access all available partitions.

Any idea about this issue?

Or any hint how to further debug this?

It seems to us that this doesn't happen with some older Hynix devices, because it just appeared recently with the HW guys switching to a new eMMC.

We think we have all RPMB related patches, including [3]. But maybe we missed anything?

Best regards

Dirk

[1]

mmc1: new high speed MMC card at address 0001
mmcblk1: mmc1:0001 H4G1d 3.64 GiB
mmcblk1boot0: mmc1:0001 H4G1d partition 1 4.00 MiB
mmcblk1boot1: mmc1:0001 H4G1d partition 2 4.00 MiB
mmcblk1rpmb: mmc1:0001 H4G1d partition 3 4.00 MiB
mmcblk1: p1
mmcblk1boot1: unknown partition table
mmcblk1boot0: unknown partition table

(below dd is the manual test case simulating the auto mounter access mentioned above)

Quoted 1 line

dd if=/dev/mmcblk1rpmb of=/dev/null bs=1 count=1

[  124.185513] mmcblk1rpmb: error -110 transferring data, sector 0, nr 32, cmd response 0x900, card status 0xb00
[  124.195506] mmcblk1rpmb: retrying using single block read
[  124.201035] mmcblk1rpmb: timed out sending r/w cmd command, card status 0x400900
[  124.208559] mmcblk1rpmb: timed out sending r/w cmd command, card status 0x400900
[  124.216049] mmcblk1rpmb: timed out sending r/w cmd command, card status 0x400900
[  124.223567] mmcblk1rpmb: timed out sending r/w cmd command, card status 0x400900
[  124.231087] mmcblk1rpmb: timed out sending r/w cmd command, card status 0x400900
[  124.238600] mmcblk1rpmb: timed out sending r/w cmd command, card status 0x400900
[  124.246012] end_request: I/O error, dev mmcblk1rpmb, sector 0
[  124.251773] Buffer I/O error on device mmcblk1rpmb, logical block 0
[  124.258065] end_request: I/O error, dev mmcblk1rpmb, sector 8
[  124.263822] Buffer I/O error on device mmcblk1rpmb, logical block 1
[  124.270102] end_request: I/O error, dev mmcblk1rpmb, sector 16
[  124.275944] Buffer I/O error on device mmcblk1rpmb, logical block 2
[  124.282222] end_request: I/O error, dev mmcblk1rpmb, sector 24
[  124.288064] Buffer I/O error on device mmcblk1rpmb, logical block 3
[  129.717711] mmcblk1rpmb: error -110 transferring data, sector 0, nr 8, cmd response 0x900, card status 0xb00
[  129.727590] mmcblk1rpmb: retrying using single block read
[  129.733088] mmcblk1rpmb: timed out sending r/w cmd command, card status 0x400900
[  129.740605] mmcblk1rpmb: timed out sending r/w cmd command, card status 0x400900
[  129.748121] mmcblk1rpmb: timed out sending r/w cmd command, card status 0x400900
[  129.755612] mmcblk1rpmb: timed out sending r/w cmd command, card status 0x400900
[  129.763125] mmcblk1rpmb: timed out sending r/w cmd command, card status 0x400900
[  129.770639] mmcblk1rpmb: timed out sending r/w cmd command, card status 0x400900
[  129.778073] end_request: I/O error, dev mmcblk1rpmb, sector 0
[  129.783834] Buffer I/O error on device mmcblk1rpmb, logical block 0

dd: /dev/mmcblk1rpmb: Input/output error

[2] (mmc0 is the SD card we are booting from)

Quoted 1 line

dd if=/dev/mmcblk1rpmb of=/dev/null bs=1 count=1

<mmc1: starting CMD23 arg 00000020 flags 00000015>

mmc1: starting CMD18 arg 00000000 flags 000000b5
mmc1:     blksz 512 blocks 32 flags 00000200 tsac 150 ms nsac 1000
mmc1:     CMD12 arg 00000000 flags 0000049d
sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000001
sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000001
mmc0: starting CMD25 arg 003440d8 flags 000000b5
mmc0:     blksz 512 blocks 40 flags 00000100 tsac 3000 ms nsac 0
mmc0:     CMD12 arg 00000000 flags 0000049d

sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00000001
sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x0000000a
sdhci [sdhci_data_irq()]: mmc0: DMA base 0x1c220000, transferred 0x060000 bytes, next 0x1c280000 sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00000001

mmc0: req done (CMD25): 0: 00000900 00000000 00000000 00000000
mmc0:     20480 bytes transferred: 0
mmc0:     (CMD12): 0: 00000c00 00000000 00000000 00000000
mmc0: starting CMD13 arg 12340000 flags 00000195
sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00000001
mmc0: req done (CMD13): 0: 00000900 00000000 00000000 00000000
mmc0: starting CMD25 arg 00344100 flags 000000b5
mmc0:     blksz 512 blocks 8 flags 00000100 tsac 3000 ms nsac 0
mmc0:     CMD12 arg 00000000 flags 0000049d

mmc0: req done (CMD25): 0: 00000900 00000000 00000000 00000000
mmc0:     4096 bytes transferred: 0
mmc0:     (CMD12): 0: 00000c00 00000000 00000000 00000000
mmc0: starting CMD13 arg 12340000 flags 00000195

sdhci [sdhci_irq()]: *** mmc0 got interrupt: 0x00000001
mmc0: req done (CMD13): 0: 00000900 00000000 00000000 00000000 sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00100000 sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000001

mmc1: req done (CMD18): 0: 00000900 00000000 00000000 00000000
mmc1:     0 bytes transferred: -110
mmc1:     (CMD12): 0: 00000b00 00000000 00000000 00000000
mmc1: starting CMD13 arg 00010000 flags 00000195

sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000001
mmc1: req done (CMD13): 0: 00000900 00000000 00000000 00000000
mmcblk1rpmb: error -110 transferring data, sector 0, nr 32, cmd response 0x900, card status 0xb00
mmcblk1rpmb: retrying using single block read
mmc1: starting CMD17 arg 00000000 flags 000000b5
mmc1: blksz 512 blocks 1 flags 00000200 tsac 150 ms nsac 1000
sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00010000
mmc1: req done (CMD17): -110: 00000000 00000000 00000000 00000000
mmc1: 0 bytes transferred: 0
mmc1: starting CMD13 arg 00010000 flags 00000195
sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000001
mmc1: req done (CMD13): 0: 00400900 00000000 00000000 00000000
mmcblk1rpmb: timed out sending r/w cmd command, card status 0x400900
mmc1: starting CMD17 arg 00000000 flags 000000b5
mmc1: blksz 512 blocks 1 flags 00000200 tsac 150 ms nsac 1000
sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00010000
mmc1: req done (CMD17): -110: 00000000 00000000 00000000 00000000
mmc1: 0 bytes transferred: 0
mmc1: starting CMD13 arg 00010000 flags 00000195
sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000001
mmc1: req done (CMD13): 0: 00400900 00000000 00000000 00000000
mmcblk1rpmb: timed out sending r/w cmd command, card status 0x400900
mmc1: starting CMD17 arg 00000000 flags 000000b5
mmc1: blksz 512 blocks 1 flags 00000200 tsac 150 ms nsac 1000
sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00010000
mmc1: req done (CMD17): -110: 00000000 00000000 00000000 00000000
mmc1: 0 bytes transferred: 0
mmc1: starting CMD13 arg 00010000 flags 00000195
sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000001
mmc1: req done (CMD13): 0: 00400900 00000000 00000000 00000000
mmcblk1rpmb: timed out sending r/w cmd command, card status 0x400900
mmc1: starting CMD17 arg 00000000 flags 000000b5
mmc1: blksz 512 blocks 1 flags 00000200 tsac 150 ms nsac 1000
sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00010000
mmc1: req done (CMD17): -110: 00000000 00000000 00000000 00000000
mmc1: 0 bytes transferred: 0
mmc1: starting CMD13 arg 00010000 flags 00000195
sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000001
mmc1: req done (CMD13): 0: 00400900 00000000 00000000 00000000
mmcblk1rpmb: timed out sending r/w cmd command, card status 0x400900
mmc1: starting CMD17 arg 00000000 flags 000000b5
mmc1: blksz 512 blocks 1 flags 00000200 tsac 150 ms nsac 1000
sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00010000
mmc1: req done (CMD17): -110: 00000000 00000000 00000000 00000000
mmc1: 0 bytes transferred: 0
mmc1: starting CMD13 arg 00010000 flags 00000195
sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000001
mmc1: req done (CMD13): 0: 00400900 00000000 00000000 00000000
mmcblk1rpmb: timed out sending r/w cmd command, card status 0x400900
mmc1: starting CMD17 arg 00000000 flags 000000b5
mmc1: blksz 512 blocks 1 flags 00000200 tsac 150 ms nsac 1000
sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00010000
mmc1: req done (CMD17): -110: 00000000 00000000 00000000 00000000
mmc1: 0 bytes transferred: 0
mmc1: starting CMD13 arg 00010000 flags 00000195
sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000001
mmc1: req done (CMD13): 0: 00400900 00000000 00000000 00000000
mmcblk1rpmb: timed out sending r/w cmd command, card status 0x400900
end_request: I/O error, dev mmcblk1rpmb, sector 0
Buffer I/O error on device mmcblk1rpmb, logical block 0
end_request: I/O error, dev mmcblk1rpmb, sector 8
Buffer I/O error on device mmcblk1rpmb, logical block 1
end_request: I/O error, dev mmcblk1rpmb, sector 16
Buffer I/O error on device mmcblk1rpmb, logical block 2
end_request: I/O error, dev mmcblk1rpmb, sector 24
Buffer I/O error on device mmcblk1rpmb, logical block 3
<mmc1: starting CMD23 arg 00000008 flags 00000015>

mmc1: starting CMD18 arg 00000000 flags 000000b5
mmc1:     blksz 512 blocks 8 flags 00000200 tsac 150 ms nsac 1000
mmc1:     CMD12 arg 00000000 flags 0000049d

sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000001 sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000001 sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00100000 sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000001

mmc1: req done (CMD18): 0: 00000900 00000000 00000000 00000000
mmc1:     0 bytes transferred: -110
mmc1:     (CMD12): 0: 00000b00 00000000 00000000 00000000
mmc1: starting CMD13 arg 00010000 flags 00000195

sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000001
mmc1: req done (CMD13): 0: 00000900 00000000 00000000 00000000
mmcblk1rpmb: error -110 transferring data, sector 0, nr 8, cmd response 0x900, card status 0xb00
mmcblk1rpmb: retrying using single block read
mmc1: starting CMD17 arg 00000000 flags 000000b5
mmc1: blksz 512 blocks 1 flags 00000200 tsac 150 ms nsac 1000
sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00010000
mmc1: req done (CMD17): -110: 00000000 00000000 00000000 00000000
mmc1: 0 bytes transferred: 0
mmc1: starting CMD13 arg 00010000 flags 00000195
sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000001
mmc1: req done (CMD13): 0: 00400900 00000000 00000000 00000000
mmcblk1rpmb: timed out sending r/w cmd command, card status 0x400900
mmc1: starting CMD17 arg 00000000 flags 000000b5
mmc1: blksz 512 blocks 1 flags 00000200 tsac 150 ms nsac 1000
sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00010000
mmc1: req done (CMD17): -110: 00000000 00000000 00000000 00000000
mmc1: 0 bytes transferred: 0
mmc1: starting CMD13 arg 00010000 flags 00000195
sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000001
mmc1: req done (CMD13): 0: 00400900 00000000 00000000 00000000
mmcblk1rpmb: timed out sending r/w cmd command, card status 0x400900
mmc1: starting CMD17 arg 00000000 flags 000000b5
mmc1: blksz 512 blocks 1 flags 00000200 tsac 150 ms nsac 1000
sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00010000
mmc1: req done (CMD17): -110: 00000000 00000000 00000000 00000000
mmc1: 0 bytes transferred: 0
mmc1: starting CMD13 arg 00010000 flags 00000195
sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000001
mmc1: req done (CMD13): 0: 00400900 00000000 00000000 00000000
mmcblk1rpmb: timed out sending r/w cmd command, card status 0x400900
mmc1: starting CMD17 arg 00000000 flags 000000b5
mmc1: blksz 512 blocks 1 flags 00000200 tsac 150 ms nsac 1000
sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00010000
mmc1: req done (CMD17): -110: 00000000 00000000 00000000 00000000
mmc1: 0 bytes transferred: 0
mmc1: starting CMD13 arg 00010000 flags 00000195
sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000001
mmc1: req done (CMD13): 0: 00400900 00000000 00000000 00000000
mmcblk1rpmb: timed out sending r/w cmd command, card status 0x400900
mmc1: starting CMD17 arg 00000000 flags 000000b5
mmc1: blksz 512 blocks 1 flags 00000200 tsac 150 ms nsac 1000
sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00010000
mmc1: req done (CMD17): -110: 00000000 00000000 00000000 00000000
mmc1: 0 bytes transferred: 0
mmc1: starting CMD13 arg 00010000 flags 00000195
sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000001
mmc1: req done (CMD13): 0: 00400900 00000000 00000000 00000000
mmcblk1rpmb: timed out sending r/w cmd command, card status 0x400900
mmc1: starting CMD17 arg 00000000 flags 000000b5
mmc1: blksz 512 blocks 1 flags 00000200 tsac 150 ms nsac 1000
sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00010000
mmc1: req done (CMD17): -110: 00000000 00000000 00000000 00000000
mmc1: 0 bytes transferred: 0
mmc1: starting CMD13 arg 00010000 flags 00000195
sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000001
mmc1: req done (CMD13): 0: 00400900 00000000 00000000 00000000
mmcblk1rpmb: timed out sending r/w cmd command, card status 0x400900
end_request: I/O error, dev mmcblk1rpmb, sector 0
Buffer I/O error on device mmcblk1rpmb, logical block 0
dd: /dev/mmcblk1rpmb: Input/output error

Quoted 1 line

[3] https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/drivers/mmc/core/mmc.c?id=d0123ccac55088811bde4f76c4a3fdbd39c3cfba

Krishna Konda

2013-07-03 06:08 UTC #1 lore raw

Quoted 10 lines · Dirk Behme

Using some recent Hynix eMMC devices [1] on our Freescale i.MX6 boards we get harmless (?), but annoying access timeouts accessing the RPMB partition:
mmcblk1rpmb: error -110 transferring data, sector 0, nr 32, cmd response 0x900, card status 0xb00
mmcblk1rpmb: retrying using single block read
...

Quoted 5 lines

The output with MMC debug enabled below [2].
This seems to be harmless because it stops, but is annoying due to some auto mounter trying to access all available partitions.

The RPMB partition should never be mounted. Its not a regular partition and does not a file system on it. So my suggestion would to be to modify the auto mounter to not mount RPMB paritions.

Signature · 7 lines

Thanks,
Krishna Konda
-----------------------------------------------------------------------
Sent by an employee of the Qualcomm Innovation Center, Inc.
The Qualcomm Innovation Center, Inc. is a member of Code Aurora Forum,
hosted by The Linux Foundation
-----------------------------------------------------------------------

Abbas Raza

2013-10-31 17:50 UTC #2 lore raw

Quoted 12 lines · Krishna Konda <kkonda <at> codeaurora.org> writes:

Quoted 10 lines · Dirk Behme
Using some recent Hynix eMMC devices [1] on our Freescale i.MX6 boards we get harmless (?), but annoying access timeouts accessing the RPMB partition:
mmcblk1rpmb: error -110 transferring data, sector 0, nr 32, cmd response 0x900, card status 0xb00
mmcblk1rpmb: retrying using single block read
...

Quoted 9 lines

Quoted 5 lines
The output with MMC debug enabled below [2].
This seems to be harmless because it stops, but is annoying due to some auto mounter trying to access all available partitions.
The RPMB partition should never be mounted. Its not a regular partition and does not a file system on it. So my suggestion would to be to modify the auto mounter to not mount RPMB paritions.

Hi Dirk, Krishna

These issues are not caused by udev/auto-mounting, but by the mmc block driver initialisation code.
During the mmc initialisation, all the non zero sized partitions (read from ext_csd register) are added in card structures. Then at the time of mmc block driver probing, mmc_blk_alloc_part function is called for each partition which initialises the mmc request queue and and starts mmc queue thread for each partition as shown below

root@mx6q35:~# ps x | grep mmc
   46 ?        S      0:00 [mmcqd/1]
  397 ?        S      0:00 [mmcqd/2]
  400 ?        S      0:00 [mmcqd/2boot0]
  401 ?        S      0:00 [mmcqd/2boot1]
  402 ?        S      0:00 [mmcqd/2rpmb]

mmc queue thread for each partition gets scheduled and calls mmc_blk_issue_rq, and here it sends CMD6 using mmc_blk_part_switch, CMD23-->CMD18 using mmc_blk_issue_rw_rq. When executed for RPMB partition, logs can be seen below

[  109.972564] mmc2: starting CMD6 arg 03b30b01 flags 0000049d --> switch to
RPMB area
[  109.972600] sdhci [sdhci_irq()]: *** mmc2 got interrupt: 0x00000001
[  109.972625] mmc2: req done (CMD6): 0: 00000800 00000000 00000000 00000000
[  109.977781] mmc2: starting CMD13 arg 00010000 flags 00000195
[  109.977823] sdhci [sdhci_irq()]: *** mmc2 got interrupt: 0x00000001
[  109.977849] mmc2: req done (CMD13): 0: 00000900 00000000 00000000 00000000
[  109.983013] <mmc2: starting CMD23 arg 00000080 flags 00000015>
[  109.983024] mmc2: starting CMD18 arg 00000000 flags 000000b5
[  109.983037] mmc2:     blksz 512 blocks 128 flags 00000200 tsac 100 ms nsac 0
[  109.983048] mmc2:     CMD12 arg 00000000 flags 0000049d
[  109.983083] sdhci [sdhci_irq()]: *** mmc2 got interrupt: 0x00000001
[  109.983218] sdhci [sdhci_irq()]: *** mmc2 got interrupt: 0x00000001
[  109.986505] sdhci [sdhci_irq()]: *** mmc2 got interrupt: 0x0000000a
[  109.986518] sdhci [sdhci_data_irq()]: mmc2: DMA base 0x3caf0000,
transferred 0x010000 bytes, next 0x3cb00000
[  109.986672] mmc2: req done (CMD18): 0: 00000900 00000000 00000000 00000000
[  109.986691] mmc2:     65536 bytes transferred: 0
[  109.986709] mmc2:     (CMD12): 0: 00000000 00000000 00000000 00000000
[  109.992355] <mmc2: starting CMD23 arg 00000080 flags 00000015>
[  109.992368] mmc2: starting CMD18 arg 00000080 flags 000000b5
[  109.992381] mmc2:     blksz 512 blocks 128 flags 00000200 tsac 100 ms nsac 0
[  109.992392] mmc2:     CMD12 arg 00000000 flags 0000049d
[  109.992424] sdhci [sdhci_irq()]: *** mmc2 got interrupt: 0x00000001
[  109.992724] sdhci [sdhci_irq()]: *** mmc2 got interrupt: 0x00000001
[  109.996010] sdhci [sdhci_irq()]: *** mmc2 got interrupt: 0x0000000a
[  109.996025] sdhci [sdhci_data_irq()]: mmc2: DMA base 0x3cb40000,
transferred 0x040000 bytes, next 0x3cb80000
[  109.996160] mmc2: req done (CMD18): 0: 00000900 00000000 00000000 00000000
[  109.996169] mmc2:     65536 bytes transferred: 0
[  109.996179] mmc2:     (CMD12): 0: 00000000 00000000 00000000 00000000
[  110.002250] mmc2: starting CMD6 arg 03b30a01 flags 0000049d --> switch to
Boot Partition 2 area
[  110.002292] sdhci [sdhci_irq()]: *** mmc2 got interrupt: 0x00000001
[  110.002318] mmc2: req done (CMD6): 0: 00000800 00000000 00000000 00000000

This is the point where you are facing issues with Hynix devices. A good way to reproduce the issue can be by unbinding/binding the eMMC device with block driver as follows

root@mx6q35:~# echo mmc2:0001 > /sys/bus/mmc/drivers/mmcblk/unbind
root@mx6q35:~# echo mmc2:0001 > /sys/bus/mmc/drivers/mmcblk/bind

Krishna, since RPMB is not a regular partition and a different command sequence(CMD6-->CMD23-->CMD25-->CMD23-->CMD18) as mentioned in JEDEC Standard No. 84-A441, is required to access it, then why mmc initialisation code is using the wrong command sequence(CMD6-->CMD23-->CMD18) to access it?

Thanks .
Abbas Raza