blob: d11e0ab2855836b039df9750de82e989e5748c22 [file] [log] [blame] [view]
Primiano Tuccia6624852020-05-21 19:12:50 +01001# Track events (Tracing SDK)
2
3Track 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
7with a *track*, which is a timeline of monotonically increasing time. A track
8corresponds to an independent sequence of execution, such as a single thread
9in a process.
10
11![Track events shown in the Perfetto UI](
12 /docs/images/track-events.png "Track events in the Perfetto UI")
13
14See the [Getting started](/docs/instrumentation/tracing-sdk#getting-started)
15section of the Tracing SDK page for instructions on how to check out and
16build the SDK.
17
Sami Kyostila2778ac82020-12-21 16:12:27 +000018TIP: The code from these examples is also available [in the
19repository](/examples/sdk/README.md).
Primiano Tuccia6624852020-05-21 19:12:50 +010020
21There 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
37The [Perfetto UI](https://ui.perfetto.dev) has built in support for track
38events, which provides a useful way to quickly visualize the internal
39processing of an app. For example, the [Chrome
40browser](https://www.chromium.org/developers/how-tos/trace-event-profiling-tool)
41is deeply instrumented with track events to assist in debugging, development
42and performance analysis.
43
44To start using track events, first define the set of categories that your events
45will fall into. Each category can be separately enabled or disabled for tracing
46(see [Category configuration](#category-configuration)).
47
48Add 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
54PERFETTO_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
61Then, 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
67PERFETTO_TRACK_EVENT_STATIC_STORAGE();
68```
69
70Finally, initialize track events after the client library is brought up:
71
72```C++
73int main(int argv, char** argc) {
74 ...
75 perfetto::Tracing::Initialize(args);
76 perfetto::TrackEvent::Register(); // Add this.
77}
78```
79
80Now you can add track events to existing functions like this:
81
82```C++
83#include "my_app_tracing_categories.h"
84
85void DrawPlayer() {
Sami Kyostila3d609432020-06-25 15:59:29 +010086 TRACE_EVENT("rendering", "DrawPlayer"); // Begin "DrawPlayer" slice.
Primiano Tuccia6624852020-05-21 19:12:50 +010087 ...
Sami Kyostila3d609432020-06-25 15:59:29 +010088 // End "DrawPlayer" slice.
Primiano Tuccia6624852020-05-21 19:12:50 +010089}
90```
91
92This type of trace event is scoped, under the hood it uses C++ [RAII]. The
93event will cover the time from when the `TRACE_EVENT` annotation is encountered
94to the end of the block (in the example above, until the function returns).
95
Sami Kyostila3d609432020-06-25 15:59:29 +010096For events that don't follow function scoping, use `TRACE_EVENT_BEGIN` and
97`TRACE_EVENT_END`:
98
99```C++
100void 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
113Note that you don't need to give a name for `TRACE_EVENT_END`, since it
114automatically closes the most recent event that began on the same thread. In
115other words, all events on a given thread share the same stack. This means
116that 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
118might terminate the original event unexpectedly; for events that cross
119function boundaries it's usually best to emit them on a [separate
120track](#tracks).
121
Primiano Tuccia6624852020-05-21 19:12:50 +0100122You can also supply (up to two) debug annotations together with the event.
123
124```C++
125int player_number = 1;
126TRACE_EVENT("rendering", "DrawPlayer", "player_number", player_number);
127```
128
Sami Kyostila655fa3d2021-03-05 13:11:08 +0000129See [below](#track-event-arguments) for the other types of supported track
130event arguments. For more complex arguments, you can define [your own
131protobuf messages](/protos/perfetto/trace/track_event/track_event.proto) and
132emit them as a parameter for the event.
Primiano Tuccia6624852020-05-21 19:12:50 +0100133
134NOTE: 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
139As 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
143message PlayerInfo {
144 optional string name = 1;
145 optional uint64 score = 2;
146}
147```
148
149This new file should also be added to
150`protos/perfetto/trace/track_event/BUILD.gn`:
151
152```json
153sources = [
154 ...
155 "player_info.proto"
156]
157```
158
159Also, a matching argument should be added to the track event message
160definition in
161`protos/perfetto/trace/track_event/track_event.proto`:
162
163```protobuf
164import "protos/perfetto/trace/track_event/player_info.proto";
165
166...
167
168message TrackEvent {
169 ...
170 // New argument types go here.
171 optional PlayerInfo player_info = 1000;
172}
173```
174
175The corresponding trace point could look like this:
176
177```C++
178Player my_player;
179TRACE_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
186The lambda function passed to the macro is only called if tracing is enabled for
187the given category. It is always called synchronously and possibly multiple
188times if multiple concurrent tracing sessions are active.
189
190Now that you have instrumented your app with track events, you are ready to
191start [recording traces](tracing-sdk.md#recording).
192
193## Category configuration
194
195All track events are assigned to one more trace categories. For example:
196
197```C++
198TRACE_EVENT("rendering", ...); // Event in the "rendering" category.
199```
200
201By default, all non-debug and non-slow track event categories are enabled for
202tracing. *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
209Category tags can be can be defined like this:
210
211```C++
212perfetto::Category("rendering.debug")
213 .SetDescription("Debug events from the graphics subsystem")
214 .SetTags("debug", "my_custom_tag")
215```
216
217A single trace event can also belong to multiple categories:
218
219```C++
220// Event in the "rendering" and "benchmark" categories.
221TRACE_EVENT("rendering,benchmark", ...);
222```
223
224A corresponding category group entry must be added to the category registry:
225
226```C++
227perfetto::Category::Group("rendering,benchmark")
228```
229
230It's also possible to efficiently query whether a given category is enabled
231for tracing:
232
233```C++
234if (TRACE_EVENT_CATEGORY_ENABLED("rendering")) {
235 // ...
236}
237```
238
239The `TrackEventConfig` field in Perfetto's `TraceConfig` can be used to
240select which categories are enabled for tracing:
241
242```protobuf
243message 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
253To determine if a category is enabled, it is checked against the filters in the
254following order:
255
2561. Exact matches in enabled categories.
2572. Exact matches in enabled tags.
2583. Exact matches in disabled categories.
2594. Exact matches in disabled tags.
2605. Pattern matches in enabled categories.
2616. Pattern matches in enabled tags.
2627. Pattern matches in disabled categories.
2638. Pattern matches in disabled tags.
264
265If none of the steps produced a match, the category is enabled by default. In
266other words, every category is implicitly enabled unless specifically disabled.
267For 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
279Ideally all trace categories should be defined at compile time as shown
280above, as this ensures trace points will have minimal runtime and binary size
281overhead. However, in some cases trace categories can only be determined at
282runtime (e.g., they come from instrumentation in a dynamically loaded JavaScript
283running in a WebView or in a NodeJS engine). These can be used by trace points
284as follows:
285
286```C++
287perfetto::DynamicCategory dynamic_category{"nodejs.something"};
288TRACE_EVENT(dynamic_category, "SomeEvent", ...);
289```
290
291TIP: 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
294Some trace categories are only useful for testing, and they should not make
295it into a production binary. These types of categories can be defined with a
296list of prefix strings:
297
298```C++
299PERFETTO_DEFINE_TEST_CATEGORY_PREFIXES(
300 "test", // Applies to test.*
301 "dontship" // Applies to dontship.*.
302);
303```
304
305## Performance
306
307Perfetto's trace points are designed to have minimal overhead when tracing is
308disabled while providing high throughput for data intensive tracing use
309cases. While exact timings will depend on your system, there is a
310[microbenchmark](/src/tracing/api_benchmark.cc) which gives some ballpark
311figures:
312
313| Scenario | Runtime on Pixel 3 XL | Runtime on ThinkStation P920 |
314| -------- | --------------------- | ---------------------------- |
315| `TRACE_EVENT(...)` (disabled) | 2 ns | 1 ns |
316| `TRACE_EVENT("cat", "name")` | 285 ns | 630 ns |
317| `TRACE_EVENT("cat", "name", <lambda>)` | 304 ns | 663 ns |
318| `TRACE_EVENT("cat", "name", "key", value)` | 354 ns | 664 ns |
319| `DataSource::Trace(<lambda>)` (disabled) | 2 ns | 1 ns |
320| `DataSource::Trace(<lambda>)` | 133 ns | 58 ns |
321
322## Advanced topics
323
Sami Kyostila655fa3d2021-03-05 13:11:08 +0000324### Track event arguments
325
326The following optional arguments can be passed to `TRACE_EVENT` to add extra
327information to events:
328
329```C++
Sami Kyostila655fa3d2021-03-05 13:11:08 +0000330TRACE_EVENT("cat", "name"[, track][, timestamp]
331 [, "debug_name1", debug_value1]
Alexander Timin129c37c2021-04-08 19:17:59 +0000332 [, "debug_name2", debug_value2]
333 ...
334 [, "debug_nameN", debug_valueN]
335 [, lambda]);
Sami Kyostila655fa3d2021-03-05 13:11:08 +0000336```
337
338Some examples of valid combinations:
339
3401. A lambda for writing custom TrackEvent fields:
341
342 ```C++
343 TRACE_EVENT("category", "Name", [&](perfetto::EventContext ctx) {
344 ctx.event()->set_custom_value(...);
345 });
346 ```
347
3482. A timestamp and a lambda:
349
350 ```C++
351 TRACE_EVENT("category", "Name", time_in_nanoseconds,
352 [&](perfetto::EventContext ctx) {
353 ctx.event()->set_custom_value(...);
354 });
355 ```
356
Alexander Timin37c8afd2021-04-06 18:42:18 +0000357 |time_in_nanoseconds| should be an uint64_t by default. To support custom
358 timestamp types,
359 |perfetto::TraceTimestampTraits<MyTimestamp>::ConvertTimestampToTraceTimeNs|
360 should be defined. See |ConvertTimestampToTraceTimeNs| for more details.
Sami Kyostila655fa3d2021-03-05 13:11:08 +0000361
Alexander Timin129c37c2021-04-08 19:17:59 +00003623. Arbitrary number of debug annotations:
Sami Kyostila655fa3d2021-03-05 13:11:08 +0000363
364 ```C++
365 TRACE_EVENT("category", "Name", "arg", value);
366 TRACE_EVENT("category", "Name", "arg", value, "arg2", value2);
Alexander Timin129c37c2021-04-08 19:17:59 +0000367 TRACE_EVENT("category", "Name", "arg", value, "arg2", value2,
368 "arg3", value3);
Sami Kyostila655fa3d2021-03-05 13:11:08 +0000369 ```
370
371 See |TracedValue| for recording custom types as debug annotations.
372
Alexander Timin129c37c2021-04-08 19:17:59 +00003734. Arbitrary number of debug annotations and a lambda:
374
375 ```C++
376 TRACE_EVENT("category", "Name", "arg", value,
377 [&](perfetto::EventContext ctx) {
378 ctx.event()->set_custom_value(...);
379 });
380 ```
381
3825. An overridden track:
Sami Kyostila655fa3d2021-03-05 13:11:08 +0000383
384 ```C++
385 TRACE_EVENT("category", "Name", perfetto::Track(1234));
386 ```
387
388 See |Track| for other types of tracks which may be used.
389
Alexander Timin129c37c2021-04-08 19:17:59 +00003906. A track and a lambda:
Sami Kyostila655fa3d2021-03-05 13:11:08 +0000391
392 ```C++
393 TRACE_EVENT("category", "Name", perfetto::Track(1234),
394 [&](perfetto::EventContext ctx) {
395 ctx.event()->set_custom_value(...);
396 });
397 ```
398
Alexander Timin129c37c2021-04-08 19:17:59 +00003997. A track and a timestamp:
Sami Kyostila655fa3d2021-03-05 13:11:08 +0000400
401 ```C++
402 TRACE_EVENT("category", "Name", perfetto::Track(1234),
403 time_in_nanoseconds);
404 ```
405
Alexander Timin129c37c2021-04-08 19:17:59 +00004068. A track, a timestamp and a lambda:
Sami Kyostila655fa3d2021-03-05 13:11:08 +0000407
408 ```C++
409 TRACE_EVENT("category", "Name", perfetto::Track(1234),
410 time_in_nanoseconds, [&](perfetto::EventContext ctx) {
411 ctx.event()->set_custom_value(...);
412 });
413 ```
414
Alexander Timin129c37c2021-04-08 19:17:59 +00004159. A track and an arbitrary number of debug annotions:
Sami Kyostila655fa3d2021-03-05 13:11:08 +0000416
417 ```C++
418 TRACE_EVENT("category", "Name", perfetto::Track(1234),
419 "arg", value);
420 TRACE_EVENT("category", "Name", perfetto::Track(1234),
421 "arg", value, "arg2", value2);
422 ```
423
Primiano Tuccia6624852020-05-21 19:12:50 +0100424### Tracks
425
426Every track event is associated with a track, which specifies the timeline
427the event belongs to. In most cases, a track corresponds to a visual
428horizontal track in the Perfetto UI like this:
429
430![Track timelines shown in the Perfetto UI](
431 /docs/images/track-timeline.png "Track timelines in the Perfetto UI")
432
433Events that describe parallel sequences (e.g., separate
434threads) should use separate tracks, while sequential events (e.g., nested
435function calls) generally belong on the same track.
436
437Perfetto supports three kinds of tracks:
438
439- `Track` – a basic timeline.
440
441- `ProcessTrack` – a timeline that represents a single process in the system.
442
443- `ThreadTrack` – a timeline that represents a single thread in the system.
444
445Tracks can have a parent track, which is used to group related tracks
446together. For example, the parent of a `ThreadTrack` is the `ProcessTrack` of
447the process the thread belongs to. By default, tracks are grouped under the
448current process's `ProcessTrack`.
449
450A track is identified by a uuid, which must be unique across the entire
451recorded trace. To minimize the chances of accidental collisions, the uuids
452of child tracks are combined with those of their parents, with each
453`ProcessTrack` having a random, per-process uuid.
454
455By default, track events (e.g., `TRACE_EVENT`) use the `ThreadTrack` for the
456calling thread. This can be overridden, for example, to mark events that
457begin and end on a different thread:
458
459```C++
460void OnNewRequest(size_t request_id) {
461 // Open a slice when the request came in.
462 TRACE_EVENT_BEGIN("category", "HandleRequest", perfetto::Track(request_id));
463
464 // Start a thread to handle the request.
465 std::thread worker_thread([=] {
466 // ... produce response ...
467
468 // Close the slice for the request now that we finished handling it.
469 TRACE_EVENT_END("category", perfetto::Track(request_id));
470 });
471```
472Tracks can also optionally be annotated with metadata:
473
474```C++
475auto desc = track.Serialize();
476desc.set_name("MyTrack");
477perfetto::TrackEvent::SetTrackDescriptor(track, desc);
478```
479
480Threads and processes can also be named in a similar way, e.g.:
481
482```C++
483auto desc = perfetto::ProcessTrack::Current().Serialize();
484desc.mutable_process()->set_process_name("MyProcess");
485perfetto::TrackEvent::SetTrackDescriptor(
486 perfetto::ProcessTrack::Current(), desc);
487```
488
489The metadata remains valid between tracing sessions. To free up data for a
490track, call EraseTrackDescriptor:
491
492```C++
493perfetto::TrackEvent::EraseTrackDescriptor(track);
494```
495
Sami Kyostilaedf7c862021-03-11 13:33:35 +0000496### Counters
497
498Time-varying numeric data can be recorded with the `TRACE_COUNTER` macro:
499
500```C++
501TRACE_COUNTER("category", "MyCounter", 1234.5);
502```
503
504This data is displayed as a counter track in the Perfetto UI:
505
506![A counter track shown in the Perfetto UI](
507 /docs/images/counter-events.png "A counter track shown in the Perfetto UI")
508
509Both integer and floating point counter values are supported. Counters can
510also be annotated with additional information such as units, for example, for
511tracking the rendering framerate in terms of frames per second or "fps":
512
513```C++
514TRACE_COUNTER("category", perfetto::CounterTrack("Framerate", "fps"), 120);
515```
516
517As another example, a memory counter that records bytes but accepts samples
518as kilobytes (to reduce trace binary size) can be defined like this:
519
520```C++
521perfetto::CounterTrack memory_track = perfetto::CounterTrack("Memory")
522 .set_unit("bytes")
523 .set_multiplier(1024);
524TRACE_COUNTER("category", memory_track, 4 /* = 4096 bytes */);
525```
526
527See
528[counter_descriptor.proto](
529/protos/perfetto/trace/track_event/counter_descriptor.proto) for the full set
530of attributes for a counter track.
531
532To record a counter value at a specific point in time (instead of the current
533time), you can pass in a custom timestamp:
534
535```C++
536// First record the current time and counter value.
537uint64_t timestamp = perfetto::TrackEvent::GetTraceTimeNs();
538int64_t value = 1234;
539
540// Later, emit a sample at that point in time.
541TRACE_COUNTER("category", "MyCounter", timestamp, value);
542```
543
Primiano Tuccia6624852020-05-21 19:12:50 +0100544### Interning
545
546Interning can be used to avoid repeating the same constant data (e.g., event
547names) throughout the trace. Perfetto automatically performs interning for
548most strings passed to `TRACE_EVENT`, but it's also possible to also define
549your own types of interned data.
550
551First, define an interning index for your type. It should map to a specific
552field of
553[interned_data.proto](/protos/perfetto/trace/interned_data/interned_data.proto)
554and specify how the interned data is written into that message when seen for
555the first time.
556
557```C++
558struct MyInternedData
559 : public perfetto::TrackEventInternedDataIndex<
560 MyInternedData,
561 perfetto::protos::pbzero::InternedData::kMyInternedDataFieldNumber,
562 const char*> {
563 static void Add(perfetto::protos::pbzero::InternedData* interned_data,
564 size_t iid,
565 const char* value) {
566 auto my_data = interned_data->add_my_interned_data();
567 my_data->set_iid(iid);
568 my_data->set_value(value);
569 }
570};
571```
572
573Next, use your interned data in a trace point as shown below. The interned
574string will only be emitted the first time the trace point is hit (unless the
575trace buffer has wrapped around).
576
577```C++
578TRACE_EVENT(
579 "category", "Event", [&](perfetto::EventContext ctx) {
580 auto my_message = ctx.event()->set_my_message();
581 size_t iid = MyInternedData::Get(&ctx, "Repeated data to be interned");
582 my_message->set_iid(iid);
583 });
584```
585
586Note that interned data is strongly typed, i.e., each class of interned data
587uses a separate namespace for identifiers.
588
Sami Kyostila2778ac82020-12-21 16:12:27 +0000589### Tracing session observers
590
591The session observer interface allows applications to be notified when track
592event tracing starts and stops:
593
594```C++
595class Observer : public perfetto::TrackEventSessionObserver {
596 public:
597 ~Observer() override = default;
598
599 void OnSetup(const perfetto::DataSourceBase::SetupArgs&) override {
600 // Called when tracing session is configured. Note tracing isn't active yet,
601 // so track events emitted here won't be recorded.
602 }
603
604 void OnStart(const DataSourceBase::SetupArgs&) override {
605 // Called when a tracing session is started. It is possible to emit track
606 // events from this callback.
607 }
608
609 void OnStop(const DataSourceBase::StartArgs&) override {
610 // Called when a tracing session is stopped. It is still possible to emit
611 // track events from this callback.
612 }
613};
614```
615
616Note that all methods of the interface are called on an internal Perfetto
617thread.
618
619For example, here's how to wait for any tracing session to start:
620
621```C++
622class Observer : public perfetto::TrackEventSessionObserver {
623 public:
624 Observer() { perfetto::TrackEvent::AddSessionObserver(this); }
625 ~Observer() { perfetto::TrackEvent::RemoveSessionObserver(this); }
626
627 void OnStart(const perfetto::DataSourceBase::StartArgs&) override {
628 std::unique_lock<std::mutex> lock(mutex);
629 cv.notify_one();
630 }
631
632 void WaitForTracingStart() {
633 printf("Waiting for tracing to start...\n");
634 std::unique_lock<std::mutex> lock(mutex);
635 cv.wait(lock, [] { return perfetto::TrackEvent::IsEnabled(); });
636 printf("Tracing started\n");
637 }
638
639 std::mutex mutex;
640 std::condition_variable cv;
641};
642
643Observer observer;
644observer.WaitForTracingToStart();
645```
646
Alexander Timin37c8afd2021-04-06 18:42:18 +0000647[RAII]: https://en.cppreference.com/w/cpp/language/raii