path: root/perfprofd/scripts/perf_proto_stack.py

#!/usr/bin/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.

# Super simplistic printer of a perfprofd output proto. Illustrates
# how to parse and traverse a perfprofd output proto in Python.

# This relies on libunwindstack's unwind_symbol. Build with
#   mmma system/core/libunwindstack

import argparse
from datetime import datetime
import itertools
import json
import logging
from multiprocessing.dummy import Pool as ThreadPool
import os.path
from sorted_collection import SortedCollection
import subprocess
from threading import Timer

# Generate with:
#  aprotoc -I=external/perf_data_converter/src/quipper \
#      --python_out=system/extras/perfprofd/scripts \
#      external/perf_data_converter/src/quipper/perf_data.proto
#  aprotoc -I=external/perf_data_converter/src/quipper -I=system/extras/perfprofd \
#      --python_out=system/extras/perfprofd/scripts \
#      system/extras/perfprofd/perfprofd_record.proto
import perfprofd_record_pb2
import perf_data_pb2

# Make sure that symbol is on the PYTHONPATH, e.g., run as
# PYTHONPATH=$PYTHONPATH:$ANDROID_BUILD_TOP/development/scripts python ...
import symbol
from symbol import SymbolInformation

logging.basicConfig(format='%(message)s')

# This is wrong. But then the symbol module is a bad quagmire.
# TODO: Check build IDs.
symbol.SetAbi(["ABI: 'arm64'"])


class MmapState(object):

    def __init__(self):
        self._list = SortedCollection((), lambda x: x[0])

    def add_map(self, start, length, pgoff, name):
        map_tuple = (start, length, pgoff, name)
        self._list.insert(map_tuple)

    def find(self, addr):
        try:
            map_tuple = self._list.find_le(addr)
            if addr < map_tuple[0] + map_tuple[1]:
                return map_tuple
            return None
        except ValueError:
            return None

    def copy(self):
        ret = MmapState()
        ret._list = self._list.copy()
        return ret

    def __str__(self):
        return 'MmapState: ' + self._list.__str__()

    def __repr__(self):
        return self.__str__()


class SymbolMap(object):
    def __init__(self, min_v):
        self._list = SortedCollection((), lambda x: x[0])
        self._min_vaddr = min_v

    def add_symbol(self, start, length, name):
        tuple = (start, length, name)
        self._list.insert(tuple)

    def find(self, addr):
        try:
            tuple = self._list.find_le(addr)
            if addr < tuple[0] + tuple[1]:
                return tuple[2]
            return None
        except ValueError:
            return None

    def copy(self):
        ret = SymbolMap()
        ret._list = self._list.copy()
        return ret

    def __str__(self):
        return "SymbolMap: " + self._list.__str__()

    def __repr__(self):
        return self.__str__()


def intern_uni(u):
    return intern(u.encode('ascii', 'replace'))


def collect_tid_names(perf_data):
    tid_name_map = {}
    for event in perf_data.events:
        if event.HasField('comm_event'):
            tid_name_map[event.comm_event.tid] = intern_uni(event.comm_event.comm)
    return tid_name_map


def create_symbol_maps(profile):
    symbol_maps = {}

    for si in profile.Extensions[perfprofd_record_pb2.symbol_info]:
        map = SymbolMap(si.min_vaddr)
        symbol_maps[si.filename] = map
        for sym in si.symbols:
            map.add_symbol(sym.addr, sym.size, intern_uni(sym.name))
    return symbol_maps


def update_mmap_states(event, state_map):
    if event.HasField('mmap_event'):
        mmap_event = event.mmap_event
        # Skip kernel stuff.
        if mmap_event.tid == 0:
            return
        # Create new map, if necessary.
        if mmap_event.pid not in state_map:
            state_map[mmap_event.pid] = MmapState()
        state_map[mmap_event.pid].add_map(mmap_event.start, mmap_event.len, mmap_event.pgoff,
                                          intern_uni(mmap_event.filename))
    elif event.HasField('fork_event'):
        fork_event = event.fork_event
        # Skip threads
        if fork_event.pid == fork_event.ppid:
            return

        if fork_event.ppid not in state_map:
            logging.warn("fork from %d without map", fork_event.ppid)
            return
        state_map[fork_event.pid] = state_map[fork_event.ppid].copy()


skip_dso = set()
vaddr = {}


def find_vaddr(vaddr_map, filename):
    if filename in vaddr_map:
        return vaddr_map[filename]

    path = "%s/%s" % (symbol.SYMBOLS_DIR, filename)
    if not os.path.isfile(path):
        logging.warn('Cannot find %s for min_vaddr', filename)
        vaddr_map[filename] = 0
        return 0

    try:
        # Use "-W" to have single-line format.
        res = subprocess.check_output(['readelf', '-lW', path])
        lines = res.split("\n")
        reading_headers = False
        min_vaddr = None

        def min_fn(x, y):
            return y if x is None else min(x, y)
        # Using counting loop for access to next line.
        for i in range(0, len(lines) - 1):
            line = lines[i].strip()
            if reading_headers:
                if line == "":
                    # Block is done, won't find anything else.
                    break
                if line.startswith("LOAD"):
                    # Look at the current line to distinguish 32-bit from 64-bit
                    line_split = line.split()
                    if len(line_split) >= 8:
                        if " R E " in line:
                            # Found something expected. So parse VirtAddr.
                            try:
                                min_vaddr = min_fn(min_vaddr, int(line_split[2], 0))
                            except ValueError:
                                pass
                    else:
                        logging.warn('Could not parse readelf line %s', line)
            else:
                if line.strip() == "Program Headers:":
                    reading_headers = True

        if min_vaddr is None:
            min_vaddr = 0
        logging.debug("min_vaddr for %s is %d", filename, min_vaddr)
        vaddr_map[filename] = min_vaddr
    except subprocess.CalledProcessError:
        logging.warn('Error finding min_vaddr for %s', filename)

        vaddr_map[filename] = 0
    return vaddr_map[filename]


unwind_symbols_cache = {}
unwind_symbols_warn_missing_cache = set()


def run_unwind_symbols(filename, offset_hex):
    path = "%s/%s" % (symbol.SYMBOLS_DIR, filename)
    if not os.path.isfile(path):
        if path not in unwind_symbols_warn_missing_cache:
            logging.warn('Cannot find %s for unwind_symbols', filename)
            unwind_symbols_warn_missing_cache.add(path)
        return None

    if (path, offset_hex) in unwind_symbols_cache:
        pair = unwind_symbols_cache[(path, offset_hex)]
        if pair is None:
            return None
        return [(pair[0], pair[1], filename)]

    try:
        res = subprocess.check_output(['unwind_symbols', path, offset_hex])
        lines = res.split("\n")
        for line in lines:
            if line.startswith('<0x'):
                parts = line.split(' ', 1)
                if len(parts) == 2:
                    # Get offset, too.
                    offset = 0
                    plus_index = parts[0].find('>+')
                    if plus_index > 0:
                        offset_str = parts[0][plus_index + 2:-1]
                        try:
                            offset = int(offset_str)
                        except ValueError:
                            logging.warn('error parsing offset from %s', parts[0])

                    # TODO C++ demangling necessary.
                    logging.debug('unwind_symbols: %s %s -> %s +%d', filename, offset_hex, parts[1],
                                  offset)
                    sym = intern(parts[1])
                    unwind_symbols_cache[(path, offset_hex)] = (sym, offset)
                    return [(sym, offset, filename)]
    except subprocess.CalledProcessError:
        logging.warn('Failed running unwind_symbols for %s', filename)
        unwind_symbols_cache[(path, offset_hex)] = None
        return None


def decode_with_symbol_lib(name, addr_rel_hex):
    info = SymbolInformation(name, addr_rel_hex)
    # As-is, only info[0] (inner-most inlined function) is recognized.
    (source_symbol, source_location, object_symbol_with_offset) = info[0]

    def parse_symbol_lib_output(s):
        i = s.rfind('+')
        if i > 0:
            try:
                off = int(s[i + 1:])
                return (s[0:i], off)
            except ValueError:
                pass
        return (s, 0)

    ret = []

    if object_symbol_with_offset is not None:
        pair = parse_symbol_lib_output(object_symbol_with_offset)
        ret.append((intern(pair[0]), pair[1], name))

    if source_symbol is not None:
        iterinfo = iter(info)
        next(iterinfo)
        for (sym_inlined, loc_inlined, _) in iterinfo:
            # TODO: Figure out what's going on here:
            if sym_inlined is not None:
                pair = parse_symbol_lib_output(sym_inlined)
                ret.insert(0, (intern(pair[0]), pair[1], name))
    if len(ret) > 0:
        return ret
    return None


def decode_addr(addr, mmap_state, device_symbols):
    """Try to decode the given address against the current mmap table and device symbols.

    First, look up the address in the mmap state. If none is found, use a simple address
    heuristic to guess kernel frames on 64-bit devices.

    Next, check on-device symbolization for a hit.

    Last, try to symbolize against host information. First try the symbol module. However,
    as it is based on addr2line, it will not work for pure-gnu_debugdata DSOs (e.g., ART
    preopt artifacts). For that case, use libunwindstack's unwind_symbols.
    """

    map = mmap_state.find(addr)
    if map is None:
        # If it looks large enough, assume it's from
        # the kernel.
        if addr > 18000000000000000000:
            return [("[kernel]", 0, "[kernel]")]
        return [("%d (no mapped segment)" % addr, 0, None)]
    name = map[3]
    logging.debug('%d is %s (%d +%d)', addr, name, map[0], map[1])

    # Once relocation packer is off, it would be:
    #   offset = addr - map.start + map.pgoff
    # Right now it is
    #   offset = addr - map.start (+ min_vaddr)
    # Note that on-device symbolization doesn't include min_vaddr but
    # does include pgoff.
    offset = addr - map[0]

    if name in device_symbols:
        offset = offset + map[2]
        symbol = device_symbols[name].find(offset)
        if symbol is None:
            return [("%s (missing on-device symbol)" % (name), offset, name)]
        else:
            # TODO: Should we change the format?
            return [(symbol, 0, name)]
    offset = offset + find_vaddr(vaddr, name)
    if (name, offset) in skip_dso:
        # We already failed, skip symbol finding.
        return [(name, offset, name)]
    else:
        addr_rel_hex = intern("%x" % offset)
        ret = decode_with_symbol_lib(name, addr_rel_hex)
        if ret is not None and len(ret) != 0:
            # Addr2line may report oatexec+xyz. Let unwind_symbols take care of that.
            if len(ret) != 1 or ret[0][0] != 'oatexec':
                logging.debug('Got result from symbol module: %s', str(ret))
                return ret
        # Try unwind_symbols
        ret = run_unwind_symbols(name, addr_rel_hex)
        if ret is not None and len(ret) != 0:
            return ret
        logging.warn("Failed to find symbol for %s +%d (%d)", name, offset, addr)
        # Remember the fail.
        skip_dso.add((name, offset))
        return [(name, offset, name)]


def print_sample(sample, tid_name_map):
    if sample[0] in tid_name_map:
        pid_name = "%s (%d)" % (tid_name_map[sample[0]], sample[0])
    elif sample[0] == 0:
        pid_name = "kernel (0)"
    else:
        pid_name = "unknown (%d)" % (sample[0])

    if sample[1] in tid_name_map:
        tid_name = "%s (%d)" % (tid_name_map[sample[1]], sample[1])
    elif sample[1] == 0:
        tid_name = "kernel (0)"
    else:
        tid_name = "unknown (%d)" % (sample[1])
    print " %s - %s:" % (pid_name, tid_name)

    for sym in sample[2]:
        print "   %s +%d (%s)" % (sym[0], sym[1], sym[2])


def print_samples(samples, tid_name_map):
    for sample in samples:
        print_sample(sample, tid_name_map)


def symbolize_events(perf_data, device_symbols, tid_name_map, printSamples=False,
                     removeKernelTop=False):
    samples = []
    mmap_states = {}
    for event in perf_data.events:
        update_mmap_states(event, mmap_states)
        if event.HasField('sample_event'):
            sample_ev = event.sample_event
            # Handle sample.
            new_sample = None
            if sample_ev.pid in mmap_states:
                mmap_state = mmap_states[sample_ev.pid]
                ip_sym = decode_addr(sample_ev.ip, mmap_state, device_symbols)
                stack = ip_sym
                for cc_ip in sample_ev.callchain:
                    cc_sym = decode_addr(cc_ip, mmap_state, device_symbols)
                    stack.extend(cc_sym)
                if removeKernelTop:
                    while len(stack) > 1 and stack[0][0] == "[kernel]":
                        stack.pop(0)
                new_sample = (sample_ev.pid, sample_ev.tid, stack)
            else:
                # Handle kernel symbols specially.
                if sample_ev.pid == 0:
                    samples.append((0, sample_ev.tid, [("[kernel]", 0, "[kernel]")]))
                elif sample_ev.pid in tid_name_map:
                    samples.append((sample_ev.pid, sample_ev.tid, [(tid_name_map[sample_ev.pid], 0,
                                                                    None)]))
                else:
                    samples.append((sample_ev.pid, sample_ev.tid, [("[unknown]", 0, None)]))
            if new_sample is not None:
                samples.append(new_sample)
                if printSamples:
                    print_sample(new_sample, tid_name_map)
    return samples


def count_key_reduce_function(x, y, key_fn):
    key = key_fn(y)
    if key not in x:
        x[key] = 0
    x[key] += 1
    return x


def print_histogram(samples, reduce_key_fn, label_key_fn, size):
    # Create a sorted list of top samples.
    sorted_count_list = sorted(
        reduce(lambda x, y: count_key_reduce_function(x, y, reduce_key_fn), samples, {}).
        iteritems(),
        cmp=lambda x, y: cmp(x[1], y[1]),
        reverse=True)
    sorted_count_topX = list(itertools.islice(sorted_count_list, size))

    # Print top-size samples.
    print 'Histogram top-%d:' % (size)
    for i in xrange(0, len(sorted_count_topX)):
        print '  %d: %s (%s)' % (i + 1, label_key_fn(sorted_count_topX[i][0]),
                                 sorted_count_topX[i][1])


def get_name(pid, tid_name_map):
    if pid in tid_name_map:
        return tid_name_map[pid]
    if pid == 0:
        return "[kernel]"
    return "[unknown]"


def create_cmd(args, f):
    ret = ['python', '-u', 'system/extras/perfprofd/scripts/perf_proto_stack.py']
    if args.syms is not None:
        ret.extend(['--syms', args.syms[0]])
    if args.print_samples is not None:
        ret.append('--print-samples')
    if args.skip_kernel_syms is not None:
        ret.append('--skip-kernel-syms')
    if args.print_pid_histogram is not None:
        ret.append('--print-pid-histogram')
    if args.print_sym_histogram is not None:
        ret.append('--print-sym-histogram')
    if args.print_dso_histogram is not None:

        ret.append('--print-dso-histogram')
    ret.extend(['--json-out', '%s.json' % (f)])
    ret.append(f)
    return ret


def run_cmd(x):

    args = x[0]
    f = x[1]
    cmd = create_cmd(args, f)
    logging.warn('Running on %s', f)
    success = False
    logging.debug('%r', cmd)
    err_out = open('%s.err' % (f), 'w')

    def kill(process):
        process.kill()
    start = datetime.now()

    p = subprocess.Popen(cmd, stderr=err_out)
    kill_timer = Timer(3600, kill, [p])
    try:
        kill_timer.start()
        p.communicate()
        success = True

    finally:
        kill_timer.cancel()
    err_out.close()
    end = datetime.now()
    logging.warn('Ended %s (%s)', f, str(end - start))
    return '%s: %r' % (f, success)


def parallel_runner(args):
    pool = ThreadPool(args.parallel)
    map_args = map(lambda f: (args, f), args.file)

    result = pool.map(run_cmd, map_args)
    pool.close()
    pool.join()
    print result


def run(args):
    if args.syms is not None:
        symbol.SYMBOLS_DIR = args.syms[0]
    print_symbols = args.print_samples is not None
    skip_kernel_syms = args.skip_kernel_syms is not None

    # TODO: accept argument for parsing.
    file = open(args.file[0], 'rb')
    data = file.read()

    file.close()

    profile = perf_data_pb2.PerfDataProto()
    # PerfprofdRecord()
    profile.ParseFromString(data)

    perf_data = profile

    print "Stats: ", perf_data.stats

    tid_name_map = collect_tid_names(perf_data)
    symbol_maps = create_symbol_maps(profile)

    samples = symbolize_events(perf_data, symbol_maps, tid_name_map, printSamples=print_symbols,
                               removeKernelTop=skip_kernel_syms)

    if args.print_pid_histogram is not None:
        print_histogram(samples, lambda x: x[0], lambda x: get_name(x, tid_name_map), 25)
    if args.print_sym_histogram is not None:
        print_histogram(samples, lambda x: x[2][0][0], lambda x: x, 100)
    if args.print_dso_histogram is not None:
        print_histogram(samples, lambda x: x[2][0][2], lambda x: x, 25)

    if args.json_out is not None:
        json_file = open(args.json_out[0], 'w')
        json_data = {'samples': samples, 'names': tid_name_map}
        json.dump(json_data, json_file)
        json_file.close()


if __name__ == "__main__":
    parser = argparse.ArgumentParser(description='Process a perfprofd record.')

    parser.add_argument('file', help='proto file to parse', metavar='file', nargs='+')
    parser.add_argument('--syms', help='directory for symbols', nargs=1)
    parser.add_argument('--json-out', help='output file for JSON', nargs=1)
    parser.add_argument('--print-samples', help='print samples', action='store_const', const=True)
    parser.add_argument('--skip-kernel-syms', help='skip kernel symbols at the top of stack',
                        action='store_const', const=True)
    parser.add_argument('--print-pid-histogram', help='print a top-25 histogram of processes',
                        action='store_const', const=True)
    parser.add_argument('--print-sym-histogram', help='print a top-100 histogram of symbols',
                        action='store_const', const=True)
    parser.add_argument('--print-dso-histogram', help='print a top-25 histogram of maps',
                        action='store_const', const=True)
    parser.add_argument('--parallel', help='run parallel jobs', type=int)

    args = parser.parse_args()
    if args is not None:
        if args.parallel is not None:
            parallel_runner(args)
        else:
            run(args)