Hi Richard Weinberger, > -----Original Message----- > From: Richard Weinberger <richard@xxxxxx> > Sent: Monday, April 17, 2023 9:09 PM > To: linux-mmc@xxxxxxxxxxxxxxx > Cc: linux-renesas-soc@xxxxxxxxxxxxxxx; wsa+renesas@xxxxxxxxxxxxxxxxxxxx; > ulf.hansson@xxxxxxxxxx > Subject: Poor write performance to boot area using rcar-gen3-sdhi > > Hi! > > Writing to the boot area of an eMMC takes significant longer than writing to > the user area on v6.1 (Tested also on v5.4). > The following trace shows write of 4k using "dd if=4k.dat > of=/dev/mmcblk1boot1 bs=512 oflag=sync". > As you can see from the timings, the whole operation took almost 80ms where > most of the time was consumed by the MMC_WRITE_MULTIPLE_BLOCK command. > > > kworker/1:1H-34 [001] ..... 5113.734166: mmc_request_start: mmc1: > start struct mmc_request[0000000005d331e4]: cmd_opcode=18 cmd_arg=0x0 > cmd_flags=0xb5 cmd_retries=0 stop_opcode=12 stop_arg=0x0 stop_flags=0x95 > stop_retries=0 sbc_opcode=23 sbc_arg=0x8 sbc_flags=0x15 sbc_retires=0 > blocks=8 block_size=512 blk_addr=0 data_flags=0x200 tag=26 can_retune=1 > doing_retune=0 retune_now=0 need_retune=0 hold_retune=1 retune_period=0 > kworker/0:1-25 [000] ..... 5113.735860: mmc_request_done: mmc1: > end struct mmc_request[0000000005d331e4]: cmd_opcode=18 cmd_err=0 > cmd_resp=0x900 0x900 0x900 0x900 cmd_retries=0 stop_opcode=12 stop_err=0 > stop_resp=0x0 0x0 0x0 0x0 stop_retries=0 sbc_opcode=23 sbc_err=0 > sbc_resp=0x900 0x900 0x900 0x900 sbc_retries=0 bytes_xfered=4096 data_err=0 > tag=26 can_retune=1 doing_retune=0 retune_now=0 need_retune=0 hold_retune=1 > retune_period=0 > kworker/1:1H-34 [001] ..... 5113.735996: mmc_request_start: mmc1: > start struct mmc_request[00000000174773b9]: cmd_opcode=25 cmd_arg=0x0 > cmd_flags=0xb5 cmd_retries=0 stop_opcode=12 stop_arg=0x0 stop_flags=0x49d > stop_retries=0 sbc_opcode=23 sbc_arg=0x8 sbc_flags=0x15 sbc_retires=0 > blocks=8 block_size=512 blk_addr=0 data_flags=0x100 tag=27 can_retune=1 > doing_retune=0 retune_now=0 need_retune=0 hold_retune=1 retune_period=0 > kworker/0:1-25 [000] ..... 5113.814376: mmc_request_done: mmc1: > end struct mmc_request[00000000174773b9]: cmd_opcode=25 cmd_err=0 > cmd_resp=0x900 0x900 0x900 0x900 cmd_retries=0 stop_opcode=12 stop_err=0 > stop_resp=0x0 0x0 0x0 0x0 stop_retries=0 sbc_opcode=23 sbc_err=0 > sbc_resp=0x900 0x900 0x900 0x900 sbc_retries=0 bytes_xfered=4096 data_err=0 > tag=27 can_retune=1 doing_retune=0 retune_now=0 need_retune=0 hold_retune=1 > retune_period=0 > kworker/0:1H-144 [000] ..... 5113.814391: mmc_request_start: mmc1: > start struct mmc_request[00000000101675e9]: cmd_opcode=13 cmd_arg=0x10000 > cmd_flags=0x195 cmd_retries=3 stop_opcode=0 stop_arg=0x0 stop_flags=0x0 > stop_retries=0 sbc_opcode=0 sbc_arg=0x0 sbc_flags=0x0 sbc_retires=0 blocks=0 > block_size=0 blk_addr=0 data_flags=0x0 tag=0 can_retune=1 doing_retune=0 > retune_now=0 need_retune=0 hold_retune=2 retune_period=0 > kworker/0:1-25 [000] ..... 5113.814408: mmc_request_done: mmc1: > end struct mmc_request[00000000101675e9]: cmd_opcode=13 cmd_err=0 > cmd_resp=0x900 0x900 0x900 0x900 cmd_retries=3 stop_opcode=0 stop_err=0 > stop_resp=0x0 0x0 0x0 0x0 stop_retries=0 sbc_opcode=0 sbc_err=0 sbc_resp=0x0 > 0x0 0x0 0x0 sbc_retries=0 bytes_xfered=0 data_err=0 tag=0 can_retune=1 > doing_retune=0 retune_now=0 need_retune=0 hold_retune=2 retune_period=0 > kworker/1:1H-34 [001] ..... 5113.814477: mmc_request_start: mmc1: > start struct mmc_request[0000000008526179]: cmd_opcode=6 cmd_arg=0x3200101 > cmd_flags=0x95 cmd_retries=3 stop_opcode=0 stop_arg=0x0 stop_flags=0x0 > stop_retries=0 sbc_opcode=0 sbc_arg=0x0 sbc_flags=0x0 sbc_retires=0 blocks=0 > block_size=0 blk_addr=0 data_flags=0x0 tag=0 can_retune=1 doing_retune=0 > retune_now=0 need_retune=0 hold_retune=2 retune_period=0 > kworker/0:1-25 [000] ..... 5113.814497: mmc_request_done: mmc1: > end struct mmc_request[0000000008526179]: cmd_opcode=6 cmd_err=0 > cmd_resp=0x800 0x900 0x900 0x800 cmd_retries=3 stop_opcode=0 stop_err=0 > stop_resp=0x0 0x0 0x0 0x0 stop_retries=0 sbc_opcode=0 sbc_err=0 sbc_resp=0x0 > 0x0 0x0 0x0 sbc_retries=0 bytes_xfered=0 data_err=0 tag=0 can_retune=1 > doing_retune=0 retune_now=0 need_retune=0 hold_retune=2 retune_period=0 > kworker/1:1H-34 [001] ..... 5113.814511: mmc_request_start: mmc1: > start struct mmc_request[0000000061873c4a]: cmd_opcode=13 cmd_arg=0x10000 > cmd_flags=0x195 cmd_retries=3 stop_opcode=0 stop_arg=0x0 stop_flags=0x0 > stop_retries=0 sbc_opcode=0 sbc_arg=0x0 sbc_flags=0x0 sbc_retires=0 blocks=0 > block_size=0 blk_addr=0 data_flags=0x0 tag=0 can_retune=1 doing_retune=0 > retune_now=0 need_retune=0 hold_retune=2 retune_period=0 > kworker/0:1-25 [000] ..... 5113.814529: mmc_request_done: mmc1: > end struct mmc_request[0000000061873c4a]: cmd_opcode=13 cmd_err=0 > cmd_resp=0x900 0x900 0x800 0x900 cmd_retries=3 stop_opcode=0 stop_err=0 > stop_resp=0x0 0x0 0x0 0x0 stop_retries=0 sbc_opcode=0 sbc_err=0 sbc_resp=0x0 > 0x0 0x0 0x0 sbc_retries=0 bytes_xfered=0 data_err=0 tag=0 can_retune=1 > doing_retune=0 retune_now=0 need_retune=0 hold_retune=2 retune_period=0O > > > On the other hand, writing to the user area using "dd if=4k.dat > of=/dev/mmcblk1p13 bs=512 oflag=sync" is fast: > > > kworker/1:1H-34 [001] ..... 5163.989096: mmc_request_start: mmc1: > start struct mmc_request[000000003c3d18f8]: cmd_opcode=6 cmd_arg=0x3b30801 > cmd_flags=0x49d cmd_retries=3 stop_opcode=0 stop_arg=0x0 stop_flags=0x0 > stop_retries=0 sbc_opcode=0 sbc_arg=0x0 sbc_flags=0x0 sbc_retires=0 blocks=0 > block_size=0 blk_addr=0 data_flags=0x0 tag=0 can_retune=1 doing_retune=0 > retune_now=0 need_retune=0 hold_retune=2 retune_period=0 > kworker/0:1-25 [000] ..... 5163.991009: mmc_request_done: mmc1: > end struct mmc_request[000000003c3d18f8]: cmd_opcode=6 cmd_err=0 > cmd_resp=0x800 0x900 0x900 0x800 cmd_retries=3 stop_opcode=0 stop_err=0 > stop_resp=0x0 0x0 0x0 0x0 stop_retries=0 sbc_opcode=0 sbc_err=0 sbc_resp=0x0 > 0x0 0x0 0x0 sbc_retries=0 bytes_xfered=0 data_err=0 tag=0 can_retune=1 > doing_retune=0 retune_now=0 need_retune=0 hold_retune=2 retune_period=0 > kworker/1:1H-34 [001] ..... 5163.991027: mmc_request_start: mmc1: > start struct mmc_request[00000000a1a3cac1]: cmd_opcode=13 cmd_arg=0x10000 > cmd_flags=0x195 cmd_retries=3 stop_opcode=0 stop_arg=0x0 stop_flags=0x0 > stop_retries=0 sbc_opcode=0 sbc_arg=0x0 sbc_flags=0x0 sbc_retires=0 blocks=0 > block_size=0 blk_addr=0 data_flags=0x0 tag=0 can_retune=1 doing_retune=0 > retune_now=0 need_retune=0 hold_retune=2 retune_period=0 > kworker/0:1-25 [000] ..... 5163.991056: mmc_request_done: mmc1: > end struct mmc_request[00000000a1a3cac1]: cmd_opcode=13 cmd_err=0 > cmd_resp=0x900 0x900 0x800 0x900 cmd_retries=3 stop_opcode=0 stop_err=0 > stop_resp=0x0 0x0 0x0 0x0 stop_retries=0 sbc_opcode=0 sbc_err=0 sbc_resp=0x0 > 0x0 0x0 0x0 sbc_retries=0 bytes_xfered=0 data_err=0 tag=0 can_retune=1 > doing_retune=0 retune_now=0 need_retune=0 hold_retune=2 retune_period=0 > kworker/1:1H-34 [001] ..... 5163.991081: mmc_request_start: mmc1: > start struct mmc_request[00000000f096e251]: cmd_opcode=18 cmd_arg=0x4ea000 > cmd_flags=0xb5 cmd_retries=0 stop_opcode=12 stop_arg=0x0 stop_flags=0x95 > stop_retries=0 sbc_opcode=23 sbc_arg=0x8 sbc_flags=0x15 sbc_retires=0 > blocks=8 block_size=512 blk_addr=5152768 data_flags=0x200 tag=6 can_retune=1 > doing_retune=0 retune_now=0 need_retune=0 hold_retune=1 retune_period=0 > kworker/0:1-25 [000] ..... 5163.991705: mmc_request_done: mmc1: > end struct mmc_request[00000000f096e251]: cmd_opcode=18 cmd_err=0 > cmd_resp=0x900 0x900 0x900 0x900 cmd_retries=0 stop_opcode=12 stop_err=0 > stop_resp=0x0 0x0 0x0 0x0 stop_retries=0 sbc_opcode=23 sbc_err=0 > sbc_resp=0x900 0x900 0x900 0x900 sbc_retries=0 bytes_xfered=4096 data_err=0 > tag=6 can_retune=1 doing_retune=0 retune_now=0 need_retune=0 hold_retune=1 > retune_period=0 > kworker/1:1H-34 [001] ..... 5163.991838: mmc_request_start: mmc1: > start struct mmc_request[00000000ec4997fb]: cmd_opcode=25 cmd_arg=0x4ea000 > cmd_flags=0xb5 cmd_retries=0 stop_opcode=12 stop_arg=0x0 stop_flags=0x49d > stop_retries=0 sbc_opcode=23 sbc_arg=0x8 sbc_flags=0x15 sbc_retires=0 > blocks=8 block_size=512 blk_addr=5152768 data_flags=0x100 tag=7 can_retune=1 > doing_retune=0 retune_now=0 need_retune=0 hold_retune=1 retune_period=0 > kworker/0:1-25 [000] ..... 5163.992203: mmc_request_done: mmc1: > end struct mmc_request[00000000ec4997fb]: cmd_opcode=25 cmd_err=0 > cmd_resp=0x900 0x900 0x900 0x900 cmd_retries=0 stop_opcode=12 stop_err=0 > stop_resp=0x0 0x0 0x0 0x0 stop_retries=0 sbc_opcode=23 sbc_err=0 > sbc_resp=0x900 0x900 0x900 0x900 sbc_retries=0 bytes_xfered=4096 data_err=0 > tag=7 can_retune=1 doing_retune=0 retune_now=0 need_retune=0 hold_retune=1 > retune_period=0 > kworker/0:1H-144 [000] ..... 5163.992215: mmc_request_start: mmc1: > start struct mmc_request[00000000101675e9]: cmd_opcode=13 cmd_arg=0x10000 > cmd_flags=0x195 cmd_retries=3 stop_opcode=0 stop_arg=0x0 stop_flags=0x0 > stop_retries=0 sbc_opcode=0 sbc_arg=0x0 sbc_flags=0x0 sbc_retires=0 blocks=0 > block_size=0 blk_addr=0 data_flags=0x0 tag=0 can_retune=1 doing_retune=0 > retune_now=0 need_retune=0 hold_retune=2 retune_period=0 > kworker/0:1-25 [000] ..... 5163.992231: mmc_request_done: mmc1: > end struct mmc_request[00000000101675e9]: cmd_opcode=13 cmd_err=0 > cmd_resp=0x900 0x900 0x900 0x900 cmd_retries=3 stop_opcode=0 stop_err=0 > stop_resp=0x0 0x0 0x0 0x0 stop_retries=0 sbc_opcode=0 sbc_err=0 sbc_resp=0x0 > 0x0 0x0 0x0 sbc_retries=0 bytes_xfered=0 data_err=0 tag=0 can_retune=1 > doing_retune=0 retune_now=0 need_retune=0 hold_retune=2 retune_period=0 > kworker/1:1H-34 [001] ..... 5163.992291: mmc_request_start: mmc1: > start struct mmc_request[0000000008526179]: cmd_opcode=6 cmd_arg=0x3200101 > cmd_flags=0x95 cmd_retries=3 stop_opcode=0 stop_arg=0x0 stop_flags=0x0 > stop_retries=0 sbc_opcode=0 sbc_arg=0x0 sbc_flags=0x0 sbc_retires=0 blocks=0 > block_size=0 blk_addr=0 data_flags=0x0 tag=0 can_retune=1 doing_retune=0 > retune_now=0 need_retune=0 hold_retune=2 retune_period=0 > kworker/0:1-25 [000] ..... 5163.992310: mmc_request_done: mmc1: > end struct mmc_request[0000000008526179]: cmd_opcode=6 cmd_err=0 > cmd_resp=0x800 0x900 0x900 0x800 cmd_retries=3 stop_opcode=0 stop_err=0 > stop_resp=0x0 0x0 0x0 0x0 stop_retries=0 sbc_opcode=0 sbc_err=0 sbc_resp=0x0 > 0x0 0x0 0x0 sbc_retries=0 bytes_xfered=0 data_err=0 tag=0 can_retune=1 > doing_retune=0 retune_now=0 need_retune=0 hold_retune=2 retune_period=0 > kworker/1:1H-34 [001] ..... 5163.992790: mmc_request_start: mmc1: > start struct mmc_request[0000000061873c4a]: cmd_opcode=13 cmd_arg=0x10000 > cmd_flags=0x195 cmd_retries=3 stop_opcode=0 stop_arg=0x0 stop_flags=0x0 > stop_retries=0 sbc_opcode=0 sbc_arg=0x0 sbc_flags=0x0 sbc_retires=0 blocks=0 > block_size=0 blk_addr=0 data_flags=0x0 tag=0 can_retune=1 doing_retune=0 > retune_now=0 need_retune=0 hold_retune=2 retune_period=0 > kworker/0:1-25 [000] ..... 5163.992808: mmc_request_done: mmc1: > end struct mmc_request[0000000061873c4a]: cmd_opcode=13 cmd_err=0 > cmd_resp=0x900 0x900 0x800 0x900 cmd_retries=3 stop_opcode=0 stop_err=0 > stop_resp=0x0 0x0 0x0 0x0 stop_retries=0 sbc_opcode=0 sbc_err=0 sbc_resp=0x0 > 0x0 0x0 0x0 sbc_retries=0 bytes_xfered=0 data_err=0 tag=0 can_retune=1 > doing_retune=0 retune_now=0 need_retune=0 hold_retune=2 retune_period=0 > > The whole operation took only about 3ms. > > Is this expected? > > Off the head I don't really see why writing to the boot area should be > slower. > BTW: Using u-boot the write is blazing fast, so the eMMC itself should be > fine. > At driver level there shouldn't be much difference between writing to boot > and user area except from MMC_SWITCH. Not sure, the file system used between /dev/mmcblk1boot1 and /dev/mmcblk1p13 is making difference at Linux? I have seen performance difference between FAT and ext4. Cheers, Biju
