196fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park#!/usr/bin/env python
296fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park#
396fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park# Copyright (C) 2016 The Android Open Source Project
496fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park#
596fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park# Licensed under the Apache License, Version 2.0 (the "License");
696fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park# you may not use this file except in compliance with the License.
796fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park# You may obtain a copy of the License at
896fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park#
996fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park#      http://www.apache.org/licenses/LICENSE-2.0
1096fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park#
1196fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park# Unless required by applicable law or agreed to in writing, software
1296fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park# distributed under the License is distributed on an "AS IS" BASIS,
1396fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
1496fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park# See the License for the specific language governing permissions and
1596fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park# limitations under the License.
1696fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park#
1796fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park"""Analyze block trace"""
1896fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park
1996fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Parkimport collections
2096fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Parkimport os
2196fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Parkimport re
2296fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Parkimport string
2396fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Parkimport sys
2496fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park
2507d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park# ex) <...>-52    [001] ...1     1.362574: block_bio_queue: 8,16 R 0 + 8 [kworker/u8:1]
263a00f978908e230f8bad034a21f5931253c10102Keun-young ParkRE_BLOCK = r'.+-([0-9]+).*\s+([0-9]+\.[0-9]+):\s+block_bio_queue:\s+([0-9]+)\,([0-9]+)\s(\S+)\s+([0-9]+)\s+\+\s+([0-9]+)\s+\[([^\]]+)'
2707d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park# ex)  <...>-453   [001] d..4     3.181854: sched_blocked_reason: pid=471 iowait=1 caller=__wait_on_buffer+0x24/0x2c
2807d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young ParkRE_SCHED_BLOCKED_READSON = r'.+-([0-9]+)\s+\[([0-9]+)\]\s.*\s+([0-9]+\.[0-9]+):\s+sched_blocked_reason:\spid=([0-9]+)\siowait=([01])\scaller=(\S+)'
2907d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park# ex) <idle>-0     [000] d..3     3.181864: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=ueventd next_pid=471 next_prio=120
3007d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young ParkRE_SCHED_SWITCH = r'.+-([0-9]+)\s+\[([0-9]+)\]\s.*\s+([0-9]+\.[0-9]+):\s+sched_switch:\sprev_comm=(.+)\sprev_pid=([0-9]+)\sprev_prio=([0-9]+)\sprev_state=(\S+).*next_comm=(.+)\snext_pid=([0-9]+)\snext_prio=([0-9]+)'
3196fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park
3296fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park# dev_num = major * MULTIPLIER + minor
3396fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young ParkDEV_MAJOR_MULTIPLIER = 1000
3496fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park
3596fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park# dm access is remapped to disk access. So account differently
3696fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young ParkDM_MAJOR = 253
3796fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park
3896fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young ParkMAX_PROCESS_DUMP = 10
3996fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park
4096fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Parkclass RwEvent:
4196fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park  def __init__(self, block_num, start_time, size):
4296fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    self.block_num = block_num
4396fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    self.start_time = start_time
4496fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    self.size = size
4596fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park
4696fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Parkdef get_string_pos(strings, string_to_find):
4796fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park  for i, s in enumerate(strings):
4896fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    if s == string_to_find:
4996fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      return i
5096fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park  return -1
5196fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park
5296fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Parkclass ProcessData:
5396fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park  def __init__(self, name):
5496fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    self.name = name
5596fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    self.reads = {} # k : dev_num, v : [] of reads
5696fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    self.per_device_total_reads = {}
5796fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    self.writes = {}
5896fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    self.per_device_total_writes = {}
5996fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    self.total_reads = 0
6096fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    self.total_writes = 0
6196fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    self.total_dm_reads = 0
6296fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    self.total_dm_writes = 0
6396fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park
6407d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park
6596fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park  def add_read_event(self, major, minor, event):
6696fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    devNum = major * DEV_MAJOR_MULTIPLIER + minor;
6796fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    events = self.reads.get(devNum)
6896fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    if not events:
6996fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      events = []
7096fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      self.reads[devNum] = events
7196fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      self.per_device_total_reads[devNum] = 0
7296fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    events.append(event)
7396fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    self.total_reads += event.size
7496fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    self.per_device_total_reads[devNum] += event.size
7596fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park
7696fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park  def add_write_event(self, major, minor, event):
7796fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    devNum = major * DEV_MAJOR_MULTIPLIER + minor;
7896fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    events = self.writes.get(devNum)
7996fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    if not events:
8096fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      events = []
8196fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      self.writes[devNum] = events
8296fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      self.per_device_total_writes[devNum] = 0
8396fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    events.append(event)
8496fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    self.total_writes += event.size
8596fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    self.per_device_total_writes[devNum] += event.size
8696fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park
8796fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park  def add_dm_read(self, size):
8896fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    self.total_dm_reads += size
8996fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park
9096fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park  def add_dm_write(self, size):
9196fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    self.total_dm_writes += size
9296fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park
9396fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park  def dump(self):
9496fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    print "Process,", self.name
9596fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    print " total reads,", self.total_reads
9696fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    print " total writes,", self.total_writes
9796fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    print " total dm reads,", self.total_dm_reads
9896fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    print " total dm writes,", self.total_dm_writes
9996fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    print " R per device"
10096fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    sorted_r = collections.OrderedDict(sorted(self.per_device_total_reads.items(), \
10196fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      key = lambda item: item[1], reverse = True))
10296fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    for i in range(len(sorted_r)):
10396fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      dev = sorted_r.popitem(last=False)
10496fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      print " ", dev[0],dev[1]
10596fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park
10696fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    print " W per device"
10796fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    sorted_w = collections.OrderedDict(sorted(self.per_device_total_writes.items(), \
10896fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      key = lambda item: item[1], reverse = True))
10996fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    for i in range(len(sorted_w)):
11096fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      dev = sorted_w.popitem(last=False)
11196fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      print " ", dev[0],dev[1]
11296fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park
11307d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Parkclass IoTrace:
11496fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park
11596fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park  def __init__(self):
11696fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    self.ios = {} #K: process name, v:ProcessData
11796fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    self.total_reads = 0
11896fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    self.total_writes = 0
11996fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    self.total_reads_per_device = {} #K: block num, V: total blocks
12096fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    self.total_writes_per_device = {}
12196fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    self.total_dm_reads = {} #K: devnum, V: blocks
12296fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    self.total_dm_writes = {}
12307d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    self.re_block = re.compile(RE_BLOCK)
12407d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park
12507d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park  def parse(self, l):
12607d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    match = self.re_block.match(l)
12707d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    if not match:
12807d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park      return False
12907d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    try:
13007d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park      self.do_parse_bio_queue(l, match)
13107d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    except ValueError:
13207d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park      print "cannot parse:", l
13307d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park      raise
13407d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    return True
13596fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park
13607d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park  def do_parse_bio_queue(self, l, match):
13796fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    pid = match.group(1)
13807d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    start_time = float(match.group(2))*1000 #ms
13996fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    major = int(match.group(3))
14096fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    minor =  int(match.group(4))
14196fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    devNum = major * DEV_MAJOR_MULTIPLIER + minor;
14296fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    operation =  match.group(5)
14396fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    block_num = int(match.group(6))
14496fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    size = int(match.group(7))
14596fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    process = match.group(8) + "-" + pid
14696fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    event = RwEvent(block_num, start_time, size)
14796fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    io = self.ios.get(process)
14896fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    if not io:
14996fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      io = ProcessData(process)
15096fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      self.ios[process] = io
15196fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    if major == DM_MAJOR:
15296fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      devNum = major * DEV_MAJOR_MULTIPLIER + minor;
1533a00f978908e230f8bad034a21f5931253c10102Keun-young Park      if 'R' in operation[0]:
15496fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park        if devNum not in self.total_dm_reads:
15596fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park          self.total_dm_reads[devNum] = 0
15696fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park        self.total_dm_reads[devNum] += size
15796fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park        io.add_dm_read(size)
1583a00f978908e230f8bad034a21f5931253c10102Keun-young Park      elif 'W' in operation[0]:
15996fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park        if devNum not in self.total_dm_writes:
16096fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park          self.total_dm_writes[devNum] = 0
16196fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park        self.total_dm_writes[devNum] += size
16296fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park        io.add_dm_write(size)
16396fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      return
1643a00f978908e230f8bad034a21f5931253c10102Keun-young Park    if 'R' in operation[0]:
16596fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      io.add_read_event(major, minor, event)
16696fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      self.total_reads += size
16796fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      per_device = self.total_reads_per_device.get(devNum)
16896fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      if not per_device:
16996fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park        self.total_reads_per_device[devNum] = 0
17096fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      self.total_reads_per_device[devNum] += size
1713a00f978908e230f8bad034a21f5931253c10102Keun-young Park    elif 'W' in operation[0]:
17296fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      io.add_write_event(major, minor, event)
17396fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      self.total_writes += size
17496fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      per_device = self.total_writes_per_device.get(devNum)
17596fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      if not per_device:
17696fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park        self.total_writes_per_device[devNum] = 0
17796fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      self.total_writes_per_device[devNum] += size
17896fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park
17996fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park  def dump(self):
18096fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    print "total read blocks,", self.total_reads
18196fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    print "total write blocks,", self.total_writes
18296fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    print "Total DM R"
18396fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    for dev,size in self.total_dm_reads.items():
18496fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      print dev, size
18596fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    print "Total DM W"
18696fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    for dev,size in self.total_dm_writes.items():
18796fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      print dev, size
18896fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    print "**Process total R/W"
18996fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    sorted_by_total_rw = collections.OrderedDict(sorted(self.ios.items(), \
19096fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      key = lambda item: item[1].total_reads + item[1].total_writes, reverse = True))
19196fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    for i in range(MAX_PROCESS_DUMP):
19296fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      process = sorted_by_total_rw.popitem(last=False)
19396fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      if not process:
19496fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park        break
19596fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      process[1].dump()
19696fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park
19796fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    print "**Process total W"
19896fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    sorted_by_total_w = collections.OrderedDict(sorted(self.ios.items(), \
19996fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      key = lambda item: item[1].total_writes, reverse = True))
20096fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    for i in range(5):
20196fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      process = sorted_by_total_w.popitem(last=False)
20296fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      if not process:
20396fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park        break
20496fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      process[1].dump()
20596fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park
20696fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    print "**Device total R"
20796fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    sorted_by_total_r = collections.OrderedDict(sorted(self.total_reads_per_device.items(), \
20896fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      key = lambda item: item[1], reverse = True))
20996fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    for i in range(len(sorted_by_total_r)):
21096fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      dev = sorted_by_total_r.popitem(last=False)
21196fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      print dev[0],dev[1]
21296fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park
21396fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    print "**Device total W"
21496fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    sorted_by_total_w = collections.OrderedDict(sorted(self.total_writes_per_device.items(), \
21596fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      key = lambda item: item[1], reverse = True))
21696fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    for i in range(len(sorted_by_total_w)):
21796fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      dev = sorted_by_total_w.popitem(last=False)
21896fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park      print dev[0],dev[1]
21996fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park
22007d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Parkclass SchedProcess:
22107d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park  def __init__(self, pid):
22207d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    self.pid = pid
22307d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    self.name = "unknown"
22407d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    self.total_execution_time = 0.0
22507d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    self.total_io_wait_time = 0.0
22607d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    self.total_other_wait_time = 0.0
22707d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    self.waiting_calls = {} # k: waiting_call, v : waiting counter
22807d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    self.io_waiting_call_times = {} # k: waiting_call, v: total wait time
22907d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    self.in_iowait = False
23007d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    self.last_waiting_call = None
23107d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    self.last_switch_out_time = 0.0
23207d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    self.last_switch_in_time = 0.0
23307d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    self.last_core = -1
23407d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    self.execution_time_per_core = {} # k: core, v : time
2353a00f978908e230f8bad034a21f5931253c10102Keun-young Park    self.io_latency_histograms = {} # k : delay in ms, v : count
23607d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park
23707d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park  def handle_reason(self, current_time, iowait, waiting_call):
23807d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    #if self.pid == 1232:
23907d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    #  print current_time, iowait, waiting_call
24007d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    if iowait == 1:
24107d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park      self.in_iowait = True
24207d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    self.last_waiting_call = waiting_call
24307d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    call_counter = self.waiting_calls.get(waiting_call, 0)
24407d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    call_counter += 1
24507d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    self.waiting_calls[waiting_call] = call_counter
24607d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park
24707d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park  def handle_switch_out(self, current_time, out_state, priority, name, core):
24807d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    #if self.pid == 1232:
24907d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    #  print "out", current_time, out_state
25007d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    if self.name != name:
25107d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park      self.name = name
25207d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    self.last_switch_out_time = current_time
25307d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    if self.last_switch_in_time == 0.0: # switch in not recorded. ignore this one
25407d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park      return
25507d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    execution_time = current_time - self.last_switch_in_time
25607d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    self.total_execution_time += execution_time
25707d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    core_execution_time = self.execution_time_per_core.get(core, 0.0)
25807d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    core_execution_time += execution_time
25907d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    self.execution_time_per_core[core] = core_execution_time
26007d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park
26107d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park  def handle_switch_in(self, current_time, priority, name, core):
26207d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    #if self.pid == 1232:
26307d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    #  print "in", current_time, self.in_iowait
26407d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    if self.name != name:
26507d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park      self.name = name
26607d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    self.last_switch_in_time = current_time
26707d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    if self.last_switch_out_time == 0.0: # in without out, probably 1st
26807d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park      self.in_iowait = False
26907d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park      return
27007d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    wait_time = current_time - self.last_switch_out_time
27107d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    if self.in_iowait:
27207d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park      self.total_io_wait_time += wait_time
27307d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park      total_waiting_call_time = self.io_waiting_call_times.get(self.last_waiting_call, 0.0)
27407d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park      total_waiting_call_time += wait_time
27507d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park      self.io_waiting_call_times[self.last_waiting_call] = total_waiting_call_time
2763a00f978908e230f8bad034a21f5931253c10102Keun-young Park      wait_time_ms = int(wait_time*10) / 10.0 # resolution up to 0.1 ms
2773a00f978908e230f8bad034a21f5931253c10102Keun-young Park      histogram_count = self.io_latency_histograms.get(wait_time_ms, 0)
2783a00f978908e230f8bad034a21f5931253c10102Keun-young Park      histogram_count += 1
2793a00f978908e230f8bad034a21f5931253c10102Keun-young Park      self.io_latency_histograms[wait_time_ms] = histogram_count
28007d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    else:
28107d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park      self.total_other_wait_time += wait_time
28207d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    self.in_iowait = False
28307d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park
28407d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park
28507d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park  def dump(self):
28607d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    print "PID:", self.pid, " name:", self.name
28707d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    print " total execution time:", self.total_execution_time,\
28807d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park      " io wait:", self.total_io_wait_time, " other wait:", self.total_other_wait_time
2893a00f978908e230f8bad034a21f5931253c10102Keun-young Park    sorted_data = collections.OrderedDict(sorted(self.execution_time_per_core.items(), \
2903a00f978908e230f8bad034a21f5931253c10102Keun-young Park      key = lambda item: item[0], reverse = False))
2913a00f978908e230f8bad034a21f5931253c10102Keun-young Park    print " Core execution:", sorted_data
2923a00f978908e230f8bad034a21f5931253c10102Keun-young Park    sorted_data = collections.OrderedDict(sorted(self.waiting_calls.items(), \
2933a00f978908e230f8bad034a21f5931253c10102Keun-young Park      key = lambda item: item[1], reverse = True))
2943a00f978908e230f8bad034a21f5931253c10102Keun-young Park    print " Wait calls:", sorted_data
2953a00f978908e230f8bad034a21f5931253c10102Keun-young Park    sorted_data = collections.OrderedDict(sorted(self.io_waiting_call_times.items(), \
2963a00f978908e230f8bad034a21f5931253c10102Keun-young Park      key = lambda item: item[1], reverse = True))
2973a00f978908e230f8bad034a21f5931253c10102Keun-young Park    print " IO Wait time per wait calls:", sorted_data
2983a00f978908e230f8bad034a21f5931253c10102Keun-young Park    sorted_data = collections.OrderedDict(sorted(self.io_latency_histograms.items(), \
2993a00f978908e230f8bad034a21f5931253c10102Keun-young Park      key = lambda item: item[0], reverse = False))
3003a00f978908e230f8bad034a21f5931253c10102Keun-young Park    print " Wait time histogram:", sorted_data
30107d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park
30207d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Parkclass SchedTrace:
30307d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park  def __init__(self):
30407d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    self.re_switch = re.compile(RE_SCHED_SWITCH)
30507d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    self.re_reason = re.compile(RE_SCHED_BLOCKED_READSON)
30607d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    self.processes = {} # key: pid, v : SchedProcess
30707d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park
30807d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park  def parse(self, l):
30907d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    checked_reason = False
31007d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    match = self.re_switch.match(l)
31107d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    if not match:
31207d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park      match = self.re_reason.match(l)
31307d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park      checked_reason = True
31407d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    if not match:
31507d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park      return False
31607d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    try:
31707d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park      if checked_reason:
31807d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park        self.do_handle_reason(l, match)
31907d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park      else:
32007d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park        self.do_handle_switch(l, match)
32107d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    except ValueError:
32207d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park      print "cannot parse:", l
32307d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park      raise
32407d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    return True
32507d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park
32607d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park  def do_handle_switch(self, l, match):
32707d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    current_pid = int(match.group(1))
32807d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    cpu_core = int(match.group(2))
32907d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    current_time = float(match.group(3))*1000 #ms
33007d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    out_name = match.group(4)
33107d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    out_pid = int(match.group(5))
33207d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    out_prio = int(match.group(6))
33307d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    out_state = match.group(7)
33407d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    in_name = match.group(8)
33507d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    in_pid = int(match.group(9))
33607d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    in_prio = int(match.group(10))
33707d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    out_process = self.processes.get(out_pid)
33807d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    if not out_process:
33907d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park      out_process = SchedProcess(out_pid)
34007d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park      self.processes[out_pid] = out_process
34107d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    in_process = self.processes.get(in_pid)
34207d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    if not in_process:
34307d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park      in_process = SchedProcess(in_pid)
34407d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park      self.processes[in_pid] = in_process
34507d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    out_process.handle_switch_out(current_time, out_state, out_prio, out_name, cpu_core)
34607d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    in_process.handle_switch_in(current_time, in_prio, in_name, cpu_core)
34707d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park
34807d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park  def do_handle_reason(self, l, match):
34907d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    current_pid = int(match.group(1))
35007d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    cpu_core = int(match.group(2))
35107d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    current_time = float(match.group(3))*1000 #ms
35207d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    pid = int(match.group(4))
35307d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    iowait = int(match.group(5))
35407d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    waiting_call = match.group(6)
35507d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    process = self.processes.get(pid)
35607d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    if not process:
35707d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park      process = SchedProcess(pid)
35807d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park      self.processes[pid] = process
35907d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    process.handle_reason(current_time, iowait, waiting_call)
36007d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park
36107d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park  def dump(self):
36207d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    sorted_by_total_execution = collections.OrderedDict(sorted(self.processes.items(), \
36307d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park      key = lambda item: item[1].total_io_wait_time, reverse = True))
36407d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park    for k, v in sorted_by_total_execution.iteritems():
36507d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park      if v.total_execution_time > 10.0 or v.total_io_wait_time != 0.0:
36607d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park        v.dump()
36707d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park
36896fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Parkdef main(argv):
36996fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park  if (len(argv) < 2):
37096fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    print "check_io_trace_all.py filename"
37196fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    return
37296fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park  filename = argv[1]
37396fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park
37407d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park  io_trace = IoTrace()
37507d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park  sched_trace = SchedTrace()
37696fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park  with open(filename) as f:
37796fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park    for l in f:
37807d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park      if io_trace.parse(l):
37907d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park        continue
38007d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park      sched_trace.parse(l)
38107d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park  io_trace.dump()
38207d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park  print "\n\n\n"
38307d2973cde8e6dfd409719ec0e1993f4101e30b1Keun-young Park  sched_trace.dump()
38496fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park
38596fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Parkif __name__ == '__main__':
38696fea8b693e89892a1a90e217d8eb76bdd2edc77Keun-young Park  main(sys.argv)
387