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 block trace""" 18 19 import collections 20 import os 21 import re 22 import string 23 import sys 24 25 RE_BLOCK = r'.+\s+(block[a-z_]+):\s+' 26 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+\[([^\]]+)' 27 28 # dev_num = major * MULTIPLIER + minor 29 DEV_MAJOR_MULTIPLIER = 1000 30 31 # dm access is remapped to disk access. So account differently 32 DM_MAJOR = 253 33 34 class RwEvent: 35 def __init__(self, block_num, start_time, size): 36 self.block_num = block_num 37 self.start_time = start_time 38 self.size = size 39 self.latency = 0 40 def set_latency(self, latency): 41 self.latency = latency 42 43 def get_string_pos(strings, string_to_find): 44 for i, s in enumerate(strings): 45 if s == string_to_find: 46 return i 47 return -1 48 49 50 class Trace: 51 def __init__(self, process): 52 self.process = process 53 self.reads = [] #(start time, RwEvent) 54 self.writes = [] #(start time, RwEvent) 55 self.recent_reads = {} # K: 56 self.total_latency = 0 57 self.total_reads = 0 58 self.total_writes = 0 59 self.total_dm_reads = {} #K: devnum, V: blocks 60 self.total_dm_writes = {} 61 self.re_block_queue = re.compile(RE_BLOCK_BIO_QUEUE) 62 self.processes = set() 63 if process[-1] == '*': 64 print "Process name starts with", process[:-1] 65 self.process_name_is_prefix = True 66 else: 67 print "Process name", process 68 self.process_name_is_prefix = False 69 70 def parse_bio_queue(self, l): 71 match = self.re_block_queue.match(l) 72 if not match: 73 return 74 start_time = int(float(match.group(1))*1000000) #us 75 major = int(match.group(2)) 76 minor = int(match.group(3)) 77 operation = match.group(4) 78 block_num = int(match.group(5)) 79 size = int(match.group(6)) 80 process = match.group(7) 81 if self.process_name_is_prefix: 82 if not process.startswith(self.process[:-1]): 83 return 84 self.processes.add(process) 85 else: 86 if process != self.process: 87 return 88 if major == DM_MAJOR: 89 devNum = major * DEV_MAJOR_MULTIPLIER + minor; 90 if operation[0] == 'R': 91 if devNum not in self.total_dm_reads: 92 self.total_dm_reads[devNum] = 0 93 self.total_dm_reads[devNum] += size 94 elif operation[0] == 'W': 95 if devNum not in self.total_dm_writes: 96 self.total_dm_writes[devNum] = 0 97 self.total_dm_writes[devNum] += size 98 return 99 event = RwEvent(block_num, start_time, size) 100 if operation[0] == 'R': 101 self.reads.append((start_time, event)) 102 self.recent_reads[block_num] = event 103 self.total_reads += size 104 elif operation[0] == 'W': 105 self.writes.append((start_time, event)) 106 self.total_writes += size 107 108 def parse_rq_complete(self, l): 109 words = string.split(l) 110 cmd_pos = get_string_pos(words, "block_rq_complete:") 111 if cmd_pos == -1: 112 cmd_pos = get_string_pos(words, "block_bio_complete:") 113 block_num = int(words[-4]) 114 event = self.recent_reads.get(block_num) 115 if not event: 116 return 117 operation = words[cmd_pos + 2] 118 if not operation.startswith("R"): 119 return 120 end_time = int(float(words[cmd_pos - 1][:-1])*1000000) #us 121 latency = end_time - event.start_time 122 if latency > 20000: 123 print "very bad latency:", latency, l 124 print "start time,", event.start_time 125 event.set_latency(latency) 126 del self.recent_reads[block_num] 127 self.total_latency += latency 128 129 def parse_block_trace(self, l, match): 130 try: 131 cmd = match.group(1) 132 if cmd == "block_bio_queue": 133 self.parse_bio_queue(l) 134 elif cmd == "block_rq_complete" or cmd == "block_bio_complete": 135 self.parse_rq_complete(l) 136 except ValueError: 137 print "cannot parse:", l 138 raise 139 140 def dump(self): 141 if self.process_name_is_prefix: 142 print "Processes:", self.processes 143 print "total read blocks,", self.total_reads 144 print "total write blocks,", self.total_writes 145 if len(self.reads) > 0: 146 total_read_time = self.reads[-1][0] + self.reads[-1][1].latency - self.reads[0][0] 147 else: 148 total_read_time = 0 149 print "Total DM R" 150 for dev,size in self.total_dm_reads.items(): 151 print dev, size 152 print "Total DM W" 153 for dev,size in self.total_dm_writes.items(): 154 print dev, size 155 print "total read time,",total_read_time 156 read_size_histogram = {} 157 latency_per_read_size = {} 158 for (time, event) in self.reads: 159 if not read_size_histogram.get(event.size): 160 read_size_histogram[event.size] = 0 161 if not latency_per_read_size.get(event.size): 162 latency_per_read_size[event.size] = [ 0, 0] # num events, total latency 163 read_size_histogram[event.size] = read_size_histogram[event.size] + 1 164 latency_sum = latency_per_read_size[event.size] 165 latency_sum[0] += 1 166 latency_sum[1] += event.latency 167 read_size_histogram = collections.OrderedDict(sorted(read_size_histogram.items())) 168 print "read histogram" 169 for k,v in read_size_histogram.iteritems(): 170 print k, ',', v 171 print "latency per read size" 172 latency_per_read_size = collections.OrderedDict(sorted(latency_per_read_size.items())) 173 for k,v in latency_per_read_size.iteritems(): 174 if v[0] != 0: 175 print k, ',', v[1] / v[0], v[0], v[1] 176 177 def main(argv): 178 if (len(argv) < 3): 179 print "check_io_trace.py processname filename" 180 return 181 keyword = argv[1] 182 filename = argv[2] 183 trace = Trace(keyword) 184 prog = re.compile(RE_BLOCK) 185 with open(filename) as f: 186 for l in f: 187 result = prog.match(l) 188 if result: 189 trace.parse_block_trace(l, result) 190 trace.dump() 191 192 if __name__ == '__main__': 193 main(sys.argv) 194
