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