diff --git a/.gitattributes b/.gitattributes index 0189dd4d..ed28193f 100644 --- a/.gitattributes +++ b/.gitattributes @@ -1,4 +1,3 @@ -catapult/* linguist-vendored sampledata/* linguist-vendored sample/* linguist-vendored diff --git a/.github/workflows/python-tests.yml b/.github/workflows/python-tests.yml index e4c0a5f7..d5aaa020 100644 --- a/.github/workflows/python-tests.yml +++ b/.github/workflows/python-tests.yml @@ -36,3 +36,12 @@ jobs: run: chmod +x scripts/test_objc_msgsend_hook.sh scripts/test_objc_msgsend_hook_experimental.sh - name: Run objc_msgSend experimental test run: ./scripts/test_objc_msgsend_hook_experimental.sh + + batching-stress: + runs-on: macos-latest + steps: + - uses: actions/checkout@v4 + - name: Make stress script executable + run: chmod +x scripts/test_batching_stress.sh + - name: Run batched-writer stress test (text + binary) + run: ./scripts/test_batching_stress.sh diff --git a/.gitignore b/.gitignore index 282766d6..b691f708 100644 --- a/.gitignore +++ b/.gitignore @@ -11,3 +11,6 @@ appletrace/appletrace.xcodeproj/xcuserdata/ *.zip *.dylib build/ +__pycache__/ +*.pyc +.pytest_cache/ diff --git a/AGENT.md b/AGENT.md index 778cd752..62743002 100644 --- a/AGENT.md +++ b/AGENT.md @@ -3,46 +3,46 @@ This reference is for AI agents and contributors working inside the AppleTrace repository. It summarizes how the project is organized, how to run and verify changes, and the expectations for contributions. ## Project Overview -- AppleTrace instruments iOS apps so you can analyze performance hotspots with Chrome's tracing viewer. -- Developers can either add manual `APTBeginSection` / `APTEndSection` markers or hook every `objc_msgSend` via HookZz (arm64 only). -- `merge.py`, `scripts/appletrace_cli.py`, Catapult's `trace2html`, and the helper `go.sh` script transform sandbox data into `trace.json` and `trace.html`. +- AppleTrace instruments iOS apps so you can analyze performance hotspots in [Perfetto](https://ui.perfetto.dev). +- Developers can either add manual `APTBeginSection` / `APTEndSection` markers (plus `APTInstant` / `APTCounter` / `APTAsyncBegin` / `APTAsyncEnd` events) or hook every `objc_msgSend` via a fishhook-style direct symbol rebind (arm64 only; see `appletrace/appletrace/src/objc/hook_objc_msgSend.m`). +- `merge.py` and `scripts/appletrace_cli.py` (and the helper `go.sh`) merge sandbox fragments into a `trace.json` you open directly in Perfetto. Visualization is Perfetto-only; there is no Catapult/Chrome HTML pipeline. - Releases bundle a loader tweaked for arm64, but the source can be rebuilt via the included Xcode projects. ## Repository Map - `appletrace/` — Core framework sources (`appletrace.xcodeproj`, Objective-C runtime hooks, exported headers). - `loader/` — Loader/packaging project plus `resign.sh` for re-signing the embedded `appletrace.framework`. -- `sample/ManualSectionDemo` and `sample/TraceAllMsgDemo` — Xcode samples that show manual instrumentation and HookZz-based tracing. +- `sample/ManualSectionDemo` and `sample/TraceAllMsgDemo` — Xcode samples that show manual instrumentation and automatic `objc_msgSend` tracing. - `springboard/AppleTraceSpringBoard` — Additional loader project for SpringBoard-focused experiments. -- `hookzz/` — Embedded HookZz dependency used to hook `objc_msgSend`. -- `go.sh`, `merge.py`, `scripts/appletrace_cli.py`, `get_catapult.sh` — Scripts for merging trace files, converting them with Catapult, and downloading Catapult. -- `sampledata/` — Ready-made traces (`trace.html`) for verifying the visualization pipeline. -- `release/` — Notes and artifacts for the prebuilt loader (arm64 only). +- `hookzz/` — Legacy embedded HookZz dependency (the current `objc_msgSend` hook uses a direct symbol rebind instead). +- `go.sh`, `merge.py`, `scripts/appletrace_cli.py` — Scripts for merging trace fragments into `trace.json` and opening Perfetto. +- `sampledata/` — Ready-made trace (`trace.json`) for verifying the visualization pipeline in Perfetto. +- `release/` — Notes and artifacts for the prebuilt loader (arm64). - `image/`, `wechat.png` — Documentation assets. ## Running the Project Locally 1. **Clone & prerequisites** - `git clone https://github.com/everettjf/AppleTrace.git` - - Install Xcode, Python 3, Chrome, LLDB, and `ldid` (for re-signing loader builds). + - Install Xcode, Python 3, LLDB, and `ldid` (for re-signing loader builds). - Optional: `python3 -m pip install -r requirements.txt` for local test tooling. - - Run `sh get_catapult.sh` once to fetch Catapult (`catapult/tracing/bin/trace2html` must exist before generating HTML reports). + - Visualization is browser-based at [ui.perfetto.dev](https://ui.perfetto.dev); nothing to download. 2. **Build instrumentation** - For manual tracing, open `appletrace/appletrace.xcodeproj`, build the framework, and embed it into your target (see `sample/ManualSectionDemo`). - - For automatic tracing, build the HookZz-based dynamic library (see `sample/TraceAllMsgDemo`). This mode must run on arm64 under LLDB. + - For automatic tracing, build the dynamic library (see `sample/TraceAllMsgDemo`). This mode runs on arm64 under LLDB. 3. **Collect data** - Run the instrumented app; trace segments are written to `/Library/appletracedata`. - Pull the folder from the Simulator or device. 4. **Process traces** - - Quick path: `sh go.sh ` to run merge + `trace2html` and open Chrome. - - Manual path: `python3 merge.py -d ` followed by `python3 catapult/tracing/bin/trace2html /trace.json --output=/trace.html`. - - Unified path: `python3 scripts/appletrace_cli.py all --open`. + - Quick path: `sh go.sh ` to merge and open Perfetto. + - Manual path: `python3 merge.py -d ` then drag `/trace.json` into [ui.perfetto.dev](https://ui.perfetto.dev). + - Unified path: `python3 scripts/appletrace_cli.py open `. ## Testing - Automated coverage exists for the Python trace merge pipeline: - `python3 -m pytest tests` - Runtime and loader validation is still manual: - - Run the sample projects and confirm the generated `trace.json`/`trace.html`. - - Inspect traces in Chrome to ensure new instrumentation appears as expected. - - When touching the loader or HookZz code, test on a real arm64 device under LLDB. + - Run the sample projects and confirm the generated `trace.json`. + - Inspect traces in Perfetto to ensure new instrumentation appears as expected. + - When touching the loader or hook code, test on a real arm64 device under LLDB. ## Linting & Formatting - No dedicated Objective-C lint/format pipeline exists. Follow existing Objective-C/C/C++/Python conventions in the repo (clang/Xcode defaults, 4-space indentation in Python). @@ -51,23 +51,24 @@ This reference is for AI agents and contributors working inside the AppleTrace r ## Build & Release - **Frameworks**: Use `appletrace.xcodeproj` targets. Make sure exported headers remain in `appletrace.framework`. - **Loader**: After swapping in a rebuilt framework (`loader/AppleTraceLoader/Package/Library/Frameworks/appletrace.framework`), run `loader/resign.sh` to re-sign with `ldid`. -- **Catapult**: Keep the downloaded Catapult copy in sync if `trace2html` changes; document updates in README/AGENT when bumping instructions. -- **Deliverables**: The `release/` folder is arm64-only; highlight this in release notes and README when publishing new binaries. +- **Visualization**: Traces open in Perfetto (`ui.perfetto.dev`) directly; there is no bundled HTML exporter to keep in sync. +- **Deliverables**: The `release/` folder targets arm64; highlight this in release notes and README when publishing new binaries. ## Coding Style & Conventions - Prefer concise Objective-C with explicit `APTBeginSection` markers; avoid introducing new macros unless necessary. - Keep Objective-C source under `appletrace/src`; Python utilities now live both at repo root (`merge.py`) and under `scripts/` for higher-level workflows. -- Use descriptive section names inside traces to keep Chrome timelines meaningful. +- Use descriptive section names inside traces to keep Perfetto timelines meaningful. ## Debugging -- Use LLDB breakpoints around the HookZz injection points (`appletrace/src/objc/hook_objc_msgSend.m`) when troubleshooting automatic tracing. +- Use LLDB breakpoints around the rebinding/wrapper code (`appletrace/appletrace/src/objc/hook_objc_msgSend.m`) when troubleshooting automatic tracing. - Inspect intermediate `trace.appletrace` files before merging to ensure data is written. -- Open `chrome://tracing` with `trace.json` to verify event ordering before generating HTML. -- Compare against `sampledata/trace.html` if output looks incorrect. +- Open `trace.json` in [ui.perfetto.dev](https://ui.perfetto.dev) to verify event ordering and timing. +- Compare against `sampledata/trace.json` if output looks incorrect. ## Rules for Making Changes - Keep changes scoped: avoid mixing instrumentation updates with tooling refactors or documentation tweaks. -- Maintain compatibility with existing arm64-only assumption unless explicitly widening platform support. +- Target arm64 only; other architectures (arm64e, x86_64) are out of scope. The `objc_msgSend` hook hard-errors if built for arm64e. +- Visualization is Perfetto-only — do not reintroduce a Catapult/Chrome HTML pipeline. - Update README/AGENT/wiki when changing workflows, scripts, or dependencies. - Never remove diagnostic scripts (`merge.py`, `go.sh`) without providing replacements. - Preserve existing assets (images, sample traces) so documentation stays accurate. diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md new file mode 100644 index 00000000..d20afbff --- /dev/null +++ b/CONTRIBUTING.md @@ -0,0 +1,65 @@ +# Contributing to AppleTrace + +Thanks for your interest in improving AppleTrace! This guide covers how to get +set up, what we expect from changes, and how to validate them. + +## Getting Started + +```bash +git clone https://github.com/everettjf/AppleTrace.git +cd AppleTrace +python3 -m pip install -r requirements.txt +``` + +You will need Xcode 12+ (macOS 10.15+) to build the framework and samples, and a +recent Python 3 for the tooling and tests. + +## Project Layout + +- `appletrace/` — core tracing framework (Objective-C/C++ runtime, public headers). +- `appletrace/appletrace/src/objc/hook_objc_msgSend.m` — arm64 `objc_msgSend` hook. +- `loader/`, `springboard/` — loader/packaging projects. +- `merge.py`, `scripts/appletrace_cli.py`, `go.sh` — tooling (merge + open in Perfetto). +- `tests/` — Python regression tests. + +See [AGENT.md](AGENT.md) for a deeper map and build/release details, and +[ROADMAP.md](ROADMAP.md) for where the project is headed. + +## Making Changes + +- Keep changes scoped: don't mix instrumentation, tooling, and docs in one PR. +- The `objc_msgSend` hook targets arm64 only — preserve that assumption + (arm64e and other architectures are out of scope; the hook hard-errors on arm64e). +- Avoid adding work to the tracing hot path; prefer caching/interning and + per-thread state over per-event allocation. +- Update `README.md` / `README_CN.md` / `AGENT.md` when workflows or APIs change. + +## Testing + +```bash +# Python tooling +python3 -m pytest tests + +# objc_msgSend hook smoke tests (run on a Mac) +./scripts/test_objc_msgsend_hook.sh +./scripts/test_objc_msgsend_hook_experimental.sh + +# Verify the merge + export pipeline on real data +python3 merge.py -d +``` + +When touching the framework, build the relevant Xcode targets and confirm a +trace renders correctly in [Perfetto](https://ui.perfetto.dev). + +## Code Style + +- **Objective-C:** [Google Objective-C Style Guide](https://google.github.io/styleguide/objcguide.html) +- **Python:** [PEP 8](https://www.python.org/dev/peps/pep-0008/) +- **Shell:** [Google Shell Style Guide](https://google.github.io/styleguide/shellguide.html) + +## Pull Requests + +1. Fork and create a feature branch. +2. Make your change with tests where applicable. +3. Run the test commands above and note any manual testing (device, iOS version). +4. Open a PR describing the change and its motivation. diff --git a/README.md b/README.md index 3ce812e9..052c7f6a 100644 --- a/README.md +++ b/README.md @@ -7,119 +7,162 @@ [![License](https://img.shields.io/badge/License-MIT-blue?style=flat-square)](LICENSE) [![Last Commit](https://img.shields.io/github/last-commit/everettjf/AppleTrace?style=flat-square)](https://github.com/everettjf/AppleTrace/commits/master) [![Contributors](https://img.shields.io/github/contributors/everettjf/AppleTrace?style=flat-square)](https://github.com/everettjf/AppleTrace/graphs/contributors) +[![Platform](https://img.shields.io/badge/platform-iOS%20%7C%20macOS-lightgrey?style=flat-square&logo=apple)](https://github.com/everettjf/AppleTrace) -**Objective-C Method Tracing & Call Graph Analysis Tool** +**A lightweight, embeddable Objective-C tracer that produces shareable [Perfetto](https://ui.perfetto.dev) traces** [English](README.md) | [中文](README_CN.md) -> ⚠️ **Note:** AppleTrace is in maintenance mode (bug fixes only). -> **Recommended:** Upgrade to **[Messier](https://messier.github.io/)** - the next-generation tracing tool that's easier to use and better maintained. +> 🚀 **Actively developed.** AppleTrace captures your app's execution timeline — +> manual sections and/or every `objc_msgSend` — and renders it in Perfetto, right +> in the browser. See [ROADMAP.md](ROADMAP.md) for what's planned next. -## 2026 Modernization Highlights +![AppleTrace Demo](https://everettjf.github.io/stuff/appletrace/appletrace.gif) -- Python tooling now targets Python 3 and produces valid JSON output reliably. -- Added a unified CLI: `scripts/appletrace_cli.py`. -- Added automated tests for trace merging plus GitHub Actions CI. -- Runtime now supports `APTFlush`, `APTSetEnabled`, `APTIsEnabled`, and `APTGetTraceDirectory`. -- Trace writing supports JSON-safe section names, configurable output directory, and configurable mmap block size. +--- + +## Table of Contents + +- [What is AppleTrace?](#-what-is-appletrace) +- [Key Features](#-key-features) +- [How It Works](#-how-it-works) +- [Quick Start](#-quick-start) +- [Installation](#-installation) +- [Usage](#-usage) +- [Processing & Visualizing Traces](#-processing--visualizing-traces) +- [Platform & Hook Support](#-platform--hook-support) +- [Testing](#-testing) +- [Project Structure](#-project-structure) +- [FAQ](#-faq) +- [Contributing](#-contributing) +- [License](#-license) --- ## 🎯 What is AppleTrace? -AppleTrace is an iOS tracing toolkit +AppleTrace is an iOS/macOS tracing toolkit. You instrument your app — either by +adding manual `APTBeginSection` / `APTEndSection` markers, or by hooking every +`objc_msgSend` automatically — and AppleTrace records a timeline of events into +sandbox trace fragments. A small Python pipeline merges those fragments into a +single `trace.json` that you open directly in [Perfetto](https://ui.perfetto.dev) +to explore the call timeline, durations, threads, and counters. -![AppleTrace Demo](https://everettjf.github.io/stuff/appletrace/appletrace.gif) that captures your app's execution timeline and renders it with Chrome's tracing tools. +![Demo Preview](image/appletrace-small.png) -![AppleTrace Demo](image/appletrace-small.png) +*The trace visualization shows the method execution timeline and call relationships.* -### Key Features +--- -- 📊 **Method Tracing** - Directly rebind `objc_msgSend` on arm64 to capture Objective-C method activity -- 🎯 **Custom Sections** - Define custom trace sections with APTBeginSection/APTEndSection -- 📈 **Call Graph** - Visualize call relationships and execution flow -- 🌐 **Chrome Integration** - Export traces to chrome://tracing or generate shareable HTML reports -- 🔧 **Dual Modes** - Manual instrumentation or dynamic hooking via direct `objc_msgSend` rebinding +## ✨ Key Features + +- 📊 **Automatic method tracing** — direct `objc_msgSend` / `objc_msgSendSuper2` + rebinding on arm64 captures Objective-C activity with no source changes. +- 🎯 **Manual sections** — `APTBeginSection` / `APTEndSection` (and the + `APTBegin` / `APTEnd` / `APTScopeSection` helpers) mark exactly the regions you + care about — the lowest-risk option, works on every OS version. +- 📈 **Rich event types** — instant markers (`APTInstant`), counter series + (`APTCounter` for memory, FPS, queue depth, …), and async/flow events + (`APTAsyncBegin` / `APTAsyncEnd`) that cross threads and dispatch queues. +- ⚡ **Built for the hot path** — `(Class, SEL)` name interning, a + zero-allocation per-thread call stack, and per-thread batched writing keep + `malloc` / `snprintf` / dispatch off the per-message path. An opt-in binary + fragment format (`APPLETRACE_BINARY=1`) keeps string formatting off it entirely. +- 🧵 **Thread names** — Perfetto shows real thread names instead of bare ids. +- 🔍 **Runtime filtering** — scope automatic tracing with class-prefix allow/deny + lists (`APPLETRACE_TRACE_CLASS_ALLOW` / `APPLETRACE_TRACE_CLASS_DENY`). +- 🌐 **Perfetto-first** — open `trace.json` at + [ui.perfetto.dev](https://ui.perfetto.dev); nothing to install, runs in the + browser, scales to large traces. Begin/end pairs export as `X` complete events + by default to halve trace size. +- 🐍 **Python 3 tooling** — a unified CLI (`scripts/appletrace_cli.py`), streaming + merge for large captures, automated tests, and GitHub Actions CI. -### Current Hook Status +### Use Cases -- Stable path: manual sections plus delayed `objc_msgSend` hook installation are covered by simulator smoke tests. -- Experimental path: app-owned nested Objective-C sends, `objc_msgSendSuper2`, cross-thread events, a 10-argument Objective-C call, floating-point argument/return handling, and small aggregate return values are now covered by a second simulator trace scenario. -- Recommended release posture: ship the current direct hook as an arm64 preview, with manual sections still available as the lowest-risk baseline. +- 🔍 **Performance analysis** — find hotspots and long methods on a real timeline. +- 🐛 **Debugging** — follow method execution flow across threads. +- 📚 **Learning** — see how iOS/macOS frameworks actually dispatch. +- 🛡️ **Security research** — analyze third-party app behavior. -### Use Cases +--- -- 🔍 **Performance Analysis** - Identify performance bottlenecks -- 🐛 **Debugging** - Trace method execution flow -- 📚 **Learning** - Understand how iOS frameworks work -- 🛡️ **Security Research** - Analyze third-party app behavior +## 🔧 How It Works + +``` + Your app (instrumented) Host tooling Browser +┌───────────────────────────┐ ┌──────────────────────┐ ┌────────────────┐ +│ APTBeginSection / APTEnd… │ │ merge.py / │ │ │ +│ APTInstant / APTCounter │ ───► │ appletrace_cli.py │ ───► │ ui.perfetto.dev│ +│ APTAsyncBegin / … │ │ │ │ │ +│ objc_msgSend auto-hook │ │ fragments → trace.json│ │ drag & drop │ +└───────────────────────────┘ └──────────────────────┘ └────────────────┘ + per-thread batched writes X-complete collapse + → /Library/appletracedata → single JSON array +``` + +1. **Instrument** — add manual markers, or install the `objc_msgSend` hook. +2. **Capture** — events accumulate in per-thread buffers and flush in bulk to + trace fragments under `/Library/appletracedata`. +3. **Merge** — pull the folder and run `merge.py`; begin/end pairs collapse into + Perfetto `X` complete events. +4. **Visualize** — drag `trace.json` into Perfetto. --- ## ⚡ Quick Start -### 1. Install Dependencies - ```bash -# macOS with Homebrew -brew install python ldid git +# 1. Prerequisites (macOS) +brew install python git ldid # ldid is only needed for re-signing loader builds -# Clone the repository +# 2. Clone git clone https://github.com/everettjf/AppleTrace.git cd AppleTrace -# Download Catapult tooling -sh get_catapult.sh - -# Optional but recommended: install Python tooling +# 3. Optional: Python tooling for merging/tests python3 -m pip install -r requirements.txt ``` -### 2. Choose Your Mode - -#### Mode A: Manual Instrumentation (Recommended) +### Mode A — Manual Instrumentation (recommended baseline) ```objc -// Add to your Objective-C code #import - (void)yourMethod { - APTBegin; - // Your code here + APTBegin; // section named "[ClassName yourMethod]" + // ... your code ... APTEnd; } ``` -#### Mode B: Dynamic Hooking (Advanced) +### Mode B — Automatic `objc_msgSend` Hook (arm64) -```bash -# Requires arm64 and explicit hook installation -# Call APTInstallObjcMsgSendHook() after app launch +```objc +// From your app, after launch: +APTInstallObjcMsgSendHook(); ``` -### 3. Capture & Visualize - ```bash -# Run your app on simulator/device -# Traces are saved to /Library/appletracedata +# …or without code changes, via environment variable: +export APPLETRACE_AUTO_HOOK_OBJC_MSGSEND=1 +``` -# Merge trace files -python3 merge.py -d /Library/appletracedata +### Capture & Visualize -# Generate HTML report (requires Catapult) -sh go.sh /Library/appletracedata +```bash +# Run the app; fragments land in /Library/appletracedata. +# Pull that folder from the simulator/device, then: -# Open in Chrome -open /Library/appletracedata/trace.html +python3 merge.py -d /path/to/appletracedata # → trace.json +# or merge AND open Perfetto in one step: +sh go.sh /path/to/appletracedata ``` -### 4. View Results - -- **Option 1:** Open `trace.html` directly in Chrome -- **Option 2:** Drag `trace.json` into chrome://tracing -- **Option 3:** Use the [online demo](sampledata/trace.html) +Open [ui.perfetto.dev](https://ui.perfetto.dev) and drag in `trace.json` (or use +**Open trace file**). --- @@ -127,59 +170,33 @@ open /Library/appletracedata/trace.html ### Requirements -| Requirement | Version | Description | -|-------------|---------|-------------| +| Requirement | Version | Used for | +|-------------|---------|----------| | **macOS** | 10.15+ | Build environment | -| **Xcode** | 12+ | iOS/macOS development | -| **Python** | 3.9+ | Trace processing scripts and test tooling | -| **Chrome** | Any | Trace visualization | -| **LLDB** | (Optional) | Dynamic hook mode | - -### Setup Steps +| **Xcode** | 12+ | iOS/macOS builds (arm64) | +| **Python** | 3.9+ | Trace merging, CLI, and tests | +| **Perfetto** | Web | Visualization at [ui.perfetto.dev](https://ui.perfetto.dev) | +| **ldid** | Optional | Re-signing the loader's embedded framework | +| **LLDB** | Optional | Driving the dynamic hook mode | -```bash -# 1. Clone the repository -git clone https://github.com/everettjf/AppleTrace.git -cd AppleTrace - -# 2. Download Catapult (required for HTML export) -sh get_catapult.sh +### Build the framework -# 3. Build the framework -cd appletrace/appletrace.xcodeproj -xcodebuild -project appletrace.xcodeproj -scheme appletrace -configuration Release build +From the repository root: -# 4. (Optional) Install signing tool for iOS -brew install ldid +```bash +# iOS device (arm64) +xcodebuild -project appletrace/appletrace.xcodeproj -scheme appletrace \ + -configuration Release -sdk iphoneos build ``` ---- - -## 📁 Project Structure +> AppleTrace targets **arm64 only**. arm64e is out of scope: the auto-hook would +> have to rebind pointer-authenticated GOT entries, so the hook source +> deliberately fails to compile for arm64e. Build a plain arm64 slice. -``` -AppleTrace/ -├── appletrace/ # Core tracing framework -│ ├── appletrace.xcodeproj -│ ├── appletrace/ # Framework source -│ └── appletraceTests/ -├── loader/ # Dynamic library loader -│ └── AppleTraceLoader/ -├── sample/ # Example projects -│ ├── ManualSectionDemo/ # Manual instrumentation demo -│ └── TraceAllMsgDemo/ # Dynamic hook demo -├── image/ # Documentation images -├── sampledata/ # Demo trace files -├── scripts/ # Utility scripts -│ └── appletrace_cli.py # Merge + HTML generation CLI -├── merge.py # Merge trace files -├── go.sh # One-shot merge + HTML generation -├── get_catapult.sh # Download Catapult -├── requirements.txt # Python dependencies -├── tests/ # Python regression tests -├── README.md # English documentation -└── README_CN.md # Chinese documentation -``` +Embed the resulting `appletrace.framework` into your target (see +`sample/ManualSectionDemo` for manual mode and `sample/TraceAllMsgDemo` for the +auto-hook). For injecting into third-party apps, see the `loader/` project and +run `loader/resign.sh` after swapping in a rebuilt framework. --- @@ -187,240 +204,251 @@ AppleTrace/ ### Manual Instrumentation -#### Objective-C +**Objective-C** ```objc #import - (void)viewDidLoad { - APTBegin; + APTBegin; // auto-named "[ClassName viewDidLoad]" [super viewDidLoad]; - // Your code APTEnd; } -// Or with custom section name - (void)networkRequest { - APTBeginSection("network"); - // Network code + APTBeginSection("network"); // explicit section name + // ... network code ... APTEndSection("network"); } ``` -#### C/C++ +**C / C++** ```cpp #include void complexFunction() { APTBeginSection("processing"); - // C++ code + // ... C++ code ... APTEndSection("processing"); } void saferCppFunction() { - APTScopeSection("processing"); - // C++ code + APTScopeSection("processing"); // RAII: ends automatically at scope exit + // ... C++ code ... } ``` -### Dynamic Hooking Smoke Test +### Instant Markers, Counters & Async Events -```bash -./scripts/test_objc_msgsend_hook.sh -./scripts/test_objc_msgsend_hook_experimental.sh +```objc +// Mark a point in time on the current thread's timeline +APTInstant("cache_miss"); + +// Plot a value over time (memory, FPS, queue depth, ...) +APTCounter("resident_mb", 142.5); +APTCounter("fps", 60); + +// Track work that crosses threads / dispatch queues (matched by name + id) +uint64_t requestID = 42; +APTAsyncBegin("image_load", requestID); +dispatch_async(queue, ^{ + // ... work on another thread ... + APTAsyncEnd("image_load", requestID); +}); ``` -The first script validates the baseline delayed-install flow. The second script validates nested sample method tracing, `super` dispatch, cross-thread events, explicit section pairing, stack-passed Objective-C arguments, floating-point Objective-C arguments and return values, and small aggregate returns. - ### Runtime Controls ```objc -APTSetEnabled(NO); // Temporarily disable trace recording -APTSetEnabled(YES); // Re-enable -APTFlush(); // Force buffered writes to disk +APTSetEnabled(NO); // Temporarily pause recording +APTSetEnabled(YES); // Resume +BOOL on = APTIsEnabled(); // Query state +APTFlush(); // Force buffered writes to disk +APTSyncWait(); // Block until pending writes complete NSLog(@"trace dir = %s", APTGetTraceDirectory()); +BOOL hooked = APTIsObjcMsgSendHookInstalled(); ``` -### Dynamic Hook Mode +### Environment Variables ```bash -# 1. Build your app with AppleTraceLoader -# 2. Run under LLDB -lldb YourApp.app +export APPLETRACE_ENABLED=1 +export APPLETRACE_DATA_DIR="$HOME/tmp/appletracedata" +export APPLETRACE_BLOCK_SIZE_MB=32 +export APPLETRACE_KEEP_EXISTING=1 -# 3. Load the dynamic library -(lldb) command script import loader/AppleTraceLoader.py -(lldb) AppleTraceLoader.load() +# Automatic objc_msgSend hook (arm64) +export APPLETRACE_AUTO_HOOK_OBJC_MSGSEND=1 +# Only trace classes whose names start with these comma-separated prefixes +export APPLETRACE_TRACE_CLASS_ALLOW="MyApp,UI" +# Never trace classes with these prefixes (takes precedence over allow) +export APPLETRACE_TRACE_CLASS_DENY="NSKVO,_" -# 4. Run your app - all objc_msgSend calls will be traced +# Opt-in binary fragment format (keeps string formatting off the hot path) +export APPLETRACE_BINARY=1 ``` -### Processing Traces +--- + +## 📊 Processing & Visualizing Traces ```bash -# Merge all trace files +# Merge all fragments into trace.json (X complete events by default) python3 merge.py -d /path/to/appletracedata -# Or use the unified CLI -python3 scripts/appletrace_cli.py merge /path/to/appletracedata +# Keep raw begin/end events instead of collapsing them +python3 merge.py -d /path/to/appletracedata --raw -# Generate HTML (requires Catapult) -python3 catapult/tracing/bin/trace2html \ - /path/to/appletracedata/trace.json \ - --output=/path/to/appletracedata/trace.html +# Unified CLI +python3 scripts/appletrace_cli.py merge /path/to/appletracedata +python3 scripts/appletrace_cli.py open /path/to/appletracedata # merge + open Perfetto -# Or use the helper script +# One-liner helper sh go.sh /path/to/appletracedata - -# One-shot merge + HTML via CLI -python3 scripts/appletrace_cli.py all /path/to/appletracedata --open ``` -### Runtime Environment Variables +`merge.py` auto-discovers both text (`trace[_N].appletrace`) and binary +(`trace[_N].appletracebin`) fragments and decodes each by its magic header. +Then drag the resulting `trace.json` into [ui.perfetto.dev](https://ui.perfetto.dev). -```bash -export APPLETRACE_ENABLED=1 -export APPLETRACE_DATA_DIR="$HOME/tmp/appletracedata" -export APPLETRACE_BLOCK_SIZE_MB=32 -export APPLETRACE_KEEP_EXISTING=1 -``` +Want to try it without building anything? Drag the prebuilt +[`sampledata/trace.json`](sampledata/trace.json) into Perfetto. --- -## 🛠️ Tech Stack +## 🧩 Platform & Hook Support -
- -**Core Technologies** -![Objective-C](https://img.shields.io/badge/Objective--C-438APD?style=flat-square&logo=apple) -![C](https://img.shields.io/badge/C-00599C?style=flat-square&logo=c) -![Python](https://img.shields.io/badge/Python-3776AB?style=flat-square&logo=python) -![Xcode](https://img.shields.io/badge/Xcode-147EFB?style=flat-square&logo=xcode) +AppleTrace targets **arm64 only**. -**Key Dependencies** -![HookZz](https://img.shields.io/badge/HookZz-FF6B6B?style=flat-square&logo=github) -![Catapult](https://img.shields.io/badge/Catapult-4ECDC4?style=flat-square&logo=google-chrome) -![LLDB](https://img.shields.io/badge/LLDB-1A73E8?style=flat-square&logo=llvm) +| Mode | arm64 | +|------|:-----:| +| Manual sections & explicit events (`APTBeginSection`, `APTInstant`, …) | ✅ | +| Automatic `objc_msgSend` / `objc_msgSendSuper2` hook | ✅ | -
+- **Manual sections** are the lowest-risk baseline and work on every iOS/macOS + version. +- The **arm64 auto-hook** is validated end-to-end on the iOS Simulator and a host + stress test — nested sends, `super` dispatch, cross-thread events, a + 10-argument call, and floating-point / small-aggregate ABI cases all survive + the tracing wrapper. +- **arm64e is not supported.** Its callers reach `objc_msgSend` through + authenticated GOT entries (`__DATA_CONST.__auth_got`), which would require + re-signing rebound pointers with the correct pointer-authentication context. + Rather than ship an unvalidated hook, the hook source hard-errors when built + for arm64e — build a plain arm64 slice instead. --- -## 📊 Demo +## ✅ Testing -### Interactive Demo - -Explore a pre-recorded trace directly in Chrome: +```bash +# Python tooling (merge pipeline + binary fragment format) +python3 -m pytest tests -- 📂 **[Interactive Trace Demo](sampledata/trace.html)** - Open in Chrome to see AppleTrace in action +# objc_msgSend hook smoke tests (builds + runs the sample on a simulator) +./scripts/test_objc_msgsend_hook.sh +./scripts/test_objc_msgsend_hook_experimental.sh -![Demo Preview](image/appletrace-small.png) +# Batched-writer concurrency stress test (host build, text + binary modes) +./scripts/test_batching_stress.sh +``` -*The trace visualization shows method execution timeline and call relationships.* +The experimental hook script additionally validates `super` dispatch, +cross-thread events, stack-passed and floating-point Objective-C arguments, and +small aggregate returns. The stress test asserts no events are lost or duplicated +across threads, flushes, and thread exits. --- -## ❓ FAQ - -### Q: Is AppleTrace still maintained? - -**AppleTrace is in maintenance mode** (bug fixes only, no new features). - -For new projects, I strongly recommend using **[Messier](https://messier.github.io/)**: -- ✅ Modern architecture -- ✅ Easier setup -- ✅ Better performance -- ✅ Active development +## 📁 Project Structure -### Q: Does AppleTrace work on iOS 17+? +``` +AppleTrace/ +├── appletrace/ # Core tracing framework (appletrace.xcodeproj) +│ └── appletrace/src/ # Framework source + objc_msgSend hook +├── loader/ # Dynamic library loader + resign.sh +├── sample/ +│ ├── ManualSectionDemo/ # Manual instrumentation demo +│ └── TraceAllMsgDemo/ # Automatic objc_msgSend hook demo +├── scripts/ # CLI + smoke/stress test scripts +│ └── appletrace_cli.py # Merge + open-in-Perfetto CLI +├── docs/ # Binary format & batching design notes +├── tests/ # Python regression tests + stress harness +├── sampledata/ # Demo trace.json for Perfetto +├── merge.py # Merge fragments → trace.json +├── appletrace_binary.py # Binary fragment encoder/decoder +├── go.sh # Merge and open Perfetto +└── requirements.txt # Python dev/test dependencies +``` -Yes, but with limitations: -- ✅ Manual instrumentation works on all iOS versions -- ⚠️ Dynamic hook mode may have compatibility issues on iOS 17+ +--- -### Q: Can I trace third-party apps? +## ❓ FAQ -Yes! See the Chinese guide: [搭载MonkeyDev可 trace 第三方 App](http://everettjf.github.io/2017/10/12/appletrace-dancewith-monkeydev/) +**Is AppleTrace still maintained?** +Yes — actively developed. Recent work focuses on hot-path performance, richer +trace events, and modern Perfetto-based visualization. See [ROADMAP.md](ROADMAP.md). -### Q: Why is Python 3 required? +**Does AppleTrace work on recent iOS versions?** +Manual instrumentation works on all iOS versions. The automatic hook mode targets +arm64 only (arm64e is out of scope — see +[Platform & Hook Support](#-platform--hook-support)). -Python 2.x reached end-of-life in 2020. AppleTrace now requires Python 3.8+ for security and compatibility. +**Can I trace third-party apps?** +Yes — see the loader project and this Chinese guide: +[搭载 MonkeyDev 可 trace 第三方 App](http://everettjf.github.io/2017/10/12/appletrace-dancewith-monkeydev/). -### Q: Can I use this on macOS apps? +**Why is Python 3 required?** +Python 2 reached end-of-life in 2020. The tooling requires Python 3.9+. -Yes! AppleTrace works for both iOS and macOS applications. +**Can I use this on macOS apps?** +Yes — AppleTrace works for both iOS and macOS applications. --- ## 🤝 Contributing -Contributions are welcome! Please read our [Contributing Guide](CONTRIBUTING.md) for details. - -### How to Contribute +Contributions are welcome! Please read the [Contributing Guide](CONTRIBUTING.md) +and the [Agent Guide](AGENT.md) for repository conventions. -1. **Fork** the repository +1. **Fork** the repository. 2. **Create** a feature branch: `git checkout -b feature/amazing-feature` -3. **Commit** your changes: `git commit -m 'Add amazing feature'` -4. **Push** to the branch: `git push origin feature/amazing-feature` -5. **Submit** a Pull Request - -### Code Style - -- **Objective-C:** [Google Objective-C Style Guide](https://google.github.io/styleguide/objcguide.html) -- **Python:** [PEP 8](https://www.python.org/dev/peps/pep-0008/) -- **Shell:** [Google Shell Style Guide](https://google.github.io/styleguide/shellguide.html) - -### Testing - -```bash -# Build the framework -xcodebuild -project appletrace/appletrace.xcodeproj \ - -scheme appletrace \ - -configuration Release \ - -sdk iphonesimulator build - -# Run merge script -python3 merge.py -d sampledata/ -``` - ---- - -## 📜 License +3. **Commit** your changes (run the test suite first). +4. **Push** and open a **Pull Request**. -AppleTrace is released under the MIT License. See [LICENSE](LICENSE) for details. +**Code style:** [Google Objective-C Style Guide](https://google.github.io/styleguide/objcguide.html) · +[PEP 8](https://www.python.org/dev/peps/pep-0008/) · +[Google Shell Style Guide](https://google.github.io/styleguide/shellguide.html) --- -## 🙏 Acknowledgements +## 🛠️ Tech Stack
-**Core Dependencies** - - - - - - - - - -**Inspired by** -- Facebook's [fbtrace](https://github.com/facebookarchive/fbtrace) -- Google's [Chrome Tracing](https://www.chromium.org/developers/how-tos/trace-event-profiling-tool) +![Objective-C](https://img.shields.io/badge/Objective--C-438EFF?style=flat-square&logo=apple) +![C](https://img.shields.io/badge/C-00599C?style=flat-square&logo=c) +![Python](https://img.shields.io/badge/Python-3776AB?style=flat-square&logo=python) +![Xcode](https://img.shields.io/badge/Xcode-147EFB?style=flat-square&logo=xcode) +![Perfetto](https://img.shields.io/badge/Perfetto-2E2E2E?style=flat-square&logo=google) +![LLDB](https://img.shields.io/badge/LLDB-1A73E8?style=flat-square&logo=llvm)
--- -## 📈 Star History +## 📜 License -
+AppleTrace is released under the MIT License. See [LICENSE](LICENSE) for details. -[![Star History Chart](https://api.star-history.com/svg?repos=everettjf/AppleTrace&type=Date&theme=dark)](https://star-history.com/#everettjf/AppleTrace&Date) +--- -
+## 🙏 Acknowledgements + +Inspired by Facebook's [fbtrace](https://github.com/facebookarchive/fbtrace), and +built around Google's [Perfetto](https://perfetto.dev) and the +[Trace Event Format](https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview). --- @@ -442,14 +470,16 @@ AppleTrace is released under the MIT License. See [LICENSE](LICENSE) for details WeChat +**Made with ❤️ by [Everett](https://github.com/everettjf)** + --- -
+## 📈 Star History -**Made with ❤️ by [Everett](https://github.com/everettjf)** +
-**Project Link:** [https://github.com/everettjf/AppleTrace](https://github.com/everettjf/AppleTrace) +[![Star History Chart](https://api.star-history.com/svg?repos=everettjf/AppleTrace&type=Date)](https://star-history.com/#everettjf/AppleTrace&Date)
diff --git a/README_CN.md b/README_CN.md index d8e466a6..01dd3d0d 100644 --- a/README_CN.md +++ b/README_CN.md @@ -1,20 +1,28 @@ # AppleTrace 中文说明 -AppleTrace 是一个面向 iOS 的方法追踪与调用链分析工具，可以把运行时事件导出成 Chrome Trace 格式进行可视化分析。 +AppleTrace 是一个面向 iOS/macOS 的方法追踪与调用链分析工具，可以把运行时事件导出成 trace 文件，直接在 [Perfetto](https://ui.perfetto.dev) 中可视化分析。 -## 2026 现代化改进 +> 🚀 AppleTrace 正在持续开发中：轻量、可内嵌、产物可直接拖入 Perfetto 分享。 +> 下一步规划见 [ROADMAP.md](ROADMAP.md)。 -- Python 工具链已升级到 Python 3。 -- 新增统一命令行入口：`scripts/appletrace_cli.py`。 -- 新增自动化测试：`python3 -m pytest tests`。 -- 新增运行时控制 API：`APTFlush`、`APTSetEnabled`、`APTIsEnabled`、`APTGetTraceDirectory`。 -- 支持通过环境变量配置 trace 输出目录和 mmap 块大小。 +## 最新改进 + +- **更快的 `objc_msgSend` hook**：对 `(Class, SEL)` 做名字 interning，配合每线程零分配调用栈，热路径不再每次 `malloc`/`snprintf`。 +- **每线程批量写入**：事件先在每线程缓冲累积、批量落盘，热路径不再每事件一次 `dispatch_async`。 +- **线程命名**：trace 现在会标注线程名，Perfetto 中不再只显示裸 id。 +- **更多事件类型**：除 begin/end section 外，新增 `APTInstant`（瞬时标记）、`APTCounter`（内存、FPS 等数值曲线），以及 `APTAsyncBegin`/`APTAsyncEnd`（跨线程/队列的异步事件）。 +- **运行时过滤**：通过类名前缀 allow/deny 列表限制自动 trace 的范围 + （`APPLETRACE_TRACE_CLASS_ALLOW` / `APPLETRACE_TRACE_CLASS_DENY`）。 +- **全面 Perfetto 可视化**：把 `trace.json` 拖入 [ui.perfetto.dev](https://ui.perfetto.dev) 即可，纯网页、无需安装；begin/end 默认折叠为 `X` complete 事件。 +- Python 3 工具链、统一 CLI（`scripts/appletrace_cli.py`）、自动化测试、CI，以及面向大 trace 的流式合并。 +- 运行时控制 API：`APTFlush`、`APTSetEnabled`、`APTIsEnabled`、`APTGetTraceDirectory`，并支持通过环境变量配置输出目录与 mmap 块大小。 ## 当前 hook 状态 -- 稳定主线：手动 section 与延迟安装的 `objc_msgSend` direct hook 已有 simulator smoke test 覆盖。 -- 实验支线：sample 自身的嵌套 Objective-C 方法调用、`objc_msgSendSuper2`、跨线程 trace、一个 10 参数 Objective-C 调用、浮点参数/返回值，以及小型聚合返回值现在也有自动化覆盖。 -- 发布建议：把 direct hook 视为 arm64 预览能力，生产上仍可继续把手动埋点作为最低风险基线。 +- **目标平台**：仅 arm64。 +- **手动 section** 是最低风险基线，适用于所有 iOS/macOS 版本。 +- **`objc_msgSend` / `objc_msgSendSuper2` direct hook**（arm64）已有 simulator smoke test 覆盖：嵌套调用、`super` 派发、跨线程事件、10 参数调用，以及浮点/小型聚合返回值等 ABI 场景。 +- **不支持 arm64e**：arm64e 通过认证 GOT（`__DATA_CONST.__auth_got`）调用 `objc_msgSend`，重绑定需要正确的指针认证（PAC）重签名。为避免发布未经验证的 hook，hook 源码在 arm64e 下会直接编译报错——请构建纯 arm64 slice。 ## 快速开始 @@ -22,18 +30,25 @@ AppleTrace 是一个面向 iOS 的方法追踪与调用链分析工具，可以 brew install python ldid git git clone https://github.com/everettjf/AppleTrace.git cd AppleTrace -sh get_catapult.sh python3 -m pip install -r requirements.txt ``` -### 合并与导出 +### 合并与可视化 ```bash +# 合并 trace 片段为 trace.json（默认输出 X complete 事件） python3 merge.py -d /path/to/appletracedata -python3 scripts/appletrace_cli.py all /path/to/appletracedata --open + +# 如需保留原始 begin/end 事件 +python3 merge.py -d /path/to/appletracedata --raw + +# 合并并直接打开 Perfetto +python3 scripts/appletrace_cli.py open /path/to/appletracedata sh go.sh /path/to/appletracedata ``` +随后把生成的 `trace.json` 拖入 [ui.perfetto.dev](https://ui.perfetto.dev) 查看。 + ### 手动埋点 ```objc @@ -56,6 +71,21 @@ void runTask() { } ``` +### 瞬时标记、计数器与异步事件 + +```objc +APTInstant("cache_miss"); // 在当前线程时间线上打一个点 +APTCounter("resident_mb", 142.5); // 随时间绘制数值曲线 +APTCounter("fps", 60); + +// 跨线程/队列的异步事件（通过 name + id 配对） +uint64_t requestID = 42; +APTAsyncBegin("image_load", requestID); +dispatch_async(queue, ^{ + APTAsyncEnd("image_load", requestID); +}); +``` + ### 运行时控制 ```objc @@ -72,21 +102,36 @@ export APPLETRACE_ENABLED=1 export APPLETRACE_DATA_DIR="$HOME/tmp/appletracedata" export APPLETRACE_BLOCK_SIZE_MB=32 export APPLETRACE_KEEP_EXISTING=1 + +# arm64 自动 objc_msgSend hook +export APPLETRACE_AUTO_HOOK_OBJC_MSGSEND=1 +# 仅 trace 这些类名前缀（逗号分隔） +export APPLETRACE_TRACE_CLASS_ALLOW="MyApp,UI" +# 永不 trace 这些类名前缀（优先级高于 allow） +export APPLETRACE_TRACE_CLASS_DENY="NSKVO,_" ``` ## 测试 ```bash +# Python 工具链 python3 -m pytest tests + +# objc_msgSend hook smoke test（在模拟器上构建并运行） ./scripts/test_objc_msgsend_hook.sh ./scripts/test_objc_msgsend_hook_experimental.sh + +# 批量写入并发压测（host 构建） +./scripts/test_batching_stress.sh ``` 其中： -- `test_objc_msgsend_hook.sh` 是当前可发布的稳定验证链路。 -- `test_objc_msgsend_hook_experimental.sh` 会验证 sample 方法级 trace、`super` 调用、跨线程事件、section 闭合情况、栈上传参的 Objective-C 调用、浮点参数和返回值，以及小型聚合返回值。 +- `test_objc_msgsend_hook.sh` 是稳定验证链路；`test_objc_msgsend_hook_experimental.sh` 额外验证方法级 trace、`super` 调用、跨线程事件、section 闭合、栈上传参、浮点参数/返回值与小型聚合返回值。 +- `test_batching_stress.sh` 多线程压测每线程批量写入器，断言事件不丢不重。 ## 说明 -仓库 README 已明确标注该项目处于 maintenance mode。当前这轮改造的目标不是重写架构，而是把工程基础、可验证性和使用体验拉到更现代的水平。 +AppleTrace 的定位是「轻量、可内嵌、产物可分享」的方法级 tracer。这一轮改造在保持 +该定位的前提下，重点提升了热路径性能、事件表达能力（instant/counter/线程名）以及 +基于 Perfetto 的现代可视化体验。后续规划详见 [ROADMAP.md](ROADMAP.md)，欢迎贡献。 diff --git a/ROADMAP.md b/ROADMAP.md new file mode 100644 index 00000000..9fb01ba9 --- /dev/null +++ b/ROADMAP.md @@ -0,0 +1,122 @@ +# AppleTrace Optimization & Roadmap + +> Status: AppleTrace is actively developed. This document captures the +> optimization opportunities, a competitive comparison, and a phased plan that +> drive the project forward. Items marked ✅ have shipped. + +## 1. Where We Are Today + +- **Platform**: arm64 only. arm64e is out of scope — the auto-hook would need + pointer-authentication-aware GOT rebinding, so the hook source hard-errors if + built for arm64e. +- **Tracing backends**: manual `APTBeginSection`/`APTEndSection` markers (plus + `APTInstant` / `APTCounter` / `APTAsyncBegin` / `APTAsyncEnd`), plus a direct + `objc_msgSend` / `objc_msgSendSuper2` rebind + (`appletrace/appletrace/src/objc/hook_objc_msgSend.m`). +- **Runtime**: a single serial dispatch queue serializes one JSON line per event + into an mmap-backed file (`appletrace/appletrace/src/appletrace.mm`). +- **Tooling**: `merge.py` / `scripts/appletrace_cli.py` merge fragments into a + Perfetto-compatible `trace.json`; `go.sh` opens it in Perfetto. +- **Visualization**: Perfetto-only (`ui.perfetto.dev`); no Catapult/Chrome HTML. +- **CI**: Python merge tests + two simulator smoke tests (`.github/workflows`). + +## 2. Optimization Opportunities + +### 2.1 Hot-path performance (highest impact on trace fidelity) + +The `objc_msgSend` hot path is far too heavy, which distorts the timings it is +meant to measure: + +- `apt_copy_trace_name` (`hook_objc_msgSend.m:360`) does a `malloc` + `snprintf` + to build `"[Class]selector"` on **every** message send, with no caching. +- `Trace::WriteSection` (`appletrace.mm:318`) builds a `std::string` JSON line and + `dispatch_async`es it (block copy + enqueue) per event. Under full + `objc_msgSend` tracing the serial queue becomes the bottleneck and memory + balloons. + +Recommended redesign: + +- **String interning**: cache the formatted name keyed by `(Class, SEL)` so the + hot path stores an integer id, not a freshly allocated string. +- **Per-thread ring buffers**: record fixed-size binary events + `(timestamp, phase, tid, name_id)` lock-free per thread; flush in bulk on a + background thread instead of one dispatch per event. +- **Defer formatting**: emit binary events at runtime and convert to JSON only in + `merge.py` (or a new exporter), removing JSON string building from the hot path. + +### 2.2 Visualization pipeline modernization (highest ROI / lowest risk) + +- ✅ Visualization is now **Perfetto-only** (`ui.perfetto.dev`): it ingests the + Chrome JSON `trace.json`, runs entirely in the browser (no download), and + scales to far larger traces. The deprecated Catapult `trace2html` pipeline + (`get_catapult.sh`, the HTML demo) has been removed. +- Longer term: emit the Perfetto protobuf format for streaming + smaller files. + +### 2.3 Trace format & expressiveness + +- ✅ Export `X` (complete) events by default to roughly halve file size vs. + paired `B`/`E` (`merge.py`; `--raw` keeps the unpaired form). +- ✅ Emit `thread_name` metadata events so threads are labeled in Perfetto + (previously only `process_name` was written). +- ✅ Add **counter** (`APTCounter`), **instant** (`APTInstant`), and + **async/flow** (`APTAsyncBegin` / `APTAsyncEnd`) events to track work across + dispatch queues. +- ✅ Stream `merge.py` output instead of loading every event into memory, so + large captures don't exhaust RAM. + +### 2.4 Filtering & control + +- ✅ Add runtime class-prefix allow/deny lists + (`APPLETRACE_TRACE_CLASS_ALLOW` / `APPLETRACE_TRACE_CLASS_DENY`). +- A sampling mode (trace 1/N sends) is intentionally deferred: it does not + compose with the nested begin/end model, so it is not on the near-term plan. + +### 2.5 Housekeeping + +- ✅ Add the `CONTRIBUTING.md` that the README references. +- ✅ Scope the project to arm64 and document it; arm64e and x86_64 are out of + scope (the hook source hard-errors on arm64e). + +## 3. Competitive Comparison + +| Tool | Mechanism | Strengths | Position vs. AppleTrace | +|------|-----------|-----------|--------------------------| +| **Frida / frida-trace** | Dynamic injection | Cross-platform, scriptable, very active | Full-featured but heavier, needs debug/jailbreak posture | +| **InspectiveC** | fishhook `objc_msgSend` | Per-object / per-class / per-selector filtering | Closest in approach; richer filtering | +| **Instruments (os_signpost)** | OS-level | First-party, low overhead, strong timeline | Could be a low-overhead backend AppleTrace targets | +| **Perfetto** | Visualization + SDK | Modern standard, protobuf, scalable UI | Should be AppleTrace's visualization target | + +**Differentiation**: AppleTrace's edge is being lightweight, embeddable directly +in an app (manual sections), and producing shareable artifacts. The roadmap +should lean into that rather than chasing Frida's full feature set. + +## 4. Phased Plan + +### Phase 1 — Modernize visualization (low risk, high value) +- ✅ Make Perfetto (`ui.perfetto.dev`) the only viewer; remove Catapult/Chrome. +- ✅ Add a `thread_name` metadata event so threads are labeled. +- ✅ Stream `merge.py` output. +- ✅ Collapse begin/end pairs into `X` complete events by default, + roughly halving section-event count. + +### Phase 2 — Hot-path performance +- ✅ Introduce `(Class, SEL)` name interning. +- ✅ Use a zero-allocation per-thread call stack (no per-message `malloc`). +- 🛠️ Move event recording to per-thread batched buffers with bulk background + flushing — implemented per + [docs/perf-batching-design.md](docs/perf-batching-design.md); **pending macOS + build + profiling verification.** +- 🛠️ Defer JSON formatting to the exporter; emit binary events at runtime. + Exporter/decoder implemented + tested (`appletrace_binary.py`, wired into + `merge.py`); native writer implemented behind opt-in `APPLETRACE_BINARY=1` + (**pending macOS verification**). See + [docs/binary-fragment-format.md](docs/binary-fragment-format.md). + +### Phase 3 — Expressiveness & control +- ✅ Add `APTInstant`, `APTCounter`, and `APTAsyncBegin`/`APTAsyncEnd` event APIs. +- ✅ Add runtime class-prefix allow/deny lists. + +### Phase 4 — Reach & polish +- ✅ Add `CONTRIBUTING.md`. +- ✅ Scope to arm64 (arm64e dropped; hook hard-errors there). +- Explore an `os_signpost` backend and/or Perfetto protobuf export. diff --git a/appletrace/appletrace/src/appletrace.h b/appletrace/appletrace/src/appletrace.h index e2f2d339..1587e88b 100644 --- a/appletrace/appletrace/src/appletrace.h +++ b/appletrace/appletrace/src/appletrace.h @@ -7,6 +7,10 @@ FOUNDATION_EXPORT void APTBeginSection(const char *name); FOUNDATION_EXPORT void APTEndSection(const char *name); +FOUNDATION_EXPORT void APTInstant(const char *name); +FOUNDATION_EXPORT void APTCounter(const char *name, double value); +FOUNDATION_EXPORT void APTAsyncBegin(const char *name, uint64_t async_id); +FOUNDATION_EXPORT void APTAsyncEnd(const char *name, uint64_t async_id); FOUNDATION_EXPORT void APTSyncWait(void); FOUNDATION_EXPORT void APTFlush(void); FOUNDATION_EXPORT void APTSetEnabled(BOOL enabled); diff --git a/appletrace/appletrace/src/appletrace.mm b/appletrace/appletrace/src/appletrace.mm index f5f86609..c950c0ae 100644 --- a/appletrace/appletrace/src/appletrace.mm +++ b/appletrace/appletrace/src/appletrace.mm @@ -6,10 +6,18 @@ #import "appletrace.h" #include +#include +#include +#include +#include #include +#include +#include +#include #include #include +#include #include #include #include @@ -23,6 +31,10 @@ constexpr size_t kMinimumBlockSize = 1 * 1024 * 1024; constexpr size_t kMaximumBlockSize = 256 * 1024 * 1024; +// Per-thread accumulation buffer tunables (see docs/perf-batching-design.md). +constexpr size_t kBatchFlushThresholdBytes = 32 * 1024; +constexpr size_t kBatchReserveBytes = 64 * 1024; + bool BoolFromEnvironment(NSString *key, bool fallback) { NSString *value = [[[NSProcessInfo processInfo] environment] objectForKey:key]; if (!value.length) { @@ -103,6 +115,23 @@ size_t BlockSizeFromEnvironment() { namespace appletrace { +// Binary fragment format (see docs/binary-fragment-format.md). Apple targets are +// little-endian, so native integers are appended as-is. +constexpr char kBinaryMagic[8] = {'A', 'P', 'L', 'T', 'R', 'C', '0', '1'}; +constexpr uint8_t kBinaryTagString = 0x01; + +static inline void AppendByte(std::string &buffer, uint8_t value) { + buffer.push_back(static_cast(value)); +} + +static inline void AppendU32(std::string &buffer, uint32_t value) { + buffer.append(reinterpret_cast(&value), sizeof(value)); +} + +static inline void AppendU64(std::string &buffer, uint64_t value) { + buffer.append(reinterpret_cast(&value), sizeof(value)); +} + class Logger { public: explicit Logger(size_t block_size) : block_size_(block_size) {} @@ -181,6 +210,20 @@ bool AddLine(const std::string &line) { return true; } + // Appends raw bytes verbatim (no newline). Used by the binary fragment path. + bool AddRaw(const std::string &bytes) { + if (!file_cur_) { + return false; + } + if (cur_size_ + bytes.size() > block_size_) { + return false; + } + memcpy(file_cur_, bytes.data(), bytes.size()); + file_cur_ += bytes.size(); + cur_size_ += bytes.size(); + return true; + } + private: size_t block_size_; int fd_ = -1; @@ -193,12 +236,20 @@ bool AddLine(const std::string &line) { public: LoggerManager() : log_(BlockSizeFromEnvironment()) {} + void EnableBinary(uint32_t pid) { + binary_ = true; + header_pid_ = pid; + } + bool Open() { std::string path = GetFilePath(); if (!log_.Open(path.c_str())) { return false; } ++file_counter_; + if (binary_) { + WriteBinaryHeader(); + } return true; } @@ -221,12 +272,60 @@ void AddLine(const std::string &line) { } } + // Writes a batch of events. In text mode it splits on '\n' and reuses + // AddLine so fragment rollover stays on line boundaries; in binary mode it + // writes the batch verbatim, rolling over whole-batch so a record is never + // split across fragments (batches always end on a record boundary). + void AddBlock(const std::string &block) { + if (binary_) { + AddRawBlock(block); + return; + } + + size_t start = 0; + const size_t size = block.size(); + while (start < size) { + size_t newline = block.find('\n', start); + size_t end = (newline == std::string::npos) ? size : newline; + if (end > start) { + AddLine(block.substr(start, end - start)); + } + if (newline == std::string::npos) { + break; + } + start = newline + 1; + } + } + static NSString *CurrentDirectory() { InitializeWorkDirectory(); return work_dir_; } private: + void WriteBinaryHeader() { + std::string header(kBinaryMagic, sizeof(kBinaryMagic)); + AppendU32(header, header_pid_); + log_.AddRaw(header); + } + + void AddRawBlock(const std::string &block) { + if (block.empty()) { + return; + } + if (log_.AddRaw(block)) { + return; + } + + NSLog(@"AppleTrace: rolling trace fragment"); + if (!Open()) { + return; + } + if (!log_.AddRaw(block)) { + NSLog(@"AppleTrace: failed to write binary batch after rollover"); + } + } + static void InitializeWorkDirectory() { static dispatch_once_t once_token; dispatch_once(&once_token, ^{ @@ -263,9 +362,10 @@ static void InitializeWorkDirectory() { InitializeWorkDirectory(); int file_index = file_counter_.load(); + NSString *extension = binary_ ? @"appletracebin" : @"appletrace"; NSString *log_name = file_index == 0 - ? @"trace.appletrace" - : [NSString stringWithFormat:@"trace_%d.appletrace", file_index]; + ? [NSString stringWithFormat:@"trace.%@", extension] + : [NSString stringWithFormat:@"trace_%d.%@", file_index, extension]; NSString *log_path = [work_dir_ stringByAppendingPathComponent:log_name]; NSLog(@"AppleTrace: log path = %@", log_path); return std::string(log_path.UTF8String); @@ -274,17 +374,50 @@ static void InitializeWorkDirectory() { static std::atomic file_counter_; static NSString *work_dir_; Logger log_; + bool binary_ = false; + uint32_t header_pid_ = 0; }; std::atomic LoggerManager::file_counter_{0}; NSString *LoggerManager::work_dir_ = nil; +class Trace; + +// Per-thread accumulation buffer. The hot path appends under `lock`; APTFlush +// and thread-exit drain it. See docs/perf-batching-design.md. +struct ThreadLog { + os_unfair_lock lock = OS_UNFAIR_LOCK_INIT; + std::string pending; + // Binary mode only: this thread's name -> globally-unique id map. Each + // thread emits its own string definitions, so a thread only ever references + // ids it defined — no cross-thread ordering hazard with batched flushing. + std::unordered_map name_ids; +}; + +static pthread_key_t gThreadLogKey; +static pthread_once_t gThreadLogKeyOnce = PTHREAD_ONCE_INIT; +static Trace *gActiveTrace = nullptr; +static std::atomic gBinaryNextNameId{0}; + +static void appletrace_thread_log_destructor(void *pointer); + +static void appletrace_make_thread_log_key() { + pthread_key_create(&gThreadLogKey, appletrace_thread_log_destructor); +} + class Trace { public: bool Open() { static dispatch_once_t once_token; dispatch_once(&once_token, ^{ enabled_.store(BoolFromEnvironment(@"APPLETRACE_ENABLED", true)); + binary_ = BoolFromEnvironment(@"APPLETRACE_BINARY", false); + pid_ = getpid(); + gActiveTrace = this; + + if (binary_) { + log_.EnableBinary(static_cast(pid_)); + } if (!log_.Open()) { return; } @@ -292,12 +425,16 @@ bool Open() { queue_ = dispatch_queue_create("appletrace.queue", DISPATCH_QUEUE_SERIAL); mach_timebase_info(&timeinfo_); begin_ = CurrentTimeNs(); - pid_ = getpid(); - dispatch_sync(queue_, ^{ - WriteMetadataLocked(); - log_.Flush(); - }); + if (binary_) { + EmitMetadata("process_name", 0, + [[NSProcessInfo processInfo] processName].UTF8String); + } else { + dispatch_sync(queue_, ^{ + WriteMetadataLocked(); + log_.Flush(); + }); + } }); return queue_ != nullptr; @@ -320,28 +457,105 @@ void WriteSection(const char *name, const char *phase) { return; } - uint64_t thread_id = 0; - pthread_threadid_np(pthread_self(), &thread_id); - if (main_thread_id_.load() == 0 && pthread_main_np() != 0) { - uint64_t expected = 0; - main_thread_id_.compare_exchange_strong(expected, thread_id); + const uint64_t thread_id = ResolveThreadId(); + const uint64_t elapsed_us = (CurrentTimeNs() - begin_) / 1000; + if (binary_) { + EmitBinaryEvent(phase[0], name, thread_id, elapsed_us, 0); + return; } - if (thread_id == main_thread_id_.load()) { - thread_id = 0; + std::string line = BuildEventLine(name, phase, thread_id, elapsed_us); + Emit(line); + } + + void WriteInstant(const char *name) { + if (!IsEnabled() || !name || name[0] == '\0' || !queue_) { + return; } + const uint64_t thread_id = ResolveThreadId(); const uint64_t elapsed_us = (CurrentTimeNs() - begin_) / 1000; - std::string line = BuildEventLine(name, phase, thread_id, elapsed_us); - dispatch_async(queue_, ^{ - log_.AddLine(line); - }); + if (binary_) { + EmitBinaryEvent('i', name, thread_id, elapsed_us, 0); + return; + } + std::string line = + "{\"name\":\"" + EscapeJSONString(name) + + "\",\"cat\":\"appletrace\",\"ph\":\"i\",\"pid\":" + std::to_string(pid_) + + ",\"tid\":" + std::to_string(thread_id) + ",\"ts\":" + std::to_string(elapsed_us) + + ",\"s\":\"t\"}"; + Emit(line); + } + + void WriteCounter(const char *name, double value) { + if (!IsEnabled() || !name || name[0] == '\0' || !queue_) { + return; + } + + const uint64_t thread_id = ResolveThreadId(); + const uint64_t elapsed_us = (CurrentTimeNs() - begin_) / 1000; + if (binary_) { + uint64_t bits = 0; + memcpy(&bits, &value, sizeof(bits)); + EmitBinaryEvent('C', name, thread_id, elapsed_us, bits); + return; + } + char value_buffer[64] = {0}; + snprintf(value_buffer, sizeof(value_buffer), "%g", value); + std::string line = + "{\"name\":\"" + EscapeJSONString(name) + + "\",\"cat\":\"appletrace\",\"ph\":\"C\",\"pid\":" + std::to_string(pid_) + + ",\"tid\":" + std::to_string(thread_id) + ",\"ts\":" + std::to_string(elapsed_us) + + ",\"args\":{\"value\":" + value_buffer + "}}"; + Emit(line); + } + + // Nestable async events ("b"/"e"): used to track work that flows across + // threads or dispatch queues, matched by (name, async_id). + void WriteAsync(const char *name, const char *phase, uint64_t async_id) { + if (!IsEnabled() || !name || name[0] == '\0' || !queue_) { + return; + } + + const uint64_t thread_id = ResolveThreadId(); + const uint64_t elapsed_us = (CurrentTimeNs() - begin_) / 1000; + if (binary_) { + EmitBinaryEvent(phase[0], name, thread_id, elapsed_us, async_id); + return; + } + std::string line = + "{\"name\":\"" + EscapeJSONString(name) + + "\",\"cat\":\"appletrace\",\"ph\":\"" + phase + "\",\"id\":" + std::to_string(async_id) + + ",\"pid\":" + std::to_string(pid_) + ",\"tid\":" + std::to_string(thread_id) + + ",\"ts\":" + std::to_string(elapsed_us) + "}"; + Emit(line); } void Flush() { if (!queue_) { return; } + + // Drain every thread's pending bytes, then flush the logger. Holding + // registry_mutex_ for the whole drain prevents a thread from exiting and + // freeing its ThreadLog mid-iteration (thread-exit takes the same lock). + auto batches = std::make_shared>(); + { + std::lock_guard guard(registry_mutex_); + for (auto &thread_log : thread_logs_) { + os_unfair_lock_lock(&thread_log->lock); + if (!thread_log->pending.empty()) { + batches->emplace_back(std::move(thread_log->pending)); + thread_log->pending.clear(); + thread_log->pending.reserve(kBatchReserveBytes); + } + os_unfair_lock_unlock(&thread_log->lock); + } + } + dispatch_sync(queue_, ^{ + for (const std::string &batch : *batches) { + log_.AddBlock(batch); + } log_.Flush(); }); } @@ -350,12 +564,200 @@ void SyncWait() { Flush(); } + // Drains and deregisters the calling thread's buffer at thread exit. Called + // from the pthread-key destructor via gActiveTrace. + void DrainThreadOnExit(ThreadLog *thread_log) { + if (!thread_log) { + return; + } + + std::string batch; + { + std::lock_guard guard(registry_mutex_); + os_unfair_lock_lock(&thread_log->lock); + batch.swap(thread_log->pending); + os_unfair_lock_unlock(&thread_log->lock); + for (auto it = thread_logs_.begin(); it != thread_logs_.end(); ++it) { + if (it->get() == thread_log) { + thread_logs_.erase(it); // destroys *thread_log + break; + } + } + } + + if (!batch.empty() && queue_) { + auto shipped = std::make_shared(std::move(batch)); + dispatch_async(queue_, ^{ + log_.AddBlock(*shipped); + }); + } + } + private: uint64_t CurrentTimeNs() const { const uint64_t now = mach_absolute_time(); return now * timeinfo_.numer / timeinfo_.denom; } + ThreadLog *AcquireThreadLog() { + pthread_once(&gThreadLogKeyOnce, appletrace_make_thread_log_key); + ThreadLog *thread_log = static_cast(pthread_getspecific(gThreadLogKey)); + if (thread_log) { + return thread_log; + } + + std::unique_ptr owned(new ThreadLog()); + owned->pending.reserve(kBatchReserveBytes); + thread_log = owned.get(); + { + std::lock_guard guard(registry_mutex_); + thread_logs_.push_back(std::move(owned)); + } + pthread_setspecific(gThreadLogKey, thread_log); + return thread_log; + } + + // Hot path: append to this thread's buffer with no allocation, shipping a + // whole batch to the writer queue only when it crosses the threshold. + void Emit(const std::string &line) { + if (!IsEnabled() || !queue_) { + return; + } + + ThreadLog *thread_log = AcquireThreadLog(); + std::string batch; + { + os_unfair_lock_lock(&thread_log->lock); + thread_log->pending.append(line); + thread_log->pending.push_back('\n'); + if (thread_log->pending.size() >= kBatchFlushThresholdBytes) { + batch.swap(thread_log->pending); + thread_log->pending.reserve(kBatchReserveBytes); + } + os_unfair_lock_unlock(&thread_log->lock); + } + + ShipBatch(batch); + } + + void ShipBatch(std::string &batch) { + if (batch.empty() || !queue_) { + return; + } + auto shipped = std::make_shared(std::move(batch)); + dispatch_async(queue_, ^{ + log_.AddBlock(*shipped); + }); + } + + // Returns this thread's id for `name`, emitting a string-definition record + // into the thread buffer the first time the thread uses it. Caller holds the + // thread buffer's lock. + uint32_t BinaryNameIdLocked(ThreadLog *thread_log, const char *name) { + std::string key(name ? name : ""); + auto found = thread_log->name_ids.find(key); + if (found != thread_log->name_ids.end()) { + return found->second; + } + uint32_t name_id = gBinaryNextNameId.fetch_add(1, std::memory_order_relaxed); + thread_log->name_ids.emplace(key, name_id); + AppendByte(thread_log->pending, kBinaryTagString); + AppendU32(thread_log->pending, name_id); + AppendU32(thread_log->pending, static_cast(key.size())); + thread_log->pending.append(key); + return name_id; + } + + void EmitBinaryEvent(char phase, const char *name, uint64_t tid, uint64_t ts, uint64_t arg) { + if (!IsEnabled() || !queue_) { + return; + } + ThreadLog *thread_log = AcquireThreadLog(); + std::string batch; + { + os_unfair_lock_lock(&thread_log->lock); + uint32_t name_id = BinaryNameIdLocked(thread_log, name); + AppendByte(thread_log->pending, static_cast(phase)); + AppendU32(thread_log->pending, name_id); + AppendU64(thread_log->pending, tid); + AppendU64(thread_log->pending, ts); + AppendU64(thread_log->pending, arg); + if (thread_log->pending.size() >= kBatchFlushThresholdBytes) { + batch.swap(thread_log->pending); + thread_log->pending.reserve(kBatchReserveBytes); + } + os_unfair_lock_unlock(&thread_log->lock); + } + ShipBatch(batch); + } + + void EmitMetadata(const char *name, uint64_t tid, const char *value) { + if (!IsEnabled() || !queue_ || !value) { + return; + } + ThreadLog *thread_log = AcquireThreadLog(); + std::string batch; + { + os_unfair_lock_lock(&thread_log->lock); + uint32_t name_id = BinaryNameIdLocked(thread_log, name); + uint32_t value_id = BinaryNameIdLocked(thread_log, value); + AppendByte(thread_log->pending, static_cast('M')); + AppendU32(thread_log->pending, name_id); + AppendU64(thread_log->pending, tid); + AppendU64(thread_log->pending, 0); + AppendU64(thread_log->pending, value_id); + if (thread_log->pending.size() >= kBatchFlushThresholdBytes) { + batch.swap(thread_log->pending); + thread_log->pending.reserve(kBatchReserveBytes); + } + os_unfair_lock_unlock(&thread_log->lock); + } + ShipBatch(batch); + } + + uint64_t ResolveThreadId() { + uint64_t thread_id = 0; + pthread_threadid_np(pthread_self(), &thread_id); + if (main_thread_id_.load() == 0 && pthread_main_np() != 0) { + uint64_t expected = 0; + main_thread_id_.compare_exchange_strong(expected, thread_id); + } + const uint64_t reported = (thread_id == main_thread_id_.load()) ? 0 : thread_id; + EmitThreadNameOnce(reported); + return reported; + } + + void EmitThreadNameOnce(uint64_t reported_thread_id) { + static __thread bool named = false; + if (named || !queue_) { + return; + } + named = true; + + std::string thread_name; + if (reported_thread_id == 0) { + thread_name = "Main Thread"; + } else { + char buffer[256] = {0}; + if (pthread_getname_np(pthread_self(), buffer, sizeof(buffer)) == 0 && buffer[0] != '\0') { + thread_name = buffer; + } else { + thread_name = "Thread " + std::to_string(reported_thread_id); + } + } + + if (binary_) { + EmitMetadata("thread_name", reported_thread_id, thread_name.c_str()); + return; + } + + std::string line = + "{\"name\":\"thread_name\",\"ph\":\"M\",\"pid\":" + std::to_string(pid_) + + ",\"tid\":" + std::to_string(reported_thread_id) + ",\"args\":{\"name\":\"" + + EscapeJSONString(thread_name.c_str()) + "\"}}"; + Emit(line); + } + std::string BuildEventLine(const char *name, const char *phase, uint64_t thread_id, uint64_t elapsed_us) const { std::string escaped_name = EscapeJSONString(name); std::string escaped_phase = EscapeJSONString(phase); @@ -379,8 +781,17 @@ void WriteMetadataLocked() { pid_t pid_ = 0; std::atomic main_thread_id_{0}; std::atomic enabled_{true}; + bool binary_ = false; + std::mutex registry_mutex_; + std::vector> thread_logs_; }; +static void appletrace_thread_log_destructor(void *pointer) { + if (gActiveTrace && pointer) { + gActiveTrace->DrainThreadOnExit(static_cast(pointer)); + } +} + class TraceManager { public: static TraceManager &Instance() { @@ -396,6 +807,22 @@ void EndSection(const char *name) { trace_.WriteSection(name, "E"); } + void Instant(const char *name) { + trace_.WriteInstant(name); + } + + void Counter(const char *name, double value) { + trace_.WriteCounter(name, value); + } + + void AsyncBegin(const char *name, uint64_t async_id) { + trace_.WriteAsync(name, "b", async_id); + } + + void AsyncEnd(const char *name, uint64_t async_id) { + trace_.WriteAsync(name, "e", async_id); + } + void Flush() { trace_.Flush(); } @@ -436,6 +863,22 @@ void APTEndSection(const char *name) { appletrace::TraceManager::Instance().EndSection(name); } +void APTInstant(const char *name) { + appletrace::TraceManager::Instance().Instant(name); +} + +void APTCounter(const char *name, double value) { + appletrace::TraceManager::Instance().Counter(name, value); +} + +void APTAsyncBegin(const char *name, uint64_t async_id) { + appletrace::TraceManager::Instance().AsyncBegin(name, async_id); +} + +void APTAsyncEnd(const char *name, uint64_t async_id) { + appletrace::TraceManager::Instance().AsyncEnd(name, async_id); +} + void APTSyncWait() { appletrace::TraceManager::Instance().SyncWait(); } diff --git a/appletrace/appletrace/src/objc/hook_objc_msgSend.m b/appletrace/appletrace/src/objc/hook_objc_msgSend.m index a7593770..c4638555 100644 --- a/appletrace/appletrace/src/objc/hook_objc_msgSend.m +++ b/appletrace/appletrace/src/objc/hook_objc_msgSend.m @@ -1,9 +1,16 @@ /** * AppleTrace objc_msgSend tracing without HookZz. * - * This arm64-only implementation uses fishhook-style symbol rebinding plus - * an assembly wrapper so objc_msgSend arguments and return registers survive - * the tracing callbacks. + * Targets arm64 only. It uses fishhook-style symbol rebinding plus an assembly + * wrapper so objc_msgSend arguments and return registers survive the tracing + * callbacks. + * + * arm64e is intentionally not supported: callers there branch to objc_msgSend + * through authenticated GOT entries (`__DATA_CONST.__auth_got`), and rebinding + * those safely requires re-signing pointers with the correct pointer- + * authentication context. Rather than ship an unvalidated auto-hook, building + * this file for arm64e is a hard error (see the guard below). Use a plain arm64 + * slice for automatic tracing. */ #import @@ -15,6 +22,7 @@ #import #import #import +#import #import #import #import @@ -24,7 +32,11 @@ #import "appletrace.h" #if !defined(__arm64__) -#error AppleTrace objc_msgSend hook currently supports arm64 only. +#error AppleTrace objc_msgSend hook requires arm64. +#endif + +#if defined(__arm64e__) +#error AppleTrace objc_msgSend hook does not support arm64e; build a plain arm64 slice. #endif typedef void (*APTObjcMsgSendFunction)(void); @@ -56,10 +68,25 @@ struct APTRebindingsEntry *next; }; -typedef struct APTTraceNode { - char *name; - struct APTTraceNode *previous; -} APTTraceNode; +// Per-thread call stack of interned section names. The names are borrowed +// (interned for the process lifetime), so the stack only stores pointers and +// never allocates on the hot path after the initial growth. +typedef struct APTThreadStack { + const char **items; + size_t count; + size_t capacity; +} APTThreadStack; + +// Interned (Class, SEL) -> formatted name. A NULL name caches a "do not trace" +// decision so the hot path never rebuilds a string or re-evaluates filters. +typedef struct APTNameEntry { + Class cls; + SEL sel; + const char *name; + struct APTNameEntry *next; +} APTNameEntry; + +#define APT_INTERN_BUCKET_COUNT 8192 static uintptr_t gLogSelectorStart = 0; static uintptr_t gLogSelectorEnd = 0; @@ -67,9 +94,15 @@ static uintptr_t gLogClassEnd = 0; static int gLogAllSelectors = 1; static int gLogAllClasses = 1; +static char **gAllowPrefixes = NULL; +static size_t gAllowPrefixCount = 0; +static char **gDenyPrefixes = NULL; +static size_t gDenyPrefixCount = 0; static __thread int gTraceGuard = 0; static pthread_key_t gTraceStackKey; static pthread_once_t gTraceStackKeyOnce = PTHREAD_ONCE_INIT; +static APTNameEntry *gInternBuckets[APT_INTERN_BUCKET_COUNT]; +static os_unfair_lock gInternLock = OS_UNFAIR_LOCK_INIT; static dispatch_once_t gHookInstallOnce; static APTObjcMsgSendFunction apt_original_objc_msgSend = NULL; static APTObjcMsgSendSuper2Function apt_original_objc_msgSendSuper2 = NULL; @@ -244,47 +277,64 @@ static BOOL apt_install_objc_msgsend_hook(void) { ); static void apt_free_trace_stack(void *pointer) { - APTTraceNode *node = (APTTraceNode *)pointer; - while (node) { - APTTraceNode *previous = node->previous; - free(node->name); - free(node); - node = previous; + APTThreadStack *stack = (APTThreadStack *)pointer; + if (!stack) { + return; } + free(stack->items); + free(stack); } static void apt_make_trace_stack_key(void) { pthread_key_create(&gTraceStackKey, apt_free_trace_stack); } -static APTTraceNode *apt_trace_stack_top(void) { - pthread_once(&gTraceStackKeyOnce, apt_make_trace_stack_key); - return (APTTraceNode *)pthread_getspecific(gTraceStackKey); -} - -static void apt_trace_stack_set(APTTraceNode *node) { +static APTThreadStack *apt_trace_stack(void) { pthread_once(&gTraceStackKeyOnce, apt_make_trace_stack_key); - pthread_setspecific(gTraceStackKey, node); + APTThreadStack *stack = (APTThreadStack *)pthread_getspecific(gTraceStackKey); + if (!stack) { + stack = calloc(1, sizeof(APTThreadStack)); + if (stack) { + pthread_setspecific(gTraceStackKey, stack); + } + } + return stack; } -static void apt_trace_stack_push(char *name) { - APTTraceNode *node = malloc(sizeof(APTTraceNode)); - if (!node) { - free(name); +// Pushes a borrowed (interned) name. NULL is a valid value: it keeps the stack +// balanced for sends that are filtered out so the matching pop does not unwind +// an unrelated parent section. +static void apt_trace_stack_push(const char *name) { + APTThreadStack *stack = apt_trace_stack(); + if (!stack) { return; } - node->name = name; - node->previous = apt_trace_stack_top(); - apt_trace_stack_set(node); + if (stack->count == stack->capacity) { + size_t new_capacity = stack->capacity ? stack->capacity * 2 : 64; + const char **items = realloc(stack->items, new_capacity * sizeof(const char *)); + if (!items) { + return; + } + stack->items = items; + stack->capacity = new_capacity; + } + + stack->items[stack->count++] = name; } -static APTTraceNode *apt_trace_stack_pop(void) { - APTTraceNode *node = apt_trace_stack_top(); - if (node) { - apt_trace_stack_set(node->previous); +static const char *apt_trace_stack_pop(BOOL *had_entry) { + APTThreadStack *stack = apt_trace_stack(); + if (!stack || stack->count == 0) { + if (had_entry) { + *had_entry = NO; + } + return NULL; } - return node; + if (had_entry) { + *had_entry = YES; + } + return stack->items[--stack->count]; } static struct section_64 *apt_find_section(struct mach_header_64 *header, const char *section_name) { @@ -304,9 +354,49 @@ static void apt_trace_stack_push(char *name) { return NULL; } +static void apt_parse_prefix_list(NSString *key, char ***out_prefixes, size_t *out_count) { + *out_prefixes = NULL; + *out_count = 0; + + NSString *value = [[[NSProcessInfo processInfo] environment] objectForKey:key]; + if (!value.length) { + return; + } + + NSMutableArray *parsed = [NSMutableArray array]; + for (NSString *component in [value componentsSeparatedByString:@","]) { + NSString *trimmed = [component stringByTrimmingCharactersInSet: + [NSCharacterSet whitespaceCharacterSet]]; + if (trimmed.length) { + [parsed addObject:trimmed]; + } + } + if (parsed.count == 0) { + return; + } + + char **prefixes = calloc(parsed.count, sizeof(char *)); + if (!prefixes) { + return; + } + + size_t count = 0; + for (NSString *prefix in parsed) { + prefixes[count] = strdup(prefix.UTF8String); + if (prefixes[count]) { + count += 1; + } + } + + *out_prefixes = prefixes; + *out_count = count; +} + static void apt_configure_trace_ranges(void) { gLogAllSelectors = apt_bool_from_environment(@"APPLETRACE_TRACE_ALL_SELECTORS", YES); gLogAllClasses = apt_bool_from_environment(@"APPLETRACE_TRACE_ALL_CLASSES", YES); + apt_parse_prefix_list(@"APPLETRACE_TRACE_CLASS_ALLOW", &gAllowPrefixes, &gAllowPrefixCount); + apt_parse_prefix_list(@"APPLETRACE_TRACE_CLASS_DENY", &gDenyPrefixes, &gDenyPrefixCount); const struct mach_header *header = _dyld_get_image_header(0); if (!header || header->magic != MH_MAGIC_64) { @@ -357,8 +447,35 @@ static BOOL apt_class_should_trace(Class cls) { return pointer >= gLogClassStart && pointer <= gLogClassEnd; } -static char *apt_copy_trace_name(id object, SEL selector) { - if (!object || !selector) { +static BOOL apt_class_passes_filters(const char *class_name) { + if (!class_name) { + return NO; + } + + for (size_t index = 0; index < gDenyPrefixCount; index++) { + const char *prefix = gDenyPrefixes[index]; + if (strncmp(class_name, prefix, strlen(prefix)) == 0) { + return NO; + } + } + + if (gAllowPrefixCount == 0) { + return YES; + } + + for (size_t index = 0; index < gAllowPrefixCount; index++) { + const char *prefix = gAllowPrefixes[index]; + if (strncmp(class_name, prefix, strlen(prefix)) == 0) { + return YES; + } + } + return NO; +} + +// Builds a freshly allocated "[Class]selector" name, or NULL when the pair +// should not be traced. Only called once per (Class, SEL) pair via interning. +static const char *apt_build_trace_name(Class cls, SEL selector) { + if (!cls || !selector) { return NULL; } @@ -366,8 +483,6 @@ static BOOL apt_class_should_trace(Class cls) { if (!apt_selector_should_trace(selector_name)) { return NULL; } - - Class cls = object_getClass(object); if (!apt_class_should_trace(cls)) { return NULL; } @@ -376,6 +491,9 @@ static BOOL apt_class_should_trace(Class cls) { if (!class_name || !selector_name) { return NULL; } + if (!apt_class_passes_filters(class_name)) { + return NULL; + } size_t required = strlen(class_name) + strlen(selector_name) + 4; char *trace_name = malloc(required); @@ -387,43 +505,36 @@ static BOOL apt_class_should_trace(Class cls) { return trace_name; } -static char *apt_copy_super_trace_name(struct objc_super *super_info, SEL selector) { - if (!super_info) { +// Returns the interned name for a (Class, SEL) pair, building it on first sight. +// A NULL result is cached too, so filtered-out pairs cost a single lookup. +static const char *apt_intern_trace_name(Class cls, SEL selector) { + if (!cls || !selector) { return NULL; } - id receiver = super_info->receiver; - if (!receiver || !selector) { - return NULL; - } + uintptr_t hash = (((uintptr_t)cls >> 3) * 2654435761u) ^ ((uintptr_t)selector >> 3); + size_t bucket = hash & (APT_INTERN_BUCKET_COUNT - 1); - const char *selector_name = sel_getName(selector); - if (!apt_selector_should_trace(selector_name)) { - return NULL; - } - - Class current_class = super_info->super_class; - Class target_class = current_class ? class_getSuperclass(current_class) : Nil; - if (!target_class) { - target_class = object_getClass(receiver); - } - if (!apt_class_should_trace(target_class)) { - return NULL; + os_unfair_lock_lock(&gInternLock); + for (APTNameEntry *entry = gInternBuckets[bucket]; entry; entry = entry->next) { + if (entry->cls == cls && entry->sel == selector) { + const char *name = entry->name; + os_unfair_lock_unlock(&gInternLock); + return name; + } } - const char *class_name = class_getName(target_class); - if (!class_name || !selector_name) { - return NULL; + const char *name = apt_build_trace_name(cls, selector); + APTNameEntry *entry = malloc(sizeof(APTNameEntry)); + if (entry) { + entry->cls = cls; + entry->sel = selector; + entry->name = name; + entry->next = gInternBuckets[bucket]; + gInternBuckets[bucket] = entry; } - - size_t required = strlen(class_name) + strlen(selector_name) + 4; - char *trace_name = malloc(required); - if (!trace_name) { - return NULL; - } - - snprintf(trace_name, required, "[%s]%s", class_name, selector_name); - return trace_name; + os_unfair_lock_unlock(&gInternLock); + return name; } static void apt_before_objc_msgSend(id object, SEL selector) { @@ -432,9 +543,12 @@ static void apt_before_objc_msgSend(id object, SEL selector) { } gTraceGuard += 1; - char *trace_name = apt_copy_trace_name(object, selector); + const char *trace_name = NULL; + if (object && selector) { + trace_name = apt_intern_trace_name(object_getClass(object), selector); + } + apt_trace_stack_push(trace_name); if (trace_name) { - apt_trace_stack_push(trace_name); APTBeginSection(trace_name); } gTraceGuard -= 1; @@ -446,9 +560,17 @@ static void apt_before_objc_msgSendSuper2(struct objc_super *super_info, SEL sel } gTraceGuard += 1; - char *trace_name = apt_copy_super_trace_name(super_info, selector); + const char *trace_name = NULL; + if (super_info && super_info->receiver && selector) { + Class current_class = super_info->super_class; + Class target_class = current_class ? class_getSuperclass(current_class) : Nil; + if (!target_class) { + target_class = object_getClass(super_info->receiver); + } + trace_name = apt_intern_trace_name(target_class, selector); + } + apt_trace_stack_push(trace_name); if (trace_name) { - apt_trace_stack_push(trace_name); APTBeginSection(trace_name); } gTraceGuard -= 1; @@ -460,11 +582,10 @@ static void apt_after_objc_msgSend(void) { } gTraceGuard += 1; - APTTraceNode *node = apt_trace_stack_pop(); - if (node) { - APTEndSection(node->name); - free(node->name); - free(node); + BOOL had_entry = NO; + const char *trace_name = apt_trace_stack_pop(&had_entry); + if (had_entry && trace_name) { + APTEndSection(trace_name); } gTraceGuard -= 1; } diff --git a/appletrace_binary.py b/appletrace_binary.py new file mode 100644 index 00000000..5c441a9f --- /dev/null +++ b/appletrace_binary.py @@ -0,0 +1,186 @@ +#!/usr/bin/env python3 +"""AppleTrace binary trace fragment format (encoder + decoder). + +The runtime can emit events as fixed-layout binary records instead of JSON +lines, keeping all string formatting off the hot path. Each unique event name is +interned once as a string-definition record; subsequent events reference it by +id. The exporter (``merge.py``) decodes these fragments back into the same +Chrome/Perfetto JSON events it produces for text fragments. + +Format (little-endian):: + + header: + magic : 8 bytes = b"APLTRC01" + pid : uint32 + + then a stream of tagged records: + 0x00 -> end / zero padding (stop decoding) + 0x01 -> string definition: name_id(uint32) len(uint32) utf8[len] + ASCII phase -> event: name_id(uint32) tid(uint64) ts(uint64) arg(uint64) + + phase is one of 'B' 'E' 'i' 'C' 'b' 'e' 'M'; ``arg`` is phase-specific: + 'C' -> IEEE-754 double bits of the counter value + 'b' / 'e' -> async id + 'M' -> name_id of the metadata value string (args.name) + others -> 0 (unused) +""" + +from __future__ import annotations + +import struct +from typing import Dict, Iterable, Iterator + +MAGIC = b"APLTRC01" + +TAG_END = 0x00 +TAG_STRING = 0x01 + +_HEADER = struct.Struct(" bool: + return data[: len(MAGIC)] == MAGIC + + +class Encoder: + """Builds a binary fragment. Used by tests and as the reference producer.""" + + def __init__(self, pid: int) -> None: + self._buffer = bytearray(MAGIC) + self._buffer += _HEADER.pack(pid) + self._ids: Dict[str, int] = {} + + def _intern(self, name: str) -> int: + existing = self._ids.get(name) + if existing is not None: + return existing + name_id = len(self._ids) + self._ids[name] = name_id + encoded = name.encode("utf-8") + self._buffer.append(TAG_STRING) + self._buffer += _STRING_HEADER.pack(name_id, len(encoded)) + self._buffer += encoded + return name_id + + def _event(self, phase: str, name: str, tid: int, ts: int, arg: int) -> None: + name_id = self._intern(name) + self._buffer.append(ord(phase)) + self._buffer += _EVENT.pack(name_id, tid, ts, arg) + + def section(self, phase: str, name: str, tid: int, ts: int) -> None: + if phase not in ("B", "E"): + raise ValueError(f"section phase must be B or E, got {phase!r}") + self._event(phase, name, tid, ts, 0) + + def instant(self, name: str, tid: int, ts: int) -> None: + self._event("i", name, tid, ts, 0) + + def counter(self, name: str, tid: int, ts: int, value: float) -> None: + (bits,) = struct.unpack(" None: + if phase not in ("b", "e"): + raise ValueError(f"async phase must be b or e, got {phase!r}") + self._event(phase, name, tid, ts, async_id) + + def metadata(self, name: str, tid: int, value: str) -> None: + value_id = self._intern(value) + self._event("M", name, tid, 0, value_id) + + def to_bytes(self) -> bytes: + return bytes(self._buffer) + + +def decode(data: bytes, *, names: Dict[int, str] | None = None) -> Iterator[dict]: + """Yield Chrome/Perfetto JSON event dicts from a binary fragment. + + Decoding stops at a 0x00 tag or when the buffer is exhausted/truncated, so + zero padding left by a crashed process is tolerated like the text path. + + Pass a shared ``names`` dict across the fragments of one run: a thread emits + a name's string definition only once, so after fragment rollover a later + fragment may reference an id defined in an earlier one. + """ + if not is_binary_fragment(data): + raise ValueError("not an AppleTrace binary fragment") + + offset = len(MAGIC) + (pid,) = _HEADER.unpack_from(data, offset) + offset += _HEADER.size + + if names is None: + names = {} + size = len(data) + + while offset < size: + tag = data[offset] + offset += 1 + + if tag == TAG_END: + break + + if tag == TAG_STRING: + if offset + _STRING_HEADER.size > size: + break + name_id, length = _STRING_HEADER.unpack_from(data, offset) + offset += _STRING_HEADER.size + if offset + length > size: + break + names[name_id] = data[offset : offset + length].decode("utf-8", errors="replace") + offset += length + continue + + if offset + _EVENT.size > size: + break + name_id, tid, ts, arg = _EVENT.unpack_from(data, offset) + offset += _EVENT.size + + phase = chr(tag) + name = names.get(name_id) + if name is None: + raise ValueError(f"event references undefined string id {name_id}") + + event: dict = {"name": name, "ph": phase, "pid": pid, "tid": tid} + if phase in _PHASES_WITH_CAT: + event["cat"] = _CAT + event["ts"] = ts + + if phase == "i": + event["s"] = "t" + elif phase == "C": + (value,) = struct.unpack(" Iterable[dict]: + return list(decode(data)) diff --git a/docs/binary-fragment-format.md b/docs/binary-fragment-format.md new file mode 100644 index 00000000..245dcd52 --- /dev/null +++ b/docs/binary-fragment-format.md @@ -0,0 +1,92 @@ +# AppleTrace Binary Fragment Format + +Status: format locked; **exporter implemented and tested** +(`appletrace_binary.py`, wired into `merge.py`); **native writer implemented** +(opt-in `APPLETRACE_BINARY=1`, **verified on the macOS host stress test** — +`scripts/test_batching_stress.sh` runs the binary mode through 200k cross-thread +event pairs with no loss or duplication). This is the follow-on to the +per-thread batching work in +[perf-batching-design.md](perf-batching-design.md). + +## Why + +The text format writes one JSON line per event, so every event pays for string +formatting on (or near) the hot path. The binary format keeps formatting off the +hot path entirely: each unique event name is interned once, and events are +fixed-layout records that reference a name by id. The exporter (`merge.py`) +decodes fragments back into the exact Chrome/Perfetto JSON it already produces, +so Perfetto/visualization is unchanged. + +## Layout (little-endian) + +``` +header: + magic : 8 bytes = "APLTRC01" + pid : uint32 + +records (repeated until 0x00 tag or EOF): + 0x00 end / zero padding -> stop decoding + 0x01 string definition -> name_id:uint32 len:uint32 utf8[len] + event -> name_id:uint32 tid:uint64 ts:uint64 arg:uint64 +``` + +- A string definition assigns `name_id -> string`. The producer emits it the + first time a name is used; later events reference the id. Decoders build the + table in stream order, so fragments are self-contained. +- `pid` is constant per fragment (per process) and is injected into every + decoded event. +- `ts` is microseconds since trace start (ignored for `M`). + +### Phase tags and `arg` + +| phase | meaning | `arg` | decoded JSON extras | +|-------|--------------------|------------------------------------|--------------------------------| +| `B` | section begin | 0 | `cat`, `ts` | +| `E` | section end | 0 | `cat`, `ts` | +| `i` | instant | 0 | `cat`, `ts`, `s:"t"` | +| `C` | counter | IEEE-754 double bits of the value | `cat`, `ts`, `args.value` | +| `b` | async begin | async id | `cat`, `ts`, `id` | +| `e` | async end | async id | `cat`, `ts`, `id` | +| `M` | metadata | name_id of the value string | `args.name` (no `cat`/`ts`) | + +Counter values are decoded as an integer when integral (e.g. `60`), else a +float (e.g. `142.5`), matching the text producer. + +## Robustness + +- Decoding stops at a `0x00` tag, so zero padding left by a crashed process + (an mmap region not truncated on clean close) is tolerated, exactly like the + text path's trailing-garbage handling. +- Truncated records at EOF stop decoding instead of raising. +- An event referencing an undefined `name_id` is a hard error (corruption). + +## Exporter integration + +- `appletrace_binary.py` provides `MAGIC`, `is_binary_fragment(bytes)`, + `decode(bytes)`, and an `Encoder` (reference producer, used by tests). +- `merge.py` discovers `trace[_N].appletrace` (text) and + `trace[_N].appletracebin` (binary) fragments, detects each file by magic, and + decodes accordingly. Both feed the same `X`-complete-event collapsing. + +## Runtime producer (implemented) + +The native writer in `appletrace.mm` is enabled by `APPLETRACE_BINARY=1`: + +- Appends fixed-layout records to the per-thread batch buffer (byte buffers + after the batching change) instead of JSON text. +- Interning is **per thread**: each thread keeps its own `(string -> name_id)` + map and emits a string definition the first time it uses a name, drawing a + globally-unique id from an atomic counter. So a thread only ever references + ids it defined — there is no cross-thread ordering hazard with batched + flushing (a process-wide table with single definitions would be unsafe, since + another thread could flush a reference before the defining thread flushes the + definition). The same string may therefore get one id per thread. +- The exporter shares one name table across a run's fragments, so a reference in + a later fragment resolves a definition emitted in an earlier one (after + rollover a thread does not re-emit a definition). +- Fragments are named `trace[_N].appletracebin`; each begins with the + magic+pid header. `LoggerManager` writes the header on every fragment and + rolls over whole batches so a record is never split across files. + +Keeping it opt-in preserves the text path (and the existing smoke-test +assertions) until the binary path is validated on device. diff --git a/docs/perf-batching-design.md b/docs/perf-batching-design.md new file mode 100644 index 00000000..5e0a2fb1 --- /dev/null +++ b/docs/perf-batching-design.md @@ -0,0 +1,245 @@ +# Design: Per-Thread Batched Trace Writing + +Status: implemented in `appletrace/appletrace/src/appletrace.mm` (Phase 2 of +[ROADMAP.md](../ROADMAP.md)); **pending macOS build + profiling verification.** +This document is the design of record; section 9 is the verification plan. + +## 1. Problem + +Today every trace event is written individually on a serial dispatch queue. +In `appletrace/appletrace/src/appletrace.mm`, `Trace::WriteSection` (and the +sibling `WriteInstant` / `WriteCounter` / `WriteAsync`) do, per event: + +1. Build a `std::string` JSON line via repeated `operator+` (several small heap + allocations). +2. `dispatch_async(queue_, ^{ log_.AddLine(line); })` — which heap-copies the + block (capturing the `std::string`) and enqueues onto the serial queue. + +Under the automatic `objc_msgSend` hook this path runs millions of times per +second. The per-event `dispatch_async` (block alloc + enqueue + cross-thread +handoff) and the per-event string allocations dominate, distort the timings we +are trying to measure, and balloon queue memory under bursts. + +Goal: amortize the cost so the hot path appends to a thread-local buffer with no +allocation and no cross-thread handoff in the common case, while a background +thread does the actual mmap writes in bulk. + +### Non-goals +- Changing the on-disk fragment format or the merge/exporter (`merge.py`). +- Lock-free data structures. A per-buffer `os_unfair_lock` is cheap enough; the + hot path stays uncontended because each thread locks only its own buffer. +- Changing the public API or event semantics. + +## 2. Overview + +Introduce a per-thread accumulation buffer. The hot path appends formatted +bytes to its own buffer under that buffer's lock. When the buffer crosses a +size threshold it is handed to the existing serial writer queue in one +`dispatch_async`. A global registry of buffers lets `APTFlush` drain every +thread, preserving the current flush contract. + +``` +hot path (any thread) writer queue (serial, existing) + append line -> tls buffer --(threshold/flush)--> log_.AddLine(batch) +``` + +The existing `LoggerManager` / `Logger` (mmap + rollover) is reused unchanged: +it already accepts a string and appends it; we just hand it a large batch +string instead of one line. `AddLine` should be complemented by an +`AddBlock(const std::string&)` that writes a multi-line batch and handles +rollover mid-batch (split on the rollover boundary, or roll then continue). + +## 3. Data structures + +```cpp +struct ThreadLog { + os_unfair_lock lock = OS_UNFAIR_LOCK_INIT; + std::string pending; // accumulated, newline-terminated lines + bool registered = false; +}; +``` + +- `static thread_local ThreadLog* tls_log = nullptr;` — the calling thread's + buffer (raw pointer; storage owned by the registry). +- Registry, owned by the singleton `Trace`: + ```cpp + std::mutex registry_mutex_; + std::vector> thread_logs_; + ``` +- Tunables (env-configurable, mirror existing `APPLETRACE_BLOCK_SIZE_MB` + pattern): `kFlushThresholdBytes` (default 32 KiB), reserved capacity for + `pending` (e.g. 64 KiB) to avoid reallocation churn. + +## 4. Behavior + +### 4.1 Acquire this thread's buffer (lazy) + +```cpp +ThreadLog* Trace::AcquireThreadLog() { + if (tls_log) return tls_log; + auto owned = std::make_unique(); + owned->pending.reserve(kReserveBytes); + ThreadLog* raw = owned.get(); + { + std::lock_guard g(registry_mutex_); + thread_logs_.push_back(std::move(owned)); + } + raw->registered = true; + tls_log = raw; + InstallThreadExitFlush(); // see 4.4 + return raw; +} +``` + +### 4.2 Append (hot path) + +`WriteSection`/`WriteInstant`/`WriteCounter`/`WriteAsync` keep building the line +string exactly as today, then instead of `dispatch_async` per event: + +```cpp +void Trace::Emit(const std::string& line) { + if (!IsEnabled() || !queue_) return; + ThreadLog* tl = AcquireThreadLog(); + std::string batch_to_ship; + { + os_unfair_lock_lock(&tl->lock); + tl->pending.append(line); + tl->pending.push_back('\n'); + if (tl->pending.size() >= kFlushThresholdBytes) { + batch_to_ship.swap(tl->pending); // hand off ownership, O(1) + tl->pending.reserve(kReserveBytes); + } + os_unfair_lock_unlock(&tl->lock); + } + if (!batch_to_ship.empty()) { + dispatch_async(queue_, ^{ log_.AddBlock(batch_to_ship); }); + } +} +``` + +Notes: +- The lock is held only around the append/swap; the `dispatch_async` happens + after unlocking. +- `swap` makes the handoff allocation-free; the freshly reserved buffer keeps + the hot path allocation-free across batches. +- The block captures `batch_to_ship` by copy (move-into-block via `__block` or a + `std::shared_ptr` is a valid optimization to avoid the copy). + +### 4.3 Flush (cross-thread, preserves contract) + +`APTFlush` must drain every thread's pending bytes, then flush the logger. + +```cpp +void Trace::Flush() { + if (!queue_) return; + std::vector batches; + { + std::lock_guard g(registry_mutex_); // blocks new registrations + for (auto& tl : thread_logs_) { + os_unfair_lock_lock(&tl->lock); + if (!tl->pending.empty()) { + batches.emplace_back(std::move(tl->pending)); + tl->pending.clear(); + tl->pending.reserve(kReserveBytes); + } + os_unfair_lock_unlock(&tl->lock); + } + } + dispatch_sync(queue_, ^{ + for (auto& b : batches) log_.AddBlock(b); + log_.Flush(); + }); +} +``` + +Holding `registry_mutex_` for the whole drain prevents a thread from exiting and +freeing its `ThreadLog` mid-iteration (thread-exit also takes this lock, 4.4). +The hot path is unaffected because it only takes the per-buffer `os_unfair_lock`. + +### 4.4 Thread exit + +A thread that produced events must flush and deregister before its `ThreadLog` +is destroyed. Use a `thread_local` RAII guard whose destructor runs at thread +exit (the singleton `Trace`, a function-local static, outlives all threads): + +```cpp +struct ThreadExitFlusher { ~ThreadExitFlusher(); }; +static thread_local ThreadExitFlusher tls_exit_flusher; // referenced in AcquireThreadLog +``` + +`~ThreadExitFlusher` (and a pthread-key fallback if `thread_local` destructor +ordering is a concern): +1. Take `registry_mutex_`. +2. Find this thread's `ThreadLog`, move out `pending`. +3. Erase it from `thread_logs_` (so a concurrent `Flush` cannot touch it). +4. Release the mutex; if `pending` is non-empty, `dispatch_async` the final + batch. +5. `tls_log = nullptr`. + +### 4.5 Disable / enable and shutdown + +- `SetEnabled(false)` keeps the buffers; `Emit` early-returns so nothing + accumulates. No flush is forced (matches today's drop-while-disabled). +- Process teardown: the existing `Logger::Close` (called from destructors) still + truncates the mmap file to the written size. Any thread-local buffers not yet + shipped at process exit are best-effort; document that callers should + `APTFlush()` (or `APTSyncWait()`) before reading traces, as today. + +## 5. Ordering + +Chrome/Perfetto sort events by `ts`, so batching does not require global +emission order. Within a thread, order is preserved (append order). Across +threads, `ts` is the source of truth. The merge step already concatenates +fragments; no change needed. + +## 6. Reentrancy & hook interaction + +The `objc_msgSend` hook calls `APTBeginSection`/`APTEndSection` under its +`gTraceGuard` thread-local guard, so any Objective-C calls made *inside* the +runtime (e.g. building thread names) are not re-traced. `Emit` must avoid +triggering traced `objc_msgSend` on the hot path — it already uses C++ `std` +types and C locks, which is fine. `AcquireThreadLog`'s first-call allocation is +plain C++ (`std::make_unique`, `std::vector`), no Objective-C dispatch. + +## 7. Edge cases / risks to verify on device + +- **Static init/destruction order**: `tls_exit_flusher` destructor must run + while the singleton `Trace` and its `queue_`/`log_` are still valid. Verify + with a worker thread that exits before `main` returns. +- **Flush during thread exit**: covered by `registry_mutex_` serialization; + add a stress test (many short-lived threads + concurrent `APTFlush`). +- **`AddBlock` rollover**: ensure a batch larger than the remaining mmap space + rolls to a new fragment without dropping or splitting a line mid-JSON. Unit + this at the `Logger` level. +- **Memory bound**: per-thread `pending` is capped near `kFlushThresholdBytes` + between ships; total ≈ threads × threshold. Confirm acceptable. +- **OOM on append**: if `append` throws `bad_alloc`, the event is lost; catch + and drop rather than propagate into app code. + +## 8. Optional follow-on: binary events at runtime + +The second Phase 2 bullet ("defer JSON formatting to the exporter") can build on +this: + +- Replace the per-event `std::string` JSON with a fixed-size binary record + `{ uint8 phase, uint64 ts, uint64 tid, uint32 name_id, double aux }` appended + to `pending` (now a byte buffer). `name_id` reuses the hook's interning table; + the runtime writes a `name_id -> string` table once per fragment. +- The exporter (`merge.py`) gains a binary fragment reader that emits the same + Chrome JSON it produces today. +- This removes all string formatting from the hot path and shrinks fragments + further. It is a larger change and should land after the batching writer is + proven. + +## 9. Verification plan (macOS) + +1. Build the framework and run `scripts/test_objc_msgsend_hook.sh` and + `scripts/test_objc_msgsend_hook_experimental.sh` — output must match today's. +2. Run `scripts/test_batching_stress.sh`: it builds `appletrace.mm` + + `tests/stress/stress_main.mm` for the host, emits N threads × M begin/end + pairs (worker threads exit before the flush to exercise the drain path), and + asserts the merged trace contains exactly N×M `stress` complete events — no + loss, no duplication. Run it a few times; concurrency bugs are intermittent. +3. Profile `TraceAllMsgDemo` with Instruments before/after; compare wall-clock + overhead and peak queue memory. Target: large reduction in `dispatch_async` + count and per-event allocations. diff --git a/get_catapult.sh b/get_catapult.sh deleted file mode 100644 index 031b6774..00000000 --- a/get_catapult.sh +++ /dev/null @@ -1,3 +0,0 @@ - -git clone https://github.com/catapult-project/catapult.git - diff --git a/go.sh b/go.sh index 1376ab37..11e36172 100755 --- a/go.sh +++ b/go.sh @@ -12,6 +12,6 @@ TRACE_DIR="$1" echo "AppleTrace export starting" echo "trace dir: $TRACE_DIR" -python3 "$SCRIPT_DIR/scripts/appletrace_cli.py" all "$TRACE_DIR" --open +python3 "$SCRIPT_DIR/scripts/appletrace_cli.py" open "$TRACE_DIR" echo "AppleTrace export finished" diff --git a/merge.py b/merge.py index 065a7e8d..bbe7e05f 100644 --- a/merge.py +++ b/merge.py @@ -9,8 +9,10 @@ from pathlib import Path from typing import Iterable, List +from appletrace_binary import decode as decode_binary_fragment, is_binary_fragment -TRACE_FILE_RE = re.compile(r"^trace(?:_(\d+))?\.appletrace$") + +TRACE_FILE_RE = re.compile(r"^trace(?:_(\d+))?\.appletrace(bin)?$") def list_trace_files(directory: Path) -> List[Path]: @@ -31,34 +33,86 @@ def list_trace_files(directory: Path) -> List[Path]: def iter_events(trace_files: Iterable[Path]) -> Iterable[dict]: - """Yield valid JSON events from AppleTrace fragment files.""" + """Yield events from AppleTrace fragments (text JSON-lines or binary).""" + binary_names: dict = {} # shared across this run's binary fragments for file_path in trace_files: print(file_path) - with file_path.open("r", encoding="utf-8") as handle: - for line_number, line in enumerate(handle, start=1): - raw_line = line.strip() - if not raw_line: - continue - - if not raw_line.startswith("{"): - break - - try: - event = json.loads(raw_line) - except json.JSONDecodeError as exc: - raise ValueError( - f"Invalid JSON in {file_path}:{line_number}: {exc.msg}" - ) from exc - - if not isinstance(event, dict): - raise ValueError( - f"Unexpected non-object event in {file_path}:{line_number}" - ) + data = file_path.read_bytes() + if is_binary_fragment(data): + yield from decode_binary_fragment(data, names=binary_names) + else: + yield from _iter_text_events(file_path, data) + + +def _iter_text_events(file_path: Path, data: bytes) -> Iterable[dict]: + text = data.decode("utf-8") + for line_number, line in enumerate(text.splitlines(), start=1): + raw_line = line.strip() + if not raw_line: + continue + if not raw_line.startswith("{"): + break + + try: + event = json.loads(raw_line) + except json.JSONDecodeError as exc: + raise ValueError( + f"Invalid JSON in {file_path}:{line_number}: {exc.msg}" + ) from exc + + if not isinstance(event, dict): + raise ValueError( + f"Unexpected non-object event in {file_path}:{line_number}" + ) + + yield event + + +def iter_complete_events(events: Iterable[dict]) -> Iterable[dict]: + """Collapse matched begin/end (`B`/`E`) pairs into `X` complete events. + + A complete event carries an explicit duration, so this roughly halves the + number of section events. Pairing is LIFO per `(pid, tid)`, matching the + nested begin/end model AppleTrace emits. Non-section events pass through + untouched, and unmatched begins are emitted as raw `B` events (viewers + auto-close them at the end of the trace). + """ + open_stacks: dict[tuple, List[dict]] = {} + for event in events: + phase = event.get("ph") + if phase == "B": + key = (event.get("pid"), event.get("tid")) + open_stacks.setdefault(key, []).append(event) + elif phase == "E": + key = (event.get("pid"), event.get("tid")) + stack = open_stacks.get(key) + if stack: + begin = stack.pop() + complete = dict(begin) + complete["ph"] = "X" + begin_ts = begin.get("ts", 0) + complete["dur"] = event.get("ts", begin_ts) - begin_ts + if "args" in event: + merged = dict(begin.get("args", {})) + merged.update(event["args"]) + complete["args"] = merged + yield complete + else: yield event + else: + yield event + + for stack in open_stacks.values(): + for begin in stack: + yield begin -def merge_trace_directory(directory: Path, output_path: Path | None = None) -> Path: +def merge_trace_directory( + directory: Path, + output_path: Path | None = None, + complete_events: bool = True, +) -> Path: """Merge all trace fragments under a directory into `trace.json`.""" if not directory.exists(): raise FileNotFoundError(f"Trace directory does not exist: {directory}") @@ -70,10 +124,19 @@ def merge_trace_directory(directory: Path, output_path: Path | None = None) -> P raise FileNotFoundError(f"No trace fragments found in {directory}") target = output_path or directory / "trace.json" - events = list(iter_events(trace_files)) + source: Iterable[dict] = iter_events(trace_files) + if complete_events: + source = iter_complete_events(source) + with target.open("w", encoding="utf-8") as handle: - json.dump(events, handle, ensure_ascii=False, separators=(",", ":")) - handle.write("\n") + handle.write("[") + first = True + for event in source: + if not first: + handle.write(",") + handle.write(json.dumps(event, ensure_ascii=False, separators=(",", ":"))) + first = False + handle.write("]\n") return target @@ -95,6 +158,12 @@ def build_parser() -> argparse.ArgumentParser: dest="output", help="Optional output JSON path. Defaults to /trace.json.", ) + parser.add_argument( + "--raw", + dest="raw", + action="store_true", + help="Emit raw begin/end events instead of collapsing into X complete events.", + ) return parser @@ -104,7 +173,7 @@ def main() -> int: output_path = Path(args.output).expanduser().resolve() if args.output else None try: - merged_path = merge_trace_directory(directory, output_path) + merged_path = merge_trace_directory(directory, output_path, not args.raw) except (FileNotFoundError, NotADirectoryError, ValueError) as exc: print(f"error: {exc}") return 1 diff --git a/requirements.txt b/requirements.txt index 907770e1..c89c8455 100644 --- a/requirements.txt +++ b/requirements.txt @@ -1,2 +1,3 @@ # Optional Python tooling for local development and testing. -pytest>=8.0,<9.0 +# >=9.0.3 picks up the fix for CVE-2025-71176 (insecure /tmp/pytest-of-* handling). +pytest>=9.0.3 diff --git a/sampledata/genhtml.sh b/sampledata/genhtml.sh deleted file mode 100644 index 6004f186..00000000 --- a/sampledata/genhtml.sh +++ /dev/null @@ -1,5 +0,0 @@ -#!/bin/bash -set -euo pipefail - -ROOT_DIR="$(cd "$(dirname "$0")/.." && pwd)" -python3 "$ROOT_DIR/scripts/appletrace_cli.py" all "$ROOT_DIR/sampledata" --open diff --git a/sampledata/trace.html b/sampledata/trace.html deleted file mode 100644 index a9a30310..00000000 --- a/sampledata/trace.html +++ /dev/null @@ -1,106202 +0,0 @@ - - - - - Trace from trace.json - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - diff --git a/scripts/appletrace_cli.py b/scripts/appletrace_cli.py index 14f0d9fd..8e230046 100755 --- a/scripts/appletrace_cli.py +++ b/scripts/appletrace_cli.py @@ -1,5 +1,5 @@ #!/usr/bin/env python3 -"""Convenience CLI for AppleTrace merge and HTML export workflows.""" +"""Convenience CLI for AppleTrace: merge fragments and open them in Perfetto.""" from __future__ import annotations @@ -16,85 +16,62 @@ from merge import merge_trace_directory +PERFETTO_URL = "https://ui.perfetto.dev" -def resolve_catapult(candidate: str | None) -> Path | None: - if candidate: - path = Path(candidate).expanduser().resolve() - return path if path.exists() else None - default_path = REPO_ROOT / "catapult" / "tracing" / "bin" / "trace2html" - return default_path if default_path.exists() else None +def open_url(url: str) -> None: + if shutil.which("open") is not None: + subprocess.run(["open", url], check=False) -def maybe_open(path: Path, should_open: bool) -> None: - if not should_open: - return - if shutil.which("open") is None: - return - subprocess.run(["open", str(path)], check=False) +def print_perfetto_hint(trace_json: Path) -> None: + print() + print(f"Trace ready: {trace_json}") + print(f"Open {PERFETTO_URL} and drag in the file above (or use 'Open trace file').") def cmd_merge(args: argparse.Namespace) -> int: output = Path(args.output).expanduser().resolve() if args.output else None - merged = merge_trace_directory(Path(args.directory).expanduser().resolve(), output) + merged = merge_trace_directory( + Path(args.directory).expanduser().resolve(), output, not args.raw + ) print(merged) return 0 -def cmd_html(args: argparse.Namespace) -> int: - trace_json = Path(args.trace_json).expanduser().resolve() - if not trace_json.exists(): - print(f"error: trace json does not exist: {trace_json}") - return 1 - - trace2html = resolve_catapult(args.catapult) - if trace2html is None: - print("error: trace2html not found. Run `sh get_catapult.sh` first.") - return 1 - - output = Path(args.output).expanduser().resolve() if args.output else trace_json.with_suffix(".html") - command = [sys.executable, str(trace2html), str(trace_json), f"--output={output}"] - print(" ".join(command)) - subprocess.run(command, check=True) - print(output) - maybe_open(output, args.open) - return 0 - - -def cmd_all(args: argparse.Namespace) -> int: - directory = Path(args.directory).expanduser().resolve() - merged = merge_trace_directory(directory) - html_args = argparse.Namespace( - trace_json=str(merged), - output=args.output, - catapult=args.catapult, - open=args.open, +def cmd_open(args: argparse.Namespace) -> int: + output = Path(args.output).expanduser().resolve() if args.output else None + merged = merge_trace_directory( + Path(args.directory).expanduser().resolve(), output, not args.raw ) - return cmd_html(html_args) + print_perfetto_hint(merged) + open_url(PERFETTO_URL) + return 0 def build_parser() -> argparse.ArgumentParser: parser = argparse.ArgumentParser(description="AppleTrace utility CLI.") subparsers = parser.add_subparsers(dest="command", required=True) - merge_parser = subparsers.add_parser("merge", help="Merge .appletrace fragments.") + merge_parser = subparsers.add_parser("merge", help="Merge .appletrace fragments into trace.json.") merge_parser.add_argument("directory", help="Directory containing .appletrace files.") merge_parser.add_argument("-o", "--output", help="Output JSON path.") + merge_parser.add_argument( + "--raw", + action="store_true", + help="Emit raw begin/end events instead of X complete events.", + ) merge_parser.set_defaults(func=cmd_merge) - html_parser = subparsers.add_parser("html", help="Generate HTML via Catapult trace2html.") - html_parser.add_argument("trace_json", help="Path to trace.json.") - html_parser.add_argument("-o", "--output", help="Output HTML path.") - html_parser.add_argument("--catapult", help="Path to Catapult trace2html script.") - html_parser.add_argument("--open", action="store_true", help="Open the generated HTML.") - html_parser.set_defaults(func=cmd_html) - - all_parser = subparsers.add_parser("all", help="Merge traces and generate HTML.") - all_parser.add_argument("directory", help="Directory containing .appletrace files.") - all_parser.add_argument("-o", "--output", help="Output HTML path.") - all_parser.add_argument("--catapult", help="Path to Catapult trace2html script.") - all_parser.add_argument("--open", action="store_true", help="Open the generated HTML.") - all_parser.set_defaults(func=cmd_all) + open_parser = subparsers.add_parser("open", help="Merge fragments and open the trace in Perfetto.") + open_parser.add_argument("directory", help="Directory containing .appletrace files.") + open_parser.add_argument("-o", "--output", help="Output JSON path.") + open_parser.add_argument( + "--raw", + action="store_true", + help="Emit raw begin/end events instead of X complete events.", + ) + open_parser.set_defaults(func=cmd_open) return parser @@ -104,9 +81,6 @@ def main() -> int: args = parser.parse_args() try: return args.func(args) - except subprocess.CalledProcessError as exc: - print(f"error: command failed with exit code {exc.returncode}") - return exc.returncode except Exception as exc: # pragma: no cover - defensive CLI fallback print(f"error: {exc}") return 1 diff --git a/scripts/test_batching_stress.sh b/scripts/test_batching_stress.sh new file mode 100755 index 00000000..578e1153 --- /dev/null +++ b/scripts/test_batching_stress.sh @@ -0,0 +1,65 @@ +#!/usr/bin/env bash +# +# Stress test for the per-thread batched trace writer (macOS host build). +# +# Compiles appletrace.mm together with tests/stress/stress_main.mm, runs a +# multi-threaded workload in both the text and binary (APPLETRACE_BINARY=1) +# output modes, then merges each run and asserts that no events were lost or +# duplicated across threads / flush / thread-exit. +# +# This builds for the host (no Xcode project, no simulator), so it is fast and +# independent of the simulator smoke tests. +set -euo pipefail + +ROOT_DIR="$(cd "$(dirname "$0")/.." && pwd)" +SRC_DIR="${ROOT_DIR}/appletrace/appletrace/src" +WORK_DIR="$(mktemp -d)" +BIN_PATH="${WORK_DIR}/appletrace_stress" + +cleanup() { rm -rf "${WORK_DIR}"; } +trap cleanup EXIT + +echo "[build] Compiling stress harness" +clang++ -std=gnu++11 -fobjc-arc -O2 \ + -I "${SRC_DIR}" \ + -framework Foundation \ + "${SRC_DIR}/appletrace.mm" \ + "${ROOT_DIR}/tests/stress/stress_main.mm" \ + -o "${BIN_PATH}" + +run_mode() { + local label="$1" + shift # remaining args are extra environment assignments + local data_dir="${WORK_DIR}/${label}" + + echo "[${label}] Running stress harness" + local output + output="$(APPLETRACE_DATA_DIR="${data_dir}" "$@" "${BIN_PATH}")" + local expected + expected="$(printf '%s\n' "${output}" | sed -n 's/^EXPECTED_STRESS_PAIRS=//p')" + if [[ -z "${expected}" ]]; then + echo "[${label}] harness did not report an expected count" >&2 + exit 1 + fi + + echo "[${label}] Merging and verifying (${expected} expected pairs)" + python3 "${ROOT_DIR}/merge.py" -d "${data_dir}" >/dev/null + python3 - "${data_dir}/trace.json" "${expected}" "${label}" <<'PY' +import json +import sys + +events = json.load(open(sys.argv[1])) +expected = int(sys.argv[2]) +label = sys.argv[3] +got = sum(1 for event in events if event.get("ph") == "X" and event.get("name") == "stress") +print(f"[{label}] stress complete events: {got} / expected {expected}") +if got != expected: + raise SystemExit(f"[{label}] MISMATCH: events lost or duplicated ({got} != {expected})") +print(f"[{label}] OK: no events lost or duplicated") +PY +} + +run_mode text +run_mode binary env APPLETRACE_BINARY=1 + +echo "batching stress test passed (text + binary)" diff --git a/tests/stress/stress_main.mm b/tests/stress/stress_main.mm new file mode 100644 index 00000000..35f48063 --- /dev/null +++ b/tests/stress/stress_main.mm @@ -0,0 +1,52 @@ +// +// stress_main.mm +// AppleTrace batched-writer stress harness. +// +// Spawns several worker threads that each emit a fixed number of +// begin/end pairs, then flushes. Worker threads exit before the flush so the +// pthread-key drain path is exercised alongside the cross-thread APTFlush. +// The accompanying script asserts that exactly threads*per_thread "stress" +// complete events survive (no loss, no duplication). +// + +#import + +#include +#include +#include + +#import "appletrace.h" + +int main(int argc, const char *argv[]) { + @autoreleasepool { + const int thread_count = 8; + const int pairs_per_thread = 25000; + + std::vector workers; + workers.reserve(thread_count); + for (int t = 0; t < thread_count; ++t) { + workers.emplace_back([pairs_per_thread]() { + for (int i = 0; i < pairs_per_thread; ++i) { + APTBeginSection("stress"); + APTEndSection("stress"); + } + }); + } + for (std::thread &worker : workers) { + worker.join(); // thread exit triggers the per-thread drain path + } + + // Smoke the other event types (not counted by the assertion). + APTInstant("stress_done"); + APTCounter("stress_threads", thread_count); + APTAsyncBegin("stress_async", 1); + APTAsyncEnd("stress_async", 1); + + APTFlush(); + APTSyncWait(); + + const long expected = (long)thread_count * pairs_per_thread; + fprintf(stdout, "EXPECTED_STRESS_PAIRS=%ld\n", expected); + } + return 0; +} diff --git a/tests/test_binary.py b/tests/test_binary.py new file mode 100644 index 00000000..d81066e8 --- /dev/null +++ b/tests/test_binary.py @@ -0,0 +1,154 @@ +from __future__ import annotations + +import json +import struct +import tempfile +import unittest +from pathlib import Path + +from appletrace_binary import MAGIC, Encoder, decode, is_binary_fragment +from merge import merge_trace_directory + + +def build(pid: int = 7): + return Encoder(pid) + + +class BinaryDecodeTests(unittest.TestCase): + def test_is_binary_fragment(self) -> None: + self.assertTrue(is_binary_fragment(MAGIC + b"\x00\x00\x00\x00")) + self.assertFalse(is_binary_fragment(b'{"name":"A"}')) + + def test_section_pair_roundtrip(self) -> None: + enc = build(pid=42) + enc.section("B", "work", tid=3, ts=10) + enc.section("E", "work", tid=3, ts=25) + events = list(decode(enc.to_bytes())) + self.assertEqual( + events, + [ + {"name": "work", "cat": "appletrace", "ph": "B", "pid": 42, "tid": 3, "ts": 10}, + {"name": "work", "cat": "appletrace", "ph": "E", "pid": 42, "tid": 3, "ts": 25}, + ], + ) + + def test_instant_has_thread_scope(self) -> None: + enc = build() + enc.instant("mark", tid=0, ts=5) + (event,) = list(decode(enc.to_bytes())) + self.assertEqual(event["ph"], "i") + self.assertEqual(event["s"], "t") + + def test_counter_integral_and_float(self) -> None: + enc = build() + enc.counter("fps", tid=0, ts=1, value=60.0) + enc.counter("mem", tid=0, ts=2, value=142.5) + events = list(decode(enc.to_bytes())) + self.assertEqual(events[0]["args"], {"value": 60}) + self.assertIsInstance(events[0]["args"]["value"], int) + self.assertEqual(events[1]["args"], {"value": 142.5}) + + def test_async_events_carry_id(self) -> None: + enc = build() + enc.async_event("b", "load", tid=1, ts=1, async_id=99) + enc.async_event("e", "load", tid=2, ts=9, async_id=99) + events = list(decode(enc.to_bytes())) + self.assertEqual([e["ph"] for e in events], ["b", "e"]) + self.assertEqual({e["id"] for e in events}, {99}) + + def test_metadata_has_args_name_and_no_cat(self) -> None: + enc = build(pid=5) + enc.metadata("thread_name", tid=0, value="Main Thread") + (event,) = list(decode(enc.to_bytes())) + self.assertEqual( + event, + {"name": "thread_name", "ph": "M", "pid": 5, "tid": 0, "args": {"name": "Main Thread"}}, + ) + self.assertNotIn("cat", event) + self.assertNotIn("ts", event) + + def test_string_table_is_shared(self) -> None: + enc = build() + for _ in range(3): + enc.section("B", "loop", tid=0, ts=1) + enc.section("E", "loop", tid=0, ts=2) + # The name bytes appear once (interned) despite six events referencing it. + self.assertEqual(enc.to_bytes().count(b"loop"), 1) + events = list(decode(enc.to_bytes())) + self.assertEqual(len(events), 6) + self.assertTrue(all(e["name"] == "loop" for e in events)) + + def test_trailing_zero_padding_stops_cleanly(self) -> None: + enc = build() + enc.section("B", "x", tid=0, ts=1) + enc.section("E", "x", tid=0, ts=2) + padded = enc.to_bytes() + b"\x00" * 4096 # simulate crash mmap padding + events = list(decode(padded)) + self.assertEqual(len(events), 2) + + def test_undefined_string_id_raises(self) -> None: + # Header + an event referencing string id 0 that was never defined. + data = MAGIC + struct.pack(" None: + # Fragment 0 defines "loop" (id 0) and uses it; fragment 1 reuses id 0 + # without re-defining it (a thread emits a string def only once). + first = build(pid=1) + first.section("B", "loop", tid=0, ts=1) + second_id = first._intern("loop") # already defined -> id 0 + + second = bytearray(MAGIC) + second += struct.pack(" None: + second = bytearray(MAGIC) + second += struct.pack(" None: + enc = build(pid=1) + enc.metadata("process_name", tid=0, value="Demo") + enc.section("B", "A", tid=0, ts=1) + enc.section("E", "A", tid=0, ts=4) + with tempfile.TemporaryDirectory() as tmp: + directory = Path(tmp) + (directory / "trace.appletracebin").write_bytes(enc.to_bytes()) + + output = merge_trace_directory(directory, complete_events=False) + events = json.loads(output.read_text(encoding="utf-8")) + + self.assertEqual([e["name"] for e in events], ["process_name", "A", "A"]) + + def test_merge_collapses_binary_pairs_by_default(self) -> None: + enc = build(pid=1) + enc.section("B", "A", tid=0, ts=1) + enc.section("E", "A", tid=0, ts=6) + with tempfile.TemporaryDirectory() as tmp: + directory = Path(tmp) + (directory / "trace.appletracebin").write_bytes(enc.to_bytes()) + + output = merge_trace_directory(directory) + events = json.loads(output.read_text(encoding="utf-8")) + + self.assertEqual(len(events), 1) + self.assertEqual(events[0]["ph"], "X") + self.assertEqual(events[0]["dur"], 5) + + +if __name__ == "__main__": + unittest.main() diff --git a/tests/test_merge.py b/tests/test_merge.py index bf8ff095..86701b9a 100644 --- a/tests/test_merge.py +++ b/tests/test_merge.py @@ -5,7 +5,7 @@ import unittest from pathlib import Path -from merge import list_trace_files, merge_trace_directory +from merge import iter_complete_events, list_trace_files, merge_trace_directory class MergeTraceDirectoryTests(unittest.TestCase): @@ -39,11 +39,32 @@ def test_merge_writes_valid_json_array(self) -> None: encoding="utf-8", ) - output = merge_trace_directory(directory) + output = merge_trace_directory(directory, complete_events=False) merged = json.loads(output.read_text(encoding="utf-8")) self.assertEqual([event["name"] for event in merged], ["A", "A", "B"]) + def test_merge_defaults_to_complete_events(self) -> None: + with tempfile.TemporaryDirectory() as tmp: + directory = Path(tmp) + (directory / "trace.appletrace").write_text( + '\n'.join( + [ + '{"name":"A","ph":"B","pid":1,"tid":0,"ts":1}', + '{"name":"A","ph":"E","pid":1,"tid":0,"ts":4}', + ] + ) + + "\n", + encoding="utf-8", + ) + + output = merge_trace_directory(directory) + merged = json.loads(output.read_text(encoding="utf-8")) + + self.assertEqual(len(merged), 1) + self.assertEqual(merged[0]["ph"], "X") + self.assertEqual(merged[0]["dur"], 3) + def test_merge_stops_on_non_json_tail(self) -> None: with tempfile.TemporaryDirectory() as tmp: directory = Path(tmp) @@ -68,5 +89,61 @@ def test_merge_raises_on_invalid_json(self) -> None: merge_trace_directory(directory) +class CompleteEventsTests(unittest.TestCase): + def test_matched_pair_becomes_complete_event(self) -> None: + events = [ + {"name": "A", "ph": "B", "pid": 1, "tid": 0, "ts": 10}, + {"name": "A", "ph": "E", "pid": 1, "tid": 0, "ts": 25}, + ] + result = list(iter_complete_events(events)) + self.assertEqual(len(result), 1) + self.assertEqual(result[0]["ph"], "X") + self.assertEqual(result[0]["dur"], 15) + self.assertEqual(result[0]["name"], "A") + + def test_nested_pairs_pair_lifo(self) -> None: + events = [ + {"name": "outer", "ph": "B", "pid": 1, "tid": 0, "ts": 0}, + {"name": "inner", "ph": "B", "pid": 1, "tid": 0, "ts": 5}, + {"name": "inner", "ph": "E", "pid": 1, "tid": 0, "ts": 8}, + {"name": "outer", "ph": "E", "pid": 1, "tid": 0, "ts": 20}, + ] + result = list(iter_complete_events(events)) + self.assertEqual([(e["name"], e["dur"]) for e in result], [("inner", 3), ("outer", 20)]) + + def test_non_section_events_pass_through(self) -> None: + events = [ + {"name": "thread_name", "ph": "M", "pid": 1, "tid": 0, "args": {"name": "Main"}}, + {"name": "fps", "ph": "C", "pid": 1, "tid": 0, "ts": 1, "args": {"value": 60}}, + {"name": "mark", "ph": "i", "pid": 1, "tid": 0, "ts": 2, "s": "t"}, + ] + result = list(iter_complete_events(events)) + self.assertEqual(result, events) + + def test_async_events_pass_through(self) -> None: + events = [ + {"name": "load", "ph": "b", "id": 7, "pid": 1, "tid": 0, "ts": 1}, + {"name": "load", "ph": "e", "id": 7, "pid": 1, "tid": 2, "ts": 9}, + ] + result = list(iter_complete_events(events)) + self.assertEqual(result, events) + + def test_unmatched_begin_is_preserved(self) -> None: + events = [{"name": "dangling", "ph": "B", "pid": 1, "tid": 0, "ts": 3}] + result = list(iter_complete_events(events)) + self.assertEqual(result, events) + + def test_pairs_are_isolated_per_thread(self) -> None: + events = [ + {"name": "A", "ph": "B", "pid": 1, "tid": 0, "ts": 0}, + {"name": "B", "ph": "B", "pid": 1, "tid": 1, "ts": 1}, + {"name": "A", "ph": "E", "pid": 1, "tid": 0, "ts": 4}, + {"name": "B", "ph": "E", "pid": 1, "tid": 1, "ts": 9}, + ] + result = list(iter_complete_events(events)) + durations = {e["name"]: e["dur"] for e in result} + self.assertEqual(durations, {"A": 4, "B": 8}) + + if __name__ == "__main__": unittest.main()