Poor write performance to boot area using rcar-gen3-sdhi

Poor write performance to boot area using rcar-gen3-sdhi

[Richard Weinberger]

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.

Thanks,
//richard

RE: Poor write performance to boot area using rcar-gen3-sdhi

[Biju Das]

Hi Richard Weinberger,

> -----Original Message-----
> From: Richard Weinberger <richard@nod.at>
> Sent: Monday, April 17, 2023 9:09 PM
> To: linux-mmc@vger.kernel.org
> Cc: linux-renesas-soc@vger.kernel.org; wsa+renesas@sang-engineering.com;
> ulf.hansson@linaro.org
> 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

Re: Poor write performance to boot area using rcar-gen3-sdhi

[Richard Weinberger]

----- Ursprüngliche Mail -----
> Von: "Biju Das" <biju.das.jz@bp.renesas.com>
> 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.

There is no filesystem, I'm writing directly using dd
to the raw block device.

Thanks,
//richard

RE: Poor write performance to boot area using rcar-gen3-sdhi

[Christian Loehle]

Your eMMC likely treats the boot partitions differently than the user area, e.g. in regards to cache.
Is this reproducible for more 4k writes? What about larger writes?
The eMMC might not even have the mapping available after boot and first has to internally switch to it, in contrast to at u-boot stage?

Anyway this is probably more a question to your eMMC manufacturer and nothing the host is to be blamed, as you mentioned yourself, the time is spent at CMD25.

-----Original Message-----
From: Richard Weinberger <richard@nod.at> 
Sent: Tuesday, April 18, 2023 8:16 AM
To: Biju Das <biju.das.jz@bp.renesas.com>
Cc: linux-mmc <linux-mmc@vger.kernel.org>; linux-renesas-soc <linux-renesas-soc@vger.kernel.org>; wsa+renesas <wsa+renesas@sang-engineering.com>; ulf hansson <ulf.hansson@linaro.org>
Subject: Re: Poor write performance to boot area using rcar-gen3-sdhi

----- Ursprüngliche Mail -----
> Von: "Biju Das" <biju.das.jz@bp.renesas.com> 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.

There is no filesystem, I'm writing directly using dd to the raw block device.

Thanks,
//richard

Hyperstone GmbH | Reichenaustr. 39a  | 78467 Konstanz
Managing Director: Dr. Jan Peter Berns.
Commercial register of local courts: Freiburg HRB381782

Re: Poor write performance to boot area using rcar-gen3-sdhi

[Richard Weinberger]

----- Ursprüngliche Mail -----
> Von: "Christian Loehle" <CLoehle@hyperstone.com>
> Your eMMC likely treats the boot partitions differently than the user area, e.g.
> in regards to cache.
> Is this reproducible for more 4k writes? What about larger writes?

Yes. So far every write size I tried is slow.
Sometimes (1 out of 50) small writes are fast, that's most likely a caching effect
of eMMC internals.

> The eMMC might not even have the mapping available after boot and first has to
> internally switch to it, in contrast to at u-boot stage?

Wouldn't that explain only the first slow write?
I see poor write speed also on repeated runs.
 
> Anyway this is probably more a question to your eMMC manufacturer and nothing
> the host is to be blamed, as you mentioned yourself, the time is spent at
> CMD25.

The eMMC manufacturer says there is nothing special about the boot area
and write speed should be equally fast.

Can it be that rcar-gen3-sdhi changes some timings after switching?
Either in software or on hardware.

Thanks,
//richard

RE: Poor write performance to boot area using rcar-gen3-sdhi

[Christian Loehle]

> Can it be that rcar-gen3-sdhi changes some timings after switching?
> Either in software or on hardware.

Neither should be aware of the notion of a boot or user area partition.
Anything below mmc/core isn't, if we exclude the boot operation which is read only, so not applicable to your problem.
So also a
while true; do dd if=/dev/zero of=/dev/mmcblkXboot0 bs=128K status=progress; done
gives you like ~50KB/s consistently?


-----Original Message-----
From: Richard Weinberger <richard@nod.at> 
Sent: Tuesday, April 18, 2023 10:11 AM
To: Christian Loehle <CLoehle@hyperstone.com>
Cc: Biju Das <biju.das.jz@bp.renesas.com>; linux-mmc <linux-mmc@vger.kernel.org>; linux-renesas-soc <linux-renesas-soc@vger.kernel.org>; wsa+renesas <wsa+renesas@sang-engineering.com>; ulf hansson <ulf.hansson@linaro.org>
Subject: Re: Poor write performance to boot area using rcar-gen3-sdhi

----- Ursprüngliche Mail -----
> Von: "Christian Loehle" <CLoehle@hyperstone.com> Your eMMC likely 
> treats the boot partitions differently than the user area, e.g.
> in regards to cache.
> Is this reproducible for more 4k writes? What about larger writes?

Yes. So far every write size I tried is slow.
Sometimes (1 out of 50) small writes are fast, that's most likely a caching effect of eMMC internals.

> The eMMC might not even have the mapping available after boot and 
> first has to internally switch to it, in contrast to at u-boot stage?

Wouldn't that explain only the first slow write?
I see poor write speed also on repeated runs.
 
> Anyway this is probably more a question to your eMMC manufacturer and 
> nothing the host is to be blamed, as you mentioned yourself, the time 
> is spent at CMD25.

The eMMC manufacturer says there is nothing special about the boot area and write speed should be equally fast.

Can it be that rcar-gen3-sdhi changes some timings after switching?
Either in software or on hardware.

Thanks,
//richard

Hyperstone GmbH | Reichenaustr. 39a  | 78467 Konstanz
Managing Director: Dr. Jan Peter Berns.
Commercial register of local courts: Freiburg HRB381782

Re: Poor write performance to boot area using rcar-gen3-sdhi

[Richard Weinberger]

----- Ursprüngliche Mail -----
> Von: "Christian Loehle" <CLoehle@hyperstone.com>
>> Can it be that rcar-gen3-sdhi changes some timings after switching?
>> Either in software or on hardware.
> 
> Neither should be aware of the notion of a boot or user area partition.
> Anything below mmc/core isn't, if we exclude the boot operation which is read
> only, so not applicable to your problem.
> So also a
> while true; do dd if=/dev/zero of=/dev/mmcblkXboot0 bs=128K status=progress;
> done
> gives you like ~50KB/s consistently?

Exactly. 

On the other hand, the very same command on /dev/mmcblk1p13 gives me always between
17 and 20 MB/s.

Thanks,
//richard

Re: Poor write performance to boot area using rcar-gen3-sdhi

[Richard Weinberger]

----- Ursprüngliche Mail -----
> ----- Ursprüngliche Mail -----
>> Von: "Christian Loehle" <CLoehle@hyperstone.com>
>>> Can it be that rcar-gen3-sdhi changes some timings after switching?
>>> Either in software or on hardware.
>> 
>> Neither should be aware of the notion of a boot or user area partition.
>> Anything below mmc/core isn't, if we exclude the boot operation which is read
>> only, so not applicable to your problem.
>> So also a
>> while true; do dd if=/dev/zero of=/dev/mmcblkXboot0 bs=128K status=progress;
>> done
>> gives you like ~50KB/s consistently?
> 
> Exactly.
> 
> On the other hand, the very same command on /dev/mmcblk1p13 gives me always
> between
> 17 and 20 MB/s.

I did further tracing and on Linux I see clearly that tmio_mmc_irq() always much
later when writing to the boot area.

Another idea, since u-boot does not really support interrupts it polls various
status bits to detect completion of commands and data transfers.
Crazy idea: Maybe u-boot writes are faster than they should because it polls not always the
right bits?

...or Linux is too conservative and it matters for the boot area.

Thanks,
//richard

RE: Poor write performance to boot area using rcar-gen3-sdhi

[Christian Loehle]

-----Original Message-----
From: Richard Weinberger <richard@nod.at> 
Sent: Thursday, April 20, 2023 5:18 PM
To: Christian Loehle <CLoehle@hyperstone.com>
Cc: Biju Das <biju.das.jz@bp.renesas.com>; linux-mmc <linux-mmc@vger.kernel.org>; linux-renesas-soc <linux-renesas-soc@vger.kernel.org>; wsa+renesas <wsa+renesas@sang-engineering.com>; ulf hansson <ulf.hansson@linaro.org>
Subject: Re: Poor write performance to boot area using rcar-gen3-sdhi
> 
> I did further tracing and on Linux I see clearly that tmio_mmc_irq() always much later when writing to the boot area.
> 
> Another idea, since u-boot does not really support interrupts it polls various status bits to detect completion of commands and data transfers.
> Crazy idea: Maybe u-boot writes are faster than they should because it polls not always the right bits?
> 
> ...or Linux is too conservative and it matters for the boot area.
> 
> Thanks,
> //richard
> 

If u-boot does not wait until the card no longer signals busy, I would expect data loss.
There are probably some more differences if you really want to go down that rabbit hole,
like different bus modes for uboot and linux.
Anyway I don't really know how I could help you out here, if you could provide a trace showing the busy times,
that would be a smoking gun for the eMMC vendor.

Regards,
Christian

Hyperstone GmbH | Reichenaustr. 39a  | 78467 Konstanz
Managing Director: Dr. Jan Peter Berns.
Commercial register of local courts: Freiburg HRB381782

Re: Poor write performance to boot area using rcar-gen3-sdhi

[Richard Weinberger]

----- Ursprüngliche Mail -----
> Von: "Christian Loehle" <CLoehle@hyperstone.com>
> There are probably some more differences if you really want to go down that
> rabbit hole,
> like different bus modes for uboot and linux.
> Anyway I don't really know how I could help you out here, if you could provide a
> trace showing the busy times,
> that would be a smoking gun for the eMMC vendor.

So I went down the rabbit hole.
After analyzing the operation traces from Linux and u-boot in more detail I had
another chat with the vendor. It turned out their boot area *is* different,
it operates on a much larger internal block size.

While u-boot does basically all IO with one op code, Linux's writeback
via page cache writes 4k wise which leads to catastrophic performance.
Using O_DIRECT mitigates the issue, though.

Thanks everyone for your valuable input!
//richard

RE: Poor write performance to boot area using rcar-gen3-sdhi

[Christian Loehle]

-----Original Message-----
From: Richard Weinberger <richard@nod.at> 
Sent: Tuesday, May 9, 2023 1:28 PM
To: Christian Loehle <CLoehle@hyperstone.com>
Cc: Biju Das <biju.das.jz@bp.renesas.com>; linux-mmc <linux-mmc@vger.kernel.org>; linux-renesas-soc <linux-renesas-soc@vger.kernel.org>; wsa+renesas <wsa+renesas@sang-engineering.com>; ulf hansson <ulf.hansson@linaro.org>
Subject: Re: Poor write performance to boot area using rcar-gen3-sdhi


> So I went down the rabbit hole.
> After analyzing the operation traces from Linux and u-boot in more detail I had another chat with the vendor. It turned out their boot area *is* different, it operates on a much larger internal block size.
> 
> While u-boot does basically all IO with one op code, Linux's writeback via page cache writes 4k wise which leads to catastrophic performance.
> Using O_DIRECT mitigates the issue, though.

Interesting, without having tried it out I would expect the 4k writebacks to be merged to a bigger IO, too? Given that they are filled sequentially, which is the case.
But good that you got it working. 
If I find the time I will play with it a bit.

> 
> Thanks everyone for your valuable input!
> //richard
>

Hyperstone GmbH | Reichenaustr. 39a  | 78467 Konstanz
Managing Director: Dr. Jan Peter Berns.
Commercial register of local courts: Freiburg HRB381782

Re: Poor write performance to boot area using rcar-gen3-sdhi

[Richard Weinberger]

----- Ursprüngliche Mail -----
> Von: "Christian Loehle" <CLoehle@hyperstone.com>
>> While u-boot does basically all IO with one op code, Linux's writeback via page
>> cache writes 4k wise which leads to catastrophic performance.
>> Using O_DIRECT mitigates the issue, though.
> 
> Interesting, without having tried it out I would expect the 4k writebacks to be
> merged to a bigger IO, too? Given that they are filled sequentially, which is
> the case.
> But good that you got it working.
> If I find the time I will play with it a bit.

I think due to the nature of rcar-gen3-sdhi merging of these BIOs is not possible.
There seems to be support for some variants, though:
https://elinux.org/R-Car/Merging-MMC-block-requests

Not sure whether I find the time to dig down that rabbit whole too. ;-)

Thanks,
//richard

RE: Poor write performance to boot area using rcar-gen3-sdhi

[Biju Das]

Hi Christian Loehle,

> -----Original Message-----
> From: Christian Loehle <CLoehle@hyperstone.com>
> Sent: Tuesday, April 18, 2023 8:48 AM
> To: Richard Weinberger <richard@nod.at>; Biju Das
> <biju.das.jz@bp.renesas.com>
> Cc: linux-mmc <linux-mmc@vger.kernel.org>; linux-renesas-soc <linux-renesas-
> soc@vger.kernel.org>; wsa+renesas <wsa+renesas@sang-engineering.com>; ulf
> hansson <ulf.hansson@linaro.org>
> Subject: RE: Poor write performance to boot area using rcar-gen3-sdhi
> 
> Your eMMC likely treats the boot partitions differently than the user area,
> e.g. in regards to cache.

Boot partition is set by TF-A[1]. How does it differs from one used in Linux?
[1] https://elixir.bootlin.com/arm-trusted-firmware/v2.8.0/source/drivers/renesas/common/io/io_emmcdrv.c#L169

Cheers,
Biju


> Is this reproducible for more 4k writes? What about larger writes?
> The eMMC might not even have the mapping available after boot and first has
> to internally switch to it, in contrast to at u-boot stage?
> 
> Anyway this is probably more a question to your eMMC manufacturer and
> nothing the host is to be blamed, as you mentioned yourself, the time is
> spent at CMD25.
> 
> -----Original Message-----
> From: Richard Weinberger <richard@nod.at>
> Sent: Tuesday, April 18, 2023 8:16 AM
> To: Biju Das <biju.das.jz@bp.renesas.com>
> Cc: linux-mmc <linux-mmc@vger.kernel.org>; linux-renesas-soc <linux-renesas-
> soc@vger.kernel.org>; wsa+renesas <wsa+renesas@sang-engineering.com>; ulf
> hansson <ulf.hansson@linaro.org>
> Subject: Re: Poor write performance to boot area using rcar-gen3-sdhi
> 
> ----- Ursprüngliche Mail -----
> > Von: "Biju Das" <biju.das.jz@bp.renesas.com> 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.
> 
> There is no filesystem, I'm writing directly using dd to the raw block
> device.
> 
> Thanks,
> //richard
> 
> Hyperstone GmbH | Reichenaustr. 39a  | 78467 Konstanz Managing Director: Dr.
> Jan Peter Berns.
> Commercial register of local courts: Freiburg HRB381782