diff options
Diffstat (limited to 'simpleperf/scripts/debug_unwind_reporter.py')
| -rwxr-xr-x | simpleperf/scripts/debug_unwind_reporter.py | 652 |
1 files changed, 226 insertions, 426 deletions
diff --git a/simpleperf/scripts/debug_unwind_reporter.py b/simpleperf/scripts/debug_unwind_reporter.py index 864003a9..238c9acd 100755 --- a/simpleperf/scripts/debug_unwind_reporter.py +++ b/simpleperf/scripts/debug_unwind_reporter.py @@ -1,4 +1,4 @@ -#!/usr/bin/env python +#!/usr/bin/env python3 # # Copyright (C) 2017 The Android Open Source Project # @@ -15,457 +15,257 @@ # limitations under the License. # -"""debug_unwind_reporter.py: report dwarf unwinding results generated by debug-unwind cmd. - Below is an example using debug_unwind_reporter.py: - 1. Record with "-g --no-unwind" option on device. - simpleperf record -g --no-unwind --app com.google.sample.tunnel --duration 10 - 2. Use debug-unwind cmd to unwind samples in perf.data on device. - simpleperf debug-unwind - 3. Pull perf.data.debug on host, and report it with this script. - python debug_unwind_reporter.py - - It reports below items: - 1. time used for offline dwarf unwinding for each sample. - 2. mem consumption before and after unwinding samples. - 3. For samples that don't have complete callchains, report their regs, stack data, - unwinding failure info, callchains. Samples having the same failure reason - in the same function are only reported once. - - It can be used to: - 1. show unwinding failures. - 2. show performance and memory consumption change caused by simpleperf/unwinder changes. -""" - -from __future__ import print_function -import argparse -import bisect -import collections -import copy -import re -import subprocess - -from utils import bytes_to_str, log_exit, log_fatal, get_host_binary_path - - -class MapEntry(object): - - def __init__(self, start, end, filename): - self.start = start - self.end = end - self.filename = filename +"""debug_unwind_reporter.py: report failed dwarf unwinding cases generated by debug-unwind cmd. - def __lt__(self, other): - return self.start < other.start +Below is an example using debug_unwind_reporter.py: +1. Record with "-g --keep-failed-unwinding-debug-info" option on device. + $ simpleperf record -g --keep-failed-unwinding-debug-info --app com.google.sample.tunnel \\ + --duration 10 + The generated perf.data can be used for normal reporting. But it also contains stack data + and binaries for debugging failed unwinding cases. -class ProcessMaps(object): +2. Generate report with debug-unwind cmd. + $ simpleperf debug-unwind -i perf.data --generate-report -o report.txt + The report contains details for each failed unwinding case. It is usually too long to + parse manually. That's why we need debug_unwind_reporter.py. - def __init__(self): - self.process_maps = {} # map from pid to a sorted list of MapEntry. - - def add(self, pid, map_entry): - old_list = self.process_maps.get(pid, []) - new_list = [] - map_entry_used = False - for entry in old_list: - if entry.end <= map_entry.start: - new_list.append(entry) - elif entry.start < map_entry.start: - entry.end = map_entry.start - new_list.append(entry) - else: - if not map_entry_used: - new_list.append(map_entry) - map_entry_used = True - if entry.start >= map_entry.end: - new_list.append(entry) - elif entry.end > map_entry.end: - entry.start = map_entry.end - new_list.append(entry) - if not map_entry_used: - new_list.append(map_entry) - self.process_maps[pid] = new_list - - def fork_pid(self, pid, ppid): - if pid == ppid: - return - entry_list = self.process_maps.get(ppid, []) - self.process_maps[pid] = copy.deepcopy(entry_list) - - def find(self, pid, addr): - key = MapEntry(addr, addr, '') - entry_list = self.process_maps.get(pid, []) - pos = bisect.bisect_right(entry_list, key) - if pos > 0 and entry_list[pos - 1].end > addr: - return entry_list[pos - 1] - return None - - def show(self): - for pid in sorted(self.process_maps): - print(' pid %d' % pid) - for entry in self.process_maps[pid]: - print(' map [%x-%x] %s' % - (entry.start, entry.end, entry.filename)) - - -class UnwindingTimes(object): - - def __init__(self): - self.total_time = 0 - self.count = 0 - self.max_time = 0 - - def add_time(self, used_time): - self.total_time += used_time - self.count += 1 - self.max_time = max(self.max_time, used_time) +3. Use debug_unwind_reporter.py to parse the report. + $ simpleperf debug-unwind -i report.txt --summary + $ simpleperf debug-unwind -i report.txt --include-error-code 1 + ... +""" +import argparse +from collections import Counter, defaultdict +from simpleperf_utils import ArgParseFormatter +from texttable import Texttable +from typing import Dict, Iterator, List -class UnwindingMemConsumption(object): +class CallChainNode: def __init__(self): - self.before_unwinding = None - self.after_unwinding = None - - -class CallChainNode(object): - - """ Representing a node in a call chain.""" - - def __init__(self, ip, sp, filename, vaddr_in_file, function_name, map_start_addr, - map_end_addr): - self.ip = ip - self.sp = sp - self.filename = filename - self.vaddr_in_file = vaddr_in_file - self.function_name = function_name - self.map_start_addr = map_start_addr - self.map_end_addr = map_end_addr + self.dso = '' + self.symbol = '' + + +class Sample: + """ A failed unwinding case """ + + def __init__(self, raw_lines: List[str]): + self.raw_lines = raw_lines + self.sample_time = 0 + self.error_code = 0 + self.callchain: List[CallChainNode] = [] + self.parse() + + def parse(self): + for line in self.raw_lines: + key, value = line.split(': ', 1) + if key == 'sample_time': + self.sample_time = int(value) + elif key == 'unwinding_error_code': + self.error_code = int(value) + elif key.startswith('dso'): + callchain_id = int(key.rsplit('_', 1)[1]) + self._get_callchain_node(callchain_id).dso = value + elif key.startswith('symbol'): + callchain_id = int(key.rsplit('_', 1)[1]) + self._get_callchain_node(callchain_id).symbol = value + + def _get_callchain_node(self, callchain_id: int) -> CallChainNode: + callchain_id -= 1 + if callchain_id == len(self.callchain): + self.callchain.append(CallChainNode()) + return self.callchain[callchain_id] + + +class SampleFilter: + def match(self, sample: Sample) -> bool: + raise Exception('unimplemented') + + +class CompleteCallChainFilter(SampleFilter): + def match(self, sample: Sample) -> bool: + for node in sample.callchain: + if node.dso.endswith('libc.so') and (node.symbol in ('__libc_init', '__start_thread')): + return True + return False -class SampleResult(object): +class ErrorCodeFilter(SampleFilter): + def __init__(self, error_code: List[int]): + self.error_code = set(error_code) - """ Unwinding result per sample. """ + def match(self, sample: Sample) -> bool: + return sample.error_code in self.error_code - def __init__(self, pid, tid, unwinding_result, callchain, sample_record): - self.pid = pid - self.tid = tid - self.unwinding_result = unwinding_result - self.callchain = callchain - self.sample_record = sample_record - def show(self): - print(' pid: %d' % self.pid) - print(' tid: %d' % self.tid) - for key, value in self.unwinding_result.items(): - print(' %s: %s' % (key, value)) - for i, node in enumerate(self.callchain): - print(' node %d: ip 0x%x, sp 0x%x, %s (%s[+%x]), map [%x-%x]' % ( - i, node.ip, node.sp, node.function_name, node.filename, node.vaddr_in_file, - node.map_start_addr, node.map_end_addr)) - if self.sample_record: - print(' original sample record:') - for line in self.sample_record: - print(' %s' % line) +class EndDsoFilter(SampleFilter): + def __init__(self, end_dso: List[str]): + self.end_dso = set(end_dso) + def match(self, sample: Sample) -> bool: + return sample.callchain[-1].dso in self.end_dso -class FunctionResult(object): - """ Unwinding result per function. """ +class EndSymbolFilter(SampleFilter): + def __init__(self, end_symbol: List[str]): + self.end_symbol = set(end_symbol) - def __init__(self): - # Map from Unwinding result reason to [SampleResult]. - self.sample_results = {} + def match(self, sample: Sample) -> bool: + return sample.callchain[-1].symbol in self.end_symbol - def add_sample_result(self, sample_result): - stop_reason = sample_result.unwinding_result['stop_reason'] - result_list = self.sample_results.get(stop_reason) - if not result_list: - result_list = self.sample_results[stop_reason] = [] - for result in result_list: - if result.callchain[-1].vaddr_in_file == sample_result.callchain[-1].vaddr_in_file: - # This sample_result duplicates with an existing one. - return - # We don't want to store too many sample results for a function. - if len(result_list) < 10: - result_list.append(sample_result) - def show(self): - for stop_reason in sorted(self.sample_results): - for sample_result in self.sample_results[stop_reason]: - sample_result.show() +class SampleTimeFilter(SampleFilter): + def __init__(self, sample_time: List[int]): + self.sample_time = set(sample_time) + def match(self, sample: Sample) -> bool: + return sample.sample_time in self.sample_time -class FileResult(object): - - """ Unwinding result per shared library. """ +class ReportInput: def __init__(self): - self.function_results = {} # Map from function_name to FunctionResult. - - def add_sample_result(self, sample_result): - function_name = sample_result.callchain[-1].function_name - function_result = self.function_results.get(function_name) - if not function_result: - function_result = self.function_results[ - function_name] = FunctionResult() - function_result.add_sample_result(sample_result) - - def show(self): - for function_name in sorted(self.function_results): - print(' function %s' % function_name) - self.function_results[function_name].show() - print('\n') - - -class UnwindingResultErrorReport(object): - - """ Report time used for unwinding and unwinding result errors. """ - - def __init__(self, omit_callchains_fixed_by_joiner): - self.omit_callchains_fixed_by_joiner = omit_callchains_fixed_by_joiner - self.process_maps = ProcessMaps() - self.unwinding_times = UnwindingTimes() - self.mem_stat = UnwindingMemConsumption() - self.file_results = {} # map from filename to FileResult. - - def add_sample_result(self, sample_result, joined_record): - self.unwinding_times.add_time(int(sample_result.unwinding_result['used_time'])) - if self.should_omit(sample_result, joined_record): - return - filename = sample_result.callchain[-1].filename - file_result = self.file_results.get(filename) - if not file_result: - file_result = self.file_results[filename] = FileResult() - file_result.add_sample_result(sample_result) - - def add_mem_stat(self, name, mem_str): - # mem_str is like VmPeak:202464 kB;VmSize:183456 kB;VmHWM:98256 kB;VmRSS:33680 kB. - items = [] - for p in mem_str.split(';'): - key, value = p.split(':') - items.append((key, value)) - if name == 'debug_unwind_mem_before': - self.mem_stat.before_unwinding = items - else: - self.mem_stat.after_unwinding = items - - def should_omit(self, sample_result, joined_record): - # 1. Can't unwind code generated in memory. - for name in ['/dev/ashmem/dalvik-jit-code-cache', '[anon:dalvik-jit-code-cache]', '//anon']: - if name in sample_result.callchain[-1].filename: - return True - # 2. Don't report complete callchains, which can reach __libc_init or __start_thread in - # libc.so. - def is_callchain_complete(callchain): - for node in callchain: - if (node.filename.endswith('libc.so') and - node.function_name in ['__libc_init', '__start_thread']): - return True - return False - if is_callchain_complete(sample_result.callchain): - return True - # 3. Omit callchains made complete by callchain joiner. - if self.omit_callchains_fixed_by_joiner and is_callchain_complete(joined_record.callchain): - return True - return False - - def show(self): - print('Unwinding time info:') - print(' total time: %f ms' % (self.unwinding_times.total_time / 1e6)) - print(' unwinding count: %d' % self.unwinding_times.count) - if self.unwinding_times.count > 0: - print(' average time: %f us' % ( - self.unwinding_times.total_time / 1e3 / self.unwinding_times.count)) - print(' max time: %f us' % (self.unwinding_times.max_time / 1e3)) - print('Unwinding mem info:') - for items in zip(self.mem_stat.before_unwinding, self.mem_stat.after_unwinding): - assert items[0][0] == items[1][0] - print(' %s: %s -> %s' % (items[0][0], items[0][1], items[1][1])) - print('Process maps:') - self.process_maps.show() - for filename in sorted(self.file_results): - print('filename %s' % filename) - self.file_results[filename].show() - print('\n') - - -class CallChainRecord(object): - """ Store data of a callchain record. """ - + self.exclude_filters: List[SampleFilter] = [] + self.include_filters: List[SampleFilter] = [] + + def set_filters(self, args: argparse.Namespace): + if not args.show_callchain_fixed_by_joiner: + self.exclude_filters.append(CompleteCallChainFilter()) + if args.exclude_error_code: + self.exclude_filters.append(ErrorCodeFilter(args.exclude_error_code)) + if args.exclude_end_dso: + self.exclude_filters.append(EndDsoFilter(args.exclude_end_dso)) + if args.exclude_end_symbol: + self.exclude_filters.append(EndSymbolFilter(args.exclude_end_symbol)) + if args.exclude_sample_time: + self.exclude_filters.append(SampleTimeFilter(args.exclude_sample_time)) + + if args.include_error_code: + self.include_filters.append(ErrorCodeFilter(args.include_error_code)) + if args.include_end_dso: + self.include_filters.append(EndDsoFilter(args.include_end_dso)) + if args.include_end_symbol: + self.include_filters.append(EndSymbolFilter(args.include_end_symbol)) + if args.include_sample_time: + self.include_filters.append(SampleTimeFilter(args.include_sample_time)) + + def get_samples(self, input_file: str) -> Iterator[Sample]: + sample_lines: List[str] = [] + in_sample = False + with open(input_file, 'r') as fh: + for line in fh.readlines(): + line = line.rstrip() + if line.startswith('sample_time:'): + in_sample = True + elif not line: + if in_sample: + in_sample = False + sample = Sample(sample_lines) + sample_lines = [] + if self.filter_sample(sample): + yield sample + if in_sample: + sample_lines.append(line) + + def filter_sample(self, sample: Sample) -> bool: + """ Return true if the input sample passes filters. """ + for exclude_filter in self.exclude_filters: + if exclude_filter.match(sample): + return False + for include_filter in self.include_filters: + if not include_filter.match(sample): + return False + return True + + +class ReportOutput: + def report(self, sample: Sample): + pass + + def end_report(self): + pass + + +class ReportOutputDetails(ReportOutput): + def report(self, sample: Sample): + for line in sample.raw_lines: + print(line) + print() + + +class ReportOutputSummary(ReportOutput): def __init__(self): - self.pid = None - self.tid = None - self.callchain = [] - -def parse_sample_record(lines, i): - """ Read the lines belong to a SampleRecord.""" - if i == len(lines) or not lines[i].startswith('record sample:'): - log_fatal('unexpected dump output near line %d' % i) - start_line = i - i += 1 - while i < len(lines) and (not lines[i] or lines[i].startswith(' ')): - i += 1 - return i, lines[start_line:i] - -def parse_callchain_record(lines, i, chain_type, process_maps): - if i == len(lines) or not lines[i].startswith('record callchain:'): - log_fatal('unexpected dump output near line %d' % i) - i += 1 - record = CallChainRecord() - ips = [] - sps = [] - function_names = [] - filenames = [] - vaddr_in_files = [] - map_start_addrs = [] - map_end_addrs = [] - in_callchain = False - while i < len(lines) and not lines[i].startswith('record'): - line = lines[i].strip() - items = line.split() - if not items: - i += 1 - continue - if items[0] == 'pid' and len(items) == 2: - record.pid = int(items[1]) - elif items[0] == 'tid' and len(items) == 2: - record.tid = int(items[1]) - elif items[0] == 'chain_type' and len(items) == 2: - if items[1] != chain_type: - log_fatal('unexpected dump output near line %d' % i) - elif items[0] == 'ip': - m = re.search(r'ip\s+0x(\w+),\s+sp\s+0x(\w+)$', line) - if m: - ips.append(int(m.group(1), 16)) - sps.append(int(m.group(2), 16)) - elif items[0] == 'callchain:': - in_callchain = True - elif in_callchain: - # "dalvik-jit-code-cache (deleted)[+346c] ([anon:dalvik-jit-code-cache] - # (deleted)[+346c])" - if re.search(r'\)\[\+\w+\]\)$', line): - break_pos = line.rfind('(', 0, line.rfind('(')) - else: - break_pos = line.rfind('(') - if break_pos > 0: - m = re.match(r'(.*)\[\+(\w+)\]\)', line[break_pos + 1:]) - if m: - function_names.append(line[:break_pos].strip()) - filenames.append(m.group(1)) - vaddr_in_files.append(int(m.group(2), 16)) - i += 1 - - for ip in ips: - map_entry = process_maps.find(record.pid, ip) - if map_entry: - map_start_addrs.append(map_entry.start) - map_end_addrs.append(map_entry.end) - else: - map_start_addrs.append(0) - map_end_addrs.append(0) - n = len(ips) - if (None in [record.pid, record.tid] or n == 0 or len(sps) != n or - len(function_names) != n or len(filenames) != n or len(vaddr_in_files) != n or - len(map_start_addrs) != n or len(map_end_addrs) != n): - log_fatal('unexpected dump output near line %d' % i) - for j in range(n): - record.callchain.append(CallChainNode(ips[j], sps[j], filenames[j], vaddr_in_files[j], - function_names[j], map_start_addrs[j], - map_end_addrs[j])) - return i, record - - -def build_unwinding_result_report(args): - simpleperf_path = get_host_binary_path('simpleperf') - proc = subprocess.Popen([simpleperf_path, 'dump', args.record_file[0]], - stdout=subprocess.PIPE) - (stdoutdata, _) = proc.communicate() - stdoutdata = bytes_to_str(stdoutdata) - if 'debug_unwind = true' not in stdoutdata: - log_exit("Can't parse unwinding result. Because " + - "%s was not generated by the debug-unwind cmd." % args.record_file[0]) - unwinding_report = UnwindingResultErrorReport(args.omit_callchains_fixed_by_joiner) - process_maps = unwinding_report.process_maps - lines = stdoutdata.split('\n') - i = 0 - while i < len(lines): - if lines[i].startswith('record mmap:') or lines[i].startswith('record mmap2:'): - i += 1 - pid = None - start = None - end = None - filename = None - while i < len(lines) and not lines[i].startswith('record'): - if lines[i].startswith(' pid'): - m = re.search(r'pid\s+(\d+).+addr\s+0x(\w+).+len\s+0x(\w+)', lines[i]) - if m: - pid = int(m.group(1)) - start = int(m.group(2), 16) - end = start + int(m.group(3), 16) - elif 'filename' in lines[i]: - pos = lines[i].find('filename') + len('filename') - filename = lines[i][pos:].strip() - i += 1 - if None in [pid, start, end, filename]: - log_fatal('unexpected dump output near line %d' % i) - process_maps.add(pid, MapEntry(start, end, filename)) - elif lines[i].startswith('record unwinding_result:'): - i += 1 - unwinding_result = collections.OrderedDict() - while i < len(lines) and not lines[i].startswith('record'): - strs = (lines[i].strip()).split() - if len(strs) == 2: - unwinding_result[strs[0]] = strs[1] - i += 1 - for key in ['time', 'used_time', 'stop_reason']: - if key not in unwinding_result: - log_fatal('unexpected dump output near line %d' % i) - - i, sample_record = parse_sample_record(lines, i) - i, original_record = parse_callchain_record(lines, i, 'ORIGINAL_OFFLINE', process_maps) - i, joined_record = parse_callchain_record(lines, i, 'JOINED_OFFLINE', process_maps) - if args.omit_sample: - sample_record = [] - sample_result = SampleResult(original_record.pid, original_record.tid, - unwinding_result, original_record.callchain, - sample_record) - unwinding_report.add_sample_result(sample_result, joined_record) - elif lines[i].startswith('record fork:'): - i += 1 - pid = None - ppid = None - while i < len(lines) and not lines[i].startswith('record'): - if lines[i].startswith(' pid'): - m = re.search(r'pid\s+(\w+),\s+ppid\s+(\w+)', lines[i]) - if m: - pid = int(m.group(1)) - ppid = int(m.group(2)) - i += 1 - if None in [pid, ppid]: - log_fatal('unexpected dump output near line %d' % i) - process_maps.fork_pid(pid, ppid) - elif lines[i].startswith(' debug_unwind_mem'): - items = lines[i].strip().split(' = ') - if len(items) == 2: - unwinding_report.add_mem_stat(items[0], items[1]) - i += 1 - else: - i += 1 - return unwinding_report + self.error_code_counter = Counter() + self.symbol_counters: Dict[int, Counter] = defaultdict(Counter) + + def report(self, sample: Sample): + symbol_key = (sample.callchain[-1].dso, sample.callchain[-1].symbol) + self.symbol_counters[sample.error_code][symbol_key] += 1 + self.error_code_counter[sample.error_code] += 1 + + def end_report(self): + self.draw_error_code_table() + self.draw_symbol_table() + + def draw_error_code_table(self): + table = Texttable() + table.set_cols_align(['l', 'c']) + table.add_row(['Count', 'Error Code']) + for error_code, count in self.error_code_counter.most_common(): + table.add_row([count, error_code]) + print(table.draw()) + + def draw_symbol_table(self): + table = Texttable() + table.set_cols_align(['l', 'c', 'l', 'l']) + table.add_row(['Count', 'Error Code', 'Dso', 'Symbol']) + for error_code, _ in self.error_code_counter.most_common(): + symbol_counter = self.symbol_counters[error_code] + for symbol_key, count in symbol_counter.most_common(): + dso, symbol = symbol_key + table.add_row([count, error_code, dso, symbol]) + print(table.draw()) + + +def get_args() -> argparse.Namespace: + parser = argparse.ArgumentParser(description=__doc__, formatter_class=ArgParseFormatter) + parser.add_argument('-i', '--input-file', required=True, + help='report file generated by debug-unwind cmd') + parser.add_argument( + '--show-callchain-fixed-by-joiner', action='store_true', + help="""By default, we don't show failed unwinding cases fixed by callchain joiner. + Use this option to show them.""") + parser.add_argument('--summary', action='store_true', + help='show summary instead of case details') + parser.add_argument('--exclude-error-code', metavar='error_code', type=int, nargs='+', + help='exclude cases with selected error code') + parser.add_argument('--exclude-end-dso', metavar='dso', nargs='+', + help='exclude cases ending at selected binary') + parser.add_argument('--exclude-end-symbol', metavar='symbol', nargs='+', + help='exclude cases ending at selected symbol') + parser.add_argument('--exclude-sample-time', metavar='time', type=int, + nargs='+', help='exclude cases with selected sample time') + parser.add_argument('--include-error-code', metavar='error_code', type=int, + nargs='+', help='include cases with selected error code') + parser.add_argument('--include-end-dso', metavar='dso', nargs='+', + help='include cases ending at selected binary') + parser.add_argument('--include-end-symbol', metavar='symbol', nargs='+', + help='include cases ending at selected symbol') + parser.add_argument('--include-sample-time', metavar='time', type=int, + nargs='+', help='include cases with selected sample time') + return parser.parse_args() def main(): - parser = argparse.ArgumentParser( - description='Report dwarf unwinding results generated by the debug-unwind cmd.') - parser.add_argument('-i', '--record_file', nargs=1, default=['perf.data.debug'], help=""" - Set profiling data to report. Default is perf.data.debug.""") - parser.add_argument('--omit-callchains-fixed-by-joiner', action='store_true', help=""" - Don't show incomplete callchains fixed by callchain joiner.""") - parser.add_argument('--omit-sample', action='store_true', help="""Don't show original sample - records.""") - args = parser.parse_args() - report = build_unwinding_result_report(args) - report.show() + args = get_args() + report_input = ReportInput() + report_input.set_filters(args) + report_output = ReportOutputSummary() if args.summary else ReportOutputDetails() + for sample in report_input.get_samples(args.input_file): + report_output.report(sample) + report_output.end_report() + if __name__ == '__main__': main() |