From dd6a06ce8c824ec16ceac792d8c9cf5f5bbabaf9 Mon Sep 17 00:00:00 2001 From: Wei Wang Date: Thu, 29 Mar 2018 14:54:18 -0700 Subject: Move boottime I/O tools to system/extra Bug: 65481007 Test: Build Change-Id: I6415b210b4acae87f5e97c980a0f032cdc75161e --- boottime_tools/io_analysis/check_file_read.py | 441 +++++++++++++++++++++++ boottime_tools/io_analysis/check_io_trace.py | 193 ++++++++++ boottime_tools/io_analysis/check_io_trace_all.py | 386 ++++++++++++++++++++ boottime_tools/io_analysis/check_verity.py | 139 +++++++ 4 files changed, 1159 insertions(+) create mode 100644 boottime_tools/io_analysis/check_file_read.py create mode 100644 boottime_tools/io_analysis/check_io_trace.py create mode 100644 boottime_tools/io_analysis/check_io_trace_all.py create mode 100644 boottime_tools/io_analysis/check_verity.py diff --git a/boottime_tools/io_analysis/check_file_read.py b/boottime_tools/io_analysis/check_file_read.py new file mode 100644 index 00000000..f7854366 --- /dev/null +++ b/boottime_tools/io_analysis/check_file_read.py @@ -0,0 +1,441 @@ +#!/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 ext4 trace with custom open trace""" +import collections +import math +import os +import re +import string +import sys + +DBG = False +DBG_ISSUE = False + +# hard coded maps to detect partition for given device or the other way around +# this can be different per each device. This works for marlin. +DEVICE_TO_PARTITION = { "253,0": "/system/", "253,1": "/vendor/", "259,19": "/data/" } +PARTITION_TO_DEVICE = {} +for key, value in DEVICE_TO_PARTITION.iteritems(): + PARTITION_TO_DEVICE[value] = key + +# init-1 [003] .... 2.703964: do_sys_open: init: open("/sys/fs/selinux/null", 131074, 0) fd = 0, inode = 22 +RE_DO_SYS_OPEN = r"""\s+\S+-([0-9]+).*\s+([0-9]+\.[0-9]+):\s+do_sys_open:\s+(\S+):\sopen..(\S+).,\s([0-9]+).\s+.+inode\s=\s([0-9]+)""" +# init-1 [003] ...1 2.703991: ext4_ext_map_blocks_enter: dev 253,0 ino 2719 lblk 154 len 30 flags +RE_EXT4_MA_BLOCKS_ENTER = r"""\s+(\S+)-([0-9]+).+\s+([0-9]+\.[0-9]+):\s+ext4_ext_map_blocks_enter:\s+dev\s+(\S+)\s+ino\s+([0-9]+)\s+lblk\s+([0-9]+)\s+len\s+([0-9]+)""" +# init-1 [002] ...1 2.687205: ext4_ext_map_blocks_exit: dev 253,0 ino 8 flags lblk 0 pblk 196608 len 1 mflags M ret 1 +RE_EXT4_MA_BLOCKS_EXIT = r"""\s+(\S+)-([0-9]+).+\s+([0-9]+\.[0-9]+):\s+ext4_ext_map_blocks_exit:\s+dev\s+(\S+)\s+ino\s+([0-9]+)\sflags.*\slblk\s+([0-9]+)\spblk\s([0-9]+)\slen\s+([0-9]+).*mflags\s(\S*)\sret\s([0-9]+)""" +# init-1 [002] ...1 2.887119: block_bio_remap: 8,0 R 10010384 + 8 <- (259,18) 3998944 +RE_BLOCK_BIO_REMAP = r""".+block_bio_remap:\s\d+,\d+\s\S+\s(\d+)\s\+\s\d+\s<-\s\([^\)]+\)\s(\d+)""" +# kworker/u9:1-83 [003] d..2 2.682991: block_rq_issue: 8,0 RA 0 () 10140208 + 32 [kworker/u9:1] +RE_BLOCK_RQ_ISSUE = r"""\s+\S+-([0-9]+).*\s+([0-9]+\.[0-9]+):\s+block_rq_issue:\s+([0-9]+)\,([0-9]+)\s+([RW]\S*)\s[0-9]+\s\([^\)]*\)\s([0-9]+)\s+\+\s+([0-9]+)\s+\[([^\]]+)\]""" + +EXT4_SIZE_TO_BLOCK_SIZE = 8 # ext4: 4KB, block device block size: 512B + +class FileAccess: + def __init__(self, file): + self.file = file + self.accesses = [] + self.total_access = 0 + self.ext4_access_size_histogram = {} #key: read size, value: occurrence + self.block_access_size_histogram = {} + self.ext4_single_block_accesses = {} # process name, occurrence + self.block_single_block_accesses = {} # process name, occurrence + self.blocks_histogram = {} # K: offset, V: read counter + + def add_if_single_block(self, container, size, offset, process_name): + if size != 1: + return + offsets = container.get(process_name) + if not offsets: + offsets = [] + container[process_name] = offsets + offsets.append(offset) + + def add_access(self, time, offset, size, process_name, read_sizes): + self.accesses.append((time, offset, size, process_name)) + self.total_access += size + self.ext4_access_size_histogram[size] = self.ext4_access_size_histogram.get(size, 0) + 1 + read_offset = offset + for s in read_sizes: + self.block_access_size_histogram[s] = self.block_access_size_histogram.get(s, 0) + 1 + self.add_if_single_block(self.block_single_block_accesses, s, read_offset, process_name) + read_offset += s + for i in range(size): + self.blocks_histogram[offset + i] = self.blocks_histogram.get(offset + i, 0) + 1 + self.add_if_single_block(self.ext4_single_block_accesses, size, offset, process_name) + + def add_merged_access(self, time, offsets, lens, process_names): + total_read_offsets = set() # each read can overwrap. So count only once for block level counting + for i in range(len(offsets)): + self.accesses.append((time, offsets[i], lens[i], process_names[i])) + self.ext4_access_size_histogram[lens[i]] = self.ext4_access_size_histogram.get(lens[i], 0) + 1 + self.add_if_single_block(self.ext4_single_block_accesses, lens[i], offsets[i], process_names[i]) + for j in range(len(lens)): + total_read_offsets.add(offsets[i] + j) + total_lens = len(total_read_offsets) + start_offset = min(total_read_offsets) + self.total_access += total_lens + self.block_access_size_histogram[total_lens] = self.block_access_size_histogram.get(total_lens, 0) \ + + 1 + self.add_if_single_block(self.block_single_block_accesses, total_lens, start_offset, \ + process_names[0]) + for s in range(total_lens): + self.blocks_histogram[start_offset + s] = self.blocks_histogram.get(start_offset + s, 0) + 1 + + + def dump(self): + if len(self.ext4_access_size_histogram) > 1: + print " Ext4 access size histograms:", collections.OrderedDict( \ + sorted(self.ext4_access_size_histogram.items(), key = lambda item: item[0])) + if len(self.ext4_single_block_accesses) > 0 and self.total_access > 1: + print " Ext4 single block accesses:", collections.OrderedDict( \ + sorted(self.ext4_single_block_accesses.items(), key = lambda item: item[1], reverse = True)) + if len(self.block_access_size_histogram) > 1: + print " Block access size histograms:", collections.OrderedDict( \ + sorted(self.block_access_size_histogram.items(), key = lambda item: item[0])) + if len(self.block_single_block_accesses) > 0 and self.total_access > 1: + print " Block single block accesses:", collections.OrderedDict( \ + sorted(self.block_single_block_accesses.items(), key = lambda item: item[1], reverse = True)) + if self.total_access > 1: + sorted_blocks_histogram = sorted(self.blocks_histogram.items(), key = lambda item: item[1], \ + reverse = True) + prints = [] + repeating_reads_counter = 0 + for entry in sorted_blocks_histogram: + offset = entry[0] + counter = entry[1] + if counter == 1: + break + prints.append(str(offset) + ":" + str(counter)) + repeating_reads_counter += (counter - 1) + if len(prints) > 0: + print " repeating accesses", repeating_reads_counter, " offset:count ->", ','.join(prints) + +class FileEvent: + def __init__(self, open_time, file_name, process_name, inode, flags): + self.file_name = file_name + self.inode = inode + self.total_open = 1 + self.processes = [] + self.processes.append((open_time, process_name, flags)) + self.read = FileAccess(self) + self.write = FileAccess(self) + + + def add_open(self, open_time, process_name, flags): + self.processes.append((open_time, process_name, flags)) + self.total_open += 1 + + def add_access(self, is_read, time, offset, size, process_name, read_sizes): + if is_read: + self.read.add_access(time, offset, size, process_name, read_sizes) + else: + self.write.add_access(time, offset, size, process_name, read_sizes) + + def add_merged_access(self, is_read, time, offsets, lens, process_names): + if is_read: + self.read.add_merged_access(time, offsets, lens, process_names) + else: + self.write.add_merged_access(time, offsets, lens, process_names) + + def dump(self, name_to_pid_map): + print " ***filename %s, total reads %d, total writes %d, total open %d inode %s" \ + % (self.file_name, self.read.total_access, self.write.total_access, self.total_open,\ + self.inode) + process_names = [] + for opener in self.processes: + process_names.append(opener[1] + "-" + name_to_pid_map.get(opener[1], '?') + " t:" + \ + str(opener[0]) + " flags:" + opener[2]) + print " Processes opened this file:", ','.join(process_names) + if self.read.total_access > 0: + print " ****Reads:" + self.read.dump() + if self.write.total_access > 0: + print " ****Writes:" + self.write.dump() + + def dump_short(self): + print " filename %s, total reads %d, total writes %d" % (self.file_name, + self.read.total_access, self.write.total_access) + +class PendingAccess: + def __init__(self, process_name, pid, time, dev, inode, lblk, pblk, len, fevent): + self.process_name = process_name + self.pid = pid + self.time = time + self.dev = dev + self.inode = inode + self.lblk = lblk + self.pblk = pblk + self.blk_len = len * EXT4_SIZE_TO_BLOCK_SIZE + self.len = len + self.fevent = fevent + self.pending_accesses = set() + for i in range(len): + self.pending_accesses.add(i) + self.access_sizes = [] # valid read for this file in block dev level. + self.block_access_counter = 0 + + def get_valid_access(self, block_offset, block_len): + ext4_offset = block_offset / EXT4_SIZE_TO_BLOCK_SIZE + if ext4_offset > self.len: + return 0, 0 + ext4_len = block_len / EXT4_SIZE_TO_BLOCK_SIZE + if (ext4_offset + ext4_len) > self.len: + ext4_len = self.len - ext4_offset + return ext4_offset, ext4_len + + def queue_block_access(self, ext4_offset, ext4_len): + if ext4_len <= 0: + return + self.block_access_counter += 1 + ext4_blocks_accessed = 0 + for i in range(ext4_len): + ext4_block_i = i + ext4_offset + if ext4_block_i in self.pending_accesses: + ext4_blocks_accessed += 1 + self.pending_accesses.remove(ext4_block_i) + if ext4_blocks_accessed > 0: + self.access_sizes.append(ext4_blocks_accessed) + + def handle_req_complete(self, time, is_read): + self.fevent.add_access(is_read, self.time, self.lblk, self.len, self.process_name,\ + self.access_sizes) + + def handle_merged_req(self, time, offsets, lens, names, is_read): + self.fevent.add_merged_access(is_read, time, offsets, lens, names) + + def is_req_complete(self): + return len(self.pending_accesses) == 0 + + def is_req_started(self): + return self.len is not len(self.pending_accesses) + +class Trace: + def __init__(self): + self.files_per_device = {} # key: device, value: { key: inode, value; FileEvent } + self.re_open = re.compile(RE_DO_SYS_OPEN) + self.re_ext4_access = re.compile(RE_EXT4_MA_BLOCKS_EXIT) + self.re_bio_remap = re.compile(RE_BLOCK_BIO_REMAP) + self.re_block_issue = re.compile(RE_BLOCK_RQ_ISSUE) + # req from ext4 that has not gone down to block level yet, K:block address, + # V: list of PendingRead + self.pending_accesses = {} + self.remap = {} + self.process_names = {} # K: PID, V : name + + def handle_line(self, line): + match = self.re_open.match(line) + if match: + self.handle_open(match) + return + match = self.re_ext4_access.match(line) + if match: + self.handle_ext4_block_exit(match) + return + match = self.re_bio_remap.match(line) + if match: + self.handle_bio_remap(match) + return + match = self.re_block_issue.match(line) + if match: + self.handle_block_issue(match) + return + + def handle_open(self, match): + pid = int(match.group(1)) + time = match.group(2) + process_name = match.group(3) + file_name = match.group(4) + flag = match.group(5) + inode = int(match.group(6)) + dev_name = None + self.process_names[pid] = process_name + #print "open", pid, process_name, file_name, inode + for p in PARTITION_TO_DEVICE: + if file_name.startswith(p): + dev_name = PARTITION_TO_DEVICE[p] + if not dev_name: + if DBG: + print "Ignore open for file", file_name + return + files = self.files_per_device[dev_name] + fevent = files.get(inode) + if not fevent: + fevent = FileEvent(time, file_name, process_name, inode, flag) + files[inode] = fevent + else: + fevent.add_open(time, process_name, flag) + + def handle_ext4_block_exit(self, match): + process_name = match.group(1) + pid = int(match.group(2)) + time = float(match.group(3)) + dev = match.group(4) + inode = int(match.group(5)) + lblk = int(match.group(6)) + pblk = int(match.group(7)) * EXT4_SIZE_TO_BLOCK_SIZE # address in ext4 blocks, ... + l = int(match.group(8)) + mflags = match.group(9) + ret = int(match.group(10)) + if ret <= 0: # no block access + return + process_name = self.process_names.get(pid, process_name) + if process_name == '<...>': + process_name = "pid-" + str(pid) + if DBG_ISSUE: + print "ext4", pblk, l, inode, process_name + files = self.files_per_device.get(dev) + if not files: + if DEVICE_TO_PARTITION.get(dev): + files = {} + self.files_per_device[dev] = files + else: + if DBG: + print "access ignored for device", dev + return + fevent = files.get(inode) + if not fevent: + if DBG: + print 'no open for device %s with inode %s' % (dev, inode) + fevent = FileEvent(time, "unknown", process_name, inode, "-") + files[inode] = fevent + pending_access = PendingAccess(process_name, pid, time, dev, inode, lblk, pblk, l,\ + fevent) + access_list = self.pending_accesses.get(pblk, []) + access_list.append(pending_access) + self.pending_accesses[pblk] = access_list + + def handle_bio_remap(self, match): + new_addr = int(match.group(1)) + old_addr = int(match.group(2)) + self.remap[new_addr] = old_addr + if DBG_ISSUE: + print "remap", new_addr, old_addr + + def handle_block_issue(self, match): + pid = int(match.group(1)) + time = float(match.group(2)) + dev_major = match.group(3) + dev_minor = match.group(4) + access = match.group(5) + new_address = int(match.group(6)) + l = int(match.group(7)) + name = match.group(8) + name = self.process_names.get(pid, name) + if name == '<...>': + name = "pid-" + str(pid) + is_read = not 'W' in access + accesses_per_inodes = {} # K:inodes, V: list of two entries, 1st: offsets, 2nd: length + addrs_to_remove = [] + completed_reqs = [] + address = self.remap.get(new_address, new_address) + if DBG_ISSUE: + print "issue", address, l, is_read, access + for access_addr, access_list in self.pending_accesses.iteritems(): + if (address >= access_addr) and (address + l) > access_addr: + reqs_to_remove = [] + for pending in access_list: + offset, valid_access_size = pending.get_valid_access(address - access_addr, l) + if valid_access_size > 0: + if pending.is_req_started(): # spread across multiple reads. complete alone + pending.queue_block_access(offset, valid_access_size) + if pending.is_req_complete(): + pending.handle_req_complete(time, is_read) + reqs_to_remove.append(pending) + else: # possible multiple reads completed in this read. complete them together + pending.queue_block_access(offset, valid_access_size) + if pending.is_req_complete(): + reads = accesses_per_inodes.get(pending.inode, [[], [], []]) + reads[0].append(offset + pending.lblk) + reads[1].append(valid_access_size) + reads[2].append(pending.process_name) + accesses_per_inodes[pending.inode] = reads + completed_reqs.append(pending) + reqs_to_remove.append(pending) + for to_remove in reqs_to_remove: + access_list.remove(to_remove) + if len(access_list) == 0: + addrs_to_remove.append(access_addr) + for addr in addrs_to_remove: + del self.pending_accesses[addr] + for pending in completed_reqs: # these will be reported as batch + accesses = accesses_per_inodes.get(pending.inode) + if not accesses: # merged one already dispatched + continue + if len(accesses[0]) == 1: + pending.handle_req_complete(time, is_read) + else: #merged + pending.handle_merged_req(time, accesses[0], accesses[1], accesses[2], is_read) + del accesses_per_inodes[pending.inode] + + def dump_partition(self, partition_name, files): + name_to_pid_map = {} + for pid, name in self.process_names.iteritems(): + name_to_pid_map[name] = str(pid) + print "**Dump partition:", partition_name, "total number of files:", len(files) + total_reads = 0 + total_writes = 0 + files_sorted_by_read = files.values() + files_sorted_by_read.sort(key=lambda f : f.read.total_access, reverse = True) + files_sorted_by_write = files.values() + files_sorted_by_write.sort(key=lambda f : f.write.total_access, reverse = True) + print " Top 10 readers:" + for i in range(min(10, len(files_sorted_by_read))): + files_sorted_by_read[i].dump_short() + print " Top 10 writers:" + for i in range(min(10, len(files_sorted_by_write))): + files_sorted_by_write[i].dump_short() + for f in files_sorted_by_read: + f.dump(name_to_pid_map) + total_reads += f.read.total_access + total_writes += f.write.total_access + print " Total reads:", total_reads, " total writes:", total_writes + return total_reads, total_writes, len(files) + + + def dump(self): + print "*Dump R/W per each partition" + total_reads = 0 + total_writes = 0 + summaries = [] + for d in self.files_per_device: + reads, writes, num_files = self.dump_partition(DEVICE_TO_PARTITION[d], \ + self.files_per_device[d]) + total_reads += reads + total_writes += writes + summaries.append((DEVICE_TO_PARTITION[d], reads, writes, num_files)) + print "*Summary*" + print "Total blocks read", total_reads + print "Total blocks wrote", total_writes + print "Partition total_reads total_writes num_files" + for s in summaries: + print s[0], s[1], s[2], s[3] + +def main(argv): + if (len(argv) < 2): + print "check_fule_read.py filename" + return + filename = argv[1] + trace = Trace() + with open(filename) as f: + for l in f: + trace.handle_line(l) + trace.dump() + +if __name__ == '__main__': + main(sys.argv) diff --git a/boottime_tools/io_analysis/check_io_trace.py b/boottime_tools/io_analysis/check_io_trace.py new file mode 100644 index 00000000..bc26c467 --- /dev/null +++ b/boottime_tools/io_analysis/check_io_trace.py @@ -0,0 +1,193 @@ +#!/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 + +RE_BLOCK = r'.+\s+(block[a-z_]+):\s+' +RE_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+\[([^\]]+)' + +# dev_num = major * MULTIPLIER + minor +DEV_MAJOR_MULTIPLIER = 1000 + +# dm access is remapped to disk access. So account differently +DM_MAJOR = 253 + +class RwEvent: + def __init__(self, block_num, start_time, size): + self.block_num = block_num + self.start_time = start_time + self.size = size + self.latency = 0 + def set_latency(self, latency): + self.latency = latency + +def get_string_pos(strings, string_to_find): + for i, s in enumerate(strings): + if s == string_to_find: + return i + return -1 + + +class Trace: + def __init__(self, process): + self.process = process + self.reads = [] #(start time, RwEvent) + self.writes = [] #(start time, RwEvent) + self.recent_reads = {} # K: + self.total_latency = 0 + self.total_reads = 0 + self.total_writes = 0 + self.total_dm_reads = {} #K: devnum, V: blocks + self.total_dm_writes = {} + self.re_block_queue = re.compile(RE_BLOCK_BIO_QUEUE) + self.processes = set() + if process[-1] == '*': + print "Process name starts with", process[:-1] + self.process_name_is_prefix = True + else: + print "Process name", process + self.process_name_is_prefix = False + + def parse_bio_queue(self, l): + match = self.re_block_queue.match(l) + if not match: + return + start_time = int(float(match.group(1))*1000000) #us + major = int(match.group(2)) + minor = int(match.group(3)) + operation = match.group(4) + block_num = int(match.group(5)) + size = int(match.group(6)) + process = match.group(7) + if self.process_name_is_prefix: + if not process.startswith(self.process[:-1]): + return + self.processes.add(process) + else: + if process != self.process: + return + if major == DM_MAJOR: + devNum = major * DEV_MAJOR_MULTIPLIER + minor; + if operation[0] == 'R': + if devNum not in self.total_dm_reads: + self.total_dm_reads[devNum] = 0 + self.total_dm_reads[devNum] += size + elif operation[0] == 'W': + if devNum not in self.total_dm_writes: + self.total_dm_writes[devNum] = 0 + self.total_dm_writes[devNum] += size + return + event = RwEvent(block_num, start_time, size) + if operation[0] == 'R': + self.reads.append((start_time, event)) + self.recent_reads[block_num] = event + self.total_reads += size + elif operation[0] == 'W': + self.writes.append((start_time, event)) + self.total_writes += size + + def parse_rq_complete(self, l): + words = string.split(l) + cmd_pos = get_string_pos(words, "block_rq_complete:") + if cmd_pos == -1: + cmd_pos = get_string_pos(words, "block_bio_complete:") + block_num = int(words[-4]) + event = self.recent_reads.get(block_num) + if not event: + return + operation = words[cmd_pos + 2] + if not operation.startswith("R"): + return + end_time = int(float(words[cmd_pos - 1][:-1])*1000000) #us + latency = end_time - event.start_time + if latency > 20000: + print "very bad latency:", latency, l + print "start time,", event.start_time + event.set_latency(latency) + del self.recent_reads[block_num] + self.total_latency += latency + + def parse_block_trace(self, l, match): + try: + cmd = match.group(1) + if cmd == "block_bio_queue": + self.parse_bio_queue(l) + elif cmd == "block_rq_complete" or cmd == "block_bio_complete": + self.parse_rq_complete(l) + except ValueError: + print "cannot parse:", l + raise + + def dump(self): + if self.process_name_is_prefix: + print "Processes:", self.processes + print "total read blocks,", self.total_reads + print "total write blocks,", self.total_writes + if len(self.reads) > 0: + total_read_time = self.reads[-1][0] + self.reads[-1][1].latency - self.reads[0][0] + else: + total_read_time = 0 + 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 "total read time,",total_read_time + read_size_histogram = {} + latency_per_read_size = {} + for (time, event) in self.reads: + if not read_size_histogram.get(event.size): + read_size_histogram[event.size] = 0 + if not latency_per_read_size.get(event.size): + latency_per_read_size[event.size] = [ 0, 0] # num events, total latency + read_size_histogram[event.size] = read_size_histogram[event.size] + 1 + latency_sum = latency_per_read_size[event.size] + latency_sum[0] += 1 + latency_sum[1] += event.latency + read_size_histogram = collections.OrderedDict(sorted(read_size_histogram.items())) + print "read histogram" + for k,v in read_size_histogram.iteritems(): + print k, ',', v + print "latency per read size" + latency_per_read_size = collections.OrderedDict(sorted(latency_per_read_size.items())) + for k,v in latency_per_read_size.iteritems(): + if v[0] != 0: + print k, ',', v[1] / v[0], v[0], v[1] + +def main(argv): + if (len(argv) < 3): + print "check_io_trace.py processname filename" + return + keyword = argv[1] + filename = argv[2] + trace = Trace(keyword) + prog = re.compile(RE_BLOCK) + with open(filename) as f: + for l in f: + result = prog.match(l) + if result: + trace.parse_block_trace(l, result) + trace.dump() + +if __name__ == '__main__': + main(sys.argv) diff --git a/boottime_tools/io_analysis/check_io_trace_all.py b/boottime_tools/io_analysis/check_io_trace_all.py new file mode 100644 index 00000000..8ea466d7 --- /dev/null +++ b/boottime_tools/io_analysis/check_io_trace_all.py @@ -0,0 +1,386 @@ +#!/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) -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) diff --git a/boottime_tools/io_analysis/check_verity.py b/boottime_tools/io_analysis/check_verity.py new file mode 100644 index 00000000..a69818fb --- /dev/null +++ b/boottime_tools/io_analysis/check_verity.py @@ -0,0 +1,139 @@ +#!/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 dm_verity trace""" +import collections +import math +import os +import re +import string +import sys + +RE_VERITY = r'.+\s+([0-9]+\.[0-9]+):\s+block_verity_msg:\s+(\S+)\s+([0-9]+)\,([0-9]+)\s+([0-9]+)\s+([0-9]+)' + +def get_average_and_std_dev(l): + sum_io = 0.0 + sum_verity = 0.0 + sum_total = 0.0 + N = len(l) + sum_blocks = 0.0 + for e in l: + sum_io += e.io_latency + sum_verity += e.verity_latency + sum_total += e.total_latency + sum_blocks += e.size + average_io = sum_io / N + average_verity = sum_verity / N + average_total = sum_total / N + var_io = 0.0 + var_verity = 0.0 + var_total = 0.0 + for e in l: + var_io += (e.io_latency - average_io)**2 + var_verity += (e.verity_latency - average_verity)**2 + var_total += (e.total_latency - average_total)**2 + sigma_io = math.sqrt(var_io / N) + sigma_verity = math.sqrt(var_verity / N) + sigma_total = math.sqrt(var_total / N) + return (average_io, sigma_io, sum_io), (average_verity, sigma_verity, sum_verity), \ + (average_total, sigma_total, sum_total), sum_blocks + + +class Event: + def __init__(self, start_time, block_num, size): + self.block_num = block_num + self.start_time = start_time + self.io_end_time = 0 + self.finish_time = 0 + self.size = size + self.total_latency = 0 + self.io_latency = 0 + self.verity_latency = 0 + + def set_io_end_time(self, io_end_time): + self.io_end_time = io_end_time + self.io_latency = io_end_time - self.start_time + + def set_finish_time(self, finish_time): + self.finish_time = finish_time + self.verity_latency = finish_time - self.io_end_time + self.total_latency = finish_time - self.start_time + +class VerityTrace: + def __init__(self): + self.reads = [] # all events in start time + self.block_size_vs_reads_histogram = {} # key: size, value: list of events + self.recents = {} # not finished, key: block_nr, value: event + self.re = re.compile(RE_VERITY) + + def handle_line(self, line): + match = self.re.match(line) + if not match: + return + time = int(float(match.group(1))*1000000) #us + step = match.group(2) + block_nr = int(match.group(5)) + size = int(match.group(6)) + recent_key = block_nr * 1000 + size + if step == "map": + event = Event(time, block_nr, size) + self.recents[recent_key] = event + self.reads.append(event) + per_size_list = self.block_size_vs_reads_histogram.get(size) + if not per_size_list: + per_size_list = [] + self.block_size_vs_reads_histogram[size] = per_size_list + per_size_list.append(event) + elif step == "end_io": + event = self.recents[recent_key] + event.set_io_end_time(time) + elif step == "finish_io": + event = self.recents[recent_key] + event.set_finish_time(time) + del self.recents[recent_key] + + def dump_list(self, msg, l): + io, verity, total, blocks = get_average_and_std_dev(l) + print msg, "counts:", len(l), "io latency:", io[0], io[1], io[2], "verity latency:", \ + verity[0], verity[1], verity[2], "total:", total[0], total[1], total[2] + return io, verity, total, blocks + + def dump(self): + print "Numbers: average (us), stddev (us), total (us)" + io, verity, total, blocks = self.dump_list ("total,", self.reads) + io_latency_per_1024KB = io[2] / blocks * (1024 / 4) + verity_latency_per_1024KB = verity[2] / blocks * (1024 / 4) + total_latency_per_1024KB = io_latency_per_1024KB + verity_latency_per_1024KB + print "Average latency for 1024KB (us), IO:", io_latency_per_1024KB, \ + "Verity:", verity_latency_per_1024KB, "Total:", total_latency_per_1024KB + sizes = sorted(self.block_size_vs_reads_histogram.keys()) + print "Latency per read size" + for s in sizes: + self.dump_list ("size " + str(s), self.block_size_vs_reads_histogram[s]) + +def main(argv): + if (len(argv) < 2): + print "check_io_trace.py filename" + return + filename = argv[1] + trace = VerityTrace() + with open(filename) as f: + for l in f: + trace.handle_line(l) + trace.dump() + +if __name__ == '__main__': + main(sys.argv) -- cgit v1.2.3 From 1c8fd56b390cae7b505c0a06ed5609941a6caea6 Mon Sep 17 00:00:00 2001 From: Wei Wang Date: Thu, 29 Mar 2018 14:58:12 -0700 Subject: io_analysis/check_file_read.py: fix typo Bug: 65481007 Test: Build Change-Id: I082bf20e181a19f6f9b7158bb6088af60c123440 --- boottime_tools/io_analysis/check_file_read.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) mode change 100644 => 100755 boottime_tools/io_analysis/check_file_read.py diff --git a/boottime_tools/io_analysis/check_file_read.py b/boottime_tools/io_analysis/check_file_read.py old mode 100644 new mode 100755 index f7854366..5f629f3a --- a/boottime_tools/io_analysis/check_file_read.py +++ b/boottime_tools/io_analysis/check_file_read.py @@ -428,7 +428,7 @@ class Trace: def main(argv): if (len(argv) < 2): - print "check_fule_read.py filename" + print "check_file_read.py filename" return filename = argv[1] trace = Trace() -- cgit v1.2.3