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
19import collections
20import os
21import re
22import string
23import sys
24
25RE_BLOCK = r'.+\s+(block[a-z_]+):\s+'
26RE_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
29DEV_MAJOR_MULTIPLIER = 1000
30
31# dm access is remapped to disk access. So account differently
32DM_MAJOR = 253
33
34class 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
43def 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
50class 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
177def 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
192if __name__ == '__main__':
193  main(sys.argv)
194