|
| 1 | +# Tracing Reactions |
| 2 | + |
| 3 | +NUClear includes a built-in tracing system that records reaction execution, scheduling, and log messages into a [Perfetto](https://perfetto.dev/)-compatible trace file. This lets you visualise exactly what your system is doing across threads and time. |
| 4 | + |
| 5 | +## Prerequisites |
| 6 | + |
| 7 | +- The `TraceController` extension must be installed in your PowerPlant |
| 8 | +- The output `.trace` file can be viewed in [Perfetto UI](https://ui.perfetto.dev/) or Chrome's `chrome://tracing` |
| 9 | + |
| 10 | +## Starting a Trace |
| 11 | + |
| 12 | +To begin recording, emit a `BeginTrace` message. This opens a trace file and starts capturing all reaction events: |
| 13 | + |
| 14 | +```cpp |
| 15 | +#include <nuclear> |
| 16 | + |
| 17 | +class MyApp : public NUClear::Reactor { |
| 18 | +public: |
| 19 | + explicit MyApp(std::unique_ptr<NUClear::Environment> environment) |
| 20 | + : Reactor(std::move(environment)) { |
| 21 | + |
| 22 | + on<Startup>().then([this] { |
| 23 | + // Start tracing to a file |
| 24 | + emit(std::make_unique<NUClear::message::BeginTrace>("my_system.trace")); |
| 25 | + }); |
| 26 | + } |
| 27 | +}; |
| 28 | +``` |
| 29 | + |
| 30 | +The `BeginTrace` message takes two parameters: |
| 31 | + |
| 32 | +| Parameter | Type | Default | Description | |
| 33 | +|-----------|------|---------|-------------| |
| 34 | +| `file` | `std::string` | `"trace.trace"` | Path to the output trace file | |
| 35 | +| `logs` | `bool` | `true` | Whether to include log messages in the trace | |
| 36 | + |
| 37 | +## Stopping a Trace |
| 38 | + |
| 39 | +To stop recording and flush the file, emit an `EndTrace` message: |
| 40 | + |
| 41 | +```cpp |
| 42 | +emit(std::make_unique<NUClear::message::EndTrace>()); |
| 43 | +``` |
| 44 | +
|
| 45 | +This closes the trace file cleanly. If you don't emit `EndTrace`, the file will be closed when the PowerPlant shuts down, but may be incomplete. |
| 46 | +
|
| 47 | +## Installing the TraceController |
| 48 | +
|
| 49 | +The `TraceController` must be installed before you can start tracing. Add it to your PowerPlant setup: |
| 50 | +
|
| 51 | +```cpp |
| 52 | +#include <nuclear> |
| 53 | +
|
| 54 | +int main(int argc, const char* argv[]) { |
| 55 | + NUClear::Configuration config; |
| 56 | + NUClear::PowerPlant plant(config, argc, argv); |
| 57 | +
|
| 58 | + // Install the trace controller |
| 59 | + plant.install<NUClear::extension::TraceController>(); |
| 60 | +
|
| 61 | + // Install your reactors |
| 62 | + plant.install<MyApp>(); |
| 63 | +
|
| 64 | + plant.start(); |
| 65 | +} |
| 66 | +``` |
| 67 | + |
| 68 | +## Viewing the Trace |
| 69 | + |
| 70 | +Once you have a `.trace` file: |
| 71 | + |
| 72 | +1. Open [https://ui.perfetto.dev/](https://ui.perfetto.dev/) in your browser |
| 73 | +2. Click **Open trace file** (or drag and drop) |
| 74 | +3. Select your `.trace` file |
| 75 | + |
| 76 | +The trace viewer shows: |
| 77 | + |
| 78 | +- **Thread lanes** — each thread pool thread gets its own lane showing which reactions ran and when |
| 79 | +- **Reaction slices** — coloured bars showing the duration of each reaction execution |
| 80 | +- **Flow arrows** — connecting task creation to task execution, showing scheduling flow |
| 81 | +- **Log messages** — if enabled, log entries appear as instant events on the thread they were emitted from |
| 82 | +- **Thread CPU time** — counter tracks showing per-thread CPU usage |
| 83 | + |
| 84 | +```mermaid |
| 85 | +gantt |
| 86 | + title Example Trace View |
| 87 | + dateFormat X |
| 88 | + axisFormat %L ms |
| 89 | +
|
| 90 | + section Default Pool 1 |
| 91 | + Vision::processImage :0, 5 |
| 92 | + Vision::detectObjects :5, 8 |
| 93 | +
|
| 94 | + section Default Pool 2 |
| 95 | + Sensor::readIMU :1, 2 |
| 96 | + Motor::updateServos :3, 4 |
| 97 | + Planner::computePath :6, 10 |
| 98 | +
|
| 99 | + section Main Thread |
| 100 | + Display::render :2, 7 |
| 101 | +``` |
| 102 | + |
| 103 | +## Tracing a Subset of Execution |
| 104 | + |
| 105 | +You can start and stop tracing at any point during execution. This is useful for capturing only the interesting portion of a long-running system: |
| 106 | + |
| 107 | +```cpp |
| 108 | +on<Trigger<StartRecording>>().then([this] { |
| 109 | + emit(std::make_unique<NUClear::message::BeginTrace>("interesting_section.trace")); |
| 110 | +}); |
| 111 | + |
| 112 | +on<Trigger<StopRecording>>().then([this] { |
| 113 | + emit(std::make_unique<NUClear::message::EndTrace>()); |
| 114 | +}); |
| 115 | +``` |
| 116 | + |
| 117 | +Starting a new trace while one is already active will close the previous trace file and begin a new one. |
| 118 | + |
| 119 | +## What Gets Recorded |
| 120 | + |
| 121 | +The trace captures these events for every reaction: |
| 122 | + |
| 123 | +| Event | Description | |
| 124 | +|-------|-------------| |
| 125 | +| **Created** | A task was generated (data emitted, preconditions checked) | |
| 126 | +| **Started** | A task began executing on a thread | |
| 127 | +| **Finished** | A task completed execution | |
| 128 | +| **Blocked** | A task was blocked by scheduling constraints (Sync, Group, etc.) | |
| 129 | +| **Missing Data** | A task was dropped because required data was unavailable | |
| 130 | + |
| 131 | +Each event records: |
| 132 | +- Wall-clock timestamp |
| 133 | +- Thread CPU time |
| 134 | +- Thread and pool identity |
| 135 | +- Reaction name (from `.then("name", callback)` labels or demangled DSL type) |
| 136 | +- Task ID for flow correlation |
| 137 | + |
| 138 | +## Tips |
| 139 | + |
| 140 | +!!! tip "Name your reactions" |
| 141 | + Give reactions descriptive labels to make traces easier to read: |
| 142 | + ```cpp |
| 143 | + on<Trigger<Image>>().then("Vision::processFrame", [](const Image& img) { |
| 144 | + // ... |
| 145 | + }); |
| 146 | + ``` |
| 147 | + Without a label, the trace uses the demangled DSL type signature, which can be verbose. |
| 148 | + |
| 149 | +!!! tip "Disable logs for performance traces" |
| 150 | + If you're measuring timing and don't need log messages cluttering the trace, disable them: |
| 151 | + ```cpp |
| 152 | + emit(std::make_unique<NUClear::message::BeginTrace>("perf.trace", false)); |
| 153 | + ``` |
| 154 | + |
| 155 | +!!! tip "Use in tests" |
| 156 | + NUClear's test utilities provide a helper for adding tracing to test binaries: |
| 157 | + ```cpp |
| 158 | + #include "test_util/common.hpp" |
| 159 | + |
| 160 | + // In your test setup: |
| 161 | + test_util::add_tracing(plant); |
| 162 | + ``` |
| 163 | + This writes a trace file alongside the test binary with a `.trace` extension. |
| 164 | + |
| 165 | +## See Also |
| 166 | + |
| 167 | +- [Logging](logging.md) — NUClear's log system (traces can include log messages) |
| 168 | +- [Threading Model](../explanation/threading.md) — understanding the thread pools shown in traces |
| 169 | +- [Built-in Extensions](../reference/extensions/built-in-extensions.md) — the TraceController extension |
0 commit comments