Move boottime I/O tools to system/extra

Bug: 65481007
Test: Build
Change-Id: I6415b210b4acae87f5e97c980a0f032cdc75161e

4 files changed, 1159 insertions, 0 deletions

diff --git a/boottime_tools/io_analysis/check_file_read.py b/boottime_tools/io_analysis/check_file_read.py
new file mode 100644
index 00000000..f7854366
--- /dev/null
+++ b/boottime_tools/io_analysis/check_file_read.py
@@ -0,0 +1,441 @@
+#!/usr/bin/env python
+#
+# Copyright (C) 2016 The Android Open Source Project
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#      http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+#
+"""Analyze ext4 trace with custom open trace"""
+import collections
+import math
+import os
+import re
+import string
+import sys
+
+DBG = False
+DBG_ISSUE = False
+
+# hard coded maps to detect partition for given device or the other way around
+# this can be different per each device. This works for marlin.
+DEVICE_TO_PARTITION = { "253,0": "/system/", "253,1": "/vendor/", "259,19": "/data/" }
+PARTITION_TO_DEVICE = {}
+for key, value in DEVICE_TO_PARTITION.iteritems():
+  PARTITION_TO_DEVICE[value] = key
+
+# init-1     [003] ....     2.703964: do_sys_open: init: open("/sys/fs/selinux/null", 131074, 0) fd = 0, inode = 22
+RE_DO_SYS_OPEN = r"""\s+\S+-([0-9]+).*\s+([0-9]+\.[0-9]+):\s+do_sys_open:\s+(\S+):\sopen..(\S+).,\s([0-9]+).\s+.+inode\s=\s([0-9]+)"""
+# init-1     [003] ...1     2.703991: ext4_ext_map_blocks_enter: dev 253,0 ino 2719 lblk 154 len 30 flags
+RE_EXT4_MA_BLOCKS_ENTER = r"""\s+(\S+)-([0-9]+).+\s+([0-9]+\.[0-9]+):\s+ext4_ext_map_blocks_enter:\s+dev\s+(\S+)\s+ino\s+([0-9]+)\s+lblk\s+([0-9]+)\s+len\s+([0-9]+)"""
+# init-1     [002] ...1     2.687205: ext4_ext_map_blocks_exit: dev 253,0 ino 8 flags  lblk 0 pblk 196608 len 1 mflags M ret 1
+RE_EXT4_MA_BLOCKS_EXIT = r"""\s+(\S+)-([0-9]+).+\s+([0-9]+\.[0-9]+):\s+ext4_ext_map_blocks_exit:\s+dev\s+(\S+)\s+ino\s+([0-9]+)\sflags.*\slblk\s+([0-9]+)\spblk\s([0-9]+)\slen\s+([0-9]+).*mflags\s(\S*)\sret\s([0-9]+)"""
+#  init-1     [002] ...1     2.887119: block_bio_remap: 8,0 R 10010384 + 8 <- (259,18) 3998944
+RE_BLOCK_BIO_REMAP = r""".+block_bio_remap:\s\d+,\d+\s\S+\s(\d+)\s\+\s\d+\s<-\s\([^\)]+\)\s(\d+)"""
+# kworker/u9:1-83    [003] d..2     2.682991: block_rq_issue: 8,0 RA 0 () 10140208 + 32 [kworker/u9:1]
+RE_BLOCK_RQ_ISSUE = r"""\s+\S+-([0-9]+).*\s+([0-9]+\.[0-9]+):\s+block_rq_issue:\s+([0-9]+)\,([0-9]+)\s+([RW]\S*)\s[0-9]+\s\([^\)]*\)\s([0-9]+)\s+\+\s+([0-9]+)\s+\[([^\]]+)\]"""
+
+EXT4_SIZE_TO_BLOCK_SIZE = 8 # ext4: 4KB, block device block size: 512B
+
+class FileAccess:
+  def __init__(self, file):
+    self.file = file
+    self.accesses = []
+    self.total_access = 0
+    self.ext4_access_size_histogram = {} #key: read size, value: occurrence
+    self.block_access_size_histogram = {}
+    self.ext4_single_block_accesses = {} # process name, occurrence
+    self.block_single_block_accesses = {} # process name, occurrence
+    self.blocks_histogram = {} # K: offset, V: read counter
+
+  def add_if_single_block(self, container, size, offset, process_name):
+    if size != 1:
+      return
+    offsets = container.get(process_name)
+    if not offsets:
+      offsets = []
+      container[process_name] = offsets
+    offsets.append(offset)
+
+  def add_access(self, time, offset, size, process_name, read_sizes):
+    self.accesses.append((time, offset, size, process_name))
+    self.total_access += size
+    self.ext4_access_size_histogram[size] = self.ext4_access_size_histogram.get(size, 0) + 1
+    read_offset = offset
+    for s in read_sizes:
+      self.block_access_size_histogram[s] = self.block_access_size_histogram.get(s, 0) + 1
+      self.add_if_single_block(self.block_single_block_accesses, s, read_offset, process_name)
+      read_offset += s
+    for i in range(size):
+      self.blocks_histogram[offset + i] = self.blocks_histogram.get(offset + i, 0) + 1
+    self.add_if_single_block(self.ext4_single_block_accesses, size, offset, process_name)
+
+  def add_merged_access(self, time, offsets, lens, process_names):
+    total_read_offsets = set() # each read can overwrap. So count only once for block level counting
+    for i in range(len(offsets)):
+      self.accesses.append((time, offsets[i], lens[i], process_names[i]))
+      self.ext4_access_size_histogram[lens[i]] = self.ext4_access_size_histogram.get(lens[i], 0) + 1
+      self.add_if_single_block(self.ext4_single_block_accesses, lens[i], offsets[i], process_names[i])
+      for j in range(len(lens)):
+        total_read_offsets.add(offsets[i] + j)
+    total_lens = len(total_read_offsets)
+    start_offset = min(total_read_offsets)
+    self.total_access += total_lens
+    self.block_access_size_histogram[total_lens] = self.block_access_size_histogram.get(total_lens, 0) \
+                                                   + 1
+    self.add_if_single_block(self.block_single_block_accesses, total_lens, start_offset, \
+                             process_names[0])
+    for s in range(total_lens):
+      self.blocks_histogram[start_offset + s] = self.blocks_histogram.get(start_offset + s, 0) + 1
+
+
+  def dump(self):
+    if len(self.ext4_access_size_histogram) > 1:
+      print "   Ext4 access size histograms:", collections.OrderedDict( \
+        sorted(self.ext4_access_size_histogram.items(), key = lambda item: item[0]))
+    if len(self.ext4_single_block_accesses) > 0 and self.total_access > 1:
+      print "   Ext4 single block accesses:", collections.OrderedDict( \
+        sorted(self.ext4_single_block_accesses.items(), key = lambda item: item[1], reverse = True))
+    if len(self.block_access_size_histogram) > 1:
+      print "   Block access size histograms:", collections.OrderedDict( \
+        sorted(self.block_access_size_histogram.items(), key = lambda item: item[0]))
+    if len(self.block_single_block_accesses) > 0 and self.total_access > 1:
+      print "   Block single block accesses:", collections.OrderedDict( \
+        sorted(self.block_single_block_accesses.items(), key = lambda item: item[1], reverse = True))
+    if self.total_access > 1:
+      sorted_blocks_histogram = sorted(self.blocks_histogram.items(), key = lambda item: item[1], \
+                                       reverse = True)
+      prints = []
+      repeating_reads_counter = 0
+      for entry in sorted_blocks_histogram:
+        offset = entry[0]
+        counter = entry[1]
+        if counter == 1:
+          break
+        prints.append(str(offset) + ":" + str(counter))
+        repeating_reads_counter += (counter - 1)
+      if len(prints) > 0:
+        print "   repeating accesses", repeating_reads_counter, " offset:count ->", ','.join(prints)
+
+class FileEvent:
+  def __init__(self, open_time, file_name, process_name, inode, flags):
+    self.file_name = file_name
+    self.inode = inode
+    self.total_open = 1
+    self.processes = []
+    self.processes.append((open_time, process_name, flags))
+    self.read = FileAccess(self)
+    self.write = FileAccess(self)
+
+
+  def add_open(self, open_time, process_name, flags):
+    self.processes.append((open_time, process_name, flags))
+    self.total_open += 1
+
+  def add_access(self, is_read, time, offset, size, process_name, read_sizes):
+    if is_read:
+      self.read.add_access(time, offset, size, process_name, read_sizes)
+    else:
+      self.write.add_access(time, offset, size, process_name, read_sizes)
+
+  def add_merged_access(self, is_read, time, offsets, lens, process_names):
+    if is_read:
+      self.read.add_merged_access(time, offsets, lens, process_names)
+    else:
+      self.write.add_merged_access(time, offsets, lens, process_names)
+
+  def dump(self, name_to_pid_map):
+    print " ***filename %s, total reads %d, total writes %d, total open %d inode %s" \
+          % (self.file_name, self.read.total_access, self.write.total_access, self.total_open,\
+             self.inode)
+    process_names = []
+    for opener in self.processes:
+      process_names.append(opener[1] + "-" + name_to_pid_map.get(opener[1], '?') + " t:" + \
+                           str(opener[0]) + " flags:" + opener[2])
+    print "  Processes opened this file:", ','.join(process_names)
+    if self.read.total_access > 0:
+      print "  ****Reads:"
+      self.read.dump()
+    if self.write.total_access > 0:
+      print "  ****Writes:"
+      self.write.dump()
+
+  def dump_short(self):
+    print "    filename %s, total reads %d, total writes %d" % (self.file_name,
+      self.read.total_access, self.write.total_access)
+
+class PendingAccess:
+  def __init__(self, process_name, pid, time, dev, inode, lblk, pblk, len, fevent):
+    self.process_name = process_name
+    self.pid = pid
+    self.time = time
+    self.dev = dev
+    self.inode = inode
+    self.lblk = lblk
+    self.pblk = pblk
+    self.blk_len = len * EXT4_SIZE_TO_BLOCK_SIZE
+    self.len = len
+    self.fevent = fevent
+    self.pending_accesses = set()
+    for i in range(len):
+      self.pending_accesses.add(i)
+    self.access_sizes = [] # valid read for this file in block dev level.
+    self.block_access_counter = 0
+
+  def get_valid_access(self, block_offset, block_len):
+    ext4_offset = block_offset / EXT4_SIZE_TO_BLOCK_SIZE
+    if ext4_offset > self.len:
+      return 0, 0
+    ext4_len = block_len / EXT4_SIZE_TO_BLOCK_SIZE
+    if (ext4_offset + ext4_len) > self.len:
+      ext4_len = self.len - ext4_offset
+    return ext4_offset, ext4_len
+
+  def queue_block_access(self, ext4_offset, ext4_len):
+    if ext4_len <= 0:
+      return
+    self.block_access_counter += 1
+    ext4_blocks_accessed = 0
+    for i in range(ext4_len):
+      ext4_block_i = i + ext4_offset
+      if ext4_block_i in self.pending_accesses:
+        ext4_blocks_accessed += 1
+        self.pending_accesses.remove(ext4_block_i)
+    if ext4_blocks_accessed > 0:
+      self.access_sizes.append(ext4_blocks_accessed)
+
+  def handle_req_complete(self, time, is_read):
+    self.fevent.add_access(is_read, self.time, self.lblk, self.len, self.process_name,\
+                           self.access_sizes)
+
+  def handle_merged_req(self, time, offsets, lens, names, is_read):
+    self.fevent.add_merged_access(is_read, time, offsets, lens, names)
+
+  def is_req_complete(self):
+    return len(self.pending_accesses) == 0
+
+  def is_req_started(self):
+    return self.len is not len(self.pending_accesses)
+
+class Trace:
+  def __init__(self):
+    self.files_per_device = {} # key: device, value: { key: inode, value; FileEvent }
+    self.re_open = re.compile(RE_DO_SYS_OPEN)
+    self.re_ext4_access = re.compile(RE_EXT4_MA_BLOCKS_EXIT)
+    self.re_bio_remap = re.compile(RE_BLOCK_BIO_REMAP)
+    self.re_block_issue = re.compile(RE_BLOCK_RQ_ISSUE)
+    # req from ext4 that has not gone down to block level yet, K:block address,
+    #  V: list of PendingRead
+    self.pending_accesses = {}
+    self.remap = {}
+    self.process_names = {} # K: PID, V : name
+
+  def handle_line(self, line):
+    match = self.re_open.match(line)
+    if match:
+      self.handle_open(match)
+      return
+    match = self.re_ext4_access.match(line)
+    if match:
+      self.handle_ext4_block_exit(match)
+      return
+    match = self.re_bio_remap.match(line)
+    if match:
+      self.handle_bio_remap(match)
+      return
+    match = self.re_block_issue.match(line)
+    if match:
+      self.handle_block_issue(match)
+      return
+
+  def handle_open(self, match):
+    pid = int(match.group(1))
+    time = match.group(2)
+    process_name = match.group(3)
+    file_name = match.group(4)
+    flag = match.group(5)
+    inode = int(match.group(6))
+    dev_name = None
+    self.process_names[pid] = process_name
+    #print "open", pid, process_name, file_name, inode
+    for p in PARTITION_TO_DEVICE:
+      if file_name.startswith(p):
+        dev_name = PARTITION_TO_DEVICE[p]
+    if not dev_name:
+      if DBG:
+        print "Ignore open for file", file_name
+      return
+    files = self.files_per_device[dev_name]
+    fevent = files.get(inode)
+    if not fevent:
+      fevent = FileEvent(time, file_name, process_name, inode, flag)
+      files[inode] = fevent
+    else:
+      fevent.add_open(time, process_name, flag)
+
+  def handle_ext4_block_exit(self, match):
+    process_name = match.group(1)
+    pid = int(match.group(2))
+    time = float(match.group(3))
+    dev = match.group(4)
+    inode = int(match.group(5))
+    lblk = int(match.group(6))
+    pblk = int(match.group(7)) * EXT4_SIZE_TO_BLOCK_SIZE # address in ext4 blocks, ...
+    l = int(match.group(8))
+    mflags = match.group(9)
+    ret = int(match.group(10))
+    if ret <= 0: # no block access
+      return
+    process_name = self.process_names.get(pid, process_name)
+    if process_name == '<...>':
+      process_name = "pid-" + str(pid)
+    if DBG_ISSUE:
+      print "ext4", pblk, l, inode, process_name
+    files = self.files_per_device.get(dev)
+    if not files:
+      if DEVICE_TO_PARTITION.get(dev):
+        files = {}
+        self.files_per_device[dev] = files
+      else:
+        if DBG:
+          print "access ignored for device", dev
+        return
+    fevent = files.get(inode)
+    if not fevent:
+      if DBG:
+        print 'no open for device %s with inode %s' % (dev, inode)
+      fevent = FileEvent(time, "unknown", process_name, inode, "-")
+      files[inode] = fevent
+    pending_access = PendingAccess(process_name, pid, time, dev, inode, lblk, pblk, l,\
+                                   fevent)
+    access_list = self.pending_accesses.get(pblk, [])
+    access_list.append(pending_access)
+    self.pending_accesses[pblk] = access_list
+
+  def handle_bio_remap(self, match):
+    new_addr = int(match.group(1))
+    old_addr = int(match.group(2))
+    self.remap[new_addr] = old_addr
+    if DBG_ISSUE:
+      print "remap", new_addr, old_addr
+
+  def handle_block_issue(self, match):
+    pid = int(match.group(1))
+    time = float(match.group(2))
+    dev_major = match.group(3)
+    dev_minor = match.group(4)
+    access = match.group(5)
+    new_address = int(match.group(6))
+    l = int(match.group(7))
+    name = match.group(8)
+    name = self.process_names.get(pid, name)
+    if name == '<...>':
+      name = "pid-" + str(pid)
+    is_read = not 'W' in access
+    accesses_per_inodes = {} # K:inodes, V: list of two entries, 1st: offsets, 2nd: length
+    addrs_to_remove = []
+    completed_reqs = []
+    address = self.remap.get(new_address, new_address)
+    if DBG_ISSUE:
+      print "issue", address, l, is_read, access
+    for access_addr, access_list in self.pending_accesses.iteritems():
+      if (address >= access_addr) and (address + l) > access_addr:
+        reqs_to_remove = []
+        for pending in access_list:
+          offset, valid_access_size = pending.get_valid_access(address - access_addr, l)
+          if valid_access_size > 0:
+            if pending.is_req_started(): # spread across multiple reads. complete alone
+              pending.queue_block_access(offset, valid_access_size)
+              if pending.is_req_complete():
+                pending.handle_req_complete(time, is_read)
+                reqs_to_remove.append(pending)
+            else: # possible multiple reads completed in this read. complete them together
+              pending.queue_block_access(offset, valid_access_size)
+              if pending.is_req_complete():
+                reads = accesses_per_inodes.get(pending.inode, [[], [], []])
+                reads[0].append(offset + pending.lblk)
+                reads[1].append(valid_access_size)
+                reads[2].append(pending.process_name)
+                accesses_per_inodes[pending.inode] = reads
+                completed_reqs.append(pending)
+                reqs_to_remove.append(pending)
+        for to_remove in reqs_to_remove:
+          access_list.remove(to_remove)
+        if len(access_list) == 0:
+          addrs_to_remove.append(access_addr)
+    for addr in addrs_to_remove:
+      del self.pending_accesses[addr]
+    for pending in completed_reqs: # these will be reported as batch
+      accesses = accesses_per_inodes.get(pending.inode)
+      if not accesses: # merged one already dispatched
+        continue
+      if len(accesses[0]) == 1:
+        pending.handle_req_complete(time, is_read)
+      else: #merged
+        pending.handle_merged_req(time, accesses[0], accesses[1], accesses[2], is_read)
+        del accesses_per_inodes[pending.inode]
+
+  def dump_partition(self, partition_name, files):
+    name_to_pid_map = {}
+    for pid, name in self.process_names.iteritems():
+      name_to_pid_map[name] = str(pid)
+    print "**Dump partition:", partition_name, "total number of files:", len(files)
+    total_reads = 0
+    total_writes = 0
+    files_sorted_by_read = files.values()
+    files_sorted_by_read.sort(key=lambda f : f.read.total_access, reverse = True)
+    files_sorted_by_write = files.values()
+    files_sorted_by_write.sort(key=lambda f : f.write.total_access, reverse = True)
+    print " Top 10 readers:"
+    for i in range(min(10, len(files_sorted_by_read))):
+      files_sorted_by_read[i].dump_short()
+    print " Top 10 writers:"
+    for i in range(min(10, len(files_sorted_by_write))):
+      files_sorted_by_write[i].dump_short()
+    for f in files_sorted_by_read:
+      f.dump(name_to_pid_map)
+      total_reads += f.read.total_access
+      total_writes += f.write.total_access
+    print " Total reads:", total_reads, " total writes:", total_writes
+    return total_reads, total_writes, len(files)
+
+
+  def dump(self):
+    print "*Dump R/W per each partition"
+    total_reads = 0
+    total_writes = 0
+    summaries = []
+    for d in self.files_per_device:
+      reads, writes, num_files = self.dump_partition(DEVICE_TO_PARTITION[d], \
+        self.files_per_device[d])
+      total_reads += reads
+      total_writes += writes
+      summaries.append((DEVICE_TO_PARTITION[d], reads, writes, num_files))
+    print "*Summary*"
+    print "Total blocks read", total_reads
+    print "Total blocks wrote", total_writes
+    print "Partition total_reads total_writes num_files"
+    for s in summaries:
+      print s[0], s[1], s[2], s[3]
+
+def main(argv):
+  if (len(argv) < 2):
+    print "check_fule_read.py filename"
+    return
+  filename = argv[1]
+  trace = Trace()
+  with open(filename) as f:
+    for l in f:
+      trace.handle_line(l)
+  trace.dump()
+
+if __name__ == '__main__':
+  main(sys.argv)
diff --git a/boottime_tools/io_analysis/check_io_trace.py b/boottime_tools/io_analysis/check_io_trace.py
new file mode 100644
index 00000000..bc26c467
--- /dev/null
+++ b/boottime_tools/io_analysis/check_io_trace.py
@@ -0,0 +1,193 @@
+#!/usr/bin/env python
+#
+# Copyright (C) 2016 The Android Open Source Project
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#      http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+#
+"""Analyze block trace"""
+
+import collections
+import os
+import re
+import string
+import sys
+
+RE_BLOCK = r'.+\s+(block[a-z_]+):\s+'
+RE_BLOCK_BIO_QUEUE = r'.+\s+([0-9]+\.[0-9]+):\s+block_bio_queue:\s+([0-9]+)\,([0-9]+)\s+([RW]\S*)\s+([0-9]+)\s+\+\s+([0-9]+)\s+\[([^\]]+)'
+
+# dev_num = major * MULTIPLIER + minor
+DEV_MAJOR_MULTIPLIER = 1000
+
+# dm access is remapped to disk access. So account differently
+DM_MAJOR = 253
+
+class RwEvent:
+  def __init__(self, block_num, start_time, size):
+    self.block_num = block_num
+    self.start_time = start_time
+    self.size = size
+    self.latency = 0
+  def set_latency(self, latency):
+    self.latency = latency
+
+def get_string_pos(strings, string_to_find):
+  for i, s in enumerate(strings):
+    if s == string_to_find:
+      return i
+  return -1
+
+
+class Trace:
+  def __init__(self, process):
+    self.process = process
+    self.reads = [] #(start time, RwEvent)
+    self.writes = [] #(start time, RwEvent)
+    self.recent_reads = {} # K:
+    self.total_latency = 0
+    self.total_reads = 0
+    self.total_writes = 0
+    self.total_dm_reads = {} #K: devnum, V: blocks
+    self.total_dm_writes = {}
+    self.re_block_queue = re.compile(RE_BLOCK_BIO_QUEUE)
+    self.processes = set()
+    if process[-1] == '*':
+      print "Process name starts with", process[:-1]
+      self.process_name_is_prefix = True
+    else:
+      print "Process name", process
+      self.process_name_is_prefix = False
+
+  def parse_bio_queue(self, l):
+    match = self.re_block_queue.match(l)
+    if not match:
+      return
+    start_time = int(float(match.group(1))*1000000) #us
+    major = int(match.group(2))
+    minor =  int(match.group(3))
+    operation =  match.group(4)
+    block_num = int(match.group(5))
+    size = int(match.group(6))
+    process = match.group(7)
+    if self.process_name_is_prefix:
+      if not process.startswith(self.process[:-1]):
+        return
+      self.processes.add(process)
+    else:
+      if process != self.process:
+        return
+    if major == DM_MAJOR:
+        devNum = major * DEV_MAJOR_MULTIPLIER + minor;
+        if operation[0] == 'R':
+          if devNum not in self.total_dm_reads:
+            self.total_dm_reads[devNum] = 0
+          self.total_dm_reads[devNum] += size
+        elif operation[0] == 'W':
+          if devNum not in self.total_dm_writes:
+            self.total_dm_writes[devNum] = 0
+          self.total_dm_writes[devNum] += size
+        return
+    event = RwEvent(block_num, start_time, size)
+    if operation[0] == 'R':
+      self.reads.append((start_time, event))
+      self.recent_reads[block_num] = event
+      self.total_reads += size
+    elif operation[0] == 'W':
+      self.writes.append((start_time, event))
+      self.total_writes += size
+
+  def parse_rq_complete(self, l):
+    words = string.split(l)
+    cmd_pos = get_string_pos(words, "block_rq_complete:")
+    if cmd_pos == -1:
+      cmd_pos = get_string_pos(words, "block_bio_complete:")
+    block_num = int(words[-4])
+    event = self.recent_reads.get(block_num)
+    if not event:
+      return
+    operation = words[cmd_pos + 2]
+    if not operation.startswith("R"):
+      return
+    end_time = int(float(words[cmd_pos - 1][:-1])*1000000) #us
+    latency = end_time - event.start_time
+    if latency > 20000:
+      print "very bad latency:", latency, l
+      print "start time,", event.start_time
+    event.set_latency(latency)
+    del self.recent_reads[block_num]
+    self.total_latency += latency
+
+  def parse_block_trace(self, l, match):
+    try:
+      cmd = match.group(1)
+      if cmd == "block_bio_queue":
+        self.parse_bio_queue(l)
+      elif cmd == "block_rq_complete" or cmd == "block_bio_complete":
+        self.parse_rq_complete(l)
+    except ValueError:
+      print "cannot parse:", l
+      raise
+
+  def dump(self):
+    if self.process_name_is_prefix:
+      print "Processes:", self.processes
+    print "total read blocks,", self.total_reads
+    print "total write blocks,", self.total_writes
+    if len(self.reads) > 0:
+      total_read_time = self.reads[-1][0] + self.reads[-1][1].latency - self.reads[0][0]
+    else:
+      total_read_time = 0
+    print "Total DM R"
+    for dev,size in self.total_dm_reads.items():
+      print dev, size
+    print "Total DM W"
+    for dev,size in self.total_dm_writes.items():
+      print dev, size
+    print "total read time,",total_read_time
+    read_size_histogram = {}
+    latency_per_read_size = {}
+    for (time, event) in self.reads:
+      if not read_size_histogram.get(event.size):
+        read_size_histogram[event.size] = 0
+      if not latency_per_read_size.get(event.size):
+        latency_per_read_size[event.size] = [ 0, 0] # num events, total latency
+      read_size_histogram[event.size] = read_size_histogram[event.size] + 1
+      latency_sum = latency_per_read_size[event.size]
+      latency_sum[0] += 1
+      latency_sum[1] += event.latency
+    read_size_histogram = collections.OrderedDict(sorted(read_size_histogram.items()))
+    print "read histogram"
+    for k,v in read_size_histogram.iteritems():
+      print k, ',', v
+    print "latency per read size"
+    latency_per_read_size = collections.OrderedDict(sorted(latency_per_read_size.items()))
+    for k,v in latency_per_read_size.iteritems():
+      if v[0] != 0:
+        print k, ',', v[1] / v[0], v[0], v[1]
+
+def main(argv):
+  if (len(argv) < 3):
+    print "check_io_trace.py processname filename"
+    return
+  keyword = argv[1]
+  filename = argv[2]
+  trace = Trace(keyword)
+  prog = re.compile(RE_BLOCK)
+  with open(filename) as f:
+    for l in f:
+      result = prog.match(l)
+      if result:
+        trace.parse_block_trace(l, result)
+  trace.dump()
+
+if __name__ == '__main__':
+  main(sys.argv)
diff --git a/boottime_tools/io_analysis/check_io_trace_all.py b/boottime_tools/io_analysis/check_io_trace_all.py
new file mode 100644
index 00000000..8ea466d7
--- /dev/null
+++ b/boottime_tools/io_analysis/check_io_trace_all.py
@@ -0,0 +1,386 @@
+#!/usr/bin/env python
+#
+# Copyright (C) 2016 The Android Open Source Project
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#      http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+#
+"""Analyze block trace"""
+
+import collections
+import os
+import re
+import string
+import sys
+
+# ex) <...>-52    [001] ...1     1.362574: block_bio_queue: 8,16 R 0 + 8 [kworker/u8:1]
+RE_BLOCK = r'.+-([0-9]+).*\s+([0-9]+\.[0-9]+):\s+block_bio_queue:\s+([0-9]+)\,([0-9]+)\s(\S+)\s+([0-9]+)\s+\+\s+([0-9]+)\s+\[([^\]]+)'
+# ex)  <...>-453   [001] d..4     3.181854: sched_blocked_reason: pid=471 iowait=1 caller=__wait_on_buffer+0x24/0x2c
+RE_SCHED_BLOCKED_READSON = r'.+-([0-9]+)\s+\[([0-9]+)\]\s.*\s+([0-9]+\.[0-9]+):\s+sched_blocked_reason:\spid=([0-9]+)\siowait=([01])\scaller=(\S+)'
+# ex) <idle>-0     [000] d..3     3.181864: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=ueventd next_pid=471 next_prio=120
+RE_SCHED_SWITCH = r'.+-([0-9]+)\s+\[([0-9]+)\]\s.*\s+([0-9]+\.[0-9]+):\s+sched_switch:\sprev_comm=(.+)\sprev_pid=([0-9]+)\sprev_prio=([0-9]+)\sprev_state=(\S+).*next_comm=(.+)\snext_pid=([0-9]+)\snext_prio=([0-9]+)'
+
+# dev_num = major * MULTIPLIER + minor
+DEV_MAJOR_MULTIPLIER = 1000
+
+# dm access is remapped to disk access. So account differently
+DM_MAJOR = 253
+
+MAX_PROCESS_DUMP = 10
+
+class RwEvent:
+  def __init__(self, block_num, start_time, size):
+    self.block_num = block_num
+    self.start_time = start_time
+    self.size = size
+
+def get_string_pos(strings, string_to_find):
+  for i, s in enumerate(strings):
+    if s == string_to_find:
+      return i
+  return -1
+
+class ProcessData:
+  def __init__(self, name):
+    self.name = name
+    self.reads = {} # k : dev_num, v : [] of reads
+    self.per_device_total_reads = {}
+    self.writes = {}
+    self.per_device_total_writes = {}
+    self.total_reads = 0
+    self.total_writes = 0
+    self.total_dm_reads = 0
+    self.total_dm_writes = 0
+
+
+  def add_read_event(self, major, minor, event):
+    devNum = major * DEV_MAJOR_MULTIPLIER + minor;
+    events = self.reads.get(devNum)
+    if not events:
+      events = []
+      self.reads[devNum] = events
+      self.per_device_total_reads[devNum] = 0
+    events.append(event)
+    self.total_reads += event.size
+    self.per_device_total_reads[devNum] += event.size
+
+  def add_write_event(self, major, minor, event):
+    devNum = major * DEV_MAJOR_MULTIPLIER + minor;
+    events = self.writes.get(devNum)
+    if not events:
+      events = []
+      self.writes[devNum] = events
+      self.per_device_total_writes[devNum] = 0
+    events.append(event)
+    self.total_writes += event.size
+    self.per_device_total_writes[devNum] += event.size
+
+  def add_dm_read(self, size):
+    self.total_dm_reads += size
+
+  def add_dm_write(self, size):
+    self.total_dm_writes += size
+
+  def dump(self):
+    print "Process,", self.name
+    print " total reads,", self.total_reads
+    print " total writes,", self.total_writes
+    print " total dm reads,", self.total_dm_reads
+    print " total dm writes,", self.total_dm_writes
+    print " R per device"
+    sorted_r = collections.OrderedDict(sorted(self.per_device_total_reads.items(), \
+      key = lambda item: item[1], reverse = True))
+    for i in range(len(sorted_r)):
+      dev = sorted_r.popitem(last=False)
+      print " ", dev[0],dev[1]
+
+    print " W per device"
+    sorted_w = collections.OrderedDict(sorted(self.per_device_total_writes.items(), \
+      key = lambda item: item[1], reverse = True))
+    for i in range(len(sorted_w)):
+      dev = sorted_w.popitem(last=False)
+      print " ", dev[0],dev[1]
+
+class IoTrace:
+
+  def __init__(self):
+    self.ios = {} #K: process name, v:ProcessData
+    self.total_reads = 0
+    self.total_writes = 0
+    self.total_reads_per_device = {} #K: block num, V: total blocks
+    self.total_writes_per_device = {}
+    self.total_dm_reads = {} #K: devnum, V: blocks
+    self.total_dm_writes = {}
+    self.re_block = re.compile(RE_BLOCK)
+
+  def parse(self, l):
+    match = self.re_block.match(l)
+    if not match:
+      return False
+    try:
+      self.do_parse_bio_queue(l, match)
+    except ValueError:
+      print "cannot parse:", l
+      raise
+    return True
+
+  def do_parse_bio_queue(self, l, match):
+    pid = match.group(1)
+    start_time = float(match.group(2))*1000 #ms
+    major = int(match.group(3))
+    minor =  int(match.group(4))
+    devNum = major * DEV_MAJOR_MULTIPLIER + minor;
+    operation =  match.group(5)
+    block_num = int(match.group(6))
+    size = int(match.group(7))
+    process = match.group(8) + "-" + pid
+    event = RwEvent(block_num, start_time, size)
+    io = self.ios.get(process)
+    if not io:
+      io = ProcessData(process)
+      self.ios[process] = io
+    if major == DM_MAJOR:
+      devNum = major * DEV_MAJOR_MULTIPLIER + minor;
+      if 'R' in operation[0]:
+        if devNum not in self.total_dm_reads:
+          self.total_dm_reads[devNum] = 0
+        self.total_dm_reads[devNum] += size
+        io.add_dm_read(size)
+      elif 'W' in operation[0]:
+        if devNum not in self.total_dm_writes:
+          self.total_dm_writes[devNum] = 0
+        self.total_dm_writes[devNum] += size
+        io.add_dm_write(size)
+      return
+    if 'R' in operation[0]:
+      io.add_read_event(major, minor, event)
+      self.total_reads += size
+      per_device = self.total_reads_per_device.get(devNum)
+      if not per_device:
+        self.total_reads_per_device[devNum] = 0
+      self.total_reads_per_device[devNum] += size
+    elif 'W' in operation[0]:
+      io.add_write_event(major, minor, event)
+      self.total_writes += size
+      per_device = self.total_writes_per_device.get(devNum)
+      if not per_device:
+        self.total_writes_per_device[devNum] = 0
+      self.total_writes_per_device[devNum] += size
+
+  def dump(self):
+    print "total read blocks,", self.total_reads
+    print "total write blocks,", self.total_writes
+    print "Total DM R"
+    for dev,size in self.total_dm_reads.items():
+      print dev, size
+    print "Total DM W"
+    for dev,size in self.total_dm_writes.items():
+      print dev, size
+    print "**Process total R/W"
+    sorted_by_total_rw = collections.OrderedDict(sorted(self.ios.items(), \
+      key = lambda item: item[1].total_reads + item[1].total_writes, reverse = True))
+    for i in range(MAX_PROCESS_DUMP):
+      process = sorted_by_total_rw.popitem(last=False)
+      if not process:
+        break
+      process[1].dump()
+
+    print "**Process total W"
+    sorted_by_total_w = collections.OrderedDict(sorted(self.ios.items(), \
+      key = lambda item: item[1].total_writes, reverse = True))
+    for i in range(5):
+      process = sorted_by_total_w.popitem(last=False)
+      if not process:
+        break
+      process[1].dump()
+
+    print "**Device total R"
+    sorted_by_total_r = collections.OrderedDict(sorted(self.total_reads_per_device.items(), \
+      key = lambda item: item[1], reverse = True))
+    for i in range(len(sorted_by_total_r)):
+      dev = sorted_by_total_r.popitem(last=False)
+      print dev[0],dev[1]
+
+    print "**Device total W"
+    sorted_by_total_w = collections.OrderedDict(sorted(self.total_writes_per_device.items(), \
+      key = lambda item: item[1], reverse = True))
+    for i in range(len(sorted_by_total_w)):
+      dev = sorted_by_total_w.popitem(last=False)
+      print dev[0],dev[1]
+
+class SchedProcess:
+  def __init__(self, pid):
+    self.pid = pid
+    self.name = "unknown"
+    self.total_execution_time = 0.0
+    self.total_io_wait_time = 0.0
+    self.total_other_wait_time = 0.0
+    self.waiting_calls = {} # k: waiting_call, v : waiting counter
+    self.io_waiting_call_times = {} # k: waiting_call, v: total wait time
+    self.in_iowait = False
+    self.last_waiting_call = None
+    self.last_switch_out_time = 0.0
+    self.last_switch_in_time = 0.0
+    self.last_core = -1
+    self.execution_time_per_core = {} # k: core, v : time
+    self.io_latency_histograms = {} # k : delay in ms, v : count
+
+  def handle_reason(self, current_time, iowait, waiting_call):
+    #if self.pid == 1232:
+    #  print current_time, iowait, waiting_call
+    if iowait == 1:
+      self.in_iowait = True
+    self.last_waiting_call = waiting_call
+    call_counter = self.waiting_calls.get(waiting_call, 0)
+    call_counter += 1
+    self.waiting_calls[waiting_call] = call_counter
+
+  def handle_switch_out(self, current_time, out_state, priority, name, core):
+    #if self.pid == 1232:
+    #  print "out", current_time, out_state
+    if self.name != name:
+      self.name = name
+    self.last_switch_out_time = current_time
+    if self.last_switch_in_time == 0.0: # switch in not recorded. ignore this one
+      return
+    execution_time = current_time - self.last_switch_in_time
+    self.total_execution_time += execution_time
+    core_execution_time = self.execution_time_per_core.get(core, 0.0)
+    core_execution_time += execution_time
+    self.execution_time_per_core[core] = core_execution_time
+
+  def handle_switch_in(self, current_time, priority, name, core):
+    #if self.pid == 1232:
+    #  print "in", current_time, self.in_iowait
+    if self.name != name:
+      self.name = name
+    self.last_switch_in_time = current_time
+    if self.last_switch_out_time == 0.0: # in without out, probably 1st
+      self.in_iowait = False
+      return
+    wait_time = current_time - self.last_switch_out_time
+    if self.in_iowait:
+      self.total_io_wait_time += wait_time
+      total_waiting_call_time = self.io_waiting_call_times.get(self.last_waiting_call, 0.0)
+      total_waiting_call_time += wait_time
+      self.io_waiting_call_times[self.last_waiting_call] = total_waiting_call_time
+      wait_time_ms = int(wait_time*10) / 10.0 # resolution up to 0.1 ms
+      histogram_count = self.io_latency_histograms.get(wait_time_ms, 0)
+      histogram_count += 1
+      self.io_latency_histograms[wait_time_ms] = histogram_count
+    else:
+      self.total_other_wait_time += wait_time
+    self.in_iowait = False
+
+
+  def dump(self):
+    print "PID:", self.pid, " name:", self.name
+    print " total execution time:", self.total_execution_time,\
+      " io wait:", self.total_io_wait_time, " other wait:", self.total_other_wait_time
+    sorted_data = collections.OrderedDict(sorted(self.execution_time_per_core.items(), \
+      key = lambda item: item[0], reverse = False))
+    print " Core execution:", sorted_data
+    sorted_data = collections.OrderedDict(sorted(self.waiting_calls.items(), \
+      key = lambda item: item[1], reverse = True))
+    print " Wait calls:", sorted_data
+    sorted_data = collections.OrderedDict(sorted(self.io_waiting_call_times.items(), \
+      key = lambda item: item[1], reverse = True))
+    print " IO Wait time per wait calls:", sorted_data
+    sorted_data = collections.OrderedDict(sorted(self.io_latency_histograms.items(), \
+      key = lambda item: item[0], reverse = False))
+    print " Wait time histogram:", sorted_data
+
+class SchedTrace:
+  def __init__(self):
+    self.re_switch = re.compile(RE_SCHED_SWITCH)
+    self.re_reason = re.compile(RE_SCHED_BLOCKED_READSON)
+    self.processes = {} # key: pid, v : SchedProcess
+
+  def parse(self, l):
+    checked_reason = False
+    match = self.re_switch.match(l)
+    if not match:
+      match = self.re_reason.match(l)
+      checked_reason = True
+    if not match:
+      return False
+    try:
+      if checked_reason:
+        self.do_handle_reason(l, match)
+      else:
+        self.do_handle_switch(l, match)
+    except ValueError:
+      print "cannot parse:", l
+      raise
+    return True
+
+  def do_handle_switch(self, l, match):
+    current_pid = int(match.group(1))
+    cpu_core = int(match.group(2))
+    current_time = float(match.group(3))*1000 #ms
+    out_name = match.group(4)
+    out_pid = int(match.group(5))
+    out_prio = int(match.group(6))
+    out_state = match.group(7)
+    in_name = match.group(8)
+    in_pid = int(match.group(9))
+    in_prio = int(match.group(10))
+    out_process = self.processes.get(out_pid)
+    if not out_process:
+      out_process = SchedProcess(out_pid)
+      self.processes[out_pid] = out_process
+    in_process = self.processes.get(in_pid)
+    if not in_process:
+      in_process = SchedProcess(in_pid)
+      self.processes[in_pid] = in_process
+    out_process.handle_switch_out(current_time, out_state, out_prio, out_name, cpu_core)
+    in_process.handle_switch_in(current_time, in_prio, in_name, cpu_core)
+
+  def do_handle_reason(self, l, match):
+    current_pid = int(match.group(1))
+    cpu_core = int(match.group(2))
+    current_time = float(match.group(3))*1000 #ms
+    pid = int(match.group(4))
+    iowait = int(match.group(5))
+    waiting_call = match.group(6)
+    process = self.processes.get(pid)
+    if not process:
+      process = SchedProcess(pid)
+      self.processes[pid] = process
+    process.handle_reason(current_time, iowait, waiting_call)
+
+  def dump(self):
+    sorted_by_total_execution = collections.OrderedDict(sorted(self.processes.items(), \
+      key = lambda item: item[1].total_io_wait_time, reverse = True))
+    for k, v in sorted_by_total_execution.iteritems():
+      if v.total_execution_time > 10.0 or v.total_io_wait_time != 0.0:
+        v.dump()
+
+def main(argv):
+  if (len(argv) < 2):
+    print "check_io_trace_all.py filename"
+    return
+  filename = argv[1]
+
+  io_trace = IoTrace()
+  sched_trace = SchedTrace()
+  with open(filename) as f:
+    for l in f:
+      if io_trace.parse(l):
+        continue
+      sched_trace.parse(l)
+  io_trace.dump()
+  print "\n\n\n"
+  sched_trace.dump()
+
+if __name__ == '__main__':
+  main(sys.argv)
diff --git a/boottime_tools/io_analysis/check_verity.py b/boottime_tools/io_analysis/check_verity.py
new file mode 100644
index 00000000..a69818fb
--- /dev/null
+++ b/boottime_tools/io_analysis/check_verity.py
@@ -0,0 +1,139 @@
+#!/usr/bin/env python
+#
+# Copyright (C) 2016 The Android Open Source Project
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#      http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+#
+"""Analyze dm_verity trace"""
+import collections
+import math
+import os
+import re
+import string
+import sys
+
+RE_VERITY = r'.+\s+([0-9]+\.[0-9]+):\s+block_verity_msg:\s+(\S+)\s+([0-9]+)\,([0-9]+)\s+([0-9]+)\s+([0-9]+)'
+
+def get_average_and_std_dev(l):
+  sum_io = 0.0
+  sum_verity = 0.0
+  sum_total = 0.0
+  N = len(l)
+  sum_blocks = 0.0
+  for e in l:
+    sum_io += e.io_latency
+    sum_verity += e.verity_latency
+    sum_total += e.total_latency
+    sum_blocks += e.size
+  average_io = sum_io / N
+  average_verity = sum_verity / N
+  average_total = sum_total / N
+  var_io = 0.0
+  var_verity = 0.0
+  var_total = 0.0
+  for e in l:
+    var_io += (e.io_latency - average_io)**2
+    var_verity += (e.verity_latency - average_verity)**2
+    var_total += (e.total_latency - average_total)**2
+  sigma_io = math.sqrt(var_io / N)
+  sigma_verity = math.sqrt(var_verity / N)
+  sigma_total = math.sqrt(var_total / N)
+  return (average_io, sigma_io, sum_io), (average_verity, sigma_verity, sum_verity), \
+    (average_total, sigma_total, sum_total), sum_blocks
+
+
+class Event:
+  def __init__(self, start_time, block_num, size):
+    self.block_num = block_num
+    self.start_time = start_time
+    self.io_end_time = 0
+    self.finish_time = 0
+    self.size = size
+    self.total_latency = 0
+    self.io_latency = 0
+    self.verity_latency = 0
+
+  def set_io_end_time(self, io_end_time):
+    self.io_end_time = io_end_time
+    self.io_latency = io_end_time - self.start_time
+
+  def set_finish_time(self, finish_time):
+    self.finish_time = finish_time
+    self.verity_latency = finish_time - self.io_end_time
+    self.total_latency = finish_time - self.start_time
+
+class VerityTrace:
+  def __init__(self):
+    self.reads = [] # all events in start time
+    self.block_size_vs_reads_histogram = {} # key: size, value: list of events
+    self.recents = {} # not finished, key: block_nr, value: event
+    self.re = re.compile(RE_VERITY)
+
+  def handle_line(self, line):
+    match = self.re.match(line)
+    if not match:
+      return
+    time = int(float(match.group(1))*1000000) #us
+    step = match.group(2)
+    block_nr = int(match.group(5))
+    size = int(match.group(6))
+    recent_key = block_nr * 1000 + size
+    if step == "map":
+      event = Event(time, block_nr, size)
+      self.recents[recent_key] = event
+      self.reads.append(event)
+      per_size_list = self.block_size_vs_reads_histogram.get(size)
+      if not per_size_list:
+        per_size_list = []
+        self.block_size_vs_reads_histogram[size] = per_size_list
+      per_size_list.append(event)
+    elif step == "end_io":
+      event = self.recents[recent_key]
+      event.set_io_end_time(time)
+    elif step == "finish_io":
+      event = self.recents[recent_key]
+      event.set_finish_time(time)
+      del self.recents[recent_key]
+
+  def dump_list(self, msg, l):
+    io, verity, total, blocks = get_average_and_std_dev(l)
+    print msg, "counts:", len(l), "io latency:", io[0], io[1], io[2], "verity latency:", \
+      verity[0], verity[1], verity[2], "total:", total[0], total[1], total[2]
+    return io, verity, total, blocks
+
+  def dump(self):
+    print "Numbers: average (us), stddev (us), total (us)"
+    io, verity, total, blocks = self.dump_list ("total,", self.reads)
+    io_latency_per_1024KB = io[2] / blocks * (1024 / 4)
+    verity_latency_per_1024KB = verity[2] / blocks * (1024 / 4)
+    total_latency_per_1024KB = io_latency_per_1024KB + verity_latency_per_1024KB
+    print "Average latency for 1024KB (us), IO:", io_latency_per_1024KB, \
+      "Verity:", verity_latency_per_1024KB, "Total:", total_latency_per_1024KB
+    sizes = sorted(self.block_size_vs_reads_histogram.keys())
+    print "Latency per read size"
+    for s in sizes:
+      self.dump_list ("size " + str(s), self.block_size_vs_reads_histogram[s])
+
+def main(argv):
+  if (len(argv) < 2):
+    print "check_io_trace.py filename"
+    return
+  filename = argv[1]
+  trace = VerityTrace()
+  with open(filename) as f:
+    for l in f:
+      trace.handle_line(l)
+  trace.dump()
+
+if __name__ == '__main__':
+  main(sys.argv)