From 738ff7b96f9a48e77dad18ad35dd3b278fa3b7e9 Mon Sep 17 00:00:00 2001 From: Mohan Srinivasan Date: Fri, 8 Sep 2017 13:58:47 -0700 Subject: Add writepage(s) blaming support to ioblame. Make ioblame use the (f2fs) writepage(s) tracepoint, to attribute writepage(s) to filenames. Useful to track down and tune apps that might be writing too much. Test: Tested the (new) -p option with f2fs (and also with ext4) ensuring that it works with the former and exits gracefully with error in the latter cases. Bug: 63939317 Change-Id: I2a3ad02a650a293dbca4c23d0276bbe86ad648fe Signed-off-by: Mohan Srinivasan --- ioblame/README | 33 +++++++- ioblame/ioblame.sh | 223 ++++++++++++++++++++++++++++++++++++++--------------- 2 files changed, 189 insertions(+), 67 deletions(-) diff --git a/ioblame/README b/ioblame/README index ebe80605..0813ff2b 100644 --- a/ioblame/README +++ b/ioblame/README @@ -13,6 +13,8 @@ What does the output from ioblame look like ? ------------------------------------------- ioblame gives 2 different views. +File view is the default. + 1) File view : For each file, it gives a list of pids that are doing IO on that file (it also gives the amount of IO each pid does and the aggregate amount of IO done to the file by all pids). @@ -40,8 +42,7 @@ File: /app/Gmail2Light/Gmail2Light.apk And ditto for writes. -2) PID view : For each pid actively doing IO, it dumps out the list of -files that the pid does IO to. +To enable PID view, use -v PID: CrRendererMain /app/Chrome/Chrome.apk Reads: 17012 KB i_size: 71354 KB @@ -80,6 +81,11 @@ PID: CrRendererMain And ditto for writes. +For the -p, writepages option, ioblame does not (and cannot) give you +the app/pid that did the original write (since the write most likely +happens from a flush thread or VM reclaim). In this mode, we only get +the pathname of the file and the amount of data written out. + Finally, it reports the total amount of file data IO done by pids and the total IO done to the block device. So we can look at IO overheads (eg block level prefetching, filesystem metadata overhead etc). @@ -91,7 +97,9 @@ How do I run ioblame ? -------------------- ioblame -r [ I am only interested in reads ] ioblame -w [ I am only interested in writes ] -ioblame -r -w [ I am only interested in reads and writes ] +ioblame -p [ I am only interested in writepage(s) - mmap'ed writes ] +ioblame -r -w -p [ I am only interested in reads, writes and writepages ] +and finally, -v adds the PID view 1) The most common way of running ioblame is to start ioblame, then go off and launch the app(s) of interest, do interesting stuff with the @@ -102,7 +110,7 @@ dump out IO stats for the app. example : -srmohan0.mtv.corp.google.com> sh ioblame.sh -r -w +srmohan0.mtv.corp.google.com> sh ioblame.sh -r -w -p Found aosp_gobo Device OK to kill sleep when test is done ^Csignal INT received, killing streaming trace capture @@ -198,3 +206,20 @@ Date: Mon Sep 19 17:33:50 2016 -0700 Change-Id: I26bd36f933108927d6903da04d8cb42fd9c3ef3d Signed-off-by: Mohan Srinivasan + +The -w (writepages) option requires this additional patch and +currently only with f2fs. + +commit c60bc59c6af4fbdeaf7bbeaebee6b55d9e488324 (HEAD -> +android-mtk-gobo-3.18) +Author: Mohan Srinivasan +Date: Fri Sep 8 13:53:01 2017 -0700 + + Tracepoints in f2fs data writepage(s). + + Tracepoints f2fs writepage(s). This is experimental (for now). + Allowing ioblame to track + for files. + + Signed-off-by: Mohan Srinivasan + Change-Id: I4c76c6f442e0a2c5872225f8113935f9f368cc64 diff --git a/ioblame/ioblame.sh b/ioblame/ioblame.sh index ec907abb..cdd1d30c 100755 --- a/ioblame/ioblame.sh +++ b/ioblame/ioblame.sh @@ -3,6 +3,8 @@ parseoptions() { trace_reads=false trace_writes=false + trace_writepages=false + pid_view=false while [ $# -ge 1 ] do @@ -13,6 +15,12 @@ parseoptions() { -w) trace_writes=true ;; + -p) + trace_writepages=true + ;; + -v) + pid_view=true + ;; *) usage ;; @@ -22,7 +30,7 @@ parseoptions() { } usage() { - echo "Usage: $0 [-r|-w]" + echo "Usage: $0 [-r|-w|-p|-v]" exit 1 } @@ -33,7 +41,7 @@ getmodel() { echo Found $model Device case $model in - aosp_gobo) + aosp_gobo | gobo) get_go_devnames ;; marlin | sailfish) @@ -87,32 +95,32 @@ get_angler_devnames () { disk_stats_before() { if [ $bdev_set == true ]; then DISKSTATS=`adb shell 'cat /proc/diskstats' | fgrep -w $block_device ` - if [ $trace_reads == true ]; then - # Get BEFORE read stats for bdev - BEFORE_RD_IOS=`echo $DISKSTATS | awk '{ print $4 }' ` - BEFORE_RD_SECTORS=`echo $DISKSTATS | awk '{ print $6 }' ` - fi - if [ $trace_writes == true ]; then - # Get BEFORE write stats for bdev - BEFORE_WR_IOS=`echo $DISKSTATS | awk '{ print $8 }' ` - BEFORE_WR_SECTORS=`echo $DISKSTATS | awk '{ print $10 }' ` - fi + # Get BEFORE read stats for bdev + BEFORE_RD_IOS=`echo $DISKSTATS | awk '{ print $4 }' ` + BEFORE_RD_SECTORS=`echo $DISKSTATS | awk '{ print $6 }' ` + # Get BEFORE write stats for bdev + BEFORE_WR_IOS=`echo $DISKSTATS | awk '{ print $8 }' ` + BEFORE_WR_SECTORS=`echo $DISKSTATS | awk '{ print $10 }' ` + fi + if [ $f2fs_fs == 1 ] ; then + adb shell 'mount -o remount,background_gc=off /data' + F2FS_GC_SEGMENTS_BEFORE=`adb shell 'cat /sys/kernel/debug/f2fs/status' | grep segments | egrep 'data|node' | awk '{ segments += $5 } END { print segments }' ` fi } disk_stats_after() { if [ $bdev_set == true ]; then DISKSTATS=`adb shell 'cat /proc/diskstats' | fgrep -w $block_device ` - if [ $trace_reads == true ]; then - # Get AFTER read stats for bdev - AFTER_RD_IOS=`echo $DISKSTATS | awk '{ print $4 }' ` - AFTER_RD_SECTORS=`echo $DISKSTATS | awk '{ print $6 }' ` - fi - if [ $trace_writes == true ]; then - # Get BEFORE write stats for bdev - AFTER_WR_IOS=`echo $DISKSTATS | awk '{ print $8 }' ` - AFTER_WR_SECTORS=`echo $DISKSTATS | awk '{ print $10 }' ` - fi + # Get AFTER read stats for bdev + AFTER_RD_IOS=`echo $DISKSTATS | awk '{ print $4 }' ` + AFTER_RD_SECTORS=`echo $DISKSTATS | awk '{ print $6 }' ` + # Get BEFORE write stats for bdev + AFTER_WR_IOS=`echo $DISKSTATS | awk '{ print $8 }' ` + AFTER_WR_SECTORS=`echo $DISKSTATS | awk '{ print $10 }' ` + fi + if [ $f2fs_fs == 1 ] ; then + F2FS_GC_SEGMENTS_AFTER=`adb shell 'cat /sys/kernel/debug/f2fs/status' | grep segments | egrep 'data|node' | awk '{ segments += $5 } END { print segments }' ` + adb shell 'mount -o remount,background_gc=on /data' fi } @@ -135,11 +143,14 @@ disk_stats_delta_wr() { # Sectors to KB WRITE_KB=`expr $AFTER_WR_SECTORS - $BEFORE_WR_SECTORS` WRITE_KB=`expr $WRITE_KB / 2` - echo "Total (ALL) Write KB $block_device = "$WRITE_KB BLOCK_MINUS_FILE=`expr $WRITE_KB - $file_data_KB` echo "WRITE DELTA: Total Blockdev Writes KB - Total File Data Writes KB = "$BLOCK_MINUS_FILE KB echo "Total (ALL) Write IOs $block_device = "`expr $AFTER_WR_IOS - $BEFORE_WR_IOS` fi + if [ $f2fs_fs == 1 ] ; then + F2FS_GC_SEGMENTS_DELTA=`expr $F2FS_GC_SEGMENTS_AFTER - $F2FS_GC_SEGMENTS_BEFORE` + F2FS_GC_KB_DELTA=`expr $F2FS_GC_SEGMENTS_DELTA \\* 2048` + fi } # For good measure clean up traces and reenable traces @@ -155,11 +166,14 @@ clean_up_tracepoints() { adb shell 'echo 0 > /sys/kernel/debug/tracing/trace' if [ $trace_reads == true ]; then adb shell 'echo 1 > /sys/kernel/debug/tracing/events/android_fs/android_fs_dataread_start/enable' - adb shell 'echo 1 > /sys/kernel/debug/tracing/events/android_fs/android_fs_dataread_end/enable' fi if [ $trace_writes == true ]; then adb shell 'echo 1 > /sys/kernel/debug/tracing/events/android_fs/android_fs_datawrite_start/enable' - adb shell 'echo 1 > /sys/kernel/debug/tracing/events/android_fs/android_fs_datawrite_end/enable' + fi + if [ $f2fs_fs == 1 ] ; then + if [ $trace_writepages == true ]; then + adb shell 'echo 1 > /sys/kernel/debug/tracing/events/android_fs/android_fs_writepages/enable' + fi fi adb shell 'echo 1 > /sys/kernel/debug/tracing/tracing_on' } @@ -184,11 +198,14 @@ copyout_trace() { streamtrace_end if [ $trace_reads == true ]; then adb shell 'echo 0 > /sys/kernel/debug/tracing/events/android_fs/android_fs_dataread_start/enable' - adb shell 'echo 0 > /sys/kernel/debug/tracing/events/android_fs/android_fs_dataread_end/enable' fi if [ $trace_writes == true ]; then adb shell 'echo 0 > /sys/kernel/debug/tracing/events/android_fs/android_fs_datawrite_start/enable' - adb shell 'echo 0 > /sys/kernel/debug/tracing/events/android_fs/android_fs_datawrite_end/enable' + fi + if [ $f2fs_fs == 1 ] ; then + if [ $trace_writepages == true ]; then + adb shell 'echo 0 > /sys/kernel/debug/tracing/events/android_fs/android_fs_writepages/enable' + fi fi adb shell 'echo 0 > /sys/kernel/debug/tracing/tracing_on' } @@ -212,6 +229,15 @@ prep_tracefile_rd() { rm foo0 } +prep_tracefile_writepages() { + prep_tracefile_common android_fs_writepages + # Throw away everything up to and including android_fs_writepages_start: + cat $infile | sed -n -e 's/^.*android_fs_writepages //p' > foo1 + mv foo1 $infile + # At this stage, $infile should the following format : + # entry_name bytes ino +} + # Latencies not supported for Writes. 'Write End' is just when the data has been # written back to page cache. prep_tracefile_wr() { @@ -225,7 +251,7 @@ prep_tracefile_wr() { rm foo0 } -get_unique_files() { +get_unique_files_rw() { # Sort first by filename, then by pid cat $infile | sed s/,//g | sort -d -k2,2 -k8,8 > foo1 mv foo1 $infile @@ -236,6 +262,16 @@ get_unique_files() { rm foo1 } +get_unique_files_writepages() { + cat $infile | sed s/,//g | sort -d -k2,2 > foo1 + # $infile now contains lines sorted by + mv foo1 $infile + # How many unique files are there ? + cat $infile | awk '{ print $2 }' > foo1 + cat foo1 | uniq > uniq_files + rm foo1 +} + get_unique_pids_byfile() { # How many unique pids are there reading this file ? cat $1 | awk '{ print $8 }' > foo1 @@ -286,40 +322,66 @@ do_something() { } # Get the aggregate list of files read/written. For each file, break up the IOs by pid -process_files() { +process_files_rw() { read_write=$1 - get_unique_files - list_of_files=`cat uniq_files` - # $list_of_files is a list of all the files involved in IO - # + get_unique_files_rw # Loop over each file that was involved in IO # Find all the pids doing IO on that file # Aggregate the IO done by each pid on that file and dump it out - # grand_total_KB=0 - for i in $list_of_files + cp $infile tempfile + for i in `cat uniq_files` do - echo "File: $i" - total_file_KB=0 # Get just the tracepoints for this file - fgrep -w "$i" $infile > subtrace - # Get all the pids doing IO on this file - get_unique_pids_byfile subtrace - list_of_pids=`cat uniq_pids_byfile` - # $list_of_pids is a list of all the pids doing IO to file $i - for j in $list_of_pids - do - echo -n " $j $read_write: " - pid_KB=`fgrep -w "$j" subtrace | awk '{ bytes += $6 } END { print bytes }' ` - pid_KB=`expr $pid_KB / 1024` - echo "$pid_KB KB" - total_file_KB=`expr $total_file_KB + $pid_KB` - done - i_size=`tail -n1 subtrace | awk '{ if ($12 > 1024) printf "%d KB", ($12/1024); else printf "%d bytes", $12; }' ` - echo " Total $read_write: $total_file_KB KB i_size: $i_size" - grand_total_KB=`expr $grand_total_KB + $total_file_KB` + fgrep -w "$i" tempfile > subtrace + if [ -s subtrace ]; then + echo "File: $i" + total_file_KB=0 + # Remove the tracepoints we just picked up + fgrep -v -w "$i" tempfile > foo + mv foo tempfile + # Get all the pids doing IO on this file + get_unique_pids_byfile subtrace + for j in `cat uniq_pids_byfile` + do + echo -n " $j $read_write: " + pid_KB=`fgrep -w "$j" subtrace | awk '{ bytes += $6 } END { print bytes }' ` + pid_KB=`expr $pid_KB / 1024` + echo "$pid_KB KB" + total_file_KB=`expr $total_file_KB + $pid_KB` + done + i_size=`tail -n1 subtrace | awk '{ if ($12 > 1024) printf "%d KB", ($12/1024); else printf "%d bytes", $12; }' ` + echo " Total $read_write: $total_file_KB KB i_size: $i_size" + grand_total_KB=`expr $grand_total_KB + $total_file_KB` + fi done echo "Grand Total File DATA KB $read_write $grand_total_KB" + rm tempfile +} + +process_files_writepages() { + get_unique_files_writepages + # Loop over each file that was involved in IO + # Aggregate the IO done on that file and dump it out + grand_total_KB=0 + cp $infile tempfile + for i in `cat uniq_files` + do + # Get just the tracepoints for this file + fgrep -w "$i" tempfile > subtrace + if [ -s subtrace ]; then + fgrep -v -w "$i" tempfile > foo + mv foo tempfile + total_file_KB=`cat subtrace | awk '{ bytes += $4 } END { print bytes }' ` + total_file_KB=`expr $total_file_KB / 1024` + if [ $total_file_KB -gt 0 ]; then + echo "File: $i Total $read_write: $total_file_KB KB" + grand_total_KB=`expr $grand_total_KB + $total_file_KB` + fi + fi + done + echo "Grand Total File DATA KB Writepages $grand_total_KB" + rm tempfile } # Get the aggregate list of pids. For each pid, break up the IOs by file @@ -371,6 +433,19 @@ parseoptions $@ adb root && sleep 2 getmodel +found_f2fs=`adb shell 'mount | grep f2fs > /dev/null; echo $?' ` + +if [ $found_f2fs == 0 ]; then + f2fs_fs=1 +else + f2fs_fs=0 +fi + +if [ $f2fs_fs == 0 ] && [ $trace_writepages == true ]; then + echo "Writepages is only supported with f2fs, please use -r, -w" + exit 1 +fi + prep_to_do_something clean_up_tracepoints @@ -393,10 +468,12 @@ if [ $trace_reads == true ]; then prep_tracefile_rd # Get file specific stats - for each file, how many pids read that file ? echo "FILE VIEW:" - process_files Reads - # Get pid specific stats - for each pid, what files do they do IO on ? - echo "PID VIEW:" - process_pids Reads + process_files_rw Reads + if [ $pid_view == true ]; then + # Get pid specific stats - for each pid, what files do they do IO on ? + echo "PID VIEW:" + process_pids Reads + fi disk_stats_delta_rd $grand_total_KB debug_FileKB_rd=`cat $infile | awk '{ bytes += $6 } END { printf "%d", bytes/1024 }' ` @@ -410,15 +487,35 @@ if [ $trace_writes == true ]; then echo prep_tracefile_wr # Get file specific stats - for each file, how many pids read that file ? + + echo "FILE VIEW:" + process_files_rw Writes + if [ $pid_view == true ]; then + # Get pid specific stats - for each pid, what files do they do IO on ? + echo "PID VIEW:" + process_pids Writes + fi + disk_stats_delta_wr $grand_total_KB + + if [ $f2fs_fs == 1 ] ; then + echo f2fs GC_KB delta = $F2FS_GC_KB_DELTA + fi +fi + +if [ $f2fs_fs == 1 ] && [ $trace_writepages == true ] ; then + echo + echo "Writepages :" + echo "__________" + echo + prep_tracefile_writepages + # Get file specific stats - for each file, how much did we writepage ? + echo "FILE VIEW:" - process_files Writes - # Get pid specific stats - for each pid, what files do they do IO on ? - echo "PID VIEW:" - process_pids Writes + process_files_writepages + disk_stats_delta_wr $grand_total_KB - debug_FileKB_wr=`cat $infile | awk '{ bytes += $6 } END { printf "%d", bytes/1024 }' ` - echo Debug Grand Total KB WRITTEN $debug_FileKB_wr + echo f2fs GC_KB delta = $F2FS_GC_KB_DELTA fi rm -rf tracefile* uniq_* subtrace trace_saved -- cgit v1.2.3