1#!/usr/bin/env python
2#
3# Copyright (C) 2022 The Android Open Source Project
4#
5# Licensed under the Apache License, Version 2.0 (the "License");
6# you may not use this file except in compliance with the License.
7# You may obtain a copy of the License at
8#
9#      http://www.apache.org/licenses/LICENSE-2.0
10#
11# Unless required by applicable law or agreed to in writing, software
12# distributed under the License is distributed on an "AS IS" BASIS,
13# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
14# See the License for the specific language governing permissions and
15# limitations under the License.
16#
17"""Reports disk I/O usage by UID/Package, process, and file level breakdowns."""
18
19from datetime import datetime
20from collections import namedtuple
21
22import androidFsParser
23import argparse
24import collections
25import os
26import psutil
27import re
28import signal
29import subprocess
30import sys
31import threading
32import time
33import uidProcessMapper
34
35# ex) lrwxrwxrwx 1 root root   16 1970-01-06 13:22 userdata -> /dev/block/sda14
36RE_LS_BLOCK_DEVICE = r"\S+\s[0-9]+\s\S+\s\S+\s+[0-9]+\s[0-9\-]+\s[0-9]+\:[0-9]+\suserdata\s\-\>\s\/dev\/block\/(\S+)"
37
38# ex) 1002 246373245 418936352 1818624 0 0 0 0 0 0 0
39RE_UID_IO_STATS_LINE = r"([0-9]+)\s([0-9]+)\s([0-9]+)\s([0-9]+)\s([0-9]+)\s([0-9]+)\s([0-9]+)\s([0-9]+)\s([0-9]+)\s([0-9]+)\s([0-9]+)"
40
41# ex) 253       5 dm-5 3117 0 354656 3324 0 0 0 0 0 2696 3324 0 0 0 0
42RE_DISK_STATS_LINE = r"\s+([0-9]+)\s+([0-9]+)\s([a-z\-0-9]+)\s([0-9]+)\s([0-9]+)\s([0-9]+)\s([0-9]+)\s([0-9]+)\s([0-9]+)\s([0-9]+)\s([0-9]+)\s([0-9]+)\s([0-9]+)\s([0-9]+)\s([0-9]+)\s([0-9]+)\s([0-9]+)\s([0-9]+)"
43
44ADB_CMD = "adb"
45
46TEMP_TRACE_FILE = "temp_trace_file.txt"
47CARWATCHDOG_DUMP = "carwatchdog_dump.txt"
48OUTPUT_FILE = "ioblame_out.txt"
49
50WATCHDOG_BUFFER_SECS = 600
51
52DID_RECEIVE_SIGINT = False
53
54
55def signal_handler(sig, frame):
56  global DID_RECEIVE_SIGINT
57  DID_RECEIVE_SIGINT = True
58  print("Received signal interrupt")
59
60
61def init_arguments():
62  parser = argparse.ArgumentParser(
63      description="Collect and process f2fs traces")
64  parser.add_argument(
65      "-s",
66      "--serial",
67      dest="serial",
68      action="store",
69      help="Android device serial number")
70  parser.add_argument(
71      "-r",
72      "--trace_reads",
73      default=False,
74      action="store_true",
75      dest="traceReads",
76      help="Trace f2fs_dataread_start")
77  parser.add_argument(
78      "-w",
79      "--trace_writes",
80      default=False,
81      action="store_true",
82      dest="traceWrites",
83      help="Trace f2fs_datawrite_start")
84  parser.add_argument(
85      "-d",
86      "--trace_duration",
87      type=int,
88      default=3600,
89      dest="traceDuration",
90      help="Total trace duration in seconds")
91  parser.add_argument(
92      "-i",
93      "--sampling_interval",
94      type=int,
95      default=300,
96      dest="samplingInterval",
97      help="Sampling interval in seconds for CarWatchdog collection (applicable only on"
98      " automotive form-factor")
99  parser.add_argument(
100      "-o",
101      "--output_directory",
102      type=dir_path,
103      default=os.getcwd(),
104      dest="outputDir",
105      help="Output directory")
106
107  return parser.parse_args()
108
109
110def verify_arguments(args):
111  if args.serial is not None:
112    global ADB_CMD
113    ADB_CMD = "%s %s" % ("adb -s", args.serial)
114  if not args.traceReads and not args.traceWrites:
115    raise argparse.ArgumentTypeError(
116        "Must provide at least one of the --trace_reads or --trace_writes options"
117    )
118
119
120def dir_path(path):
121  if os.path.isdir(path):
122    return path
123  else:
124    raise argparse.ArgumentTypeError(
125        "{} is not a valid directory path".format(path))
126
127
128def run_adb_cmd(cmd):
129  r = subprocess.check_output(ADB_CMD + " " + cmd, shell=True)
130  return r.decode("utf-8")
131
132
133def run_adb_shell_cmd(cmd):
134  return run_adb_cmd("shell " + cmd)
135
136
137def run_adb_shell_cmd_strip_output(cmd):
138  return run_adb_cmd("shell " + cmd).strip()
139
140
141def run_adb_shell_cmd_ignore_err(cmd):
142  try:
143    r = subprocess.run(
144        ADB_CMD + " shell " + cmd, shell=True, capture_output=True)
145    return r.stdout.decode("utf-8")
146  except Exception:
147    return ""
148
149
150def run_shell_cmd(cmd):
151  return subprocess.check_output(cmd, shell=True)
152
153
154def run_bg_adb_shell_cmd(cmd):
155  return subprocess.Popen(ADB_CMD + " shell " + cmd, shell=True)
156
157
158def run_bg_shell_cmd(cmd):
159  return subprocess.Popen(cmd, shell=True)
160
161
162def get_block_dev():
163  model = run_adb_shell_cmd_strip_output(
164      "'getprop ro.product.name' | sed \'s/[ \\t\\r\\n]*$//\'")
165  print("Found %s Device" % model)
166
167  if "emu" in model:
168    return "vda"
169
170  result = run_adb_shell_cmd_strip_output(
171      "'ls -la /dev/block/bootdevice/by-name | grep userdata'")
172
173  match = re.compile(RE_LS_BLOCK_DEVICE).match(result)
174  if not match:
175    print("Unknown Device {} -- trying Pixel config".format(model))
176    return "sda"
177
178  return match.group(1)
179
180
181def prep_to_do_something():
182  run_adb_shell_cmd("'echo 3 > /proc/sys/vm/drop_caches'")
183  time.sleep(1)
184
185
186def setup_tracepoints(shouldTraceReads, shouldTraceWrites):
187  # This is a good point to check if the Android FS tracepoints are enabled in the
188  # kernel or not
189  isTraceEnabled = run_adb_shell_cmd(
190      "'if [ -d /sys/kernel/tracing/events/f2fs ]; then echo 0; else echo 1; fi'"
191  )
192
193  if isTraceEnabled == 0:
194    raise RuntimeError("Android FS tracing is not enabled")
195
196  run_adb_shell_cmd("'echo 0 > /sys/kernel/tracing/tracing_on;\
197    echo 0 > /sys/kernel/tracing/trace;\
198    echo 0 > /sys/kernel/tracing/events/ext4/enable;\
199    echo 0 > /sys/kernel/tracing/events/block/enable'")
200
201  if shouldTraceReads:
202    run_adb_shell_cmd(
203        "'echo 1 > /sys/kernel/tracing/events/f2fs/f2fs_dataread_start/enable'"
204    )
205
206  if shouldTraceWrites:
207    run_adb_shell_cmd(
208        "'echo 1 > /sys/kernel/tracing/events/f2fs/f2fs_datawrite_start/enable'"
209    )
210
211  run_adb_shell_cmd("'echo 1 > /sys/kernel/tracing/tracing_on'")
212
213
214def clear_tracing(shouldTraceReads, shouldTraceWrites):
215  if shouldTraceReads:
216    run_adb_shell_cmd(
217        "'echo 0 > /sys/kernel/tracing/events/f2fs/f2fs_dataread_start/enable'"
218    )
219
220  if shouldTraceWrites:
221    run_adb_shell_cmd(
222        "'echo 0 > /sys/kernel/tracing/events/f2fs/f2fs_datawrite_start/enable'"
223    )
224
225  run_adb_shell_cmd("'echo 0 > /sys/kernel/tracing/tracing_on'")
226
227
228def start_streaming_trace(traceFile):
229  return run_bg_adb_shell_cmd(
230      "'cat /sys/kernel/tracing/trace_pipe | grep -e f2fs_data -e f2fs_writepages'\
231      > {}".format(traceFile))
232
233
234def stop_streaming_trace(sub_proc):
235  process = psutil.Process(sub_proc.pid)
236  for child_proc in process.children(recursive=True):
237    child_proc.kill()
238  process.kill()
239
240
241class carwatchdog_collection(threading.Thread):
242
243  def __init__(self, traceDuration, samplingInterval):
244    threading.Thread.__init__(self)
245    self.traceDuration = traceDuration
246    self.samplingInterval = samplingInterval
247
248  def run(self):
249    isBootCompleted = 0
250
251    while isBootCompleted == 0:
252      isBootCompleted = run_adb_shell_cmd_strip_output(
253          "'getprop sys.boot_completed'")
254      time.sleep(1)
255
256    # Clean up previous state.
257    run_adb_shell_cmd(
258        "'dumpsys android.automotive.watchdog.ICarWatchdog/default\
259                       --stop_perf &>/dev/null'")
260
261    run_adb_shell_cmd(
262        "'dumpsys android.automotive.watchdog.ICarWatchdog/default \
263                      --start_perf --max_duration  {} --interval {}'".format(
264            self.traceDuration + WATCHDOG_BUFFER_SECS, self.samplingInterval))
265
266
267def stop_carwatchdog_collection(outputDir):
268  run_adb_shell_cmd("'dumpsys android.automotive.watchdog.ICarWatchdog/default"
269                    " --stop_perf' > {}/{}".format(outputDir, CARWATCHDOG_DUMP))
270
271
272def do_something(outpuDir, traceDuration, samplingInterval, uidProcessMapperObj):
273  buildChars = run_adb_shell_cmd_strip_output(
274      "'getprop ro.build.characteristics'")
275
276  carwatchdog_collection_thread = None
277  if "automotive" in buildChars:
278    carwatchdog_collection_thread = carwatchdog_collection(
279        traceDuration, samplingInterval)
280    carwatchdog_collection_thread.start()
281
282  for i in range(1, traceDuration):
283    if DID_RECEIVE_SIGINT:
284      break
285    now = time.process_time()
286    read_uid_process_mapping(uidProcessMapperObj)
287    taken = time.process_time() - now
288    if (taken < 1):
289      time.sleep(1 - taken)
290
291  read_uid_package_mapping(uidProcessMapperObj)
292
293  if "automotive" in buildChars:
294    carwatchdog_collection_thread.join()
295    stop_carwatchdog_collection(outpuDir)
296
297
298def read_uid_process_mapping(uidProcessMapperObj):
299  procStatusDump = run_adb_shell_cmd_ignore_err(
300      "'cat /proc/*/status /proc/*/task/*/status 2> /dev/null'")
301
302  uidProcessMapperObj.parse_proc_status_dump(procStatusDump)
303
304
305def read_uid_package_mapping(uidProcessMapperObj):
306  packageMappingDump = run_adb_shell_cmd_ignore_err(
307      "'pm list packages -a -U | sort | uniq'")
308
309  uidProcessMapperObj.parse_uid_package_dump(packageMappingDump)
310
311
312# Parser for "/proc/diskstats".
313class DiskStats:
314
315  def __init__(self, readIos, readSectors, writeIos, writeSectors):
316    self.readIos = readIos
317    self.readSectors = readSectors
318    self.writeIos = writeIos
319    self.writeSectors = writeSectors
320
321  def delta(self, other):
322    return DiskStats(self.readIos - other.readIos,
323                     self.readSectors - other.readSectors,
324                     self.writeIos - other.writeIos,
325                     self.writeSectors - other.writeSectors)
326
327  def dump(self, shouldDumpReads, shouldDumpWrites, outputFile):
328    if self.readIos is None or self.readIos is None or self.readIos is None\
329       or self.readIos is None:
330      outputFile.write("Missing disk stats")
331      return
332
333    if (shouldDumpReads):
334      outputFile.write("Total dev block reads: {} KB, IOs: {}\n".format(
335          self.readSectors / 2, self.readIos))
336
337    if (shouldDumpWrites):
338      outputFile.write("Total dev block writes: {} KB, IOs: {}\n".format(
339          self.writeSectors / 2, self.writeIos))
340
341
342def get_disk_stats(blockDev):
343  line = run_adb_shell_cmd(
344      "'cat /proc/diskstats' | fgrep -w {}".format(blockDev))
345  matcher = re.compile(RE_DISK_STATS_LINE)
346  match = matcher.match(line)
347
348  if not match:
349    return None
350
351  readIos = int(match.group(4))
352  readSectors = int(match.group(6))
353  writeIos = int(match.group(8))
354  writeSectors = int(match.group(10))
355
356  return DiskStats(readIos, readSectors, writeIos, writeSectors)
357
358
359IoBytes = namedtuple("IoBytes", "rdBytes wrBytes")
360
361
362# Parser for "/proc/uid_io/stats".
363class UidIoStats:
364
365  def __init__(self):
366    self.uidIoStatsReMatcher = re.compile(RE_UID_IO_STATS_LINE)
367    self.ioBytesByUid = {}  # Key: UID, Value: IoBytes
368    self.totalIoBytes = IoBytes(rdBytes=0, wrBytes=0)
369
370  def parse(self, dump):
371    totalRdBytes = 0
372    totalWrBytes = 0
373    for line in dump.split("\n"):
374      (uid, ioBytes) = self.parse_uid_io_bytes(line)
375      self.ioBytesByUid[uid] = ioBytes
376      totalRdBytes += ioBytes.rdBytes
377      totalWrBytes += ioBytes.wrBytes
378
379    self.totalIoBytes = IoBytes(rdBytes=totalRdBytes, wrBytes=totalWrBytes)
380
381  def parse_uid_io_bytes(self, line):
382    match = self.uidIoStatsReMatcher.match(line)
383    if not match:
384      return None
385    return (int(match.group(1)),
386            IoBytes(
387                rdBytes=(int(match.group(4)) + int(match.group(8))),
388                wrBytes=(int(match.group(5)) + int(match.group(9)))))
389
390  def delta(self, other):
391    deltaStats = UidIoStats()
392    deltaStats.totalIoBytes = IoBytes(
393        rdBytes=self.totalIoBytes.rdBytes - other.totalIoBytes.rdBytes,
394        wrBytes=self.totalIoBytes.wrBytes - other.totalIoBytes.wrBytes)
395
396    for uid, ioBytes in self.ioBytesByUid.items():
397      if uid not in other.ioBytesByUid:
398        deltaStats.ioBytesByUid[uid] = ioBytes
399        continue
400      otherIoBytes = other.ioBytesByUid[uid]
401      rdBytes = ioBytes.rdBytes - otherIoBytes.rdBytes if ioBytes.rdBytes > otherIoBytes.rdBytes\
402          else 0
403      wrBytes = ioBytes.wrBytes - otherIoBytes.wrBytes if ioBytes.wrBytes > otherIoBytes.wrBytes\
404          else 0
405      deltaStats.ioBytesByUid[uid] = IoBytes(rdBytes=rdBytes, wrBytes=wrBytes)
406    return deltaStats
407
408  def dumpTotal(self, mode, outputFile):
409    totalBytes = self.totalIoBytes.wrBytes if mode == "write" else self.totalIoBytes.rdBytes
410    outputFile.write("Total system-wide {} KB: {}\n".format(
411        mode, to_kib(totalBytes)))
412
413  def dump(self, uidProcessMapperObj, mode, func, outputFile):
414    sortedEntries = collections.OrderedDict(
415        sorted(
416            self.ioBytesByUid.items(),
417            key=lambda item: item[1].wrBytes
418            if mode == "write" else item[1].rdBytes,
419            reverse=True))
420    totalEntries = len(sortedEntries)
421    for i in range(totalEntries):
422      uid, ioBytes = sortedEntries.popitem(last=False)
423      totalBytes = ioBytes.wrBytes if mode == "write" else ioBytes.rdBytes
424      if totalBytes < androidFsParser.MIN_PID_BYTES:
425        continue
426      uidInfo = uidProcessMapperObj.get_uid_info(uid)
427      outputFile.write("{}, Total {} KB: {}\n".format(uidInfo.to_string(), mode,
428                                                      to_kib(totalBytes)))
429      func(uid)
430      outputFile.write("\n" + ("=" * 100) + "\n")
431      if i < totalEntries - 1:
432        outputFile.write("\n")
433
434
435def get_uid_io_stats():
436  uidIoStatsDump = run_adb_shell_cmd_strip_output("'cat /proc/uid_io/stats'")
437  uidIoStats = UidIoStats()
438  uidIoStats.parse(uidIoStatsDump)
439  return uidIoStats
440
441
442def to_kib(bytes):
443  return bytes / 1024
444
445
446def main(argv):
447  signal.signal(signal.SIGINT, signal_handler)
448
449  args = init_arguments()
450  verify_arguments(args)
451
452  run_adb_cmd("root")
453  buildDesc = run_adb_shell_cmd_strip_output("'getprop ro.build.description'")
454  blockDev = get_block_dev()
455
456  prep_to_do_something()
457  setup_tracepoints(args.traceReads, args.traceWrites)
458  diskStatsBefore = get_disk_stats(blockDev)
459  uidIoStatsBefore = get_uid_io_stats()
460
461  traceFile = "{}/{}".format(args.outputDir, TEMP_TRACE_FILE)
462
463  startDateTime = datetime.now()
464  proc = start_streaming_trace(traceFile)
465  print("Started trace streaming")
466
467  uidProcessMapperObj = uidProcessMapper.UidProcessMapper()
468  do_something(args.outputDir, args.traceDuration, args.samplingInterval,
469               uidProcessMapperObj)
470
471  stop_streaming_trace(proc)
472  endDateTime = datetime.now()
473  print("Stopped trace streaming")
474
475  clear_tracing(args.traceReads, args.traceWrites)
476
477  diskStatsAfter = get_disk_stats(blockDev)
478  uidIoStatsAfter = get_uid_io_stats()
479  diskStatsDelta = diskStatsAfter.delta(diskStatsBefore)
480  uidIoStatsDelta = uidIoStatsAfter.delta(uidIoStatsBefore)
481
482  print("Completed device side collection")
483
484  writeParser = androidFsParser.AndroidFsParser(androidFsParser.RE_WRITE_START,
485                                                uidProcessMapperObj)
486  readParser = androidFsParser.AndroidFsParser(androidFsParser.RE_READ_START,
487                                               uidProcessMapperObj)
488  with open(traceFile) as file:
489    for line in file:
490      if args.traceWrites and writeParser.parse(line):
491        continue
492      if args.traceReads:
493        readParser.parse(line)
494
495  outputFile = open("{}/{}".format(args.outputDir, OUTPUT_FILE), "w")
496  outputFile.write("Collection datetime: {}, Total duration: {}\n".format(
497      endDateTime, endDateTime - startDateTime))
498  outputFile.write("Build description: {}\n".format(buildDesc))
499  outputFile.write(
500      "Minimum KB per process or UID: {}, Small file KB: {}\n\n".format(
501          to_kib(androidFsParser.MIN_PID_BYTES),
502          to_kib(androidFsParser.SMALL_FILE_BYTES)))
503
504  diskStatsDelta.dump(args.traceReads, args.traceWrites, outputFile)
505
506  if args.traceWrites:
507    uidIoStatsDelta.dumpTotal("write", outputFile)
508    writeParser.dumpTotal(outputFile)
509    uidIoStatsDelta.dump(uidProcessMapperObj, "write",
510                         lambda uid: writeParser.dump(uid, outputFile),
511                         outputFile)
512
513  if args.traceWrites and args.traceReads:
514    outputFile.write("\n\n\n")
515
516  if args.traceReads:
517    uidIoStatsDelta.dumpTotal("read", outputFile)
518    readParser.dumpTotal(outputFile)
519    uidIoStatsDelta.dump(uidProcessMapperObj, "read",
520                         lambda uid: readParser.dump(uid, outputFile),
521                         outputFile)
522
523  outputFile.close()
524  run_shell_cmd("rm {}/{}".format(args.outputDir, TEMP_TRACE_FILE))
525
526
527if __name__ == "__main__":
528  main(sys.argv)
529