boottime_tools/io_analysis/check_verity.py

#!/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)