ioblame/ioblame.sh

   1 #!/bin/sh -u
   2
   3 parseoptions() {
   4     trace_reads=false
   5     trace_writes=false
   6     trace_writepages=false
   7     pid_view=false
   8
   9     while [ $# -ge 1 ]
  10     do
  11         case $1 in
  12             -r)
  13                 trace_reads=true
  14                 ;;
  15             -w)
  16                 trace_writes=true
  17                 ;;
  18             -p)
  19                 trace_writepages=true
  20                 ;;
  21             -v)
  22                 pid_view=true
  23                 ;;
  24             *)
  25                 usage
  26                 ;;
  27             esac
  28         shift
  29     done
  30 }
  31
  32 usage() {
  33     echo "Usage: $0 [-r|-w|-p|-v]"
  34     exit 1
  35 }
  36
  37 getmodel() {
  38     model=`adb shell getprop ro.product.name`
  39     # Releases are inconsistent with various trailing characters, remove them all
  40     model=`echo $model | sed 's/[ \t\r\n]*$//' `
  41     echo Found $model Device
  42
  43     case $model in
  44         aosp_gobo | gobo)
  45             get_go_devnames
  46             ;;
  47         marlin | sailfish)
  48             get_marlin_sailfish_devnames
  49             ;;
  50         angler)
  51             get_angler_devnames
  52             ;;
  53         bullhead)
  54             get_bullhead_devnames
  55             ;;
  56         volantis | volantisg)
  57             get_volantis_devnames
  58             ;;
  59         *)
  60             echo Unknown Device $model
  61             exit 1
  62             ;;
  63     esac
  64 }
  65
  66 get_go_devnames () {
  67     # Hardcoding all of the mmcblk0 device for now
  68     block_device=mmcblk0
  69     bdev_set=true
  70 }
  71
  72 get_volantis_devnames() {
  73     bdev_set=true
  74     block_device=mmcblk0
  75 }
  76
  77 get_bullhead_devnames() {
  78     bdev_set=true
  79     block_device=mmcblk0
  80 }
  81
  82 get_marlin_sailfish_devnames() {
  83     bdev_set=true
  84     block_device=sda
  85 }
  86
  87 get_angler_devnames () {
  88     # Get the underlying bdev from the "by-name" mapping
  89     block_device=`adb shell 'find /dev/block/platform -name by-name | xargs ls -l' | grep system | awk '{ print $10 }' `
  90     # extract the last component of the absolute device pathname we got above
  91     block_device=`echo $block_device | awk 'BEGIN { FS ="/" } ; { print $4 }' | sed 's/p.*//g' `
  92     bdev_set=true
  93 }
  94
  95 disk_stats_before() {
  96     if [ $bdev_set == true ]; then
  97         DISKSTATS=`adb shell 'cat /proc/diskstats' | fgrep -w $block_device `
  98         # Get BEFORE read stats for bdev
  99         BEFORE_RD_IOS=`echo $DISKSTATS | awk '{ print $4 }' `
 100         BEFORE_RD_SECTORS=`echo $DISKSTATS | awk '{ print $6 }' `
 101         # Get BEFORE write stats for bdev
 102         BEFORE_WR_IOS=`echo $DISKSTATS | awk '{ print $8 }' `
 103         BEFORE_WR_SECTORS=`echo $DISKSTATS | awk '{ print $10 }' `
 104     fi
 105     if [ $f2fs_fs == 1 ] ; then
 106         adb shell 'mount -o remount,background_gc=off /data'
 107         F2FS_GC_SEGMENTS_BEFORE=`adb shell 'cat /sys/kernel/debug/f2fs/status' | grep segments | egrep 'data|node' | awk '{ segments += $5 } END { print segments }' `
 108     fi
 109 }
 110
 111 disk_stats_after() {
 112     if [ $bdev_set == true ]; then
 113         DISKSTATS=`adb shell 'cat /proc/diskstats' | fgrep -w $block_device `
 114         # Get AFTER read stats for bdev
 115         AFTER_RD_IOS=`echo $DISKSTATS | awk '{ print $4 }' `
 116         AFTER_RD_SECTORS=`echo $DISKSTATS | awk '{ print $6 }' `
 117         # Get BEFORE write stats for bdev
 118         AFTER_WR_IOS=`echo $DISKSTATS | awk '{ print $8 }' `
 119         AFTER_WR_SECTORS=`echo $DISKSTATS | awk '{ print $10 }' `
 120     fi
 121     if [ $f2fs_fs == 1 ] ; then
 122         F2FS_GC_SEGMENTS_AFTER=`adb shell 'cat /sys/kernel/debug/f2fs/status' | grep segments | egrep 'data|node' | awk '{ segments += $5 } END { print segments }' `
 123         adb shell 'mount -o remount,background_gc=on /data'
 124     fi
 125 }
 126
 127 disk_stats_delta_rd() {
 128     file_data_KB=$1
 129     if [ $bdev_set == true ]; then
 130         # Sectors to KB
 131         READ_KB=`expr $AFTER_RD_SECTORS - $BEFORE_RD_SECTORS`
 132         READ_KB=`expr $READ_KB / 2`
 133         echo "Total (ALL) Read KB $block_device = "$READ_KB
 134         BLOCK_MINUS_FILE=`expr $READ_KB - $file_data_KB`
 135         echo "READ DELTA: Total Blockdev Reads KB - Total File Data Reads KB = "$BLOCK_MINUS_FILE KB
 136         echo "Total (ALL) Read IOs $block_device = "`expr $AFTER_RD_IOS - $BEFORE_RD_IOS`
 137     fi
 138 }
 139
 140 disk_stats_delta_wr() {
 141     file_data_KB=$1
 142     if [ $bdev_set == true ]; then
 143         # Sectors to KB
 144         WRITE_KB=`expr $AFTER_WR_SECTORS - $BEFORE_WR_SECTORS`
 145         WRITE_KB=`expr $WRITE_KB / 2`
 146         BLOCK_MINUS_FILE=`expr $WRITE_KB - $file_data_KB`
 147         echo "WRITE DELTA: Total Blockdev Writes KB - Total File Data Writes KB = "$BLOCK_MINUS_FILE KB
 148         echo "Total (ALL) Write IOs $block_device = "`expr $AFTER_WR_IOS - $BEFORE_WR_IOS`
 149     fi
 150     if [ $f2fs_fs == 1 ] ; then
 151         F2FS_GC_SEGMENTS_DELTA=`expr $F2FS_GC_SEGMENTS_AFTER - $F2FS_GC_SEGMENTS_BEFORE`
 152         F2FS_GC_KB_DELTA=`expr $F2FS_GC_SEGMENTS_DELTA \\* 2048`
 153     fi
 154 }
 155
 156 # For good measure clean up traces and reenable traces
 157 clean_up_tracepoints() {
 158     # This is a good point to check if the Android FS tracepoints are enabled in the
 159     # kernel or not
 160     tracepoint_exists=`adb shell 'if [ -d /sys/kernel/debug/tracing/events/android_fs ]; then echo 0; else echo 1; fi' `
 161     if [ $tracepoint_exists == 1 ]; then
 162         echo "Android FS tracepoints not enabled in kernel. Exiting..."
 163         exit 1
 164     fi
 165     adb shell 'echo 0 > /sys/kernel/debug/tracing/tracing_on'
 166     adb shell 'echo 0 > /sys/kernel/debug/tracing/trace'
 167     if [ $trace_reads == true ]; then
 168         adb shell 'echo 1 > /sys/kernel/debug/tracing/events/android_fs/android_fs_dataread_start/enable'
 169     fi
 170     if [ $trace_writes == true ]; then
 171         adb shell 'echo 1 > /sys/kernel/debug/tracing/events/android_fs/android_fs_datawrite_start/enable'
 172     fi
 173     if [ $f2fs_fs == 1 ] ; then
 174         if [ $trace_writepages == true ]; then
 175             adb shell 'echo 1 > /sys/kernel/debug/tracing/events/android_fs/android_fs_writepages/enable'
 176         fi
 177     fi
 178     adb shell 'echo 1 > /sys/kernel/debug/tracing/tracing_on'
 179 }
 180
 181 # stream trace out of trace_pipe
 182 # Start this in the background ('&')
 183 streamtrace_start() {
 184     adb shell cat /sys/kernel/debug/tracing/trace_pipe > trace_saved
 185 }
 186
 187 # When signal is received, the trace_pipe reader will get killed
 188 # Call this (just to make sure anyway)
 189 streamtrace_end() {
 190     ps_line=`ps -ef | grep trace_pipe | grep adb `
 191     if [ $? == 0 ]; then
 192         echo Killing `echo $ps_line | awk '{s = ""; for (i=8; i <= NF ; i++) s = s $i " "; print s}' `
 193         kill `echo $ps_line | awk '{print $2}' `
 194     fi
 195 }
 196
 197 copyout_trace() {
 198     streamtrace_end
 199     if [ $trace_reads == true ]; then
 200         adb shell 'echo 0 > /sys/kernel/debug/tracing/events/android_fs/android_fs_dataread_start/enable'
 201     fi
 202     if [ $trace_writes == true ]; then
 203         adb shell 'echo 0 > /sys/kernel/debug/tracing/events/android_fs/android_fs_datawrite_start/enable'
 204     fi
 205     if [ $f2fs_fs == 1 ] ; then
 206         if [ $trace_writepages == true ]; then
 207             adb shell 'echo 0 > /sys/kernel/debug/tracing/events/android_fs/android_fs_writepages/enable'
 208         fi
 209     fi
 210     adb shell 'echo 0 > /sys/kernel/debug/tracing/tracing_on'
 211 }
 212
 213 prep_tracefile_common() {
 214     cp trace_saved $infile
 215     # Strip away all the extraneous stuff first
 216     fgrep $1 $infile | sed 's/^.* \[.*\] //' | sed s/://g | sed s/,//g > foo
 217     mv foo $infile
 218 }
 219
 220 prep_tracefile_rd() {
 221     prep_tracefile_common android_fs_dataread
 222     # Strip away unnecessary stuff so we can compute latencies easily
 223     fgrep android_fs_dataread_start $infile > foo0
 224     # Throw away everything upto and including android_fs_dataread:
 225     cat foo0 | sed -n -e 's/^.*android_fs_dataread_start //p' > foo1
 226     mv foo1 $infile
 227     # At this stage, $infile should the following format :
 228     # entry_name <filename> offset <offset> bytes <bytes> cmdline <cmdline> pid <pid> i_size <i_size> ino <ino>
 229     rm foo0
 230 }
 231
 232 prep_tracefile_writepages() {
 233     prep_tracefile_common android_fs_writepages
 234     # Throw away everything up to and including android_fs_writepages_start:
 235     cat $infile | sed -n -e 's/^.*android_fs_writepages //p' > foo1
 236     mv foo1 $infile
 237     # At this stage, $infile should the following format :
 238     # entry_name <filename> bytes <bytes> ino <ino>
 239 }
 240
 241 # Latencies not supported for Writes. 'Write End' is just when the data has been
 242 # written back to page cache.
 243 prep_tracefile_wr() {
 244     prep_tracefile_common android_fs_datawrite
 245     fgrep android_fs_datawrite_start $infile > foo0
 246     # Throw away everything upto and including android_fs_datawrite:
 247     cat foo0 | sed -n -e 's/^.*android_fs_datawrite_start //p' > foo1
 248     mv foo1 $infile
 249     # At this stage, $infile should the following format :
 250     # entry_name <filename> offset <offset> bytes <bytes> cmdline <cmdline> pid <pid> i_size <i_size> ino <ino>
 251     rm foo0
 252 }
 253
 254 get_unique_files_rw() {
 255     # Sort first by filename, then by pid
 256     cat $infile | sed s/,//g  | sort -d -k2,2 -k8,8 > foo1
 257     mv foo1 $infile
 258     # $infile now contains lines sorted by <filename, pid>
 259     # How many unique files are there ?
 260     cat $infile | awk '{ print $2 }' > foo1
 261     cat foo1 | uniq > uniq_files
 262     rm foo1
 263 }
 264
 265 get_unique_files_writepages() {
 266     cat $infile | sed s/,//g  | sort -d -k2,2 > foo1
 267     # $infile now contains lines sorted by <filename>
 268     mv foo1 $infile
 269     # How many unique files are there ?
 270     cat $infile | awk '{ print $2 }' > foo1
 271     cat foo1 | uniq > uniq_files
 272     rm foo1
 273 }
 274
 275 get_unique_pids_byfile() {
 276     # How many unique pids are there reading this file ?
 277     cat $1 | awk '{ print $8 }' > foo1
 278     cat foo1 | uniq > uniq_pids_byfile
 279     rm foo1
 280 }
 281
 282 get_unique_pids() {
 283     # Sort first by pid, then by filename
 284     cat $infile | sed s/,//g  | sort -d -k8,8 -k2,2 > foo1
 285     mv foo1 $infile
 286     # $infile now contains lines sorted by <pid, filename>
 287     # How many unique pids are there ?
 288     cat $infile | awk '{ print $8 }' > foo1
 289     cat foo1 | uniq > uniq_pids
 290     rm foo1
 291 }
 292
 293 get_unique_files_bypid() {
 294     # How many unique files are there read by this pid ?
 295     cat $1 | awk '{ print $2 }' > foo1
 296     cat foo1 | uniq > uniq_files_bypid
 297     rm foo1
 298 }
 299
 300 catch_sigint()
 301 {
 302     echo "signal INT received, killing streaming trace capture"
 303     streamtrace_end
 304 }
 305
 306
 307 prep_to_do_something() {
 308 #    adb shell "am force-stop com.android.chrome"
 309 #    adb shell "am force-stop com.google.android.gm"
 310     adb shell 'echo 3 > /proc/sys/vm/drop_caches'
 311     sleep 1
 312 }
 313
 314 do_something() {
 315     # Arrange things so that the first SIGINT will kill the
 316     # child process (sleep), but will return to the parent.
 317     trap 'catch_sigint'  INT
 318     echo "OK to kill sleep when test is done"
 319     sleep 30d
 320 #    adb shell "am start -W -n com.android.chrome/com.google.android.apps.chrome.Main"
 321 #    adb shell "am start -W -n com.google.android.gm/.ConversationListActivityGmail"
 322 }
 323
 324 # Get the aggregate list of files read/written. For each file, break up the IOs by pid
 325 process_files_rw() {
 326     read_write=$1
 327     get_unique_files_rw
 328     # Loop over each file that was involved in IO
 329     # Find all the pids doing IO on that file
 330     # Aggregate the IO done by each pid on that file and dump it out
 331     grand_total_KB=0
 332     cp $infile tempfile
 333     for i in `cat uniq_files`
 334     do
 335         # Get just the tracepoints for this file
 336         fgrep -w "$i" tempfile > subtrace
 337         if [ -s subtrace ]; then
 338             echo "File: $i"
 339             total_file_KB=0
 340             # Remove the tracepoints we just picked up
 341             fgrep -v -w "$i" tempfile > foo
 342             mv foo tempfile
 343             # Get all the pids doing IO on this file
 344             get_unique_pids_byfile subtrace
 345             for j in `cat uniq_pids_byfile`
 346             do
 347                 echo -n "            $j $read_write: "
 348                 pid_KB=`fgrep -w "$j" subtrace | awk '{ bytes += $6 } END { print bytes }' `
 349                 pid_KB=`expr $pid_KB / 1024`
 350                 echo "$pid_KB KB"
 351                 total_file_KB=`expr $total_file_KB + $pid_KB`
 352             done
 353             i_size=`tail -n1 subtrace  | awk '{ if ($12 > 1024) printf "%d KB", ($12/1024); else printf "%d bytes", $12; }' `
 354             echo "            Total $read_write: $total_file_KB KB i_size: $i_size"
 355             grand_total_KB=`expr $grand_total_KB + $total_file_KB`
 356         fi
 357     done
 358     echo "Grand Total File DATA KB $read_write $grand_total_KB"
 359     rm tempfile
 360 }
 361
 362 process_files_writepages() {
 363     get_unique_files_writepages
 364     # Loop over each file that was involved in IO
 365     # Aggregate the IO done on that file and dump it out
 366     grand_total_KB=0
 367     cp $infile tempfile
 368     for i in `cat uniq_files`
 369     do
 370         # Get just the tracepoints for this file
 371         fgrep -w "$i" tempfile > subtrace
 372         if [ -s subtrace ]; then
 373             fgrep -v -w "$i" tempfile > foo
 374             mv foo tempfile
 375             total_file_KB=`cat subtrace | awk '{ bytes += $4 } END { print bytes }' `
 376             total_file_KB=`expr $total_file_KB / 1024`
 377             if [ $total_file_KB -gt 0 ]; then
 378                 echo "File: $i Total $read_write: $total_file_KB KB"
 379                 grand_total_KB=`expr $grand_total_KB + $total_file_KB`
 380             fi
 381         fi
 382     done
 383     echo "Grand Total File DATA KB Writepages $grand_total_KB"
 384     rm tempfile
 385 }
 386
 387 # Get the aggregate list of pids. For each pid, break up the IOs by file
 388 process_pids() {
 389     read_write=$1
 390     get_unique_pids
 391     list_of_pids=`cat uniq_pids`
 392     # $list_of_pids is a list of all the pids involved in IO
 393     #
 394     # Loop over each pid that was involved in IO
 395     # Find all the files the pid was doing IO on
 396     # Aggregate the IO done by the pid for each file and dump it out
 397     #
 398     grand_total_KB=0
 399     for i in $list_of_pids
 400     do
 401         echo "PID: $i"
 402         total_pid_KB=0
 403         # Get just the tracepoints for this pid
 404         fgrep -w "$i" $infile > subtrace
 405         # Get all the pids doing IO on this file
 406         get_unique_files_bypid subtrace
 407         list_of_files=`cat uniq_files_bypid`
 408         # $list_of_files is a list of all the files IO'ed by this pid
 409         for j in $list_of_files
 410         do
 411             i_size=`fgrep -w "$j" subtrace | tail -n1 | awk '{ if ($12 > 1024) printf "%d KB", ($12/1024); else printf "%d bytes", $12; }' `
 412             file_KB=`fgrep -w "$j" subtrace | awk '{ bytes += $6 } END { print bytes }' `
 413             file_KB=`expr $file_KB / 1024`
 414             echo "            $j $read_write: $file_KB KB i_size: $i_size"
 415             total_pid_KB=`expr $total_pid_KB + $file_KB`
 416         done
 417         echo "            Total $read_write: $total_pid_KB KB"
 418         grand_total_KB=`expr $grand_total_KB + $total_pid_KB`
 419     done
 420     echo "Grand Total File DATA KB $read_write $grand_total_KB"
 421 }
 422
 423 # main() starts here :
 424
 425 if [ $# -lt 1 ]; then
 426     usage
 427 fi
 428
 429 bdev_set=false
 430 infile=tracefile.$$
 431
 432 parseoptions $@
 433 adb root && sleep 2
 434 getmodel
 435
 436 found_f2fs=`adb shell 'mount | grep f2fs > /dev/null; echo $?' `
 437
 438 if [ $found_f2fs == 0 ]; then
 439     f2fs_fs=1
 440 else
 441     f2fs_fs=0
 442 fi
 443
 444 if [ $f2fs_fs == 0 ] && [ $trace_writepages == true ]; then
 445     echo "Writepages is only supported with f2fs, please use -r, -w"
 446     exit 1
 447 fi
 448
 449 prep_to_do_something
 450
 451 clean_up_tracepoints
 452 disk_stats_before
 453 # Start streaming the trace into the tracefile
 454 streamtrace_start &
 455
 456 do_something
 457
 458 streamtrace_end
 459 disk_stats_after
 460
 461 copyout_trace
 462
 463 if [ $trace_reads == true ]; then
 464     echo
 465     echo "READS :"
 466     echo "_______"
 467     echo
 468     prep_tracefile_rd
 469     # Get file specific stats - for each file, how many pids read that file ?
 470     echo "FILE VIEW:"
 471     process_files_rw Reads
 472     if [ $pid_view == true ]; then
 473         # Get pid specific stats - for each pid, what files do they do IO on ?
 474         echo "PID VIEW:"
 475         process_pids Reads
 476     fi
 477     disk_stats_delta_rd $grand_total_KB
 478
 479     debug_FileKB_rd=`cat $infile | awk '{ bytes += $6 } END { printf "%d", bytes/1024 }' `
 480     echo Debug Grand Total KB READ $debug_FileKB_rd
 481 fi
 482
 483 if [ $trace_writes == true ]; then
 484     echo
 485     echo "Writes :"
 486     echo "_______"
 487     echo
 488     prep_tracefile_wr
 489     # Get file specific stats - for each file, how many pids read that file ?
 490
 491     echo "FILE VIEW:"
 492     process_files_rw Writes
 493     if [ $pid_view == true ]; then
 494         # Get pid specific stats - for each pid, what files do they do IO on ?
 495         echo "PID VIEW:"
 496         process_pids Writes
 497     fi
 498     disk_stats_delta_wr $grand_total_KB
 499
 500     if [ $f2fs_fs == 1 ] ; then
 501         echo f2fs GC_KB delta = $F2FS_GC_KB_DELTA
 502     fi
 503 fi
 504
 505 if [ $f2fs_fs == 1 ] && [ $trace_writepages == true ] ; then
 506     echo
 507     echo "Writepages :"
 508     echo "__________"
 509     echo
 510     prep_tracefile_writepages
 511     # Get file specific stats - for each file, how much did we writepage ?
 512
 513     echo "FILE VIEW:"
 514     process_files_writepages
 515
 516     disk_stats_delta_wr $grand_total_KB
 517
 518     echo f2fs GC_KB delta = $F2FS_GC_KB_DELTA
 519 fi
 520
 521 rm -rf tracefile* uniq_* subtrace trace_saved