| #!/usr/bin/env python3 |
| # |
| # Copyright (C) 2024 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. |
| # |
| |
| import argparse |
| import pathlib |
| import subprocess |
| from bisect import bisect |
| from collections import deque |
| from dataclasses import dataclass |
| from itertools import chain |
| from math import ceil |
| from typing import BinaryIO, Callable, Deque, Dict, List, Optional, Tuple |
| |
| import etm_types as etm |
| from simpleperf_report_lib import ReportLib |
| from simpleperf_utils import bytes_to_str, BinaryFinder, EtmContext, log_exit, ReadElf, Objdump, ToolFinder |
| |
| |
| class TraceWriter: |
| """A writer for the Fuchsia trace format: |
| https://fuchsia.dev/fuchsia-src/reference/tracing/trace-format |
| """ |
| |
| def __init__(self, output: BinaryIO): |
| self.output = output |
| |
| # The following dictionaries are for keeping track of the fuchsia records already made, to |
| # use them as references. They map the "value" of the record to their index that can be used |
| # as the reference. |
| |
| # Strings are strings. |
| self.strings: Dict[str, int] = {} |
| # Providers are just strings. |
| self.providers: Dict[str, int] = {} |
| # Kernel objects are a type and a name. |
| self.kernel_objects: Dict[Tuple[int, str], int] = {} |
| # Threads are made of two kernel object ids, the first is for the process, the second for |
| # the thread. |
| self.threads: Dict[Tuple[int, int], int] = {} |
| |
| def _write_bits(self, desc: List[Tuple[int, int, int]]) -> None: |
| v = 0 |
| for (start, end, value) in desc: |
| old_value = value |
| # Check if the value fits into its field. |
| value &= (1 << (end+1)) - 1 |
| assert old_value == value |
| v |= value << start |
| self.output.write(v.to_bytes(8, 'little')) |
| |
| def _write_padded(self, array: bytearray) -> None: |
| pad = 8 - (len(array) % 8) |
| if pad == 8: |
| pad = 0 |
| |
| self.output.write(array) |
| self.output.write(bytearray(pad)) |
| |
| def magic(self) -> None: |
| self._write_bits([(0, 3, 0), |
| (4, 15, 1), |
| (16, 19, 4), |
| (20, 23, 0), |
| (24, 55, 0x16547846), |
| (56, 63, 0)]) |
| |
| def switch_provider(self, name: str) -> None: |
| if name not in self.providers: |
| n = bytearray(name, 'utf-8') |
| length = ceil(len(n) / 8) |
| provider_id = len(self.providers) |
| self._write_bits([(0, 3, 0), |
| (4, 15, 1 + length), |
| (20, 51, provider_id), |
| (52, 59, len(n)), |
| (60, 63, 0)]) |
| self._write_padded(n) |
| self.providers[name] = provider_id |
| |
| provider_id = self.providers[name] |
| self._write_bits([(0, 3, 0), |
| (4, 15, 1), |
| (16, 19, 2), |
| (20, 51, provider_id), |
| (52, 63, 0)]) |
| |
| def encode_string(self, value: str) -> int: |
| if value in self.strings: |
| return self.strings[value] |
| |
| if len(self.strings) >= 0x7fff - 1: |
| raise RuntimeError("Ran out of space in the string table!") |
| |
| n = bytearray(value, 'utf-8') |
| length = ceil(len(n) / 8) |
| string_id = len(self.strings) + 1 |
| self._write_bits([(0, 3, 2), |
| (4, 15, 1 + length), |
| (16, 30, string_id), |
| (31, 31, 0), |
| (32, 46, len(n)), |
| (47, 47, 0), |
| (48, 63, 0)]) |
| self._write_padded(n) |
| self.strings[value] = string_id |
| return string_id |
| |
| def kernel_object(self, kobj_type: int, name: str, process: Optional[int] = None) -> int: |
| if (kobj_type, name) in self.kernel_objects: |
| return self.kernel_objects[(kobj_type, name)] |
| |
| name_ref = self.encode_string(name) |
| arg_name = 0 |
| if process: |
| arg_name = self.encode_string("process") |
| |
| self._write_bits([(0, 3, 7), |
| (4, 15, 4 if process else 2), |
| (16, 23, kobj_type), |
| (24, 39, name_ref), |
| (40, 43, 1 if process else 0), |
| (44, 63, 0)]) |
| |
| koid = len(self.kernel_objects) |
| self._write_bits([(0, 63, koid)]) |
| |
| if process: |
| self._write_bits([(0, 3, 8), |
| (4, 15, 2), |
| (16, 31, arg_name), |
| (32, 63, 0)]) |
| self._write_bits([(0, 63, process)]) |
| |
| self.kernel_objects[(kobj_type, name)] = koid |
| return koid |
| |
| def thread(self, process_koid: int, thread_koid: int) -> int: |
| if (process_koid, thread_koid) in self.threads: |
| return self.threads[(process_koid, thread_koid)] |
| |
| thread_index = len(self.threads) + 1 |
| self._write_bits([(0, 3, 3), |
| (4, 15, 3), |
| (16, 23, thread_index), |
| (24, 63, 0)]) |
| self._write_bits([(0, 63, process_koid)]) |
| self._write_bits([(0, 63, thread_koid)]) |
| self.threads[(process_koid, thread_koid)] = thread_index |
| return thread_index |
| |
| def duration(self, begin: bool, thread: int, category: Optional[str], |
| name: Optional[str], timestamp: int) -> None: |
| category_ref = self.encode_string(category) if category else 0 |
| name_ref = self.encode_string(name) if name else 0 |
| self._write_bits([(0, 3, 4), |
| (4, 15, 2), |
| (16, 19, 2 if begin else 3), |
| (20, 23, 0), |
| (24, 31, thread), |
| (32, 47, category_ref), |
| (48, 63, name_ref)]) |
| self._write_bits([(0, 63, timestamp)]) |
| |
| |
| @dataclass |
| class Event: |
| call: bool |
| name: str |
| timestamp: Optional[int] |
| |
| |
| class Stacker: |
| """Stacker tries to keep track of how a thread's stack changes, and uses TraceWriter to |
| generate the corresponding Fuchsia trace. |
| """ |
| |
| def __init__(self, writer: TraceWriter, thread: int): |
| self.writer = writer |
| self.thread = thread |
| self.stack: List[str] = [] |
| self.events: Deque[Event] = deque() |
| self.early_events: List[Event] = [] |
| self.waiting: List[Event] = [] |
| |
| self.reset() |
| |
| def reset(self) -> None: |
| self.was_call = False |
| self.was_ret = False |
| self.was_plt = False |
| self.last_symbol: Optional[str] = None |
| self.exception_name: Optional[str] = None |
| self.excepted_return: Optional[int] = None |
| self.first_timestamp: Optional[int] = None |
| self.last_timestamp: Optional[int] = None |
| |
| def flush(self) -> None: |
| last = -1 |
| for event in chain(self.early_events, self.events): |
| if event.timestamp: |
| assert last <= event.timestamp |
| last = event.timestamp |
| self.writer.duration(event.call, self.thread, None, event.name, event.timestamp) |
| |
| self.early_events.clear() |
| self.events.clear() |
| self.events.extend(self.waiting) |
| |
| def check_waiting(self, timestamp: Optional[int]) -> None: |
| if not timestamp: |
| return |
| |
| if not self.first_timestamp: |
| self.first_timestamp = timestamp |
| self.last_timestamp = timestamp |
| |
| for event in self.waiting: |
| event.timestamp = timestamp |
| |
| self.waiting.clear() |
| |
| def call(self, symbol: str, timestamp: Optional[int], front: bool = False) -> None: |
| event = Event(True, symbol, timestamp) |
| |
| if not timestamp: |
| self.waiting.append(event) |
| |
| for entry in self.stack: |
| if entry.startswith('Exception: '): |
| raise RuntimeError("New call while an exception is still on the stack!", |
| symbol, self.stack) |
| |
| if front and self.events and not self.events[0].call: |
| # If the front of the events is a return, and we need to fake a call at the start, the |
| # returns will have to come before the call, otherwise Perfetto can't deal with it. |
| assert( |
| not timestamp or not self.events[0].timestamp or self.events[0].timestamp <= |
| timestamp) |
| while self.events and not self.events[0].call: |
| self.early_events.append(self.events.popleft()) |
| |
| self.stack.append(symbol) |
| insert = self.events.appendleft if front else self.events.append |
| insert(event) |
| |
| def ret(self, symbol: str, timestamp: Optional[int]) -> None: |
| event = Event(False, symbol, timestamp) |
| if not timestamp: |
| self.waiting.append(event) |
| |
| if self.stack and self.stack[-1] != symbol: |
| raise RuntimeError('Top of the stack does not match the function being returned from! ' |
| f'Current function: {symbol}, top of the stack: {self.stack[-1]}') |
| |
| if self.stack: |
| self.stack.pop() |
| self.events.append(event) |
| |
| def lost_stack(self, timestamp: Optional[int]) -> None: |
| self.check_waiting(timestamp) |
| |
| for symbol in reversed(self.stack): |
| self.ret(symbol, timestamp) |
| self.stack.clear() |
| self.flush() |
| self.reset() |
| |
| def gap(self, timestamp: Optional[int]) -> None: |
| self.last_timestamp = None |
| if self.exception_name: |
| return |
| |
| if self.last_symbol and self.last_symbol.endswith('@plt'): |
| self.was_plt = True |
| return |
| |
| self.lost_stack(timestamp) |
| |
| def timestamp(self, timestamp: Optional[int]) -> None: |
| self.check_waiting(timestamp) |
| |
| def exception(self, timestamp: Optional[int], |
| name: str, excepted_return: Optional[int]) -> None: |
| self.check_waiting(timestamp) |
| |
| if self.exception_name: |
| if excepted_return is not None and self.excepted_return == excepted_return: |
| # Same return, mark the end of the previous but carry on: |
| self.ret(self.exception_name, timestamp) |
| else: |
| # Interrupted, but for a different return. This most likely means some trace was |
| # lost. Drop the stack. |
| self.lost_stack(timestamp) |
| |
| for e in self.stack: |
| if e.startswith('Exception '): |
| raise RuntimeError("Exception while another exception is already on the stack!", |
| name, self.stack) |
| |
| self.exception_name = name |
| self.excepted_return = excepted_return |
| self.call(name, timestamp) |
| if timestamp: |
| self.last_timestamp = timestamp |
| |
| def instr_range(self, timestamp: Optional[int], start: str, start_addr: int, |
| end: str, _end_addr: int, isubtype: etm.InstrSubtype) -> None: |
| self.check_waiting(timestamp) |
| |
| if self.exception_name: |
| self.ret(self.exception_name, timestamp) |
| self.exception_name = None |
| |
| if start_addr != self.excepted_return: |
| # If we are in the same symbol, assume we managed to get back safe and sound. |
| # Otherwise, drop the stack. |
| if not self.stack or self.stack[-1] != start: |
| self.lost_stack(self.last_timestamp) |
| |
| if self.was_plt: |
| self.was_plt = False |
| if len(self.stack) > 1 and self.stack[-2] == start: |
| # When was_plt was set, last_symbol should have been too. |
| assert self.last_symbol |
| self.ret(self.last_symbol, timestamp) |
| self.last_symbol = start |
| else: |
| self.lost_stack(timestamp) |
| |
| if self.last_symbol == 'art_quick_do_long_jump' and self.last_symbol != start: |
| # Art's long jump rewinds the stack to a previous state. |
| self.lost_stack(timestamp) |
| |
| # check_waiting already set the timestamps, but lost_stack above might have nulled them. Set |
| # them again to make sure everything below can use the timestamps correctly. |
| self.first_timestamp = self.first_timestamp or timestamp |
| self.last_timestamp = timestamp or self.last_timestamp |
| |
| if not self.was_call and not self.was_ret and self.last_symbol != start: |
| # If the symbol changed without us detecting a call or a return, we recognize two cases: |
| # if there's a last symbol saved, this was a tail call, and we emit a return and a call. |
| # Otherwise, this is the beginning of a new reconstruction of a stack, and we emit only |
| # the call. |
| if self.last_symbol: |
| # Tail call. |
| self.ret(self.last_symbol, timestamp) |
| self.call(start, timestamp) |
| if self.was_ret and not self.stack: |
| # If we have just returned into a function but the stack is empty, pretend that the |
| # current (new) function has been running since the first known timestamp. |
| self.call(start, self.first_timestamp, front=True) |
| if self.was_call: |
| # If the last instruction of the previous instruction range was a call (branch with |
| # link), emit a call. |
| self.call(start, timestamp) |
| if start != end: |
| # If for some reason the symbol changes inside an instruction range, pretend it was a |
| # tail call, even though this really shouldn't happen. |
| self.ret(start, timestamp) |
| self.call(end, timestamp) |
| if isubtype == etm.InstrSubtype.V8_RET: |
| # If the last instruction of the range is a return, we are returning from the current |
| # symbol. |
| self.ret(end, timestamp) |
| |
| self.was_ret = isubtype == etm.InstrSubtype.V8_RET |
| self.was_call = isubtype == etm.InstrSubtype.BR_LINK |
| self.last_symbol = end |
| if timestamp: |
| self.last_timestamp = timestamp |
| |
| |
| class Tracer: |
| def __init__(self, lib: ReportLib, binary_finder: BinaryFinder, readelf: ReadElf, |
| objdump: Objdump, w: TraceWriter) -> None: |
| self.abort: bool = False |
| |
| self.last_timestamp: Optional[int] = None |
| self.lost_decoding: bool = False |
| |
| self.context: EtmContext = EtmContext() |
| |
| self.lib: ReportLib = lib |
| self.binary_finder: BinaryFinder = binary_finder |
| self.readelf: ReadElf = readelf |
| self.objdump: Objdump = objdump |
| |
| self.processes: Dict[int, str] = {} |
| |
| self.symbols: Dict[str, Tuple[List[Tuple[int, int, str]], List[int]]] = {} |
| self.symbol_cache: Optional[Tuple[str, Tuple[int, int, str]]] = None |
| |
| self.stacks: Dict[int, Stacker] = {} |
| self.w: TraceWriter = w |
| w.magic() |
| w.switch_provider('etm') |
| |
| self.s: Optional[Stacker] = None |
| |
| def __call__(self, trace_id: int, elem: etm.GenericTraceElement) -> None: |
| if self.abort: |
| return |
| |
| try: |
| self.process(trace_id, elem) |
| except Exception as e: |
| self.abort = True |
| self.gap() |
| self.flush() |
| raise e |
| |
| def reset_trace(self) -> None: |
| self.context = EtmContext() |
| self.lost_decoding = False |
| self.last_timestamp = None |
| |
| def process(self, trace_id: int, elem: etm.GenericTraceElement) -> None: |
| if elem.elem_type == etm.ElemType.TRACE_ON or elem.elem_type == etm.ElemType.NO_SYNC: |
| if self.s: |
| self.s.gap(self.last_timestamp) |
| self.reset_trace() |
| return |
| |
| if elem.elem_type == etm.ElemType.PE_CONTEXT: |
| if self.context.update(elem.context): |
| tid = self.context.tid |
| if tid: |
| process = self.lib.GetThread(tid) |
| if process: |
| pid, tid, comm = process |
| else: |
| pid = tid |
| comm = f'Unknown process' |
| else: |
| pid = -1 |
| tid = -1 |
| comm = 'Unknown process' |
| |
| kernel = "" if self.context.ex_level == etm.ExLevel.EL0 else " (kernel)" |
| thread_name = f'{tid} {comm or ""}{kernel}' |
| |
| if pid in self.processes: |
| process_name = self.processes[pid] |
| else: |
| if pid == tid: |
| parent_name = comm |
| else: |
| t = self.lib.GetThread(pid) |
| parent_name = t[2] if t else "Unknown process" |
| process_name = f'{pid} {parent_name or ""}' |
| self.processes[pid] = process_name |
| |
| pobj = self.w.kernel_object(1, process_name) |
| tobj = self.w.kernel_object(2, thread_name, process=pobj) |
| thread = self.w.thread(pobj, tobj) |
| # It is possible that the thread_name changed and we have the old one saved here. |
| # The Fuchsia trace does not seem to have any nice ways to handle changing names, |
| # therefore we are sticking with the first name we saw. |
| if tid not in self.stacks: |
| self.stacks[tid] = Stacker(self.w, thread) |
| |
| self.s = self.stacks[tid] |
| return |
| |
| if elem.elem_type == etm.ElemType.TIMESTAMP: |
| if self.last_timestamp != elem.timestamp: |
| self.last_timestamp = elem.timestamp |
| if self.s: |
| self.s.timestamp(elem.timestamp) |
| |
| # For the other elements, a context should have happened before and must have set s. |
| assert self.s |
| |
| if elem.elem_type == etm.ElemType.ADDR_NACC: |
| if not self.lost_decoding: |
| self.lost_decoding = True |
| mapped = self.lib.ConvertETMAddressToVaddrInFile(trace_id, elem.st_addr) |
| if mapped: |
| print(f'ADDR_NACC: path {mapped[0]} cannot be decoded! ({hex(elem.st_addr)})') |
| else: |
| print(f'ADDR_NACC: trace address {hex(elem.st_addr)} is not mapped!') |
| |
| # We have lost trace. Give up on the stack. |
| # print(self.s.stack) |
| # print(self.last_timestamp, self.s.last_timestamp, self.s.waiting) |
| self.s.lost_stack(self.last_timestamp) |
| # print(self.last_timestamp, self.s.last_timestamp, self.s.waiting) |
| |
| return |
| |
| if elem.elem_type == etm.ElemType.EXCEPTION: |
| name = f'Exception: "{elem.exception_type()}" ({elem.exception_number})!' |
| self.s.exception(self.last_timestamp, name, |
| elem.en_addr if elem.excep_ret_addr else None) |
| return |
| |
| if elem.elem_type != etm.ElemType.INSTR_RANGE: |
| return |
| |
| self.lost_decoding = False |
| |
| start_path, start_offset = self.lib.ConvertETMAddressToVaddrInFile( |
| trace_id, elem.st_addr) or ("", 0) |
| end_path, end_offset = self.lib.ConvertETMAddressToVaddrInFile( |
| trace_id, elem.en_addr - elem.last_instr_sz) or ("", 0) |
| |
| error_messages = [] |
| if not start_path: |
| error_messages.append(f"Couldn't determine start path for address {elem.st_addr}!") |
| if not end_path: |
| error_messages.append( |
| f"Couldn't determine start path for address {elem.en_addr - elem.last_instr_sz}!") |
| if error_messages: |
| raise RuntimeError(' '.join(error_messages)) |
| |
| start = self.get_symbol(start_path, start_offset) or "Unknown" |
| end = self.get_symbol(end_path, end_offset) or "Unknown" |
| |
| if not elem.last_instr_cond and not elem.last_instr_exec: |
| buildid = self.lib.GetBuildIdForPath(end_path) |
| raise RuntimeError(f"Wrong binary! Unconditional branch at {hex(end_offset)}" |
| f" in {end_path} (build id: {buildid}) was not taken!") |
| |
| self.s.instr_range(self.last_timestamp, |
| start, elem.st_addr, |
| end, elem.en_addr, |
| elem.last_i_subtype) |
| |
| def gap(self) -> None: |
| for stack in self.stacks.values(): |
| stack.lost_stack(stack.last_timestamp) |
| |
| def flush(self) -> None: |
| for stack in self.stacks.values(): |
| stack.flush() |
| |
| def get_symbol(self, path: str, offset: int) -> Optional[str]: |
| if (self.symbol_cache and self.symbol_cache[0] == path and |
| (self.symbol_cache[1][0]) <= offset < (self.symbol_cache[1][0] + self.symbol_cache[1][1])): |
| return self.symbol_cache[1][2] |
| |
| (symbols, offsets) = self.get_symbols(path) |
| if symbols: |
| i = bisect(offsets, offset) |
| if i: |
| i -= 1 |
| if symbols[i][0] <= offset < symbols[i][0] + symbols[i][1]: |
| self.symbol_cache = (path, symbols[i]) |
| return symbols[i][2] |
| |
| return None |
| |
| def get_symbols(self, path: str) -> Tuple[List[Tuple[int, int, str]], List[int]]: |
| if path not in self.symbols: |
| s = self.lib.GetSymbols(path) |
| |
| if not s: |
| log_exit(f"Can't find symbols for unknown binary '{path}'!") |
| return ([], []) |
| |
| # Since other use cases don't care about the PLT, simpleperf represents it only as a |
| # single symbol called '@plt'. If it is present, try to get the actual names by parsing |
| # objdump's output. |
| if s[-1][2] == '@plt': |
| dso_info = self.objdump.get_dso_info(path, self.lib.GetBuildIdForPath(path)) |
| plts = self.objdump.get_plt_symbols(dso_info) |
| if plts: |
| del s[-1] |
| s.extend(plts) |
| |
| self.symbols[path] = (s, [e[0] for e in s]) |
| |
| return self.symbols[path] |
| |
| |
| def get_args() -> argparse.Namespace: |
| parser = argparse.ArgumentParser(description='Generate Fuchsia trace from ETM data.') |
| parser.add_argument('-i', '--record_file', nargs=1, default=['perf.data'], help=""" |
| Set profiling data file to process.""") |
| parser.add_argument('--binary_cache', nargs=1, default=["binary_cache"], help=""" |
| Set path to the binary cache.""") |
| parser.add_argument('--ndk_path', nargs=1, help='Find tools in the ndk path.') |
| parser.add_argument('-o', '--output', nargs=1, help=""" |
| Output path for the trace. If not specified, the record file's name is |
| used, with .fxt appended.""") |
| return parser.parse_args() |
| |
| |
| def main() -> None: |
| args = get_args() |
| |
| binary_cache_path = args.binary_cache[0] |
| if not pathlib.Path(binary_cache_path).is_dir(): |
| log_exit(f"Binary cache '{binary_cache_path}' is not a directory!") |
| return |
| |
| ndk_path = args.ndk_path[0] if args.ndk_path else None |
| |
| lib = ReportLib() |
| try: |
| lib.SetRecordFile(args.record_file[0]) |
| lib.SetSymfs(binary_cache_path) |
| lib.SetLogSeverity('error') |
| |
| readelf = ReadElf(ndk_path) |
| binary_finder = BinaryFinder(binary_cache_path, readelf) |
| objdump = Objdump(ndk_path, binary_finder) |
| |
| filename = args.output[0] if args.output else f'{args.record_file[0]}.fxt' |
| |
| with open(filename, 'wb') as f: |
| callback = Tracer(lib, binary_finder, readelf, objdump, TraceWriter(f)) |
| lib.SetETMCallback(callback) |
| while not callback.abort and lib.GetNextSample(): |
| pass |
| |
| # Trace has ended, make sure every call has a corresponding return. Use the largest |
| # timestamp and end everything there. |
| last_timestamps = [stacker.last_timestamp for stacker |
| in callback.stacks.values() |
| if stacker.last_timestamp] |
| last_timestamp = max(last_timestamps, default=None) |
| for stacker in callback.stacks.values(): |
| stacker.last_timestamp = last_timestamp |
| callback.gap() |
| callback.flush() |
| |
| finally: |
| lib.Close() |
| |
| |
| if __name__ == '__main__': |
| main() |
