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"""
18import collections
19import math
20import os
21import re
22import string
23import sys
24
25RE_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
27def 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
55class 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
75class 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
127def 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
138if __name__ == '__main__':
139  main(sys.argv)
140