blockIO trace

[DESCRIPTION]

1) 本FAQ介绍如何抓取 block trace 和 android_fs trace, 及需要查看那些相关的 trace log。

2) 带有root版本的手机，可以直接抓取blockIO trace。

3) 不带root版本的手机，修改 "/sys/kernel/debug/tracing/events/***/enable" 为可读可写的权限后，就可以抓其trace了。

[SOLUTION]

1. 通常需要抓取的 block IO trace

• block trace

 k65v1_bsp: /sys/kernel/debug/tracing/events/block # ls
 block_bio_backmerge    block_dirty_buffer    block_rq_issue          block_unplug
 block_bio_bounce          block_getrq             block_rq_remap        enable
 block_bio_complete       block_plug               block_rq_requeue     filter
 block_bio_frontmerge    block_rq_abort         block_sleeprq
 block_bio_queue           block_rq_complete    block_split
 block_bio_remap           block_rq_insert         block_touch_buffer

• android_fs trace

 k65v1_bsp: /sys/kernel/debug/tracing/events/android_fs # ls
 android_fs_dataread_end       android_fs_datawrite_end        enable
 android_fs_dataread_start      android_fs_datawrite_start       filter

• emmc trace

 k65v1_bsp: /sys/kernel/debug/tracing/events/mmc # ls
 enable       mmc_request_done       mmc_request_start       filter

 2. 抓取 block IO 的 ftrace

• 抓ftrace需要 root 权限，建议在user+root版本分析 IO performance问题，不要在eng版本上分析performance问题
• 方法和抓其他模块的ftrace一样，添加 "block android_fs mmc" 到 /sys/kernel/debug/tracing/set_event，然后和通常抓取ftrace的方法一样抓取即可
• 如果觉得trace文件太大，可以把"mmc"去掉，保留"block android_fs"即可，如：

 adb shell "echo 'android_fs block sched_switch sched_wakeup sched_blocked_reason *****'  > /sys/kernel/debug/tracing/set_event"

3. 抓取 block IO 的 systrace

• 由于systrace使用android原生的接口，而 android_fs 不在android原生的接口里，所以非root版本上就无法抓到 android_fs 的trace
• systrace代码参考： frameworks/native/cmds/atrace/atrace.cpp

• 如果有root权限，在使用 systrace.py 脚本方法抓取systrace前，执行如下命令即可打开"android_fs"和"block"的trace 

adb shell "echo 1 > /sys/kernel/debug/tracing/events/android_fs/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/block/enable"

• 无root的user版本上如何抓取 block IO trace? 需要修改代码：
  • 在init.rc里添加 trace enable 节点为可读可写。比如添加 android_fs 的可读可写权限

In system/core/rootdir/init.rc

on late-fs
# Ensure that tracefs has the correct permissions.
# This does not work correctly if it is called in post-fs.
chmod 0755 /sys/kernel/debug/tracing

# Debug trace add begin
chmod 0666 /sys/kernel/debug/tracing/events/android_fs/enable
chmod 0666 /sys/kernel/debug/tracing/events/android_fs/android_fs_dataread_start/enable
chmod 0666 /sys/kernel/debug/tracing/events/android_fs/android_fs_dataread_end/enable
chmod 0666 /sys/kernel/debug/tracing/events/android_fs/android_fs_datawrite_start/enable
chmod 0666 /sys/kernel/debug/tracing/events/android_fs/android_fs_datawrite_end/enable
# Debug trace add end

# HALs required before storage encryption can get unlocked (FBE/FDE)
class_start early_hal

• • 在atrace中添加systrace接口

In frameworks/native/cmds/atrace/atrace.cpp

93/* Tracing categories */
94static const TracingCategory k_categories[] = {
95 { "gfx", "Graphics", ATRACE_TAG_GRAPHICS, {
...................................................
218 { "pagecache", "Page cache", 0, {
219 { REQ, "events/filemap/enable" },
220 } },
/* Debug trace add begin */
{ "android_fs", "Android filesystem I/O", 0, {
{ REQ, "events/android_fs/android_fs_datawrite_start/enable" },
{ REQ, "events/android_fs/android_fs_datawrite_end/enable" },
{ REQ, "events/android_fs/android_fs_dataread_start/enable" },
{ REQ, "events/android_fs/android_fs_dataread_end/enable" },
} },
/* Debug trace add end */
221};

• • 如果使用python脚本抓systrace, 需要添加tag: “android_fs”, 例如：
    “python systrace.py --time=8 -o systrace1.html gfx android_fs ******”

• • 如果用Android Monitor DDMS抓systrace，需要勾上 “Android filesystem I/O”，如：

4. Block IO trace log 查看

• 需要用文本工具打开，比如 UltraEdit、notepad++等等
• trace中查看Block log，搜"block_rq_"

 

• trace中查看Android FS log, 搜"android_fs_"

 

• trace中查看MMC log, 搜"mmc_request_"

 5. block IO trace log 分析举例：

滴滴 UI thread read file 出现 Uninterruptible Sleep - Block I/O

•  根据 Uninterruptible Sleep - Block I/O 的 sched_blocked_reason，找到trace 对应的log:

exe_cq-246 ( 246) [006] .... 60082.757243: block_rq_complete: 179,0 R () 22547696 + 160 [0]
exe_cq-246 ( 246) [006] .... 60082.757256: android_fs_dataread_end: ino 74664, offset 64647168, bytes 81920
exe_cq-246 ( 246) [006] d..2 60082.757262: sched_waking: comm=sdu.didi.psnger pid=14559 prio=110 success=1 target_cpu=005 state=D|K|d overutil=0
exe_cq-246 ( 246) [006] d..3 60082.757286: sched_blocked_reason: pid=14559 iowait=1 caller=__lock_page_or_retry+0x1dc/0x20c
<idle>-0 (-----) [005] dn.1 60082.757305: cpu_idle: state=4294967295 cpu_id=5
exe_cq-246 ( 246) [006] d..3 60082.757306: sched_wakeup: comm=sdu.didi.psnger pid=14559 prio=110 success=1 target_cpu=005 state=R overutil=0

• fs 收到读操作后，通常会读完成后再返回。而写操作是写到cache里就返回，没有真正的去写。所以我们可以根据block_rq_complete来找具体读那个文件。

exe_cq-246 ( 246) [006] .... 60082.757243: block_rq_complete: 179,0 R () 22547696 + 160 [0]
exe_cq-246 ( 246) [006] .... 60082.757256: android_fs_dataread_end: ino 74664, offset 64647168, bytes 81920

可以看到read完成的log，即read offset 64647168, bytes 81920。 bytes 正好和 block_rq_complete size对的上： 160个块 = 160*512B = 81920B

• 那么搜offset "64647168", 即 60081.383898的时候在读 /app/com.sdu.didi.psnger-E05uSP1jXUyWy9TaLncGLA==/oat/arm/base.vdex

         sdu.didi.psnger-14559 (14559) [005] .... 60081.383898: android_fs_dataread_start: entry_name /app/com.sdu.didi.psnger-E05uSP1jXUyWy9TaLncGLA==/oat/arm/base.vdex, offset 64647168, bytes 81920, cmdline sdu.didi.psnger, pid 14559, i_size 70318844, ino 74664

• 这样可以看到 APP 的pid 什么时候开始read那个文件了。 如果要知道driver层什么开始read, 还可以搜 block_rq_complete: 对应的地址 22547696

mmcqd/0-248 ( 248) [005] d..1 60082.750624: block_rq_issue: 179,0 R 0 () 22547696 + 160 [mmcqd/0]
exe_cq-246 ( 246) [006] .... 60082.757243: block_rq_complete: 179,0 R () 22547696 + 160 [0]

• 本题IO read慢的原因是有很多IO write操作在排队，虽然之前发了读操作，但它要等runqueue里的其他操作完成才能到它执行。