Tests:mmc-delay-refactor

From eLinux.org
Revision as of 13:36, 13 November 2017 by W sang (talk | contribs) (first very early draft)
(diff) ← Older revision | Latest revision (diff) | Newer revision → (diff)
Jump to: navigation, search

!DRAFT! 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

The following kernel options need to be set in addition to the defconfig:

CONFIG_FTRACE=y

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

before this task

Preparations

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

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

Testing

# cat /sys/kernel/debug/tracing/trace

# tracer: nop
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
     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

after this task

Now, the test with the full branch applied:

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

Testing

# cat /sys/kernel/debug/tracing/trace

# tracer: nop
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
     kworker/0:3-968   [000] ....   162.351661: mmc_power_off.part.10: 1 ms
     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

Conclusion