Primiano Tucci | a662485 | 2020-05-21 19:12:50 +0100 | [diff] [blame] | 1 | # Track events (Tracing SDK) |
| 2 | |
| 3 | Track events are part of the [Perfetto Tracing SDK](tracing-sdk.md). |
| 4 | |
| 5 | *Track events* are application specific, time bounded events recorded into a |
| 6 | *trace* while the application is running. Track events are always associated |
| 7 | with a *track*, which is a timeline of monotonically increasing time. A track |
| 8 | corresponds to an independent sequence of execution, such as a single thread |
| 9 | in a process. |
| 10 | |
| 11 |  |
| 13 | |
| 14 | See the [Getting started](/docs/instrumentation/tracing-sdk#getting-started) |
| 15 | section of the Tracing SDK page for instructions on how to check out and |
| 16 | build the SDK. |
| 17 | |
Sami Kyostila | 2778ac8 | 2020-12-21 16:12:27 +0000 | [diff] [blame] | 18 | TIP: The code from these examples is also available [in the |
| 19 | repository](/examples/sdk/README.md). |
Primiano Tucci | a662485 | 2020-05-21 19:12:50 +0100 | [diff] [blame] | 20 | |
| 21 | There are a few main types of track events: |
| 22 | |
| 23 | - **Slices**, which represent nested, time bounded operations. For example, |
| 24 | a slice could cover the time period from when a function begins executing |
| 25 | to when it returns, the time spent loading a file from the network or the |
| 26 | time to complete a user journey. |
| 27 | |
| 28 | - **Counters**, which are snapshots of time-varying numeric values. For |
| 29 | example, a track event can record instantaneous the memory usage of a |
| 30 | process during its execution. |
| 31 | |
| 32 | - **Flows**, which are used to connect related slices that span different |
| 33 | tracks together. For example, if an image file is first loaded from |
| 34 | the network and then decoded on a thread pool, a flow event can be used to |
| 35 | highlight its path through the system. (Not fully implemented yet). |
| 36 | |
| 37 | The [Perfetto UI](https://ui.perfetto.dev) has built in support for track |
| 38 | events, which provides a useful way to quickly visualize the internal |
| 39 | processing of an app. For example, the [Chrome |
| 40 | browser](https://www.chromium.org/developers/how-tos/trace-event-profiling-tool) |
| 41 | is deeply instrumented with track events to assist in debugging, development |
| 42 | and performance analysis. |
| 43 | |
| 44 | To start using track events, first define the set of categories that your events |
| 45 | will fall into. Each category can be separately enabled or disabled for tracing |
| 46 | (see [Category configuration](#category-configuration)). |
| 47 | |
| 48 | Add the list of categories into a header file (e.g., |
| 49 | `my_app_tracing_categories.h`) like this: |
| 50 | |
| 51 | ```C++ |
| 52 | #include <perfetto.h> |
| 53 | |
| 54 | PERFETTO_DEFINE_CATEGORIES( |
| 55 | perfetto::Category("rendering") |
| 56 | .SetDescription("Events from the graphics subsystem"), |
| 57 | perfetto::Category("network") |
| 58 | .SetDescription("Network upload and download statistics")); |
| 59 | ``` |
| 60 | |
| 61 | Then, declare static storage for the categories in a cc file (e.g., |
| 62 | `my_app_tracing_categories.cc`): |
| 63 | |
| 64 | ```C++ |
| 65 | #include "my_app_tracing_categories.h" |
| 66 | |
| 67 | PERFETTO_TRACK_EVENT_STATIC_STORAGE(); |
| 68 | ``` |
| 69 | |
| 70 | Finally, initialize track events after the client library is brought up: |
| 71 | |
| 72 | ```C++ |
Huichun Feng | 89895d0 | 2022-05-21 16:03:55 +0800 | [diff] [blame] | 73 | int main(int argc, char** argv) { |
Primiano Tucci | a662485 | 2020-05-21 19:12:50 +0100 | [diff] [blame] | 74 | ... |
| 75 | perfetto::Tracing::Initialize(args); |
| 76 | perfetto::TrackEvent::Register(); // Add this. |
| 77 | } |
| 78 | ``` |
| 79 | |
| 80 | Now you can add track events to existing functions like this: |
| 81 | |
| 82 | ```C++ |
| 83 | #include "my_app_tracing_categories.h" |
| 84 | |
| 85 | void DrawPlayer() { |
Sami Kyostila | 3d60943 | 2020-06-25 15:59:29 +0100 | [diff] [blame] | 86 | TRACE_EVENT("rendering", "DrawPlayer"); // Begin "DrawPlayer" slice. |
Primiano Tucci | a662485 | 2020-05-21 19:12:50 +0100 | [diff] [blame] | 87 | ... |
Sami Kyostila | 3d60943 | 2020-06-25 15:59:29 +0100 | [diff] [blame] | 88 | // End "DrawPlayer" slice. |
Primiano Tucci | a662485 | 2020-05-21 19:12:50 +0100 | [diff] [blame] | 89 | } |
| 90 | ``` |
| 91 | |
| 92 | This type of trace event is scoped, under the hood it uses C++ [RAII]. The |
| 93 | event will cover the time from when the `TRACE_EVENT` annotation is encountered |
| 94 | to the end of the block (in the example above, until the function returns). |
| 95 | |
Sami Kyostila | 3d60943 | 2020-06-25 15:59:29 +0100 | [diff] [blame] | 96 | For events that don't follow function scoping, use `TRACE_EVENT_BEGIN` and |
| 97 | `TRACE_EVENT_END`: |
| 98 | |
| 99 | ```C++ |
| 100 | void LoadGame() { |
| 101 | DisplayLoadingScreen(); |
| 102 | |
| 103 | TRACE_EVENT_BEGIN("io", "Loading"); // Begin "Loading" slice. |
| 104 | LoadCollectibles(); |
| 105 | LoadVehicles(); |
| 106 | LoadPlayers(); |
| 107 | TRACE_EVENT_END("io"); // End "Loading" slice. |
| 108 | |
| 109 | StartGame(); |
| 110 | } |
| 111 | ``` |
| 112 | |
| 113 | Note that you don't need to give a name for `TRACE_EVENT_END`, since it |
| 114 | automatically closes the most recent event that began on the same thread. In |
| 115 | other words, all events on a given thread share the same stack. This means |
| 116 | that it's not recommended to have a matching pair of `TRACE_EVENT_BEGIN` and |
| 117 | `TRACE_EVENT_END` markers in separate functions, since an unrelated event |
| 118 | might terminate the original event unexpectedly; for events that cross |
| 119 | function boundaries it's usually best to emit them on a [separate |
| 120 | track](#tracks). |
| 121 | |
Primiano Tucci | a662485 | 2020-05-21 19:12:50 +0100 | [diff] [blame] | 122 | You can also supply (up to two) debug annotations together with the event. |
| 123 | |
| 124 | ```C++ |
| 125 | int player_number = 1; |
| 126 | TRACE_EVENT("rendering", "DrawPlayer", "player_number", player_number); |
| 127 | ``` |
| 128 | |
Sami Kyostila | 655fa3d | 2021-03-05 13:11:08 +0000 | [diff] [blame] | 129 | See [below](#track-event-arguments) for the other types of supported track |
| 130 | event arguments. For more complex arguments, you can define [your own |
| 131 | protobuf messages](/protos/perfetto/trace/track_event/track_event.proto) and |
| 132 | emit them as a parameter for the event. |
Primiano Tucci | a662485 | 2020-05-21 19:12:50 +0100 | [diff] [blame] | 133 | |
| 134 | NOTE: Currently custom protobuf messages need to be added directly to the |
| 135 | Perfetto repository under `protos/perfetto/trace`, and Perfetto itself |
| 136 | must also be rebuilt. We are working |
| 137 | [to lift this limitation](https://github.com/google/perfetto/issues/11). |
| 138 | |
| 139 | As an example of a custom track event argument type, save the following as |
| 140 | `protos/perfetto/trace/track_event/player_info.proto`: |
| 141 | |
| 142 | ```protobuf |
| 143 | message PlayerInfo { |
| 144 | optional string name = 1; |
| 145 | optional uint64 score = 2; |
| 146 | } |
| 147 | ``` |
| 148 | |
| 149 | This new file should also be added to |
| 150 | `protos/perfetto/trace/track_event/BUILD.gn`: |
| 151 | |
| 152 | ```json |
| 153 | sources = [ |
| 154 | ... |
| 155 | "player_info.proto" |
| 156 | ] |
| 157 | ``` |
| 158 | |
| 159 | Also, a matching argument should be added to the track event message |
| 160 | definition in |
| 161 | `protos/perfetto/trace/track_event/track_event.proto`: |
| 162 | |
| 163 | ```protobuf |
| 164 | import "protos/perfetto/trace/track_event/player_info.proto"; |
| 165 | |
| 166 | ... |
| 167 | |
| 168 | message TrackEvent { |
| 169 | ... |
| 170 | // New argument types go here. |
| 171 | optional PlayerInfo player_info = 1000; |
| 172 | } |
| 173 | ``` |
| 174 | |
| 175 | The corresponding trace point could look like this: |
| 176 | |
| 177 | ```C++ |
| 178 | Player my_player; |
| 179 | TRACE_EVENT("category", "MyEvent", [&](perfetto::EventContext ctx) { |
| 180 | auto player = ctx.event()->set_player_info(); |
| 181 | player->set_name(my_player.name()); |
| 182 | player->set_player_score(my_player.score()); |
| 183 | }); |
| 184 | ``` |
| 185 | |
| 186 | The lambda function passed to the macro is only called if tracing is enabled for |
| 187 | the given category. It is always called synchronously and possibly multiple |
| 188 | times if multiple concurrent tracing sessions are active. |
| 189 | |
| 190 | Now that you have instrumented your app with track events, you are ready to |
| 191 | start [recording traces](tracing-sdk.md#recording). |
| 192 | |
| 193 | ## Category configuration |
| 194 | |
| 195 | All track events are assigned to one more trace categories. For example: |
| 196 | |
| 197 | ```C++ |
| 198 | TRACE_EVENT("rendering", ...); // Event in the "rendering" category. |
| 199 | ``` |
| 200 | |
| 201 | By default, all non-debug and non-slow track event categories are enabled for |
| 202 | tracing. *Debug* and *slow* categories are categories with special tags: |
| 203 | |
| 204 | - `"debug"` categories can give more verbose debugging output for a particular |
| 205 | subsystem. |
| 206 | - `"slow"` categories record enough data that they can affect the interactive |
| 207 | performance of your app. |
| 208 | |
Huichun Feng | 89895d0 | 2022-05-21 16:03:55 +0800 | [diff] [blame] | 209 | Category tags can be defined like this: |
Primiano Tucci | a662485 | 2020-05-21 19:12:50 +0100 | [diff] [blame] | 210 | |
| 211 | ```C++ |
| 212 | perfetto::Category("rendering.debug") |
| 213 | .SetDescription("Debug events from the graphics subsystem") |
| 214 | .SetTags("debug", "my_custom_tag") |
| 215 | ``` |
| 216 | |
| 217 | A single trace event can also belong to multiple categories: |
| 218 | |
| 219 | ```C++ |
| 220 | // Event in the "rendering" and "benchmark" categories. |
| 221 | TRACE_EVENT("rendering,benchmark", ...); |
| 222 | ``` |
| 223 | |
| 224 | A corresponding category group entry must be added to the category registry: |
| 225 | |
| 226 | ```C++ |
| 227 | perfetto::Category::Group("rendering,benchmark") |
| 228 | ``` |
| 229 | |
| 230 | It's also possible to efficiently query whether a given category is enabled |
| 231 | for tracing: |
| 232 | |
| 233 | ```C++ |
| 234 | if (TRACE_EVENT_CATEGORY_ENABLED("rendering")) { |
| 235 | // ... |
| 236 | } |
| 237 | ``` |
| 238 | |
| 239 | The `TrackEventConfig` field in Perfetto's `TraceConfig` can be used to |
| 240 | select which categories are enabled for tracing: |
| 241 | |
| 242 | ```protobuf |
| 243 | message TrackEventConfig { |
| 244 | // Each list item is a glob. Each category is matched against the lists |
| 245 | // as explained below. |
| 246 | repeated string disabled_categories = 1; // Default: [] |
| 247 | repeated string enabled_categories = 2; // Default: [] |
| 248 | repeated string disabled_tags = 3; // Default: [“slow”, “debug”] |
| 249 | repeated string enabled_tags = 4; // Default: [] |
| 250 | } |
| 251 | ``` |
| 252 | |
| 253 | To determine if a category is enabled, it is checked against the filters in the |
| 254 | following order: |
| 255 | |
| 256 | 1. Exact matches in enabled categories. |
| 257 | 2. Exact matches in enabled tags. |
| 258 | 3. Exact matches in disabled categories. |
| 259 | 4. Exact matches in disabled tags. |
| 260 | 5. Pattern matches in enabled categories. |
| 261 | 6. Pattern matches in enabled tags. |
| 262 | 7. Pattern matches in disabled categories. |
| 263 | 8. Pattern matches in disabled tags. |
| 264 | |
| 265 | If none of the steps produced a match, the category is enabled by default. In |
| 266 | other words, every category is implicitly enabled unless specifically disabled. |
| 267 | For example: |
| 268 | |
| 269 | | Setting | Needed configuration | |
| 270 | | ------------------------------- | -------------------------------------------- | |
| 271 | | Enable just specific categories | `enabled_categories = [“foo”, “bar”, “baz”]` | |
| 272 | | | `disabled_categories = [“*”]` | |
| 273 | | Enable all non-slow categories | (Happens by default.) | |
| 274 | | Enable specific tags | `disabled_tags = [“*”]` | |
| 275 | | | `enabled_tags = [“foo”, “bar”]` | |
| 276 | |
| 277 | ## Dynamic and test-only categories |
| 278 | |
| 279 | Ideally all trace categories should be defined at compile time as shown |
| 280 | above, as this ensures trace points will have minimal runtime and binary size |
| 281 | overhead. However, in some cases trace categories can only be determined at |
| 282 | runtime (e.g., they come from instrumentation in a dynamically loaded JavaScript |
| 283 | running in a WebView or in a NodeJS engine). These can be used by trace points |
| 284 | as follows: |
| 285 | |
| 286 | ```C++ |
| 287 | perfetto::DynamicCategory dynamic_category{"nodejs.something"}; |
Daniele Di Proietto | 860ddee | 2022-11-22 13:58:37 +0000 | [diff] [blame] | 288 | TRACE_EVENT_BEGIN(dynamic_category, "SomeEvent", ...); |
Primiano Tucci | a662485 | 2020-05-21 19:12:50 +0100 | [diff] [blame] | 289 | ``` |
| 290 | |
| 291 | TIP: It's also possible to use dynamic event names by passing `nullptr` as |
| 292 | the name and filling in the `TrackEvent::name` field manually. |
| 293 | |
| 294 | Some trace categories are only useful for testing, and they should not make |
| 295 | it into a production binary. These types of categories can be defined with a |
| 296 | list of prefix strings: |
| 297 | |
| 298 | ```C++ |
| 299 | PERFETTO_DEFINE_TEST_CATEGORY_PREFIXES( |
| 300 | "test", // Applies to test.* |
| 301 | "dontship" // Applies to dontship.*. |
| 302 | ); |
| 303 | ``` |
| 304 | |
Mohit Saini | 6e00031 | 2022-05-31 12:26:28 +0100 | [diff] [blame] | 305 | ## Dynamic event names |
| 306 | |
| 307 | Ideally all event name should be compile time string constants. For example: |
| 308 | |
Primiano Tucci | 8b8e596 | 2022-06-08 19:56:58 +0100 | [diff] [blame] | 309 | ```C++ |
Mohit Saini | 6e00031 | 2022-05-31 12:26:28 +0100 | [diff] [blame] | 310 | TRACE_EVENT_BEGIN("rendering", "DrawGame"); |
| 311 | ``` |
| 312 | |
| 313 | Here `"DrawGame"` is a compile time string. If we pass a dynamic string here, |
| 314 | we will get compile time static_assert failure. For example : |
| 315 | |
| 316 | ```C++ |
| 317 | const char* name = "DrawGame"; |
| 318 | TRACE_EVENT_BEGIN("rendering", name); // Error. Event name is not static. |
| 319 | ``` |
| 320 | |
| 321 | There are two ways to use dynamic event name: |
| 322 | |
| 323 | 1) If the event name is actually dynamic (e.g., std::string), write it using |
Mohit Saini | 8037318 | 2022-07-14 00:16:25 +0100 | [diff] [blame] | 324 | `perfetto::DynamicString`: |
Mohit Saini | 6e00031 | 2022-05-31 12:26:28 +0100 | [diff] [blame] | 325 | |
| 326 | ```C++ |
Mohit Saini | 8037318 | 2022-07-14 00:16:25 +0100 | [diff] [blame] | 327 | TRACE_EVENT("category", perfetto::DynamicString{dynamic_name}); |
Mohit Saini | 6e00031 | 2022-05-31 12:26:28 +0100 | [diff] [blame] | 328 | ``` |
| 329 | |
| 330 | Note: Below is the old way of using dynamic event names. It's not recommended |
| 331 | anymore. |
| 332 | |
| 333 | ```C++ |
| 334 | TRACE_EVENT("category", nullptr, [&](perfetto::EventContext ctx) { |
| 335 | ctx.event()->set_name(dynamic_name); |
| 336 | }); |
| 337 | ``` |
| 338 | |
| 339 | 2) If the name is static, but the pointer is computed at runtime, wrap it |
| 340 | with perfetto::StaticString: |
| 341 | |
| 342 | ```C++ |
| 343 | TRACE_EVENT("category", perfetto::StaticString{name}); |
| 344 | TRACE_EVENT("category", perfetto::StaticString{i % 2 == 0 ? "A" : "B"}); |
| 345 | ``` |
| 346 | |
| 347 | DANGER: Using perfetto::StaticString with strings whose contents change |
| 348 | dynamically can cause silent trace data corruption. |
| 349 | |
Primiano Tucci | a662485 | 2020-05-21 19:12:50 +0100 | [diff] [blame] | 350 | ## Performance |
| 351 | |
| 352 | Perfetto's trace points are designed to have minimal overhead when tracing is |
| 353 | disabled while providing high throughput for data intensive tracing use |
| 354 | cases. While exact timings will depend on your system, there is a |
| 355 | [microbenchmark](/src/tracing/api_benchmark.cc) which gives some ballpark |
| 356 | figures: |
| 357 | |
| 358 | | Scenario | Runtime on Pixel 3 XL | Runtime on ThinkStation P920 | |
| 359 | | -------- | --------------------- | ---------------------------- | |
| 360 | | `TRACE_EVENT(...)` (disabled) | 2 ns | 1 ns | |
| 361 | | `TRACE_EVENT("cat", "name")` | 285 ns | 630 ns | |
| 362 | | `TRACE_EVENT("cat", "name", <lambda>)` | 304 ns | 663 ns | |
| 363 | | `TRACE_EVENT("cat", "name", "key", value)` | 354 ns | 664 ns | |
| 364 | | `DataSource::Trace(<lambda>)` (disabled) | 2 ns | 1 ns | |
| 365 | | `DataSource::Trace(<lambda>)` | 133 ns | 58 ns | |
| 366 | |
| 367 | ## Advanced topics |
| 368 | |
Sami Kyostila | 655fa3d | 2021-03-05 13:11:08 +0000 | [diff] [blame] | 369 | ### Track event arguments |
| 370 | |
| 371 | The following optional arguments can be passed to `TRACE_EVENT` to add extra |
| 372 | information to events: |
| 373 | |
| 374 | ```C++ |
Sami Kyostila | 655fa3d | 2021-03-05 13:11:08 +0000 | [diff] [blame] | 375 | TRACE_EVENT("cat", "name"[, track][, timestamp] |
Alexander Timin | 129bdcf | 2021-04-16 11:36:37 +0000 | [diff] [blame] | 376 | (, "debug_name", debug_value |, TrackEvent::kFieldName, value)* |
| 377 | [, lambda]); |
Sami Kyostila | 655fa3d | 2021-03-05 13:11:08 +0000 | [diff] [blame] | 378 | ``` |
| 379 | |
| 380 | Some examples of valid combinations: |
| 381 | |
| 382 | 1. A lambda for writing custom TrackEvent fields: |
| 383 | |
| 384 | ```C++ |
| 385 | TRACE_EVENT("category", "Name", [&](perfetto::EventContext ctx) { |
| 386 | ctx.event()->set_custom_value(...); |
| 387 | }); |
| 388 | ``` |
| 389 | |
| 390 | 2. A timestamp and a lambda: |
| 391 | |
| 392 | ```C++ |
| 393 | TRACE_EVENT("category", "Name", time_in_nanoseconds, |
| 394 | [&](perfetto::EventContext ctx) { |
| 395 | ctx.event()->set_custom_value(...); |
| 396 | }); |
| 397 | ``` |
| 398 | |
Alexander Timin | 37c8afd | 2021-04-06 18:42:18 +0000 | [diff] [blame] | 399 | |time_in_nanoseconds| should be an uint64_t by default. To support custom |
Alexander Timin | 129bdcf | 2021-04-16 11:36:37 +0000 | [diff] [blame] | 400 | timestamp types, |
Alexander Timin | 37c8afd | 2021-04-06 18:42:18 +0000 | [diff] [blame] | 401 | |perfetto::TraceTimestampTraits<MyTimestamp>::ConvertTimestampToTraceTimeNs| |
| 402 | should be defined. See |ConvertTimestampToTraceTimeNs| for more details. |
Sami Kyostila | 655fa3d | 2021-03-05 13:11:08 +0000 | [diff] [blame] | 403 | |
Alexander Timin | 129c37c | 2021-04-08 19:17:59 +0000 | [diff] [blame] | 404 | 3. Arbitrary number of debug annotations: |
Sami Kyostila | 655fa3d | 2021-03-05 13:11:08 +0000 | [diff] [blame] | 405 | |
| 406 | ```C++ |
| 407 | TRACE_EVENT("category", "Name", "arg", value); |
| 408 | TRACE_EVENT("category", "Name", "arg", value, "arg2", value2); |
Alexander Timin | 129bdcf | 2021-04-16 11:36:37 +0000 | [diff] [blame] | 409 | TRACE_EVENT("category", "Name", "arg", value, "arg2", value2, |
| 410 | "arg3", value3); |
Sami Kyostila | 655fa3d | 2021-03-05 13:11:08 +0000 | [diff] [blame] | 411 | ``` |
| 412 | |
| 413 | See |TracedValue| for recording custom types as debug annotations. |
| 414 | |
Alexander Timin | 129bdcf | 2021-04-16 11:36:37 +0000 | [diff] [blame] | 415 | 4. Arbitrary number of TrackEvent fields (including extensions): |
| 416 | |
| 417 | ```C++ |
| 418 | TRACE_EVENT("category", "Name", |
| 419 | perfetto::protos::pbzero::TrackEvent::kFieldName, value); |
| 420 | ``` |
| 421 | |
| 422 | 5. Arbitrary combination of debug annotations and TrackEvent fields: |
| 423 | |
| 424 | ```C++ |
| 425 | TRACE_EVENT("category", "Name", |
| 426 | perfetto::protos::pbzero::TrackEvent::kFieldName, value1, |
| 427 | "arg", value2); |
| 428 | ``` |
| 429 | |
| 430 | 6. Arbitrary combination of debug annotations / TrackEvent fields and a lambda: |
Alexander Timin | 129c37c | 2021-04-08 19:17:59 +0000 | [diff] [blame] | 431 | |
| 432 | ```C++ |
Alexander Timin | 129bdcf | 2021-04-16 11:36:37 +0000 | [diff] [blame] | 433 | TRACE_EVENT("category", "Name", "arg", value1, |
| 434 | pbzero::TrackEvent::kFieldName, value2, |
| 435 | [&](perfetto::EventContext ctx) { |
| 436 | ctx.event()->set_custom_value(...); |
| 437 | }); |
Alexander Timin | 129c37c | 2021-04-08 19:17:59 +0000 | [diff] [blame] | 438 | ``` |
| 439 | |
Alexander Timin | 129bdcf | 2021-04-16 11:36:37 +0000 | [diff] [blame] | 440 | 7. An overridden track: |
Sami Kyostila | 655fa3d | 2021-03-05 13:11:08 +0000 | [diff] [blame] | 441 | |
| 442 | ```C++ |
| 443 | TRACE_EVENT("category", "Name", perfetto::Track(1234)); |
| 444 | ``` |
| 445 | |
| 446 | See |Track| for other types of tracks which may be used. |
| 447 | |
Alexander Timin | 129bdcf | 2021-04-16 11:36:37 +0000 | [diff] [blame] | 448 | 8. A track and a lambda: |
Sami Kyostila | 655fa3d | 2021-03-05 13:11:08 +0000 | [diff] [blame] | 449 | |
| 450 | ```C++ |
| 451 | TRACE_EVENT("category", "Name", perfetto::Track(1234), |
Alexander Timin | 129bdcf | 2021-04-16 11:36:37 +0000 | [diff] [blame] | 452 | [&](perfetto::EventContext ctx) { |
| 453 | ctx.event()->set_custom_value(...); |
| 454 | }); |
Sami Kyostila | 655fa3d | 2021-03-05 13:11:08 +0000 | [diff] [blame] | 455 | ``` |
| 456 | |
Alexander Timin | 129bdcf | 2021-04-16 11:36:37 +0000 | [diff] [blame] | 457 | 9. A track and a timestamp: |
Sami Kyostila | 655fa3d | 2021-03-05 13:11:08 +0000 | [diff] [blame] | 458 | |
| 459 | ```C++ |
| 460 | TRACE_EVENT("category", "Name", perfetto::Track(1234), |
Alexander Timin | 129bdcf | 2021-04-16 11:36:37 +0000 | [diff] [blame] | 461 | time_in_nanoseconds); |
Sami Kyostila | 655fa3d | 2021-03-05 13:11:08 +0000 | [diff] [blame] | 462 | ``` |
| 463 | |
Alexander Timin | 129bdcf | 2021-04-16 11:36:37 +0000 | [diff] [blame] | 464 | 10. A track, a timestamp and a lambda: |
Sami Kyostila | 655fa3d | 2021-03-05 13:11:08 +0000 | [diff] [blame] | 465 | |
| 466 | ```C++ |
| 467 | TRACE_EVENT("category", "Name", perfetto::Track(1234), |
Alexander Timin | 129bdcf | 2021-04-16 11:36:37 +0000 | [diff] [blame] | 468 | time_in_nanoseconds, [&](perfetto::EventContext ctx) { |
| 469 | ctx.event()->set_custom_value(...); |
| 470 | }); |
Sami Kyostila | 655fa3d | 2021-03-05 13:11:08 +0000 | [diff] [blame] | 471 | ``` |
| 472 | |
Alexander Timin | 129bdcf | 2021-04-16 11:36:37 +0000 | [diff] [blame] | 473 | 11. A track and any combination of debug annotions and TrackEvent fields: |
Sami Kyostila | 655fa3d | 2021-03-05 13:11:08 +0000 | [diff] [blame] | 474 | |
| 475 | ```C++ |
| 476 | TRACE_EVENT("category", "Name", perfetto::Track(1234), |
| 477 | "arg", value); |
| 478 | TRACE_EVENT("category", "Name", perfetto::Track(1234), |
| 479 | "arg", value, "arg2", value2); |
Alexander Timin | 129bdcf | 2021-04-16 11:36:37 +0000 | [diff] [blame] | 480 | TRACE_EVENT("category", "Name", perfetto::Track(1234), |
| 481 | "arg", value, "arg2", value2, |
| 482 | pbzero::TrackEvent::kFieldName, value3); |
Sami Kyostila | 655fa3d | 2021-03-05 13:11:08 +0000 | [diff] [blame] | 483 | ``` |
| 484 | |
Primiano Tucci | a662485 | 2020-05-21 19:12:50 +0100 | [diff] [blame] | 485 | ### Tracks |
| 486 | |
| 487 | Every track event is associated with a track, which specifies the timeline |
| 488 | the event belongs to. In most cases, a track corresponds to a visual |
| 489 | horizontal track in the Perfetto UI like this: |
| 490 | |
| 491 |  |
| 493 | |
| 494 | Events that describe parallel sequences (e.g., separate |
| 495 | threads) should use separate tracks, while sequential events (e.g., nested |
| 496 | function calls) generally belong on the same track. |
| 497 | |
| 498 | Perfetto supports three kinds of tracks: |
| 499 | |
| 500 | - `Track` – a basic timeline. |
| 501 | |
| 502 | - `ProcessTrack` – a timeline that represents a single process in the system. |
| 503 | |
| 504 | - `ThreadTrack` – a timeline that represents a single thread in the system. |
| 505 | |
| 506 | Tracks can have a parent track, which is used to group related tracks |
| 507 | together. For example, the parent of a `ThreadTrack` is the `ProcessTrack` of |
| 508 | the process the thread belongs to. By default, tracks are grouped under the |
| 509 | current process's `ProcessTrack`. |
| 510 | |
| 511 | A track is identified by a uuid, which must be unique across the entire |
| 512 | recorded trace. To minimize the chances of accidental collisions, the uuids |
| 513 | of child tracks are combined with those of their parents, with each |
| 514 | `ProcessTrack` having a random, per-process uuid. |
| 515 | |
| 516 | By default, track events (e.g., `TRACE_EVENT`) use the `ThreadTrack` for the |
| 517 | calling thread. This can be overridden, for example, to mark events that |
| 518 | begin and end on a different thread: |
| 519 | |
| 520 | ```C++ |
| 521 | void OnNewRequest(size_t request_id) { |
| 522 | // Open a slice when the request came in. |
| 523 | TRACE_EVENT_BEGIN("category", "HandleRequest", perfetto::Track(request_id)); |
| 524 | |
| 525 | // Start a thread to handle the request. |
| 526 | std::thread worker_thread([=] { |
| 527 | // ... produce response ... |
| 528 | |
| 529 | // Close the slice for the request now that we finished handling it. |
| 530 | TRACE_EVENT_END("category", perfetto::Track(request_id)); |
| 531 | }); |
| 532 | ``` |
| 533 | Tracks can also optionally be annotated with metadata: |
| 534 | |
| 535 | ```C++ |
| 536 | auto desc = track.Serialize(); |
| 537 | desc.set_name("MyTrack"); |
| 538 | perfetto::TrackEvent::SetTrackDescriptor(track, desc); |
| 539 | ``` |
| 540 | |
| 541 | Threads and processes can also be named in a similar way, e.g.: |
| 542 | |
| 543 | ```C++ |
| 544 | auto desc = perfetto::ProcessTrack::Current().Serialize(); |
| 545 | desc.mutable_process()->set_process_name("MyProcess"); |
| 546 | perfetto::TrackEvent::SetTrackDescriptor( |
| 547 | perfetto::ProcessTrack::Current(), desc); |
| 548 | ``` |
| 549 | |
| 550 | The metadata remains valid between tracing sessions. To free up data for a |
| 551 | track, call EraseTrackDescriptor: |
| 552 | |
| 553 | ```C++ |
| 554 | perfetto::TrackEvent::EraseTrackDescriptor(track); |
| 555 | ``` |
| 556 | |
Sami Kyostila | edf7c86 | 2021-03-11 13:33:35 +0000 | [diff] [blame] | 557 | ### Counters |
| 558 | |
| 559 | Time-varying numeric data can be recorded with the `TRACE_COUNTER` macro: |
| 560 | |
| 561 | ```C++ |
| 562 | TRACE_COUNTER("category", "MyCounter", 1234.5); |
| 563 | ``` |
| 564 | |
| 565 | This data is displayed as a counter track in the Perfetto UI: |
| 566 | |
| 567 |  |
| 569 | |
| 570 | Both integer and floating point counter values are supported. Counters can |
| 571 | also be annotated with additional information such as units, for example, for |
| 572 | tracking the rendering framerate in terms of frames per second or "fps": |
| 573 | |
| 574 | ```C++ |
| 575 | TRACE_COUNTER("category", perfetto::CounterTrack("Framerate", "fps"), 120); |
| 576 | ``` |
| 577 | |
| 578 | As another example, a memory counter that records bytes but accepts samples |
| 579 | as kilobytes (to reduce trace binary size) can be defined like this: |
| 580 | |
| 581 | ```C++ |
| 582 | perfetto::CounterTrack memory_track = perfetto::CounterTrack("Memory") |
| 583 | .set_unit("bytes") |
| 584 | .set_multiplier(1024); |
| 585 | TRACE_COUNTER("category", memory_track, 4 /* = 4096 bytes */); |
| 586 | ``` |
| 587 | |
| 588 | See |
| 589 | [counter_descriptor.proto]( |
| 590 | /protos/perfetto/trace/track_event/counter_descriptor.proto) for the full set |
| 591 | of attributes for a counter track. |
| 592 | |
| 593 | To record a counter value at a specific point in time (instead of the current |
| 594 | time), you can pass in a custom timestamp: |
| 595 | |
| 596 | ```C++ |
| 597 | // First record the current time and counter value. |
| 598 | uint64_t timestamp = perfetto::TrackEvent::GetTraceTimeNs(); |
| 599 | int64_t value = 1234; |
| 600 | |
| 601 | // Later, emit a sample at that point in time. |
| 602 | TRACE_COUNTER("category", "MyCounter", timestamp, value); |
| 603 | ``` |
| 604 | |
Primiano Tucci | a662485 | 2020-05-21 19:12:50 +0100 | [diff] [blame] | 605 | ### Interning |
| 606 | |
| 607 | Interning can be used to avoid repeating the same constant data (e.g., event |
| 608 | names) throughout the trace. Perfetto automatically performs interning for |
| 609 | most strings passed to `TRACE_EVENT`, but it's also possible to also define |
| 610 | your own types of interned data. |
| 611 | |
| 612 | First, define an interning index for your type. It should map to a specific |
| 613 | field of |
| 614 | [interned_data.proto](/protos/perfetto/trace/interned_data/interned_data.proto) |
| 615 | and specify how the interned data is written into that message when seen for |
| 616 | the first time. |
| 617 | |
| 618 | ```C++ |
| 619 | struct MyInternedData |
| 620 | : public perfetto::TrackEventInternedDataIndex< |
| 621 | MyInternedData, |
| 622 | perfetto::protos::pbzero::InternedData::kMyInternedDataFieldNumber, |
| 623 | const char*> { |
| 624 | static void Add(perfetto::protos::pbzero::InternedData* interned_data, |
| 625 | size_t iid, |
| 626 | const char* value) { |
| 627 | auto my_data = interned_data->add_my_interned_data(); |
| 628 | my_data->set_iid(iid); |
| 629 | my_data->set_value(value); |
| 630 | } |
| 631 | }; |
| 632 | ``` |
| 633 | |
| 634 | Next, use your interned data in a trace point as shown below. The interned |
| 635 | string will only be emitted the first time the trace point is hit (unless the |
| 636 | trace buffer has wrapped around). |
| 637 | |
| 638 | ```C++ |
| 639 | TRACE_EVENT( |
| 640 | "category", "Event", [&](perfetto::EventContext ctx) { |
| 641 | auto my_message = ctx.event()->set_my_message(); |
| 642 | size_t iid = MyInternedData::Get(&ctx, "Repeated data to be interned"); |
| 643 | my_message->set_iid(iid); |
| 644 | }); |
| 645 | ``` |
| 646 | |
| 647 | Note that interned data is strongly typed, i.e., each class of interned data |
| 648 | uses a separate namespace for identifiers. |
| 649 | |
Sami Kyostila | 2778ac8 | 2020-12-21 16:12:27 +0000 | [diff] [blame] | 650 | ### Tracing session observers |
| 651 | |
| 652 | The session observer interface allows applications to be notified when track |
| 653 | event tracing starts and stops: |
| 654 | |
| 655 | ```C++ |
| 656 | class Observer : public perfetto::TrackEventSessionObserver { |
| 657 | public: |
| 658 | ~Observer() override = default; |
| 659 | |
| 660 | void OnSetup(const perfetto::DataSourceBase::SetupArgs&) override { |
| 661 | // Called when tracing session is configured. Note tracing isn't active yet, |
| 662 | // so track events emitted here won't be recorded. |
| 663 | } |
| 664 | |
Sami Kyostila | 66905a6 | 2021-04-09 15:52:59 +0100 | [diff] [blame] | 665 | void OnStart(const perfetto::DataSourceBase::StartArgs&) override { |
Sami Kyostila | 2778ac8 | 2020-12-21 16:12:27 +0000 | [diff] [blame] | 666 | // Called when a tracing session is started. It is possible to emit track |
| 667 | // events from this callback. |
| 668 | } |
| 669 | |
Sami Kyostila | 66905a6 | 2021-04-09 15:52:59 +0100 | [diff] [blame] | 670 | void OnStop(const perfetto::DataSourceBase::StopArgs&) override { |
Sami Kyostila | 2778ac8 | 2020-12-21 16:12:27 +0000 | [diff] [blame] | 671 | // Called when a tracing session is stopped. It is still possible to emit |
| 672 | // track events from this callback. |
| 673 | } |
| 674 | }; |
| 675 | ``` |
| 676 | |
| 677 | Note that all methods of the interface are called on an internal Perfetto |
| 678 | thread. |
| 679 | |
| 680 | For example, here's how to wait for any tracing session to start: |
| 681 | |
| 682 | ```C++ |
| 683 | class Observer : public perfetto::TrackEventSessionObserver { |
| 684 | public: |
| 685 | Observer() { perfetto::TrackEvent::AddSessionObserver(this); } |
| 686 | ~Observer() { perfetto::TrackEvent::RemoveSessionObserver(this); } |
| 687 | |
| 688 | void OnStart(const perfetto::DataSourceBase::StartArgs&) override { |
| 689 | std::unique_lock<std::mutex> lock(mutex); |
| 690 | cv.notify_one(); |
| 691 | } |
| 692 | |
| 693 | void WaitForTracingStart() { |
| 694 | printf("Waiting for tracing to start...\n"); |
| 695 | std::unique_lock<std::mutex> lock(mutex); |
| 696 | cv.wait(lock, [] { return perfetto::TrackEvent::IsEnabled(); }); |
| 697 | printf("Tracing started\n"); |
| 698 | } |
| 699 | |
| 700 | std::mutex mutex; |
| 701 | std::condition_variable cv; |
| 702 | }; |
| 703 | |
| 704 | Observer observer; |
| 705 | observer.WaitForTracingToStart(); |
| 706 | ``` |
| 707 | |
Alexander Timin | 37c8afd | 2021-04-06 18:42:18 +0000 | [diff] [blame] | 708 | [RAII]: https://en.cppreference.com/w/cpp/language/raii |