387 lines
14 KiB
Python
387 lines
14 KiB
Python
#!/usr/bin/env python
|
|
#
|
|
# Copyright (C) 2016 The Android Open Source Project
|
|
#
|
|
# Licensed under the Apache License, Version 2.0 (the "License");
|
|
# you may not use this file except in compliance with the License.
|
|
# You may obtain a copy of the License at
|
|
#
|
|
# http://www.apache.org/licenses/LICENSE-2.0
|
|
#
|
|
# Unless required by applicable law or agreed to in writing, software
|
|
# distributed under the License is distributed on an "AS IS" BASIS,
|
|
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
|
|
# See the License for the specific language governing permissions and
|
|
# limitations under the License.
|
|
#
|
|
"""Analyze block trace"""
|
|
|
|
import collections
|
|
import os
|
|
import re
|
|
import string
|
|
import sys
|
|
|
|
# ex) <...>-52 [001] ...1 1.362574: block_bio_queue: 8,16 R 0 + 8 [kworker/u8:1]
|
|
RE_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+\[([^\]]+)'
|
|
# ex) <...>-453 [001] d..4 3.181854: sched_blocked_reason: pid=471 iowait=1 caller=__wait_on_buffer+0x24/0x2c
|
|
RE_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+)'
|
|
# 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
|
|
RE_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]+)'
|
|
|
|
# dev_num = major * MULTIPLIER + minor
|
|
DEV_MAJOR_MULTIPLIER = 1000
|
|
|
|
# dm access is remapped to disk access. So account differently
|
|
DM_MAJOR = 253
|
|
|
|
MAX_PROCESS_DUMP = 10
|
|
|
|
class RwEvent:
|
|
def __init__(self, block_num, start_time, size):
|
|
self.block_num = block_num
|
|
self.start_time = start_time
|
|
self.size = size
|
|
|
|
def get_string_pos(strings, string_to_find):
|
|
for i, s in enumerate(strings):
|
|
if s == string_to_find:
|
|
return i
|
|
return -1
|
|
|
|
class ProcessData:
|
|
def __init__(self, name):
|
|
self.name = name
|
|
self.reads = {} # k : dev_num, v : [] of reads
|
|
self.per_device_total_reads = {}
|
|
self.writes = {}
|
|
self.per_device_total_writes = {}
|
|
self.total_reads = 0
|
|
self.total_writes = 0
|
|
self.total_dm_reads = 0
|
|
self.total_dm_writes = 0
|
|
|
|
|
|
def add_read_event(self, major, minor, event):
|
|
devNum = major * DEV_MAJOR_MULTIPLIER + minor;
|
|
events = self.reads.get(devNum)
|
|
if not events:
|
|
events = []
|
|
self.reads[devNum] = events
|
|
self.per_device_total_reads[devNum] = 0
|
|
events.append(event)
|
|
self.total_reads += event.size
|
|
self.per_device_total_reads[devNum] += event.size
|
|
|
|
def add_write_event(self, major, minor, event):
|
|
devNum = major * DEV_MAJOR_MULTIPLIER + minor;
|
|
events = self.writes.get(devNum)
|
|
if not events:
|
|
events = []
|
|
self.writes[devNum] = events
|
|
self.per_device_total_writes[devNum] = 0
|
|
events.append(event)
|
|
self.total_writes += event.size
|
|
self.per_device_total_writes[devNum] += event.size
|
|
|
|
def add_dm_read(self, size):
|
|
self.total_dm_reads += size
|
|
|
|
def add_dm_write(self, size):
|
|
self.total_dm_writes += size
|
|
|
|
def dump(self):
|
|
print "Process,", self.name
|
|
print " total reads,", self.total_reads
|
|
print " total writes,", self.total_writes
|
|
print " total dm reads,", self.total_dm_reads
|
|
print " total dm writes,", self.total_dm_writes
|
|
print " R per device"
|
|
sorted_r = collections.OrderedDict(sorted(self.per_device_total_reads.items(), \
|
|
key = lambda item: item[1], reverse = True))
|
|
for i in range(len(sorted_r)):
|
|
dev = sorted_r.popitem(last=False)
|
|
print " ", dev[0],dev[1]
|
|
|
|
print " W per device"
|
|
sorted_w = collections.OrderedDict(sorted(self.per_device_total_writes.items(), \
|
|
key = lambda item: item[1], reverse = True))
|
|
for i in range(len(sorted_w)):
|
|
dev = sorted_w.popitem(last=False)
|
|
print " ", dev[0],dev[1]
|
|
|
|
class IoTrace:
|
|
|
|
def __init__(self):
|
|
self.ios = {} #K: process name, v:ProcessData
|
|
self.total_reads = 0
|
|
self.total_writes = 0
|
|
self.total_reads_per_device = {} #K: block num, V: total blocks
|
|
self.total_writes_per_device = {}
|
|
self.total_dm_reads = {} #K: devnum, V: blocks
|
|
self.total_dm_writes = {}
|
|
self.re_block = re.compile(RE_BLOCK)
|
|
|
|
def parse(self, l):
|
|
match = self.re_block.match(l)
|
|
if not match:
|
|
return False
|
|
try:
|
|
self.do_parse_bio_queue(l, match)
|
|
except ValueError:
|
|
print "cannot parse:", l
|
|
raise
|
|
return True
|
|
|
|
def do_parse_bio_queue(self, l, match):
|
|
pid = match.group(1)
|
|
start_time = float(match.group(2))*1000 #ms
|
|
major = int(match.group(3))
|
|
minor = int(match.group(4))
|
|
devNum = major * DEV_MAJOR_MULTIPLIER + minor;
|
|
operation = match.group(5)
|
|
block_num = int(match.group(6))
|
|
size = int(match.group(7))
|
|
process = match.group(8) + "-" + pid
|
|
event = RwEvent(block_num, start_time, size)
|
|
io = self.ios.get(process)
|
|
if not io:
|
|
io = ProcessData(process)
|
|
self.ios[process] = io
|
|
if major == DM_MAJOR:
|
|
devNum = major * DEV_MAJOR_MULTIPLIER + minor;
|
|
if 'R' in operation[0]:
|
|
if devNum not in self.total_dm_reads:
|
|
self.total_dm_reads[devNum] = 0
|
|
self.total_dm_reads[devNum] += size
|
|
io.add_dm_read(size)
|
|
elif 'W' in operation[0]:
|
|
if devNum not in self.total_dm_writes:
|
|
self.total_dm_writes[devNum] = 0
|
|
self.total_dm_writes[devNum] += size
|
|
io.add_dm_write(size)
|
|
return
|
|
if 'R' in operation[0]:
|
|
io.add_read_event(major, minor, event)
|
|
self.total_reads += size
|
|
per_device = self.total_reads_per_device.get(devNum)
|
|
if not per_device:
|
|
self.total_reads_per_device[devNum] = 0
|
|
self.total_reads_per_device[devNum] += size
|
|
elif 'W' in operation[0]:
|
|
io.add_write_event(major, minor, event)
|
|
self.total_writes += size
|
|
per_device = self.total_writes_per_device.get(devNum)
|
|
if not per_device:
|
|
self.total_writes_per_device[devNum] = 0
|
|
self.total_writes_per_device[devNum] += size
|
|
|
|
def dump(self):
|
|
print "total read blocks,", self.total_reads
|
|
print "total write blocks,", self.total_writes
|
|
print "Total DM R"
|
|
for dev,size in self.total_dm_reads.items():
|
|
print dev, size
|
|
print "Total DM W"
|
|
for dev,size in self.total_dm_writes.items():
|
|
print dev, size
|
|
print "**Process total R/W"
|
|
sorted_by_total_rw = collections.OrderedDict(sorted(self.ios.items(), \
|
|
key = lambda item: item[1].total_reads + item[1].total_writes, reverse = True))
|
|
for i in range(MAX_PROCESS_DUMP):
|
|
process = sorted_by_total_rw.popitem(last=False)
|
|
if not process:
|
|
break
|
|
process[1].dump()
|
|
|
|
print "**Process total W"
|
|
sorted_by_total_w = collections.OrderedDict(sorted(self.ios.items(), \
|
|
key = lambda item: item[1].total_writes, reverse = True))
|
|
for i in range(5):
|
|
process = sorted_by_total_w.popitem(last=False)
|
|
if not process:
|
|
break
|
|
process[1].dump()
|
|
|
|
print "**Device total R"
|
|
sorted_by_total_r = collections.OrderedDict(sorted(self.total_reads_per_device.items(), \
|
|
key = lambda item: item[1], reverse = True))
|
|
for i in range(len(sorted_by_total_r)):
|
|
dev = sorted_by_total_r.popitem(last=False)
|
|
print dev[0],dev[1]
|
|
|
|
print "**Device total W"
|
|
sorted_by_total_w = collections.OrderedDict(sorted(self.total_writes_per_device.items(), \
|
|
key = lambda item: item[1], reverse = True))
|
|
for i in range(len(sorted_by_total_w)):
|
|
dev = sorted_by_total_w.popitem(last=False)
|
|
print dev[0],dev[1]
|
|
|
|
class SchedProcess:
|
|
def __init__(self, pid):
|
|
self.pid = pid
|
|
self.name = "unknown"
|
|
self.total_execution_time = 0.0
|
|
self.total_io_wait_time = 0.0
|
|
self.total_other_wait_time = 0.0
|
|
self.waiting_calls = {} # k: waiting_call, v : waiting counter
|
|
self.io_waiting_call_times = {} # k: waiting_call, v: total wait time
|
|
self.in_iowait = False
|
|
self.last_waiting_call = None
|
|
self.last_switch_out_time = 0.0
|
|
self.last_switch_in_time = 0.0
|
|
self.last_core = -1
|
|
self.execution_time_per_core = {} # k: core, v : time
|
|
self.io_latency_histograms = {} # k : delay in ms, v : count
|
|
|
|
def handle_reason(self, current_time, iowait, waiting_call):
|
|
#if self.pid == 1232:
|
|
# print current_time, iowait, waiting_call
|
|
if iowait == 1:
|
|
self.in_iowait = True
|
|
self.last_waiting_call = waiting_call
|
|
call_counter = self.waiting_calls.get(waiting_call, 0)
|
|
call_counter += 1
|
|
self.waiting_calls[waiting_call] = call_counter
|
|
|
|
def handle_switch_out(self, current_time, out_state, priority, name, core):
|
|
#if self.pid == 1232:
|
|
# print "out", current_time, out_state
|
|
if self.name != name:
|
|
self.name = name
|
|
self.last_switch_out_time = current_time
|
|
if self.last_switch_in_time == 0.0: # switch in not recorded. ignore this one
|
|
return
|
|
execution_time = current_time - self.last_switch_in_time
|
|
self.total_execution_time += execution_time
|
|
core_execution_time = self.execution_time_per_core.get(core, 0.0)
|
|
core_execution_time += execution_time
|
|
self.execution_time_per_core[core] = core_execution_time
|
|
|
|
def handle_switch_in(self, current_time, priority, name, core):
|
|
#if self.pid == 1232:
|
|
# print "in", current_time, self.in_iowait
|
|
if self.name != name:
|
|
self.name = name
|
|
self.last_switch_in_time = current_time
|
|
if self.last_switch_out_time == 0.0: # in without out, probably 1st
|
|
self.in_iowait = False
|
|
return
|
|
wait_time = current_time - self.last_switch_out_time
|
|
if self.in_iowait:
|
|
self.total_io_wait_time += wait_time
|
|
total_waiting_call_time = self.io_waiting_call_times.get(self.last_waiting_call, 0.0)
|
|
total_waiting_call_time += wait_time
|
|
self.io_waiting_call_times[self.last_waiting_call] = total_waiting_call_time
|
|
wait_time_ms = int(wait_time*10) / 10.0 # resolution up to 0.1 ms
|
|
histogram_count = self.io_latency_histograms.get(wait_time_ms, 0)
|
|
histogram_count += 1
|
|
self.io_latency_histograms[wait_time_ms] = histogram_count
|
|
else:
|
|
self.total_other_wait_time += wait_time
|
|
self.in_iowait = False
|
|
|
|
|
|
def dump(self):
|
|
print "PID:", self.pid, " name:", self.name
|
|
print " total execution time:", self.total_execution_time,\
|
|
" io wait:", self.total_io_wait_time, " other wait:", self.total_other_wait_time
|
|
sorted_data = collections.OrderedDict(sorted(self.execution_time_per_core.items(), \
|
|
key = lambda item: item[0], reverse = False))
|
|
print " Core execution:", sorted_data
|
|
sorted_data = collections.OrderedDict(sorted(self.waiting_calls.items(), \
|
|
key = lambda item: item[1], reverse = True))
|
|
print " Wait calls:", sorted_data
|
|
sorted_data = collections.OrderedDict(sorted(self.io_waiting_call_times.items(), \
|
|
key = lambda item: item[1], reverse = True))
|
|
print " IO Wait time per wait calls:", sorted_data
|
|
sorted_data = collections.OrderedDict(sorted(self.io_latency_histograms.items(), \
|
|
key = lambda item: item[0], reverse = False))
|
|
print " Wait time histogram:", sorted_data
|
|
|
|
class SchedTrace:
|
|
def __init__(self):
|
|
self.re_switch = re.compile(RE_SCHED_SWITCH)
|
|
self.re_reason = re.compile(RE_SCHED_BLOCKED_READSON)
|
|
self.processes = {} # key: pid, v : SchedProcess
|
|
|
|
def parse(self, l):
|
|
checked_reason = False
|
|
match = self.re_switch.match(l)
|
|
if not match:
|
|
match = self.re_reason.match(l)
|
|
checked_reason = True
|
|
if not match:
|
|
return False
|
|
try:
|
|
if checked_reason:
|
|
self.do_handle_reason(l, match)
|
|
else:
|
|
self.do_handle_switch(l, match)
|
|
except ValueError:
|
|
print "cannot parse:", l
|
|
raise
|
|
return True
|
|
|
|
def do_handle_switch(self, l, match):
|
|
current_pid = int(match.group(1))
|
|
cpu_core = int(match.group(2))
|
|
current_time = float(match.group(3))*1000 #ms
|
|
out_name = match.group(4)
|
|
out_pid = int(match.group(5))
|
|
out_prio = int(match.group(6))
|
|
out_state = match.group(7)
|
|
in_name = match.group(8)
|
|
in_pid = int(match.group(9))
|
|
in_prio = int(match.group(10))
|
|
out_process = self.processes.get(out_pid)
|
|
if not out_process:
|
|
out_process = SchedProcess(out_pid)
|
|
self.processes[out_pid] = out_process
|
|
in_process = self.processes.get(in_pid)
|
|
if not in_process:
|
|
in_process = SchedProcess(in_pid)
|
|
self.processes[in_pid] = in_process
|
|
out_process.handle_switch_out(current_time, out_state, out_prio, out_name, cpu_core)
|
|
in_process.handle_switch_in(current_time, in_prio, in_name, cpu_core)
|
|
|
|
def do_handle_reason(self, l, match):
|
|
current_pid = int(match.group(1))
|
|
cpu_core = int(match.group(2))
|
|
current_time = float(match.group(3))*1000 #ms
|
|
pid = int(match.group(4))
|
|
iowait = int(match.group(5))
|
|
waiting_call = match.group(6)
|
|
process = self.processes.get(pid)
|
|
if not process:
|
|
process = SchedProcess(pid)
|
|
self.processes[pid] = process
|
|
process.handle_reason(current_time, iowait, waiting_call)
|
|
|
|
def dump(self):
|
|
sorted_by_total_execution = collections.OrderedDict(sorted(self.processes.items(), \
|
|
key = lambda item: item[1].total_io_wait_time, reverse = True))
|
|
for k, v in sorted_by_total_execution.iteritems():
|
|
if v.total_execution_time > 10.0 or v.total_io_wait_time != 0.0:
|
|
v.dump()
|
|
|
|
def main(argv):
|
|
if (len(argv) < 2):
|
|
print "check_io_trace_all.py filename"
|
|
return
|
|
filename = argv[1]
|
|
|
|
io_trace = IoTrace()
|
|
sched_trace = SchedTrace()
|
|
with open(filename) as f:
|
|
for l in f:
|
|
if io_trace.parse(l):
|
|
continue
|
|
sched_trace.parse(l)
|
|
io_trace.dump()
|
|
print "\n\n\n"
|
|
sched_trace.dump()
|
|
|
|
if __name__ == '__main__':
|
|
main(sys.argv)
|