#!/usr/bin/env python
|
#
|
# Copyright (C) 2017 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.
|
#
|
|
"""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
|
|
def __lt__(self, other):
|
return self.start < other.start
|
|
class ProcessMaps(object):
|
|
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)
|
|
|
class UnwindingMemConsumption(object):
|
|
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
|
|
|
class SampleResult(object):
|
|
""" Unwinding result per sample. """
|
|
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 FunctionResult(object):
|
|
""" Unwinding result per function. """
|
|
def __init__(self):
|
# Map from Unwinding result reason to [SampleResult].
|
self.sample_results = {}
|
|
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 FileResult(object):
|
|
""" Unwinding result per shared library. """
|
|
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. """
|
|
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
|
|
|
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()
|
|
if __name__ == '__main__':
|
main()
|
