| #!/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) |