Tests:mmc-delay-refactor

This document describes how to test that the Linux MMC core does not use busy-looping in its mmc_delay helper anymore.

=Setup=

Kernel Version and Configuration
Support for this feature is expected to land upstream in v4.16. It is currently available in a topic branch:

git://git.kernel.org/pub/scm/linux/kernel/git/wsa/linux.git renesas/topic/mmc-delay-refactor

This branch contains example configs for testing, named lager-mmc-delay-config and salvator-mmc-delay-config. Because all udelay calls will be logged during tests, these configs are needed to keep the amount of enabled drivers minimal. Otherwise, there would be simply too much output. For the same reason, it is needed to disable the ethernet interface before testing.

Hardware Environment
Test were done on two boards


 * Salvator-X/r8a7796 (R-Car M3-W SoC)
 * Lager/r8a7790 (R-Car H2 SoC)

with some random microSD card (Lager) or some random SD card (Salvator-X).

Software Environment
A standard busybox is needed only. Commands used are ifconfig, echo and cat

= mmc_delay behaviour =

Preparations
On the host, to get the base Kernel tree without the MMC core improvements:

$ git checkout renesas/topic/mmc-delay-refactor-without-fix

Boot the kernel on the target, and after logging in, disable the ethernet interface:
 * 1) ifconfig eth0 down

Testing
Clear the trace first:
 * 1) echo > /sys/kernel/debug/tracing/trace

Now, insert a SD card to any of the slots. (Note: we mainly test the insert/eject cycle because powering up the cards triggers most delays. Transferring data does usually not cause any calls to mmc_delay).

Then, do:


 * 1) cat /sys/kernel/debug/tracing/trace

kworker/1:1-908  [001] .... 20.646434: __delay: 0 kworker/1:1-908  [001] .... 20.647390: mmc_power_up.part.9: 10 ms    kworker/1:1-908   [001] .... 20.666645: mmc_power_up.part.9: 10 ms    kworker/1:1-908   [001] .... 20.690323: mmc_go_idle: 1 ms    kworker/1:1-908   [001] .... 20.691324: __delay: 8333 kworker/1:1-908  [001] .... 20.691499: mmc_go_idle: 1 ms    kworker/1:1-908   [001] .... 20.692500: __delay: 8333 kworker/1:1-908  [001] .... 20.692717: mmc_go_idle: 1 ms    kworker/1:1-908   [001] .... 20.693718: __delay: 8333 kworker/1:1-908  [001] .... 20.702239: mmc_go_idle: 1 ms    kworker/1:1-908   [001] .... 20.703240: __delay: 8333 kworker/1:1-908  [001] .... 20.703415: mmc_go_idle: 1 ms    kworker/1:1-908   [001] .... 20.704415: __delay: 8333 kworker/1:1-908  [001] .... 20.704632: mmc_go_idle: 1 ms    kworker/1:1-908   [001] .... 20.705633: __delay: 8333 kworker/1:1-908  [001] .... 20.706582: mmc_send_app_op_cond: 10 ms    kworker/1:1-908   [001] .... 20.727045: mmc_send_app_op_cond: 10 ms    kworker/1:1-908   [001] .... 20.747044: mmc_send_app_op_cond: 10 ms    kworker/1:1-908   [001] .... 20.767043: mmc_send_app_op_cond: 10 ms    kworker/1:1-908   [001] .... 20.787042: mmc_send_app_op_cond: 10 ms    kworker/1:1-908   [001] .... 20.807043: mmc_send_app_op_cond: 10 ms    kworker/1:1-908   [001] .... 20.827042: mmc_send_app_op_cond: 10 ms    kworker/1:1-908   [001] .... 20.847044: mmc_send_app_op_cond: 10 ms    kworker/1:1-908   [001] .... 20.867045: mmc_send_app_op_cond: 10 ms    kworker/1:1-908   [001] .... 20.887043: mmc_send_app_op_cond: 10 ms    kworker/1:1-908   [001] .... 20.907365: mmc_set_uhs_voltage: 1 ms    kworker/1:1-908   [001] .... 20.908365: __delay: 8333 kworker/1:1-908  [001] .... 20.908665: mmc_host_set_uhs_voltage: 10 ms    kworker/1:1-908   [001] .... 20.926626: mmc_set_uhs_voltage: 1 ms    kworker/1:1-908   [001] .... 20.927627: __delay: 8333
 * 1) tracer: nop
 * 2)                              _-=> irqs-off
 * 3)                             / _=> need-resched
 * 4)                            | / _---=> hardirq/softirq
 * 5)                            || / _--=> preempt-depth
 * 6)                            ||| /     delay
 * 7)           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
 * 1)           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION

How to read this trace: The only relevant information for us here is the FUNCTION column. Every line containing __delay is a call to udelay/mdelay and means busy-looping. Every line starting with mmc_ is a call to mmc_delay which gets inlined to its caller function, so we see varying names there. We can see that mmc_delay is called with either 10ms or 1ms as an argument. Because HZ=100 in this kernel config, the 10ms calls result in msleep rather then mdelay, so it is not busy-looping and we don't see the __delay printout. For 1ms, things are different. We see a call to __delay which means here is now busy-looping involved. Note: The very first __udelay: 0 comes from the SDHI driver while waiting with udelay(1) for a register to be cleared. This is expected behaviour.

Preparations
Now, the test with the full branch applied:

$ git checkout renesas/topic/mmc-delay-refactor

Boot the kernel on the target, and after logging in, disable the ethernet interface:
 * 1) ifconfig eth0 down

Testing
Clear the trace first:
 * 1) echo > /sys/kernel/debug/tracing/trace

Now, insert a SD card to any of the slots. Then, do:


 * 1) cat /sys/kernel/debug/tracing/trace

kworker/0:3-968  [000] .... 165.014474: __delay: 0 kworker/0:3-968  [000] .... 165.015311: mmc_power_up.part.9: 10 ms    kworker/0:3-968   [000] .... 165.028043: mmc_power_up.part.9: 10 ms    kworker/0:3-968   [000] .... 165.044455: mmc_go_idle: 1 ms    kworker/0:3-968   [000] .... 165.045881: mmc_go_idle: 1 ms    kworker/0:3-968   [000] .... 165.047354: mmc_go_idle: 1 ms    kworker/0:3-968   [000] .... 165.057109: mmc_go_idle: 1 ms    kworker/0:3-968   [000] .... 165.058537: mmc_go_idle: 1 ms    kworker/0:3-968   [000] .... 165.060007: mmc_go_idle: 1 ms    kworker/0:3-968   [000] .... 165.062206: mmc_send_app_op_cond: 10 ms    kworker/0:3-968   [000] .... 165.075342: mmc_send_app_op_cond: 10 ms    kworker/0:3-968   [000] .... 165.088474: mmc_send_app_op_cond: 10 ms    kworker/0:3-968   [000] .... 165.101607: mmc_send_app_op_cond: 10 ms    kworker/0:3-968   [000] .... 165.114741: mmc_send_app_op_cond: 10 ms    kworker/0:3-968   [000] .... 165.127873: mmc_send_app_op_cond: 10 ms    kworker/0:3-968   [000] .... 165.141006: mmc_send_app_op_cond: 10 ms    kworker/0:3-968   [000] .... 165.154139: mmc_send_app_op_cond: 10 ms    kworker/0:3-968   [000] .... 165.167271: mmc_send_app_op_cond: 10 ms    kworker/0:3-968   [000] .... 165.180404: mmc_send_app_op_cond: 10 ms    kworker/0:3-968   [000] .... 165.193537: mmc_send_app_op_cond: 10 ms    kworker/0:3-968   [000] .... 165.206671: mmc_send_app_op_cond: 10 ms    kworker/0:3-968   [000] .... 165.219803: mmc_send_app_op_cond: 10 ms    kworker/0:3-968   [000] .... 165.232938: mmc_send_app_op_cond: 10 ms    kworker/0:3-968   [000] .... 165.246071: mmc_send_app_op_cond: 10 ms    kworker/0:3-968   [000] .... 165.259526: mmc_set_uhs_voltage: 1 ms    kworker/0:3-968   [000] .... 165.261123: mmc_host_set_uhs_voltage: 10 ms    kworker/0:3-968   [000] .... 165.273847: mmc_set_uhs_voltage: 1 ms Here, we see a ver similar output as before with the exception that the __delay calls for the 1ms case are also gone. This means there is no busy looping involved anymore in mmc_delay. Neither for 10ms nor for 1ms. All delays are now done with either msleep or usleep_range as suggested by the Kernel timer documentation.
 * 1) tracer: nop
 * 2)                              _-=> irqs-off
 * 3)                             / _=> need-resched
 * 4)                            | / _---=> hardirq/softirq
 * 5)                            || / _--=> preempt-depth
 * 6)                            ||| /     delay
 * 7)           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
 * 1)           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION

=Conclusion=

It could be shown that previously calls to mmc_delay caused busy-looping and burned CPU cycles. It could also be shown a fix that changes this behaviour to delay mechanisms which do not use busy-looping. The now involved sleeping methods give the Kernel a chance to use the time slices for another task.

Note: all the test results here were obtained using a Salvator-X/r8a7796 (R-Car M3-W SoC) board. All the tests have been done on a Lager/r8a7790 (R-Car H2 SoC) board, too. Only the values for __udelay will differ. This is architecture specific and not relevant for the general conclusions taken above. In fact, any board can be used to verify the results. In practice, the above branch can only be used on ARM and ARM64 because only there, the __udelay printout is generated currently.