1 #!/usr/bin/env python 2 # 3 # Copyright (C) 2016 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 """Analyze dm_verity trace""" 18 import collections 19 import math 20 import os 21 import re 22 import string 23 import sys 24 25 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]+)' 26 27 def get_average_and_std_dev(l): 28 sum_io = 0.0 29 sum_verity = 0.0 30 sum_total = 0.0 31 N = len(l) 32 sum_blocks = 0.0 33 for e in l: 34 sum_io += e.io_latency 35 sum_verity += e.verity_latency 36 sum_total += e.total_latency 37 sum_blocks += e.size 38 average_io = sum_io / N 39 average_verity = sum_verity / N 40 average_total = sum_total / N 41 var_io = 0.0 42 var_verity = 0.0 43 var_total = 0.0 44 for e in l: 45 var_io += (e.io_latency - average_io)**2 46 var_verity += (e.verity_latency - average_verity)**2 47 var_total += (e.total_latency - average_total)**2 48 sigma_io = math.sqrt(var_io / N) 49 sigma_verity = math.sqrt(var_verity / N) 50 sigma_total = math.sqrt(var_total / N) 51 return (average_io, sigma_io, sum_io), (average_verity, sigma_verity, sum_verity), \ 52 (average_total, sigma_total, sum_total), sum_blocks 53 54 55 class Event: 56 def __init__(self, start_time, block_num, size): 57 self.block_num = block_num 58 self.start_time = start_time 59 self.io_end_time = 0 60 self.finish_time = 0 61 self.size = size 62 self.total_latency = 0 63 self.io_latency = 0 64 self.verity_latency = 0 65 66 def set_io_end_time(self, io_end_time): 67 self.io_end_time = io_end_time 68 self.io_latency = io_end_time - self.start_time 69 70 def set_finish_time(self, finish_time): 71 self.finish_time = finish_time 72 self.verity_latency = finish_time - self.io_end_time 73 self.total_latency = finish_time - self.start_time 74 75 class VerityTrace: 76 def __init__(self): 77 self.reads = [] # all events in start time 78 self.block_size_vs_reads_histogram = {} # key: size, value: list of events 79 self.recents = {} # not finished, key: block_nr, value: event 80 self.re = re.compile(RE_VERITY) 81 82 def handle_line(self, line): 83 match = self.re.match(line) 84 if not match: 85 return 86 time = int(float(match.group(1))*1000000) #us 87 step = match.group(2) 88 block_nr = int(match.group(5)) 89 size = int(match.group(6)) 90 recent_key = block_nr * 1000 + size 91 if step == "map": 92 event = Event(time, block_nr, size) 93 self.recents[recent_key] = event 94 self.reads.append(event) 95 per_size_list = self.block_size_vs_reads_histogram.get(size) 96 if not per_size_list: 97 per_size_list = [] 98 self.block_size_vs_reads_histogram[size] = per_size_list 99 per_size_list.append(event) 100 elif step == "end_io": 101 event = self.recents[recent_key] 102 event.set_io_end_time(time) 103 elif step == "finish_io": 104 event = self.recents[recent_key] 105 event.set_finish_time(time) 106 del self.recents[recent_key] 107 108 def dump_list(self, msg, l): 109 io, verity, total, blocks = get_average_and_std_dev(l) 110 print msg, "counts:", len(l), "io latency:", io[0], io[1], io[2], "verity latency:", \ 111 verity[0], verity[1], verity[2], "total:", total[0], total[1], total[2] 112 return io, verity, total, blocks 113 114 def dump(self): 115 print "Numbers: average (us), stddev (us), total (us)" 116 io, verity, total, blocks = self.dump_list ("total,", self.reads) 117 io_latency_per_1024KB = io[2] / blocks * (1024 / 4) 118 verity_latency_per_1024KB = verity[2] / blocks * (1024 / 4) 119 total_latency_per_1024KB = io_latency_per_1024KB + verity_latency_per_1024KB 120 print "Average latency for 1024KB (us), IO:", io_latency_per_1024KB, \ 121 "Verity:", verity_latency_per_1024KB, "Total:", total_latency_per_1024KB 122 sizes = sorted(self.block_size_vs_reads_histogram.keys()) 123 print "Latency per read size" 124 for s in sizes: 125 self.dump_list ("size " + str(s), self.block_size_vs_reads_histogram[s]) 126 127 def main(argv): 128 if (len(argv) < 2): 129 print "check_io_trace.py filename" 130 return 131 filename = argv[1] 132 trace = VerityTrace() 133 with open(filename) as f: 134 for l in f: 135 trace.handle_line(l) 136 trace.dump() 137 138 if __name__ == '__main__': 139 main(sys.argv) 140
