1#!/usr/bin/env python3 2# 3# Copyright (C) 2024 The Android Open Source Project 4# 5# Licensed under the Apache License, Version 2.0 (the "License"); 6# you may not use this file except in compliance with the License. 7# You may obtain a copy of the License at 8# 9# http://www.apache.org/licenses/LICENSE-2.0 10# 11# Unless required by applicable law or agreed to in writing, software 12# distributed under the License is distributed on an "AS IS" BASIS, 13# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 14# See the License for the specific language governing permissions and 15# limitations under the License. 16# 17 18import argparse 19import pathlib 20import subprocess 21from bisect import bisect 22from collections import deque 23from dataclasses import dataclass 24from itertools import chain 25from math import ceil 26from typing import BinaryIO, Callable, Deque, Dict, List, Optional, Tuple 27 28import etm_types as etm 29from simpleperf_report_lib import ReportLib 30from simpleperf_utils import bytes_to_str, BinaryFinder, EtmContext, log_exit, ReadElf, Objdump, ToolFinder 31 32 33class TraceWriter: 34 """A writer for the Fuchsia trace format: 35 https://fuchsia.dev/fuchsia-src/reference/tracing/trace-format 36 """ 37 38 def __init__(self, output: BinaryIO): 39 self.output = output 40 41 # The following dictionaries are for keeping track of the fuchsia records already made, to 42 # use them as references. They map the "value" of the record to their index that can be used 43 # as the reference. 44 45 # Strings are strings. 46 self.strings: Dict[str, int] = {} 47 # Providers are just strings. 48 self.providers: Dict[str, int] = {} 49 # Kernel objects are a type and a name. 50 self.kernel_objects: Dict[Tuple[int, str], int] = {} 51 # Threads are made of two kernel object ids, the first is for the process, the second for 52 # the thread. 53 self.threads: Dict[Tuple[int, int], int] = {} 54 55 def _write_bits(self, desc: List[Tuple[int, int, int]]) -> None: 56 v = 0 57 for (start, end, value) in desc: 58 old_value = value 59 # Check if the value fits into its field. 60 value &= (1 << (end+1)) - 1 61 assert old_value == value 62 v |= value << start 63 self.output.write(v.to_bytes(8, 'little')) 64 65 def _write_padded(self, array: bytearray) -> None: 66 pad = 8 - (len(array) % 8) 67 if pad == 8: 68 pad = 0 69 70 self.output.write(array) 71 self.output.write(bytearray(pad)) 72 73 def magic(self) -> None: 74 self._write_bits([(0, 3, 0), 75 (4, 15, 1), 76 (16, 19, 4), 77 (20, 23, 0), 78 (24, 55, 0x16547846), 79 (56, 63, 0)]) 80 81 def switch_provider(self, name: str) -> None: 82 if name not in self.providers: 83 n = bytearray(name, 'utf-8') 84 length = ceil(len(n) / 8) 85 provider_id = len(self.providers) 86 self._write_bits([(0, 3, 0), 87 (4, 15, 1 + length), 88 (20, 51, provider_id), 89 (52, 59, len(n)), 90 (60, 63, 0)]) 91 self._write_padded(n) 92 self.providers[name] = provider_id 93 94 provider_id = self.providers[name] 95 self._write_bits([(0, 3, 0), 96 (4, 15, 1), 97 (16, 19, 2), 98 (20, 51, provider_id), 99 (52, 63, 0)]) 100 101 def encode_string(self, value: str) -> int: 102 if value in self.strings: 103 return self.strings[value] 104 105 if len(self.strings) >= 0x7fff - 1: 106 raise RuntimeError("Ran out of space in the string table!") 107 108 n = bytearray(value, 'utf-8') 109 length = ceil(len(n) / 8) 110 string_id = len(self.strings) + 1 111 self._write_bits([(0, 3, 2), 112 (4, 15, 1 + length), 113 (16, 30, string_id), 114 (31, 31, 0), 115 (32, 46, len(n)), 116 (47, 47, 0), 117 (48, 63, 0)]) 118 self._write_padded(n) 119 self.strings[value] = string_id 120 return string_id 121 122 def kernel_object(self, kobj_type: int, name: str, process: Optional[int] = None) -> int: 123 if (kobj_type, name) in self.kernel_objects: 124 return self.kernel_objects[(kobj_type, name)] 125 126 name_ref = self.encode_string(name) 127 arg_name = 0 128 if process: 129 arg_name = self.encode_string("process") 130 131 self._write_bits([(0, 3, 7), 132 (4, 15, 4 if process else 2), 133 (16, 23, kobj_type), 134 (24, 39, name_ref), 135 (40, 43, 1 if process else 0), 136 (44, 63, 0)]) 137 138 koid = len(self.kernel_objects) 139 self._write_bits([(0, 63, koid)]) 140 141 if process: 142 self._write_bits([(0, 3, 8), 143 (4, 15, 2), 144 (16, 31, arg_name), 145 (32, 63, 0)]) 146 self._write_bits([(0, 63, process)]) 147 148 self.kernel_objects[(kobj_type, name)] = koid 149 return koid 150 151 def thread(self, process_koid: int, thread_koid: int) -> int: 152 if (process_koid, thread_koid) in self.threads: 153 return self.threads[(process_koid, thread_koid)] 154 155 thread_index = len(self.threads) + 1 156 self._write_bits([(0, 3, 3), 157 (4, 15, 3), 158 (16, 23, thread_index), 159 (24, 63, 0)]) 160 self._write_bits([(0, 63, process_koid)]) 161 self._write_bits([(0, 63, thread_koid)]) 162 self.threads[(process_koid, thread_koid)] = thread_index 163 return thread_index 164 165 def duration(self, begin: bool, thread: int, category: Optional[str], 166 name: Optional[str], timestamp: int) -> None: 167 category_ref = self.encode_string(category) if category else 0 168 name_ref = self.encode_string(name) if name else 0 169 self._write_bits([(0, 3, 4), 170 (4, 15, 2), 171 (16, 19, 2 if begin else 3), 172 (20, 23, 0), 173 (24, 31, thread), 174 (32, 47, category_ref), 175 (48, 63, name_ref)]) 176 self._write_bits([(0, 63, timestamp)]) 177 178 179@dataclass 180class Event: 181 call: bool 182 name: str 183 timestamp: Optional[int] 184 185 186class Stacker: 187 """Stacker tries to keep track of how a thread's stack changes, and uses TraceWriter to 188 generate the corresponding Fuchsia trace. 189 """ 190 191 def __init__(self, writer: TraceWriter, thread: int): 192 self.writer = writer 193 self.thread = thread 194 self.stack: List[str] = [] 195 self.events: Deque[Event] = deque() 196 self.early_events: List[Event] = [] 197 self.waiting: List[Event] = [] 198 199 self.reset() 200 201 def reset(self) -> None: 202 self.was_call = False 203 self.was_ret = False 204 self.was_plt = False 205 self.last_symbol: Optional[str] = None 206 self.exception_name: Optional[str] = None 207 self.excepted_return: Optional[int] = None 208 self.first_timestamp: Optional[int] = None 209 self.last_timestamp: Optional[int] = None 210 211 def flush(self) -> None: 212 last = -1 213 for event in chain(self.early_events, self.events): 214 if event.timestamp: 215 assert last <= event.timestamp 216 last = event.timestamp 217 self.writer.duration(event.call, self.thread, None, event.name, event.timestamp) 218 219 self.early_events.clear() 220 self.events.clear() 221 self.events.extend(self.waiting) 222 223 def check_waiting(self, timestamp: Optional[int]) -> None: 224 if not timestamp: 225 return 226 227 if not self.first_timestamp: 228 self.first_timestamp = timestamp 229 self.last_timestamp = timestamp 230 231 for event in self.waiting: 232 event.timestamp = timestamp 233 234 self.waiting.clear() 235 236 def call(self, symbol: str, timestamp: Optional[int], front: bool = False) -> None: 237 event = Event(True, symbol, timestamp) 238 239 if not timestamp: 240 self.waiting.append(event) 241 242 for entry in self.stack: 243 if entry.startswith('Exception: '): 244 raise RuntimeError("New call while an exception is still on the stack!", 245 symbol, self.stack) 246 247 if front and self.events and not self.events[0].call: 248 # If the front of the events is a return, and we need to fake a call at the start, the 249 # returns will have to come before the call, otherwise Perfetto can't deal with it. 250 assert( 251 not timestamp or not self.events[0].timestamp or self.events[0].timestamp <= 252 timestamp) 253 while self.events and not self.events[0].call: 254 self.early_events.append(self.events.popleft()) 255 256 self.stack.append(symbol) 257 insert = self.events.appendleft if front else self.events.append 258 insert(event) 259 260 def ret(self, symbol: str, timestamp: Optional[int]) -> None: 261 event = Event(False, symbol, timestamp) 262 if not timestamp: 263 self.waiting.append(event) 264 265 if self.stack and self.stack[-1] != symbol: 266 raise RuntimeError('Top of the stack does not match the function being returned from! ' 267 f'Current function: {symbol}, top of the stack: {self.stack[-1]}') 268 269 if self.stack: 270 self.stack.pop() 271 self.events.append(event) 272 273 def lost_stack(self, timestamp: Optional[int]) -> None: 274 self.check_waiting(timestamp) 275 276 for symbol in reversed(self.stack): 277 self.ret(symbol, timestamp) 278 self.stack.clear() 279 self.flush() 280 self.reset() 281 282 def gap(self, timestamp: Optional[int]) -> None: 283 self.last_timestamp = None 284 if self.exception_name: 285 return 286 287 if self.last_symbol and self.last_symbol.endswith('@plt'): 288 self.was_plt = True 289 return 290 291 self.lost_stack(timestamp) 292 293 def timestamp(self, timestamp: Optional[int]) -> None: 294 self.check_waiting(timestamp) 295 296 def exception(self, timestamp: Optional[int], 297 name: str, excepted_return: Optional[int]) -> None: 298 self.check_waiting(timestamp) 299 300 if self.exception_name: 301 if excepted_return is not None and self.excepted_return == excepted_return: 302 # Same return, mark the end of the previous but carry on: 303 self.ret(self.exception_name, timestamp) 304 else: 305 # Interrupted, but for a different return. This most likely means some trace was 306 # lost. Drop the stack. 307 self.lost_stack(timestamp) 308 309 for e in self.stack: 310 if e.startswith('Exception '): 311 raise RuntimeError("Exception while another exception is already on the stack!", 312 name, self.stack) 313 314 self.exception_name = name 315 self.excepted_return = excepted_return 316 self.call(name, timestamp) 317 if timestamp: 318 self.last_timestamp = timestamp 319 320 def instr_range(self, timestamp: Optional[int], start: str, start_addr: int, 321 end: str, _end_addr: int, isubtype: etm.InstrSubtype) -> None: 322 self.check_waiting(timestamp) 323 324 if self.exception_name: 325 self.ret(self.exception_name, timestamp) 326 self.exception_name = None 327 328 if start_addr != self.excepted_return: 329 # If we are in the same symbol, assume we managed to get back safe and sound. 330 # Otherwise, drop the stack. 331 if not self.stack or self.stack[-1] != start: 332 self.lost_stack(self.last_timestamp) 333 334 if self.was_plt: 335 self.was_plt = False 336 if len(self.stack) > 1 and self.stack[-2] == start: 337 # When was_plt was set, last_symbol should have been too. 338 assert self.last_symbol 339 self.ret(self.last_symbol, timestamp) 340 self.last_symbol = start 341 else: 342 self.lost_stack(timestamp) 343 344 if self.last_symbol == 'art_quick_do_long_jump' and self.last_symbol != start: 345 # Art's long jump rewinds the stack to a previous state. 346 self.lost_stack(timestamp) 347 348 # check_waiting already set the timestamps, but lost_stack above might have nulled them. Set 349 # them again to make sure everything below can use the timestamps correctly. 350 self.first_timestamp = self.first_timestamp or timestamp 351 self.last_timestamp = timestamp or self.last_timestamp 352 353 if not self.was_call and not self.was_ret and self.last_symbol != start: 354 # If the symbol changed without us detecting a call or a return, we recognize two cases: 355 # if there's a last symbol saved, this was a tail call, and we emit a return and a call. 356 # Otherwise, this is the beginning of a new reconstruction of a stack, and we emit only 357 # the call. 358 if self.last_symbol: 359 # Tail call. 360 self.ret(self.last_symbol, timestamp) 361 self.call(start, timestamp) 362 if self.was_ret and not self.stack: 363 # If we have just returned into a function but the stack is empty, pretend that the 364 # current (new) function has been running since the first known timestamp. 365 self.call(start, self.first_timestamp, front=True) 366 if self.was_call: 367 # If the last instruction of the previous instruction range was a call (branch with 368 # link), emit a call. 369 self.call(start, timestamp) 370 if start != end: 371 # If for some reason the symbol changes inside an instruction range, pretend it was a 372 # tail call, even though this really shouldn't happen. 373 self.ret(start, timestamp) 374 self.call(end, timestamp) 375 if isubtype == etm.InstrSubtype.V8_RET: 376 # If the last instruction of the range is a return, we are returning from the current 377 # symbol. 378 self.ret(end, timestamp) 379 380 self.was_ret = isubtype == etm.InstrSubtype.V8_RET 381 self.was_call = isubtype == etm.InstrSubtype.BR_LINK 382 self.last_symbol = end 383 if timestamp: 384 self.last_timestamp = timestamp 385 386 387class Tracer: 388 def __init__(self, lib: ReportLib, binary_finder: BinaryFinder, readelf: ReadElf, 389 objdump: Objdump, w: TraceWriter) -> None: 390 self.abort: bool = False 391 392 self.last_timestamp: Optional[int] = None 393 self.lost_decoding: bool = False 394 395 self.context: EtmContext = EtmContext() 396 397 self.lib: ReportLib = lib 398 self.binary_finder: BinaryFinder = binary_finder 399 self.readelf: ReadElf = readelf 400 self.objdump: Objdump = objdump 401 402 self.processes: Dict[int, str] = {} 403 404 self.symbols: Dict[str, Tuple[List[Tuple[int, int, str]], List[int]]] = {} 405 self.symbol_cache: Optional[Tuple[str, Tuple[int, int, str]]] = None 406 407 self.stacks: Dict[int, Stacker] = {} 408 self.w: TraceWriter = w 409 w.magic() 410 w.switch_provider('etm') 411 412 self.s: Optional[Stacker] = None 413 414 def __call__(self, trace_id: int, elem: etm.GenericTraceElement) -> None: 415 if self.abort: 416 return 417 418 try: 419 self.process(trace_id, elem) 420 except Exception as e: 421 self.abort = True 422 self.gap() 423 self.flush() 424 raise e 425 426 def reset_trace(self) -> None: 427 self.context = EtmContext() 428 self.lost_decoding = False 429 self.last_timestamp = None 430 431 def process(self, trace_id: int, elem: etm.GenericTraceElement) -> None: 432 if elem.elem_type == etm.ElemType.TRACE_ON or elem.elem_type == etm.ElemType.NO_SYNC: 433 if self.s: 434 self.s.gap(self.last_timestamp) 435 self.reset_trace() 436 return 437 438 if elem.elem_type == etm.ElemType.PE_CONTEXT: 439 if self.context.update(elem.context): 440 tid = self.context.tid 441 if tid: 442 process = self.lib.GetThread(tid) 443 if process: 444 pid, tid, comm = process 445 else: 446 pid = tid 447 comm = f'Unknown process' 448 else: 449 pid = -1 450 tid = -1 451 comm = 'Unknown process' 452 453 kernel = "" if self.context.ex_level == etm.ExLevel.EL0 else " (kernel)" 454 thread_name = f'{tid} {comm or ""}{kernel}' 455 456 if pid in self.processes: 457 process_name = self.processes[pid] 458 else: 459 if pid == tid: 460 parent_name = comm 461 else: 462 t = self.lib.GetThread(pid) 463 parent_name = t[2] if t else "Unknown process" 464 process_name = f'{pid} {parent_name or ""}' 465 self.processes[pid] = process_name 466 467 pobj = self.w.kernel_object(1, process_name) 468 tobj = self.w.kernel_object(2, thread_name, process=pobj) 469 thread = self.w.thread(pobj, tobj) 470 # It is possible that the thread_name changed and we have the old one saved here. 471 # The Fuchsia trace does not seem to have any nice ways to handle changing names, 472 # therefore we are sticking with the first name we saw. 473 if tid not in self.stacks: 474 self.stacks[tid] = Stacker(self.w, thread) 475 476 self.s = self.stacks[tid] 477 return 478 479 if elem.elem_type == etm.ElemType.TIMESTAMP: 480 if self.last_timestamp != elem.timestamp: 481 self.last_timestamp = elem.timestamp 482 if self.s: 483 self.s.timestamp(elem.timestamp) 484 485 # For the other elements, a context should have happened before and must have set s. 486 assert self.s 487 488 if elem.elem_type == etm.ElemType.ADDR_NACC: 489 if not self.lost_decoding: 490 self.lost_decoding = True 491 mapped = self.lib.ConvertETMAddressToVaddrInFile(trace_id, elem.st_addr) 492 if mapped: 493 print(f'ADDR_NACC: path {mapped[0]} cannot be decoded! ({hex(elem.st_addr)})') 494 else: 495 print(f'ADDR_NACC: trace address {hex(elem.st_addr)} is not mapped!') 496 497 # We have lost trace. Give up on the stack. 498 # print(self.s.stack) 499 # print(self.last_timestamp, self.s.last_timestamp, self.s.waiting) 500 self.s.lost_stack(self.last_timestamp) 501 # print(self.last_timestamp, self.s.last_timestamp, self.s.waiting) 502 503 return 504 505 if elem.elem_type == etm.ElemType.EXCEPTION: 506 name = f'Exception: "{elem.exception_type()}" ({elem.exception_number})!' 507 self.s.exception(self.last_timestamp, name, 508 elem.en_addr if elem.excep_ret_addr else None) 509 return 510 511 if elem.elem_type != etm.ElemType.INSTR_RANGE: 512 return 513 514 self.lost_decoding = False 515 516 start_path, start_offset = self.lib.ConvertETMAddressToVaddrInFile( 517 trace_id, elem.st_addr) or ("", 0) 518 end_path, end_offset = self.lib.ConvertETMAddressToVaddrInFile( 519 trace_id, elem.en_addr - elem.last_instr_sz) or ("", 0) 520 521 error_messages = [] 522 if not start_path: 523 error_messages.append(f"Couldn't determine start path for address {elem.st_addr}!") 524 if not end_path: 525 error_messages.append( 526 f"Couldn't determine start path for address {elem.en_addr - elem.last_instr_sz}!") 527 if error_messages: 528 raise RuntimeError(' '.join(error_messages)) 529 530 start = self.get_symbol(start_path, start_offset) or "Unknown" 531 end = self.get_symbol(end_path, end_offset) or "Unknown" 532 533 if not elem.last_instr_cond and not elem.last_instr_exec: 534 buildid = self.lib.GetBuildIdForPath(end_path) 535 raise RuntimeError(f"Wrong binary! Unconditional branch at {hex(end_offset)}" 536 f" in {end_path} (build id: {buildid}) was not taken!") 537 538 self.s.instr_range(self.last_timestamp, 539 start, elem.st_addr, 540 end, elem.en_addr, 541 elem.last_i_subtype) 542 543 def gap(self) -> None: 544 for stack in self.stacks.values(): 545 stack.lost_stack(stack.last_timestamp) 546 547 def flush(self) -> None: 548 for stack in self.stacks.values(): 549 stack.flush() 550 551 def get_symbol(self, path: str, offset: int) -> Optional[str]: 552 if (self.symbol_cache and self.symbol_cache[0] == path and 553 (self.symbol_cache[1][0]) <= offset < (self.symbol_cache[1][0] + self.symbol_cache[1][1])): 554 return self.symbol_cache[1][2] 555 556 (symbols, offsets) = self.get_symbols(path) 557 if symbols: 558 i = bisect(offsets, offset) 559 if i: 560 i -= 1 561 if symbols[i][0] <= offset < symbols[i][0] + symbols[i][1]: 562 self.symbol_cache = (path, symbols[i]) 563 return symbols[i][2] 564 565 return None 566 567 def get_symbols(self, path: str) -> Tuple[List[Tuple[int, int, str]], List[int]]: 568 if path not in self.symbols: 569 s = self.lib.GetSymbols(path) 570 571 if not s: 572 log_exit(f"Can't find symbols for unknown binary '{path}'!") 573 return ([], []) 574 575 # Since other use cases don't care about the PLT, simpleperf represents it only as a 576 # single symbol called '@plt'. If it is present, try to get the actual names by parsing 577 # objdump's output. 578 if s[-1][2] == '@plt': 579 dso_info = self.objdump.get_dso_info(path, self.lib.GetBuildIdForPath(path)) 580 plts = self.objdump.get_plt_symbols(dso_info) 581 if plts: 582 del s[-1] 583 s.extend(plts) 584 585 self.symbols[path] = (s, [e[0] for e in s]) 586 587 return self.symbols[path] 588 589 590def get_args() -> argparse.Namespace: 591 parser = argparse.ArgumentParser(description='Generate Fuchsia trace from ETM data.') 592 parser.add_argument('-i', '--record_file', nargs=1, default=['perf.data'], help=""" 593 Set profiling data file to process.""") 594 parser.add_argument('--binary_cache', nargs=1, default=["binary_cache"], help=""" 595 Set path to the binary cache.""") 596 parser.add_argument('--ndk_path', nargs=1, help='Find tools in the ndk path.') 597 parser.add_argument('-o', '--output', nargs=1, help=""" 598 Output path for the trace. If not specified, the record file's name is 599 used, with .fxt appended.""") 600 return parser.parse_args() 601 602 603def main() -> None: 604 args = get_args() 605 606 binary_cache_path = args.binary_cache[0] 607 if not pathlib.Path(binary_cache_path).is_dir(): 608 log_exit(f"Binary cache '{binary_cache_path}' is not a directory!") 609 return 610 611 ndk_path = args.ndk_path[0] if args.ndk_path else None 612 613 lib = ReportLib() 614 try: 615 lib.SetRecordFile(args.record_file[0]) 616 lib.SetSymfs(binary_cache_path) 617 lib.SetLogSeverity('error') 618 619 readelf = ReadElf(ndk_path) 620 binary_finder = BinaryFinder(binary_cache_path, readelf) 621 objdump = Objdump(ndk_path, binary_finder) 622 623 filename = args.output[0] if args.output else f'{args.record_file[0]}.fxt' 624 625 with open(filename, 'wb') as f: 626 callback = Tracer(lib, binary_finder, readelf, objdump, TraceWriter(f)) 627 lib.SetETMCallback(callback) 628 while not callback.abort and lib.GetNextSample(): 629 pass 630 631 # Trace has ended, make sure every call has a corresponding return. Use the largest 632 # timestamp and end everything there. 633 last_timestamps = [stacker.last_timestamp for stacker 634 in callback.stacks.values() 635 if stacker.last_timestamp] 636 last_timestamp = max(last_timestamps, default=None) 637 for stacker in callback.stacks.values(): 638 stacker.last_timestamp = last_timestamp 639 callback.gap() 640 callback.flush() 641 642 finally: 643 lib.Close() 644 645 646if __name__ == '__main__': 647 main() 648