1 /*
2 * Copyright (C) 2019 The Android Open Source Project
3 *
4 * Licensed under the Apache License, Version 2.0 (the "License");
5 * you may not use this file except in compliance with the License.
6 * You may obtain a copy of the License at
7 *
8 * http://www.apache.org/licenses/LICENSE-2.0
9 *
10 * Unless required by applicable law or agreed to in writing, software
11 * distributed under the License is distributed on an "AS IS" BASIS,
12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13 * See the License for the specific language governing permissions and
14 * limitations under the License.
15 */
16
17 #include <fcntl.h>
18
19 #include <chrono>
20 #include <condition_variable>
21 #include <fstream>
22 #include <functional>
23 #include <list>
24 #include <mutex>
25 #include <regex>
26 #include <thread>
27 #include <unordered_set>
28 #include <vector>
29
30 // We also want to test legacy trace events.
31 #define PERFETTO_ENABLE_LEGACY_TRACE_EVENTS 1
32
33 #include "perfetto/tracing.h"
34 #include "test/gtest_and_gmock.h"
35
36 #if PERFETTO_BUILDFLAG(PERFETTO_OS_WIN)
37 #include <Windows.h> // For CreateFile().
38 #endif
39
40 // Deliberately not pulling any non-public perfetto header to spot accidental
41 // header public -> non-public dependency while building this file.
42
43 // These two are the only headers allowed here, see comments in
44 // api_test_support.h.
45 #include "src/tracing/test/api_test_support.h"
46 #include "src/tracing/test/tracing_module.h"
47
48 #include "perfetto/protozero/scattered_heap_buffer.h"
49 #include "perfetto/tracing/core/data_source_descriptor.h"
50 #include "perfetto/tracing/core/trace_config.h"
51
52 // xxx.pbzero.h includes are for the writing path (the code that pretends to be
53 // production code).
54 // yyy.gen.h includes are for the test readback path (the code in the test that
55 // checks that the results are valid).
56 #include "protos/perfetto/common/builtin_clock.pbzero.h"
57 #include "protos/perfetto/common/interceptor_descriptor.gen.h"
58 #include "protos/perfetto/common/trace_stats.gen.h"
59 #include "protos/perfetto/common/tracing_service_state.gen.h"
60 #include "protos/perfetto/common/track_event_descriptor.gen.h"
61 #include "protos/perfetto/common/track_event_descriptor.pbzero.h"
62 #include "protos/perfetto/config/interceptor_config.gen.h"
63 #include "protos/perfetto/config/track_event/track_event_config.gen.h"
64 #include "protos/perfetto/trace/clock_snapshot.gen.h"
65 #include "protos/perfetto/trace/clock_snapshot.pbzero.h"
66 #include "protos/perfetto/trace/gpu/gpu_render_stage_event.gen.h"
67 #include "protos/perfetto/trace/gpu/gpu_render_stage_event.pbzero.h"
68 #include "protos/perfetto/trace/interned_data/interned_data.gen.h"
69 #include "protos/perfetto/trace/interned_data/interned_data.pbzero.h"
70 #include "protos/perfetto/trace/profiling/profile_common.gen.h"
71 #include "protos/perfetto/trace/test_event.gen.h"
72 #include "protos/perfetto/trace/test_event.pbzero.h"
73 #include "protos/perfetto/trace/test_extensions.pbzero.h"
74 #include "protos/perfetto/trace/trace.gen.h"
75 #include "protos/perfetto/trace/trace.pbzero.h"
76 #include "protos/perfetto/trace/trace_packet.gen.h"
77 #include "protos/perfetto/trace/trace_packet.pbzero.h"
78 #include "protos/perfetto/trace/trace_packet_defaults.gen.h"
79 #include "protos/perfetto/trace/track_event/chrome_process_descriptor.gen.h"
80 #include "protos/perfetto/trace/track_event/chrome_process_descriptor.pbzero.h"
81 #include "protos/perfetto/trace/track_event/counter_descriptor.gen.h"
82 #include "protos/perfetto/trace/track_event/debug_annotation.gen.h"
83 #include "protos/perfetto/trace/track_event/debug_annotation.pbzero.h"
84 #include "protos/perfetto/trace/track_event/log_message.gen.h"
85 #include "protos/perfetto/trace/track_event/log_message.pbzero.h"
86 #include "protos/perfetto/trace/track_event/process_descriptor.gen.h"
87 #include "protos/perfetto/trace/track_event/process_descriptor.pbzero.h"
88 #include "protos/perfetto/trace/track_event/source_location.gen.h"
89 #include "protos/perfetto/trace/track_event/source_location.pbzero.h"
90 #include "protos/perfetto/trace/track_event/thread_descriptor.gen.h"
91 #include "protos/perfetto/trace/track_event/thread_descriptor.pbzero.h"
92 #include "protos/perfetto/trace/track_event/track_descriptor.gen.h"
93 #include "protos/perfetto/trace/track_event/track_event.gen.h"
94
95 // Events in categories starting with "dynamic" will use dynamic category
96 // lookup.
97 PERFETTO_DEFINE_TEST_CATEGORY_PREFIXES("dynamic");
98
99 // Trace categories used in the tests.
100 PERFETTO_DEFINE_CATEGORIES(
101 perfetto::Category("test")
102 .SetDescription("This is a test category")
103 .SetTags("tag"),
104 perfetto::Category("foo"),
105 perfetto::Category("bar"),
106 perfetto::Category("cat").SetTags("slow"),
107 perfetto::Category("cat.verbose").SetTags("debug"),
108 perfetto::Category("cat-with-dashes"),
109 perfetto::Category::Group("foo,bar"),
110 perfetto::Category::Group("baz,bar,quux"),
111 perfetto::Category::Group("red,green,blue,foo"),
112 perfetto::Category::Group("red,green,blue,yellow"),
113 perfetto::Category(TRACE_DISABLED_BY_DEFAULT("cat")));
114 PERFETTO_TRACK_EVENT_STATIC_STORAGE();
115
116 // For testing interning of complex objects.
117 using SourceLocation = std::tuple<const char* /* file_name */,
118 const char* /* function_name */,
119 uint32_t /* line_number */>;
120
121 template <>
122 struct std::hash<SourceLocation> {
operator ()std::hash123 size_t operator()(const SourceLocation& value) const {
124 auto hasher = hash<size_t>();
125 return hasher(reinterpret_cast<size_t>(get<0>(value))) ^
126 hasher(reinterpret_cast<size_t>(get<1>(value))) ^
127 hasher(get<2>(value));
128 }
129 };
130
WriteFile(const std::string & file_name,const char * content,size_t len)131 static void WriteFile(const std::string& file_name,
132 const char* content,
133 size_t len) {
134 std::ofstream output;
135 output.open(file_name.c_str(), std::ios::out | std::ios::binary);
136 output.write(content, static_cast<std::streamsize>(len));
137 output.close();
138 }
139
140 // Unused in merged code, but very handy for debugging when trace generated in
141 // a test needs to be exported, to understand it further with other tools.
WriteFile(const std::string & file_name,const std::vector<char> & data)142 __attribute__((unused)) static void WriteFile(const std::string& file_name,
143 const std::vector<char>& data) {
144 return WriteFile(file_name, data.data(), data.size());
145 }
146
147 // Represents an opaque (from Perfetto's point of view) thread identifier (e.g.,
148 // base::PlatformThreadId in Chromium).
149 struct MyThreadId {
MyThreadIdMyThreadId150 explicit MyThreadId(int tid_) : tid(tid_) {}
151
152 const int tid = 0;
153 };
154
155 // Represents an opaque timestamp (e.g., base::TimeTicks in Chromium).
156 class MyTimestamp {
157 public:
MyTimestamp(uint64_t ts_)158 explicit MyTimestamp(uint64_t ts_) : ts(ts_) {}
159
160 const uint64_t ts;
161 };
162
163 namespace perfetto {
164 namespace legacy {
165
166 template <>
ConvertThreadId(const MyThreadId & thread)167 ThreadTrack ConvertThreadId(const MyThreadId& thread) {
168 return perfetto::ThreadTrack::ForThread(
169 static_cast<base::PlatformThreadId>(thread.tid));
170 }
171
172 } // namespace legacy
173
174 template <>
175 struct TraceTimestampTraits<MyTimestamp> {
ConvertTimestampToTraceTimeNsperfetto::TraceTimestampTraits176 static TraceTimestamp ConvertTimestampToTraceTimeNs(
177 const MyTimestamp& timestamp) {
178 return {TrackEvent::GetTraceClockId(), timestamp.ts};
179 }
180 };
181
182 } // namespace perfetto
183
184 namespace {
185
186 using perfetto::TracingInitArgs;
187 using perfetto::internal::TrackEventInternal;
188 using ::testing::_;
189 using ::testing::ContainerEq;
190 using ::testing::ElementsAre;
191 using ::testing::HasSubstr;
192 using ::testing::Invoke;
193 using ::testing::InvokeWithoutArgs;
194 using ::testing::NiceMock;
195 using ::testing::Not;
196 using ::testing::Property;
197 using ::testing::StrEq;
198
199 // ------------------------------
200 // Declarations of helper classes
201 // ------------------------------
202
203 class WaitableTestEvent {
204 public:
notified()205 bool notified() {
206 std::unique_lock<std::mutex> lock(mutex_);
207 return notified_;
208 }
209
Wait()210 void Wait() {
211 std::unique_lock<std::mutex> lock(mutex_);
212 // TSAN gets confused by wait_for, which we would use here in a perfect
213 // world.
214 cv_.wait(lock, [this] { return notified_; });
215 }
216
Notify()217 void Notify() {
218 {
219 std::lock_guard<std::mutex> lock(mutex_);
220 notified_ = true;
221 }
222 // Do not notify while holding the lock, because then we wake up the other
223 // end, only for it to fail to acquire the lock.
224 cv_.notify_one();
225 }
226
227 private:
228 std::mutex mutex_;
229 std::condition_variable cv_;
230 bool notified_ = false;
231 };
232
233 class MockDataSource;
234
235 // We can't easily use gmock here because instances of data sources are lazily
236 // created by the service and are not owned by the test fixture.
237 struct TestDataSourceHandle {
238 WaitableTestEvent on_create;
239 WaitableTestEvent on_setup;
240 WaitableTestEvent on_start;
241 WaitableTestEvent on_stop;
242 MockDataSource* instance;
243 perfetto::DataSourceConfig config;
244 bool handle_stop_asynchronously = false;
245 std::function<void()> on_start_callback;
246 std::function<void()> on_stop_callback;
247 std::function<void()> async_stop_closure;
248 };
249
250 class MockDataSource : public perfetto::DataSource<MockDataSource> {
251 public:
252 void OnSetup(const SetupArgs&) override;
253 void OnStart(const StartArgs&) override;
254 void OnStop(const StopArgs&) override;
255 TestDataSourceHandle* handle_ = nullptr;
256 };
257
258 constexpr int kTestDataSourceArg = 123;
259
260 class MockDataSource2 : public perfetto::DataSource<MockDataSource2> {
261 public:
MockDataSource2(int arg)262 MockDataSource2(int arg) { EXPECT_EQ(arg, kTestDataSourceArg); }
OnSetup(const SetupArgs &)263 void OnSetup(const SetupArgs&) override {}
OnStart(const StartArgs &)264 void OnStart(const StartArgs&) override {}
OnStop(const StopArgs &)265 void OnStop(const StopArgs&) override {}
266 };
267
268 // Used to verify that track event data sources in different namespaces register
269 // themselves correctly in the muxer.
270 class MockTracingMuxer : public perfetto::internal::TracingMuxer {
271 public:
272 struct DataSource {
273 perfetto::DataSourceDescriptor dsd;
274 perfetto::internal::DataSourceStaticState* static_state;
275 };
276
MockTracingMuxer()277 MockTracingMuxer() : TracingMuxer(nullptr), prev_instance_(instance_) {
278 instance_ = this;
279 }
~MockTracingMuxer()280 ~MockTracingMuxer() override { instance_ = prev_instance_; }
281
RegisterDataSource(const perfetto::DataSourceDescriptor & dsd,DataSourceFactory,perfetto::internal::DataSourceStaticState * static_state)282 bool RegisterDataSource(
283 const perfetto::DataSourceDescriptor& dsd,
284 DataSourceFactory,
285 perfetto::internal::DataSourceStaticState* static_state) override {
286 data_sources.emplace_back(DataSource{dsd, static_state});
287 return true;
288 }
289
UpdateDataSourceDescriptor(const perfetto::DataSourceDescriptor & dsd,const perfetto::internal::DataSourceStaticState * static_state)290 void UpdateDataSourceDescriptor(
291 const perfetto::DataSourceDescriptor& dsd,
292 const perfetto::internal::DataSourceStaticState* static_state) override {
293 for (auto& rds : data_sources) {
294 if (rds.static_state == static_state) {
295 rds.dsd = dsd;
296 return;
297 }
298 }
299 }
300
CreateTraceWriter(perfetto::internal::DataSourceStaticState *,uint32_t,perfetto::internal::DataSourceState *,perfetto::BufferExhaustedPolicy)301 std::unique_ptr<perfetto::TraceWriterBase> CreateTraceWriter(
302 perfetto::internal::DataSourceStaticState*,
303 uint32_t,
304 perfetto::internal::DataSourceState*,
305 perfetto::BufferExhaustedPolicy) override {
306 return nullptr;
307 }
308
DestroyStoppedTraceWritersForCurrentThread()309 void DestroyStoppedTraceWritersForCurrentThread() override {}
RegisterInterceptor(const perfetto::InterceptorDescriptor &,InterceptorFactory,perfetto::InterceptorBase::TLSFactory,perfetto::InterceptorBase::TracePacketCallback)310 void RegisterInterceptor(
311 const perfetto::InterceptorDescriptor&,
312 InterceptorFactory,
313 perfetto::InterceptorBase::TLSFactory,
314 perfetto::InterceptorBase::TracePacketCallback) override {}
315
316 std::vector<DataSource> data_sources;
317
318 private:
319 TracingMuxer* prev_instance_;
320 };
321
322 struct TestIncrementalState {
TestIncrementalState__anon22b779c30111::TestIncrementalState323 TestIncrementalState() { constructed = true; }
324 // Note: a virtual destructor is not required for incremental state.
~TestIncrementalState__anon22b779c30111::TestIncrementalState325 ~TestIncrementalState() { destroyed = true; }
326
327 int count = 100;
328 bool flag = false;
329 static bool constructed;
330 static bool destroyed;
331 };
332
333 bool TestIncrementalState::constructed;
334 bool TestIncrementalState::destroyed;
335
336 struct TestIncrementalDataSourceTraits
337 : public perfetto::DefaultDataSourceTraits {
338 using IncrementalStateType = TestIncrementalState;
339 using CustomTlsState = void;
340 };
341
342 class TestIncrementalDataSource
343 : public perfetto::DataSource<TestIncrementalDataSource,
344 TestIncrementalDataSourceTraits> {
345 public:
OnSetup(const SetupArgs &)346 void OnSetup(const SetupArgs&) override {}
OnStart(const StartArgs &)347 void OnStart(const StartArgs&) override {}
OnStop(const StopArgs &)348 void OnStop(const StopArgs&) override {}
349 };
350
351 // A convenience wrapper around TracingSession that allows to do block on
352 //
353 struct TestTracingSessionHandle {
get__anon22b779c30111::TestTracingSessionHandle354 perfetto::TracingSession* get() { return session.get(); }
355 std::unique_ptr<perfetto::TracingSession> session;
356 WaitableTestEvent on_stop;
357 };
358
359 class MyDebugAnnotation : public perfetto::DebugAnnotation {
360 public:
361 ~MyDebugAnnotation() override = default;
362
Add(perfetto::protos::pbzero::DebugAnnotation * annotation) const363 void Add(
364 perfetto::protos::pbzero::DebugAnnotation* annotation) const override {
365 annotation->set_legacy_json_value(R"({"key": 123})");
366 }
367 };
368
369 class TestTracingPolicy : public perfetto::TracingPolicy {
370 public:
ShouldAllowConsumerSession(const ShouldAllowConsumerSessionArgs & args)371 void ShouldAllowConsumerSession(
372 const ShouldAllowConsumerSessionArgs& args) override {
373 EXPECT_NE(args.backend_type, perfetto::BackendType::kUnspecifiedBackend);
374 args.result_callback(should_allow_consumer_connection);
375 }
376
377 bool should_allow_consumer_connection = true;
378 };
379
380 TestTracingPolicy* g_test_tracing_policy = new TestTracingPolicy(); // Leaked.
381
382 class ParsedIncrementalState {
383 public:
ClearIfNeeded(const perfetto::protos::gen::TracePacket & packet)384 void ClearIfNeeded(const perfetto::protos::gen::TracePacket& packet) {
385 if (packet.sequence_flags() &
386 perfetto::protos::pbzero::TracePacket::SEQ_INCREMENTAL_STATE_CLEARED) {
387 incremental_state_was_cleared_ = true;
388 categories_.clear();
389 event_names_.clear();
390 debug_annotation_names_.clear();
391 seen_tracks_.clear();
392 }
393 }
394
Parse(const perfetto::protos::gen::TracePacket & packet)395 void Parse(const perfetto::protos::gen::TracePacket& packet) {
396 // Update incremental state.
397 if (packet.has_interned_data()) {
398 const auto& interned_data = packet.interned_data();
399 for (const auto& it : interned_data.event_categories()) {
400 EXPECT_EQ(categories_.find(it.iid()), categories_.end());
401 categories_[it.iid()] = it.name();
402 }
403 for (const auto& it : interned_data.event_names()) {
404 EXPECT_EQ(event_names_.find(it.iid()), event_names_.end());
405 event_names_[it.iid()] = it.name();
406 }
407 for (const auto& it : interned_data.debug_annotation_names()) {
408 EXPECT_EQ(debug_annotation_names_.find(it.iid()),
409 debug_annotation_names_.end());
410 debug_annotation_names_[it.iid()] = it.name();
411 }
412 }
413 }
414
HasSeenTrack(uint64_t uuid) const415 bool HasSeenTrack(uint64_t uuid) const {
416 return seen_tracks_.count(uuid) != 0;
417 }
418
InsertTrack(uint64_t uuid)419 void InsertTrack(uint64_t uuid) { seen_tracks_.insert(uuid); }
420
GetCategory(uint64_t iid)421 std::string GetCategory(uint64_t iid) { return categories_[iid]; }
422
GetEventName(const perfetto::protos::gen::TrackEvent & event)423 std::string GetEventName(const perfetto::protos::gen::TrackEvent& event) {
424 if (event.has_name_iid())
425 return event_names_[event.name_iid()];
426 return event.name();
427 }
428
GetDebugAnnotationName(uint64_t iid)429 std::string GetDebugAnnotationName(uint64_t iid) {
430 return debug_annotation_names_[iid];
431 }
432
WasCleared() const433 bool WasCleared() const { return incremental_state_was_cleared_; }
434
435 private:
436 bool incremental_state_was_cleared_ = false;
437 std::map<uint64_t, std::string> categories_;
438 std::map<uint64_t, std::string> event_names_;
439 std::map<uint64_t, std::string> debug_annotation_names_;
440 std::set<uint64_t> seen_tracks_;
441 };
442
443 // -------------------------
444 // Declaration of test class
445 // -------------------------
446 class PerfettoApiTest : public ::testing::TestWithParam<perfetto::BackendType> {
447 public:
448 static PerfettoApiTest* instance;
449
SetUp()450 void SetUp() override {
451 instance = this;
452 g_test_tracing_policy->should_allow_consumer_connection = true;
453
454 // Start a fresh system service for this test, tearing down any previous
455 // service that was running. If the system backend isn't supported, skip all
456 // system backend tests.
457 if (GetParam() == perfetto::kSystemBackend &&
458 !perfetto::test::StartSystemService()) {
459 GTEST_SKIP();
460 }
461
462 EXPECT_FALSE(perfetto::Tracing::IsInitialized());
463 TracingInitArgs args;
464 args.backends = GetParam();
465 args.tracing_policy = g_test_tracing_policy;
466 perfetto::Tracing::Initialize(args);
467 RegisterDataSource<MockDataSource>("my_data_source");
468 perfetto::TrackEvent::Register();
469
470 // Make sure our data source always has a valid handle.
471 data_sources_["my_data_source"];
472
473 // If this wasn't the first test to run in this process, any producers
474 // connected to the old system service will have been disconnected by the
475 // service restarting above. Wait for all producers to connect again before
476 // proceeding with the test.
477 perfetto::test::SyncProducers();
478
479 perfetto::test::DisableReconnectLimit();
480 }
481
TearDown()482 void TearDown() override {
483 instance = nullptr;
484 sessions_.clear();
485 perfetto::Tracing::ResetForTesting();
486 }
487
488 template <typename DataSourceType>
RegisterDataSource(std::string name)489 TestDataSourceHandle* RegisterDataSource(std::string name) {
490 perfetto::DataSourceDescriptor dsd;
491 dsd.set_name(name);
492 return RegisterDataSource<DataSourceType>(dsd);
493 }
494
495 template <typename DataSourceType>
RegisterDataSource(const perfetto::DataSourceDescriptor & dsd)496 TestDataSourceHandle* RegisterDataSource(
497 const perfetto::DataSourceDescriptor& dsd) {
498 EXPECT_EQ(data_sources_.count(dsd.name()), 0u);
499 TestDataSourceHandle* handle = &data_sources_[dsd.name()];
500 DataSourceType::Register(dsd);
501 return handle;
502 }
503
504 template <typename DataSourceType>
UpdateDataSource(const perfetto::DataSourceDescriptor & dsd)505 TestDataSourceHandle* UpdateDataSource(
506 const perfetto::DataSourceDescriptor& dsd) {
507 EXPECT_EQ(data_sources_.count(dsd.name()), 1u);
508 TestDataSourceHandle* handle = &data_sources_[dsd.name()];
509 DataSourceType::UpdateDescriptor(dsd);
510 return handle;
511 }
512
NewTrace(const perfetto::TraceConfig & cfg,int fd=-1)513 TestTracingSessionHandle* NewTrace(const perfetto::TraceConfig& cfg,
514 int fd = -1) {
515 return NewTrace(cfg, /*backend_type=*/GetParam(), fd);
516 }
517
NewTrace(const perfetto::TraceConfig & cfg,perfetto::BackendType backend_type,int fd=-1)518 TestTracingSessionHandle* NewTrace(const perfetto::TraceConfig& cfg,
519 perfetto::BackendType backend_type,
520 int fd = -1) {
521 sessions_.emplace_back();
522 TestTracingSessionHandle* handle = &sessions_.back();
523 handle->session = perfetto::Tracing::NewTrace(backend_type);
524 handle->session->SetOnStopCallback([handle] { handle->on_stop.Notify(); });
525 handle->session->Setup(cfg, fd);
526 return handle;
527 }
528
NewTraceWithCategories(std::vector<std::string> categories,perfetto::protos::gen::TrackEventConfig te_cfg={})529 TestTracingSessionHandle* NewTraceWithCategories(
530 std::vector<std::string> categories,
531 perfetto::protos::gen::TrackEventConfig te_cfg = {}) {
532 perfetto::TraceConfig cfg;
533 cfg.set_duration_ms(500);
534 cfg.add_buffers()->set_size_kb(1024);
535 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
536 ds_cfg->set_name("track_event");
537 te_cfg.add_disabled_categories("*");
538 for (const auto& category : categories)
539 te_cfg.add_enabled_categories(category);
540 ds_cfg->set_track_event_config_raw(te_cfg.SerializeAsString());
541
542 return NewTrace(cfg);
543 }
544
ReadLogMessagesFromTrace(perfetto::TracingSession * tracing_session)545 std::vector<std::string> ReadLogMessagesFromTrace(
546 perfetto::TracingSession* tracing_session) {
547 std::vector<char> raw_trace = tracing_session->ReadTraceBlocking();
548 EXPECT_GE(raw_trace.size(), 0u);
549
550 // Read back the trace, maintaining interning tables as we go.
551 std::vector<std::string> log_messages;
552 std::map<uint64_t, std::string> log_message_bodies;
553 std::map<uint64_t, perfetto::protos::gen::SourceLocation> source_locations;
554 perfetto::protos::gen::Trace parsed_trace;
555 EXPECT_TRUE(
556 parsed_trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
557
558 for (const auto& packet : parsed_trace.packet()) {
559 if (!packet.has_track_event())
560 continue;
561
562 if (packet.has_interned_data()) {
563 const auto& interned_data = packet.interned_data();
564 for (const auto& it : interned_data.log_message_body()) {
565 EXPECT_GE(it.iid(), 1u);
566 EXPECT_EQ(log_message_bodies.find(it.iid()),
567 log_message_bodies.end());
568 log_message_bodies[it.iid()] = it.body();
569 }
570 for (const auto& it : interned_data.source_locations()) {
571 EXPECT_GE(it.iid(), 1u);
572 EXPECT_EQ(source_locations.find(it.iid()), source_locations.end());
573 source_locations[it.iid()] = it;
574 }
575 }
576 const auto& track_event = packet.track_event();
577 if (track_event.type() !=
578 perfetto::protos::gen::TrackEvent::TYPE_SLICE_BEGIN)
579 continue;
580
581 EXPECT_TRUE(track_event.has_log_message());
582 const auto& log = track_event.log_message();
583 if (log.source_location_iid()) {
584 std::stringstream msg;
585 const auto& source_location =
586 source_locations[log.source_location_iid()];
587 msg << source_location.function_name() << "("
588 << source_location.file_name() << ":"
589 << source_location.line_number()
590 << "): " << log_message_bodies[log.body_iid()];
591 log_messages.emplace_back(msg.str());
592 } else {
593 log_messages.emplace_back(log_message_bodies[log.body_iid()]);
594 }
595 }
596 return log_messages;
597 }
598
ReadSlicesFromTrace(perfetto::TracingSession * tracing_session)599 std::vector<std::string> ReadSlicesFromTrace(
600 perfetto::TracingSession* tracing_session) {
601 return ReadSlicesFromTrace(tracing_session->ReadTraceBlocking());
602 }
603
ReadSlicesFromTrace(const std::vector<char> & raw_trace)604 std::vector<std::string> ReadSlicesFromTrace(
605 const std::vector<char>& raw_trace) {
606 EXPECT_GE(raw_trace.size(), 0u);
607
608 // Read back the trace, maintaining interning tables as we go.
609 std::vector<std::string> slices;
610 perfetto::protos::gen::Trace parsed_trace;
611 EXPECT_TRUE(
612 parsed_trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
613
614 ParsedIncrementalState incremental_state;
615
616 uint32_t sequence_id = 0;
617 for (const auto& packet : parsed_trace.packet()) {
618 incremental_state.ClearIfNeeded(packet);
619
620 if (packet.has_track_descriptor()) {
621 // Make sure we haven't seen any events on this track before the
622 // descriptor was written.
623 EXPECT_FALSE(
624 incremental_state.HasSeenTrack(packet.track_descriptor().uuid()));
625 }
626
627 if (!packet.has_track_event())
628 continue;
629
630 // Make sure we only see track events on one sequence.
631 if (packet.trusted_packet_sequence_id()) {
632 if (!sequence_id)
633 sequence_id = packet.trusted_packet_sequence_id();
634 EXPECT_EQ(sequence_id, packet.trusted_packet_sequence_id());
635 }
636
637 incremental_state.Parse(packet);
638
639 const auto& track_event = packet.track_event();
640 std::string slice;
641
642 if (track_event.has_track_uuid()) {
643 incremental_state.InsertTrack(track_event.track_uuid());
644 std::stringstream track;
645 track << "[track=" << track_event.track_uuid() << "]";
646 slice += track.str();
647 }
648
649 switch (track_event.type()) {
650 case perfetto::protos::gen::TrackEvent::TYPE_SLICE_BEGIN:
651 slice += "B";
652 break;
653 case perfetto::protos::gen::TrackEvent::TYPE_SLICE_END:
654 slice += "E";
655 break;
656 case perfetto::protos::gen::TrackEvent::TYPE_INSTANT:
657 slice += "I";
658 break;
659 case perfetto::protos::gen::TrackEvent::TYPE_UNSPECIFIED: {
660 EXPECT_TRUE(track_event.has_legacy_event());
661 EXPECT_FALSE(track_event.type());
662 auto legacy_event = track_event.legacy_event();
663 slice += "Legacy_" +
664 std::string(1, static_cast<char>(legacy_event.phase()));
665 break;
666 }
667 case perfetto::protos::gen::TrackEvent::TYPE_COUNTER:
668 slice += "C";
669 break;
670 default:
671 ADD_FAILURE();
672 }
673 if (track_event.has_legacy_event()) {
674 auto legacy_event = track_event.legacy_event();
675 std::stringstream id;
676 if (legacy_event.has_unscoped_id()) {
677 id << "(unscoped_id=" << legacy_event.unscoped_id() << ")";
678 } else if (legacy_event.has_local_id()) {
679 id << "(local_id=" << legacy_event.local_id() << ")";
680 } else if (legacy_event.has_global_id()) {
681 id << "(global_id=" << legacy_event.global_id() << ")";
682 } else if (legacy_event.has_bind_id()) {
683 id << "(bind_id=" << legacy_event.bind_id() << ")";
684 }
685 if (legacy_event.has_id_scope())
686 id << "(id_scope=\"" << legacy_event.id_scope() << "\")";
687 if (legacy_event.use_async_tts())
688 id << "(use_async_tts)";
689 if (legacy_event.bind_to_enclosing())
690 id << "(bind_to_enclosing)";
691 if (legacy_event.has_flow_direction())
692 id << "(flow_direction=" << legacy_event.flow_direction() << ")";
693 if (legacy_event.has_pid_override())
694 id << "(pid_override=" << legacy_event.pid_override() << ")";
695 if (legacy_event.has_tid_override())
696 id << "(tid_override=" << legacy_event.tid_override() << ")";
697 slice += id.str();
698 }
699 size_t category_count = 0;
700 for (const auto& it : track_event.category_iids())
701 slice +=
702 (category_count++ ? "," : ":") + incremental_state.GetCategory(it);
703 for (const auto& it : track_event.categories())
704 slice += (category_count++ ? ",$" : ":$") + it;
705 if (track_event.has_name() || track_event.has_name_iid())
706 slice += "." + incremental_state.GetEventName(track_event);
707
708 if (track_event.debug_annotations_size()) {
709 slice += "(";
710 bool first_annotation = true;
711 for (const auto& it : track_event.debug_annotations()) {
712 if (!first_annotation) {
713 slice += ",";
714 }
715 slice +=
716 incremental_state.GetDebugAnnotationName(it.name_iid()) + "=";
717 std::stringstream value;
718 if (it.has_bool_value()) {
719 value << "(bool)" << it.bool_value();
720 } else if (it.has_uint_value()) {
721 value << "(uint)" << it.uint_value();
722 } else if (it.has_int_value()) {
723 value << "(int)" << it.int_value();
724 } else if (it.has_double_value()) {
725 value << "(double)" << it.double_value();
726 } else if (it.has_string_value()) {
727 value << "(string)" << it.string_value();
728 } else if (it.has_pointer_value()) {
729 value << "(pointer)" << std::hex << it.pointer_value();
730 } else if (it.has_legacy_json_value()) {
731 value << "(json)" << it.legacy_json_value();
732 } else if (it.has_nested_value()) {
733 value << "(nested)" << it.nested_value().string_value();
734 }
735 slice += value.str();
736 first_annotation = false;
737 }
738 slice += ")";
739 }
740
741 if (track_event.flow_ids_size()) {
742 slice += "(flow_ids=";
743 std::stringstream value;
744 bool first_annotation = true;
745 for (uint64_t id : track_event.flow_ids()) {
746 if (!first_annotation) {
747 value << ",";
748 }
749 first_annotation = false;
750 value << id;
751 }
752 slice += value.str() + ")";
753 }
754
755 if (track_event.terminating_flow_ids_size()) {
756 slice += "(terminating_flow_ids=";
757 std::stringstream value;
758 bool first_annotation = true;
759 for (uint64_t id : track_event.terminating_flow_ids()) {
760 if (!first_annotation) {
761 value << ",";
762 }
763 value << id;
764 first_annotation = false;
765 }
766 slice += value.str() + ")";
767 }
768
769 slices.push_back(slice);
770 }
771 EXPECT_TRUE(incremental_state.WasCleared());
772 return slices;
773 }
774
GetMainThreadPacketSequenceId(const perfetto::protos::gen::Trace & trace)775 uint32_t GetMainThreadPacketSequenceId(
776 const perfetto::protos::gen::Trace& trace) {
777 for (const auto& packet : trace.packet()) {
778 if (packet.has_track_descriptor() &&
779 packet.track_descriptor().thread().tid() ==
780 static_cast<int32_t>(perfetto::base::GetThreadId())) {
781 return packet.trusted_packet_sequence_id();
782 }
783 }
784 ADD_FAILURE() << "Main thread not found";
785 return 0;
786 }
787
788 std::map<std::string, TestDataSourceHandle> data_sources_;
789 std::list<TestTracingSessionHandle> sessions_; // Needs stable pointers.
790 };
791
792 // ---------------------------------------------
793 // Definitions for non-inlineable helper methods
794 // ---------------------------------------------
795 PerfettoApiTest* PerfettoApiTest::instance;
796
OnSetup(const SetupArgs & args)797 void MockDataSource::OnSetup(const SetupArgs& args) {
798 EXPECT_EQ(handle_, nullptr);
799 auto it = PerfettoApiTest::instance->data_sources_.find(args.config->name());
800
801 // We should not see an OnSetup for a data source that we didn't register
802 // before via PerfettoApiTest::RegisterDataSource().
803 EXPECT_NE(it, PerfettoApiTest::instance->data_sources_.end());
804 handle_ = &it->second;
805 handle_->config = *args.config; // Deliberate copy.
806 handle_->on_setup.Notify();
807 }
808
OnStart(const StartArgs &)809 void MockDataSource::OnStart(const StartArgs&) {
810 EXPECT_NE(handle_, nullptr);
811 if (handle_->on_start_callback)
812 handle_->on_start_callback();
813 handle_->on_start.Notify();
814 }
815
OnStop(const StopArgs & args)816 void MockDataSource::OnStop(const StopArgs& args) {
817 EXPECT_NE(handle_, nullptr);
818 if (handle_->handle_stop_asynchronously)
819 handle_->async_stop_closure = args.HandleStopAsynchronously();
820 if (handle_->on_stop_callback)
821 handle_->on_stop_callback();
822 handle_->on_stop.Notify();
823 }
824
825 // -------------
826 // Test fixtures
827 // -------------
828
TEST_P(PerfettoApiTest,StartAndStopWithoutDataSources)829 TEST_P(PerfettoApiTest, StartAndStopWithoutDataSources) {
830 // Create a new trace session without any data sources configured.
831 perfetto::TraceConfig cfg;
832 cfg.add_buffers()->set_size_kb(1024);
833 auto* tracing_session = NewTrace(cfg);
834 // This should not timeout.
835 tracing_session->get()->StartBlocking();
836 tracing_session->get()->StopBlocking();
837 }
838
839 // Disabled by default because it leaks tracing sessions into subsequent tests,
840 // which can result in the per-uid tracing session limit (5) to be hit in later
841 // tests.
TEST_P(PerfettoApiTest,DISABLED_TrackEventStartStopAndDestroy)842 TEST_P(PerfettoApiTest, DISABLED_TrackEventStartStopAndDestroy) {
843 // This test used to cause a use after free as the tracing session got
844 // destroyed. It needed to be run approximately 2000 times to catch it so test
845 // with --gtest_repeat=3000 (less if running under GDB).
846
847 // Setup the trace config.
848 perfetto::TraceConfig cfg;
849 cfg.set_duration_ms(500);
850 cfg.add_buffers()->set_size_kb(1024);
851 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
852 ds_cfg->set_name("track_event");
853
854 // Create five new trace sessions.
855 std::vector<std::unique_ptr<perfetto::TracingSession>> sessions;
856 for (size_t i = 0; i < 5; ++i) {
857 sessions.push_back(perfetto::Tracing::NewTrace(/*BackendType=*/GetParam()));
858 sessions[i]->Setup(cfg);
859 sessions[i]->Start();
860 sessions[i]->Stop();
861 }
862 }
863
TEST_P(PerfettoApiTest,TrackEventStartStopAndStopBlocking)864 TEST_P(PerfettoApiTest, TrackEventStartStopAndStopBlocking) {
865 // This test used to cause a deadlock (due to StopBlocking() after the session
866 // already stopped). This usually occurred within 1 or 2 runs of the test so
867 // use --gtest_repeat=10
868
869 // Setup the trace config.
870 perfetto::TraceConfig cfg;
871 cfg.set_duration_ms(500);
872 cfg.add_buffers()->set_size_kb(1024);
873 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
874 ds_cfg->set_name("track_event");
875
876 // Create five new trace sessions.
877 std::vector<std::unique_ptr<perfetto::TracingSession>> sessions;
878 for (size_t i = 0; i < 5; ++i) {
879 sessions.push_back(perfetto::Tracing::NewTrace(/*BackendType=*/GetParam()));
880 sessions[i]->Setup(cfg);
881 sessions[i]->Start();
882 sessions[i]->Stop();
883 }
884 for (auto& session : sessions) {
885 session->StopBlocking();
886 }
887 }
888
TEST_P(PerfettoApiTest,ChangeTraceConfiguration)889 TEST_P(PerfettoApiTest, ChangeTraceConfiguration) {
890 // Setup the trace config.
891 perfetto::TraceConfig trace_config;
892 trace_config.set_duration_ms(2000);
893 trace_config.add_buffers()->set_size_kb(1024);
894 auto* data_source = trace_config.add_data_sources();
895
896 // Configure track events with category "foo".
897 auto* ds_cfg = data_source->mutable_config();
898 ds_cfg->set_name("track_event");
899 perfetto::protos::gen::TrackEventConfig te_cfg;
900 te_cfg.add_disabled_categories("*");
901 te_cfg.add_enabled_categories("foo");
902 ds_cfg->set_track_event_config_raw(te_cfg.SerializeAsString());
903
904 // Initially, exclude all producers (the client library's producer is named
905 // after current process's name, which will not match
906 // "all_producers_excluded").
907 data_source->add_producer_name_filter("all_producers_excluded");
908
909 auto* tracing_session = NewTrace(trace_config);
910
911 tracing_session->get()->StartBlocking();
912
913 // Emit a first trace event, this one should be filtered out due
914 // to the mismatching producer name filter.
915 TRACE_EVENT_BEGIN("foo", "EventFilteredOut");
916 TRACE_EVENT_END("foo");
917
918 // Remove the producer name filter by changing configs.
919 data_source->clear_producer_name_filter();
920 tracing_session->get()->ChangeTraceConfig(trace_config);
921
922 // We don't have a blocking version of ChangeTraceConfig, because there is
923 // currently no response to it from producers or the service. Instead, we sync
924 // the consumer and producer IPC streams for this test, to ensure that the
925 // producer_name_filter change has propagated.
926 tracing_session->get()->GetTraceStatsBlocking(); // sync consumer stream.
927 perfetto::test::SyncProducers(); // sync producer stream.
928
929 // Emit a second trace event, this one should be included because
930 // the producer name filter was cleared.
931 TRACE_EVENT_BEGIN("foo", "EventIncluded");
932 TRACE_EVENT_END("foo");
933 tracing_session->get()->StopBlocking();
934
935 // Verify that only the second event is in the trace data.
936 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
937 std::string trace(raw_trace.data(), raw_trace.size());
938 EXPECT_THAT(trace, Not(HasSubstr("EventFilteredOut")));
939 EXPECT_THAT(trace, HasSubstr("EventIncluded"));
940 }
941
942 // This is a build-only regression test that checks you can have a track event
943 // inside a template.
944 template <typename T>
TestTrackEventInsideTemplate(T)945 void TestTrackEventInsideTemplate(T) {
946 TRACE_EVENT_BEGIN("cat", "Name");
947 }
948
949 // This is a build-only regression test that checks you can specify the tracing
950 // category as a template argument.
951 constexpr const char kTestCategory[] = "foo";
952 template <const char* category>
TestCategoryAsTemplateParameter()953 void TestCategoryAsTemplateParameter() {
954 TRACE_EVENT_BEGIN(category, "Name");
955 }
956
TEST_P(PerfettoApiTest,TrackEvent)957 TEST_P(PerfettoApiTest, TrackEvent) {
958 // Create a new trace session.
959 auto* tracing_session = NewTraceWithCategories({"test"});
960 tracing_session->get()->StartBlocking();
961
962 // Emit one complete track event.
963 TRACE_EVENT_BEGIN("test", "TestEvent");
964 TRACE_EVENT_END("test");
965 perfetto::TrackEvent::Flush();
966
967 tracing_session->on_stop.Wait();
968 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
969 ASSERT_GE(raw_trace.size(), 0u);
970
971 // Read back the trace, maintaining interning tables as we go.
972 perfetto::protos::gen::Trace trace;
973 std::map<uint64_t, std::string> categories;
974 std::map<uint64_t, std::string> event_names;
975 ASSERT_TRUE(trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
976
977 auto now = perfetto::TrackEvent::GetTraceTimeNs();
978 #if !PERFETTO_BUILDFLAG(PERFETTO_OS_APPLE) && \
979 !PERFETTO_BUILDFLAG(PERFETTO_OS_WIN)
980 auto clock_id = perfetto::protos::pbzero::BUILTIN_CLOCK_BOOTTIME;
981 #else
982 auto clock_id = perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC;
983 #endif
984 EXPECT_EQ(clock_id, perfetto::TrackEvent::GetTraceClockId());
985
986 bool incremental_state_was_cleared = false;
987 bool begin_found = false;
988 bool end_found = false;
989 bool process_descriptor_found = false;
990 uint32_t sequence_id = 0;
991 int32_t cur_pid = perfetto::test::GetCurrentProcessId();
992 uint64_t recent_absolute_time_ns = 0;
993 bool found_incremental_clock = false;
994 constexpr auto kClockIdIncremental =
995 perfetto::internal::TrackEventIncrementalState::kClockIdIncremental;
996
997 for (const auto& packet : trace.packet()) {
998 if (packet.has_track_descriptor()) {
999 const auto& desc = packet.track_descriptor();
1000 if (desc.has_process()) {
1001 EXPECT_FALSE(process_descriptor_found);
1002 const auto& pd = desc.process();
1003 EXPECT_EQ(cur_pid, pd.pid());
1004 process_descriptor_found = true;
1005 }
1006 }
1007 if (packet.sequence_flags() &
1008 perfetto::protos::pbzero::TracePacket::SEQ_INCREMENTAL_STATE_CLEARED) {
1009 EXPECT_TRUE(packet.has_trace_packet_defaults());
1010 incremental_state_was_cleared = true;
1011 categories.clear();
1012 event_names.clear();
1013 EXPECT_EQ(kClockIdIncremental,
1014 packet.trace_packet_defaults().timestamp_clock_id());
1015 }
1016 if (packet.has_clock_snapshot()) {
1017 for (auto& clock : packet.clock_snapshot().clocks()) {
1018 if (clock.is_incremental()) {
1019 found_incremental_clock = true;
1020 recent_absolute_time_ns = clock.timestamp();
1021 EXPECT_EQ(kClockIdIncremental, clock.clock_id());
1022 }
1023 }
1024 }
1025
1026 if (!packet.has_track_event())
1027 continue;
1028 EXPECT_TRUE(
1029 packet.sequence_flags() &
1030 (perfetto::protos::pbzero::TracePacket::SEQ_INCREMENTAL_STATE_CLEARED |
1031 perfetto::protos::pbzero::TracePacket::SEQ_NEEDS_INCREMENTAL_STATE));
1032 const auto& track_event = packet.track_event();
1033
1034 // Make sure we only see track events on one sequence.
1035 if (packet.trusted_packet_sequence_id()) {
1036 if (!sequence_id)
1037 sequence_id = packet.trusted_packet_sequence_id();
1038 EXPECT_EQ(sequence_id, packet.trusted_packet_sequence_id());
1039 }
1040
1041 // Update incremental state.
1042 if (packet.has_interned_data()) {
1043 const auto& interned_data = packet.interned_data();
1044 for (const auto& it : interned_data.event_categories()) {
1045 EXPECT_EQ(categories.find(it.iid()), categories.end());
1046 categories[it.iid()] = it.name();
1047 }
1048 for (const auto& it : interned_data.event_names()) {
1049 EXPECT_EQ(event_names.find(it.iid()), event_names.end());
1050 event_names[it.iid()] = it.name();
1051 }
1052 }
1053 EXPECT_TRUE(found_incremental_clock);
1054 uint64_t absolute_timestamp = packet.timestamp() + recent_absolute_time_ns;
1055 recent_absolute_time_ns = absolute_timestamp;
1056 EXPECT_GT(absolute_timestamp, 0u);
1057 EXPECT_LE(absolute_timestamp, now);
1058 // Packet uses default (incremental) clock.
1059 EXPECT_FALSE(packet.has_timestamp_clock_id());
1060 if (track_event.type() ==
1061 perfetto::protos::gen::TrackEvent::TYPE_SLICE_BEGIN) {
1062 EXPECT_FALSE(begin_found);
1063 EXPECT_EQ(track_event.category_iids().size(), 1u);
1064 EXPECT_GE(track_event.category_iids()[0], 1u);
1065 EXPECT_EQ("test", categories[track_event.category_iids()[0]]);
1066 EXPECT_EQ("TestEvent", event_names[track_event.name_iid()]);
1067 begin_found = true;
1068 } else if (track_event.type() ==
1069 perfetto::protos::gen::TrackEvent::TYPE_SLICE_END) {
1070 EXPECT_FALSE(end_found);
1071 EXPECT_EQ(track_event.category_iids().size(), 0u);
1072 EXPECT_EQ(0u, track_event.name_iid());
1073 end_found = true;
1074 }
1075 }
1076 EXPECT_TRUE(incremental_state_was_cleared);
1077 EXPECT_TRUE(process_descriptor_found);
1078 EXPECT_TRUE(begin_found);
1079 EXPECT_TRUE(end_found);
1080
1081 // Dummy instantiation of test templates.
1082 TestTrackEventInsideTemplate(true);
1083 TestCategoryAsTemplateParameter<kTestCategory>();
1084 }
1085
TEST_P(PerfettoApiTest,TrackEventWithIncrementalTimestamp)1086 TEST_P(PerfettoApiTest, TrackEventWithIncrementalTimestamp) {
1087 for (auto disable_incremental_timestamps : {false, true}) {
1088 // Create a new trace session.
1089 perfetto::protos::gen::TrackEventConfig te_cfg;
1090 te_cfg.set_disable_incremental_timestamps(disable_incremental_timestamps);
1091 auto* tracing_session = NewTraceWithCategories({"bar"}, te_cfg);
1092 constexpr auto kClockIdIncremental =
1093 perfetto::internal::TrackEventIncrementalState::kClockIdIncremental;
1094 tracing_session->get()->StartBlocking();
1095
1096 std::map<uint64_t, std::string> event_names;
1097
1098 auto empty_lambda = [](perfetto::EventContext) {};
1099
1100 constexpr uint64_t kInstantEvent1Time = 92718891479583;
1101 TRACE_EVENT_INSTANT(
1102 "bar", "InstantEvent1",
1103 perfetto::TraceTimestamp{kClockIdIncremental, kInstantEvent1Time},
1104 empty_lambda);
1105
1106 constexpr uint64_t kInstantEvent2Time = 92718891618959;
1107 TRACE_EVENT_INSTANT(
1108 "bar", "InstantEvent2",
1109 perfetto::TraceTimestamp{kClockIdIncremental, kInstantEvent2Time},
1110 empty_lambda);
1111
1112 perfetto::TrackEvent::Flush();
1113 tracing_session->get()->StopBlocking();
1114
1115 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
1116
1117 perfetto::protos::gen::Trace trace;
1118 ASSERT_TRUE(trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
1119 uint64_t absolute_timestamp = 0;
1120 uint64_t prv_timestamp = 0;
1121 int event_count = 0;
1122 // Go through the packets and add the timestamps of those packets that use
1123 // the incremental clock - in order to get the absolute timestamps of the
1124 // track events.
1125
1126 uint64_t default_clock_id = 0;
1127 bool is_incremental = false;
1128
1129 for (const auto& packet : trace.packet()) {
1130 if (!packet.has_track_event() && !packet.has_clock_snapshot())
1131 continue;
1132 if (packet.has_trace_packet_defaults()) {
1133 auto& defaults = packet.trace_packet_defaults();
1134 if (defaults.has_timestamp_clock_id()) {
1135 default_clock_id = defaults.timestamp_clock_id();
1136 }
1137 }
1138 if (packet.has_clock_snapshot()) {
1139 for (auto& clock : packet.clock_snapshot().clocks()) {
1140 if (clock.is_incremental()) {
1141 is_incremental = true;
1142 absolute_timestamp = clock.timestamp();
1143 EXPECT_EQ(clock.clock_id(), kClockIdIncremental);
1144 EXPECT_FALSE(disable_incremental_timestamps);
1145 }
1146 }
1147 } else {
1148 auto clock_id = packet.has_timestamp_clock_id()
1149 ? packet.timestamp_clock_id()
1150 : default_clock_id;
1151 if (clock_id == kClockIdIncremental) {
1152 absolute_timestamp = prv_timestamp + packet.timestamp();
1153 EXPECT_FALSE(disable_incremental_timestamps);
1154 } else {
1155 absolute_timestamp = packet.timestamp();
1156 EXPECT_TRUE(disable_incremental_timestamps);
1157 }
1158 }
1159 prv_timestamp = absolute_timestamp;
1160
1161 if (packet.sequence_flags() & perfetto::protos::pbzero::TracePacket::
1162 SEQ_INCREMENTAL_STATE_CLEARED) {
1163 event_names.clear();
1164 }
1165
1166 // Update incremental state.
1167 if (packet.has_interned_data()) {
1168 const auto& interned_data = packet.interned_data();
1169 for (const auto& it : interned_data.event_names()) {
1170 EXPECT_EQ(event_names.find(it.iid()), event_names.end());
1171 event_names[it.iid()] = it.name();
1172 }
1173 }
1174
1175 if (event_names[packet.track_event().name_iid()] == "InstantEvent1") {
1176 event_count++;
1177 EXPECT_EQ(absolute_timestamp, kInstantEvent1Time);
1178 } else if (event_names[packet.track_event().name_iid()] ==
1179 "InstantEvent2") {
1180 event_count++;
1181 EXPECT_EQ(absolute_timestamp, kInstantEvent2Time);
1182 }
1183 }
1184 EXPECT_NE(is_incremental, disable_incremental_timestamps);
1185 EXPECT_EQ(event_count, 2);
1186 }
1187 }
1188
TEST_P(PerfettoApiTest,TrackEventCategories)1189 TEST_P(PerfettoApiTest, TrackEventCategories) {
1190 // Create a new trace session.
1191 auto* tracing_session = NewTraceWithCategories({"bar"});
1192 tracing_session->get()->StartBlocking();
1193
1194 // Emit some track events.
1195 TRACE_EVENT_BEGIN("foo", "NotEnabled");
1196 TRACE_EVENT_END("foo");
1197 TRACE_EVENT_BEGIN("bar", "Enabled");
1198 TRACE_EVENT_END("bar");
1199
1200 tracing_session->get()->StopBlocking();
1201 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
1202 std::string trace(raw_trace.data(), raw_trace.size());
1203 // TODO(skyostil): Come up with a nicer way to verify trace contents.
1204 EXPECT_THAT(trace, HasSubstr("Enabled"));
1205 EXPECT_THAT(trace, Not(HasSubstr("NotEnabled")));
1206 }
1207
TEST_P(PerfettoApiTest,ClearIncrementalState)1208 TEST_P(PerfettoApiTest, ClearIncrementalState) {
1209 perfetto::DataSourceDescriptor dsd;
1210 dsd.set_name("incr_data_source");
1211 TestIncrementalDataSource::Register(dsd);
1212 perfetto::test::SyncProducers();
1213
1214 // Setup the trace config with an incremental state clearing period.
1215 perfetto::TraceConfig cfg;
1216 cfg.set_duration_ms(500);
1217 cfg.add_buffers()->set_size_kb(1024);
1218 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
1219 ds_cfg->set_name("incr_data_source");
1220 auto* is_cfg = cfg.mutable_incremental_state_config();
1221 is_cfg->set_clear_period_ms(10);
1222
1223 // Create a new trace session.
1224 auto* tracing_session = NewTrace(cfg);
1225 tracing_session->get()->StartBlocking();
1226
1227 // Observe at least 5 incremental state resets.
1228 constexpr size_t kMaxLoops = 100;
1229 size_t loops = 0;
1230 size_t times_cleared = 0;
1231 while (times_cleared < 5) {
1232 ASSERT_LT(loops++, kMaxLoops);
1233 TestIncrementalDataSource::Trace(
1234 [&](TestIncrementalDataSource::TraceContext ctx) {
1235 auto* incr_state = ctx.GetIncrementalState();
1236 if (!incr_state->flag) {
1237 incr_state->flag = true;
1238 times_cleared++;
1239 }
1240 });
1241 std::this_thread::sleep_for(std::chrono::milliseconds(10));
1242 }
1243 tracing_session->get()->StopBlocking();
1244 }
1245
TEST_P(PerfettoApiTest,TrackEventRegistrationWithModule)1246 TEST_P(PerfettoApiTest, TrackEventRegistrationWithModule) {
1247 MockTracingMuxer muxer;
1248
1249 // Each track event namespace registers its own data source.
1250 perfetto::TrackEvent::Register();
1251 EXPECT_EQ(1u, muxer.data_sources.size());
1252
1253 tracing_module::InitializeCategories();
1254 EXPECT_EQ(2u, muxer.data_sources.size());
1255
1256 // Both data sources have the same name but distinct static data (i.e.,
1257 // individual instance states).
1258 EXPECT_EQ("track_event", muxer.data_sources[0].dsd.name());
1259 EXPECT_EQ("track_event", muxer.data_sources[1].dsd.name());
1260 EXPECT_NE(muxer.data_sources[0].static_state,
1261 muxer.data_sources[1].static_state);
1262 }
1263
TEST_P(PerfettoApiTest,TrackEventDescriptor)1264 TEST_P(PerfettoApiTest, TrackEventDescriptor) {
1265 MockTracingMuxer muxer;
1266
1267 perfetto::TrackEvent::Register();
1268 EXPECT_EQ(1u, muxer.data_sources.size());
1269 EXPECT_EQ("track_event", muxer.data_sources[0].dsd.name());
1270
1271 perfetto::protos::gen::TrackEventDescriptor desc;
1272 auto desc_raw = muxer.data_sources[0].dsd.track_event_descriptor_raw();
1273 EXPECT_TRUE(desc.ParseFromArray(desc_raw.data(), desc_raw.size()));
1274
1275 // Check that the advertised categories match PERFETTO_DEFINE_CATEGORIES (see
1276 // above).
1277 EXPECT_EQ(7, desc.available_categories_size());
1278 EXPECT_EQ("test", desc.available_categories()[0].name());
1279 EXPECT_EQ("This is a test category",
1280 desc.available_categories()[0].description());
1281 EXPECT_EQ("tag", desc.available_categories()[0].tags()[0]);
1282 EXPECT_EQ("foo", desc.available_categories()[1].name());
1283 EXPECT_EQ("bar", desc.available_categories()[2].name());
1284 EXPECT_EQ("cat", desc.available_categories()[3].name());
1285 EXPECT_EQ("slow", desc.available_categories()[3].tags()[0]);
1286 EXPECT_EQ("cat.verbose", desc.available_categories()[4].name());
1287 EXPECT_EQ("debug", desc.available_categories()[4].tags()[0]);
1288 EXPECT_EQ("cat-with-dashes", desc.available_categories()[5].name());
1289 EXPECT_EQ("disabled-by-default-cat", desc.available_categories()[6].name());
1290 EXPECT_EQ("slow", desc.available_categories()[6].tags()[0]);
1291 }
1292
TEST_P(PerfettoApiTest,TrackEventSharedIncrementalState)1293 TEST_P(PerfettoApiTest, TrackEventSharedIncrementalState) {
1294 tracing_module::InitializeCategories();
1295
1296 // Setup the trace config.
1297 perfetto::TraceConfig cfg;
1298 cfg.set_duration_ms(500);
1299 cfg.add_buffers()->set_size_kb(1024);
1300 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
1301 ds_cfg->set_name("track_event");
1302 auto* tracing_session = NewTrace(cfg);
1303 tracing_session->get()->StartBlocking();
1304
1305 perfetto::internal::TrackEventIncrementalState* main_state = nullptr;
1306 perfetto::TrackEvent::Trace(
1307 [&main_state](perfetto::TrackEvent::TraceContext ctx) {
1308 main_state = ctx.GetIncrementalState();
1309 });
1310 perfetto::internal::TrackEventIncrementalState* module_state =
1311 tracing_module::GetIncrementalState();
1312
1313 // Both track event data sources should use the same incremental state (thanks
1314 // to sharing TLS).
1315 EXPECT_NE(nullptr, main_state);
1316 EXPECT_EQ(main_state, module_state);
1317 tracing_session->get()->StopBlocking();
1318 }
1319
TEST_P(PerfettoApiTest,TrackEventCategoriesWithModule)1320 TEST_P(PerfettoApiTest, TrackEventCategoriesWithModule) {
1321 // Check that categories defined in two different category registries are
1322 // enabled and disabled correctly.
1323 tracing_module::InitializeCategories();
1324
1325 // Create a new trace session. Only the "foo" category is enabled. It also
1326 // exists both locally and in the existing module.
1327 auto* tracing_session = NewTraceWithCategories({"foo"});
1328 tracing_session->get()->StartBlocking();
1329
1330 // Emit some track events locally and from the test module.
1331 TRACE_EVENT_BEGIN("foo", "FooEventFromMain");
1332 TRACE_EVENT_END("foo");
1333 tracing_module::EmitTrackEvents();
1334 tracing_module::EmitTrackEvents2();
1335 TRACE_EVENT_BEGIN("bar", "DisabledEventFromMain");
1336 TRACE_EVENT_END("bar");
1337
1338 tracing_session->get()->StopBlocking();
1339 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
1340 std::string trace(raw_trace.data(), raw_trace.size());
1341 EXPECT_THAT(trace, HasSubstr("FooEventFromMain"));
1342 EXPECT_THAT(trace, Not(HasSubstr("DisabledEventFromMain")));
1343 EXPECT_THAT(trace, HasSubstr("FooEventFromModule"));
1344 EXPECT_THAT(trace, Not(HasSubstr("DisabledEventFromModule")));
1345 EXPECT_THAT(trace, HasSubstr("FooEventFromModule2"));
1346 EXPECT_THAT(trace, Not(HasSubstr("DisabledEventFromModule2")));
1347
1348 perfetto::protos::gen::Trace parsed_trace;
1349 ASSERT_TRUE(parsed_trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
1350
1351 uint32_t sequence_id = 0;
1352 for (const auto& packet : parsed_trace.packet()) {
1353 if (!packet.has_track_event())
1354 continue;
1355
1356 // Make sure we only see track events on one sequence. This means all track
1357 // event modules are sharing the same trace writer (by using the same TLS
1358 // index).
1359 if (packet.trusted_packet_sequence_id()) {
1360 if (!sequence_id)
1361 sequence_id = packet.trusted_packet_sequence_id();
1362 EXPECT_EQ(sequence_id, packet.trusted_packet_sequence_id());
1363 }
1364 }
1365 }
1366
TEST_P(PerfettoApiTest,TrackEventDynamicCategories)1367 TEST_P(PerfettoApiTest, TrackEventDynamicCategories) {
1368 // Setup the trace config.
1369 perfetto::TraceConfig cfg;
1370 cfg.set_duration_ms(500);
1371 cfg.add_buffers()->set_size_kb(1024);
1372 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
1373 ds_cfg->set_name("track_event");
1374
1375 // Session #1 enabled the "dynamic" category.
1376 auto* tracing_session = NewTraceWithCategories({"dynamic"});
1377 tracing_session->get()->StartBlocking();
1378
1379 // Session #2 enables "dynamic_2".
1380 auto* tracing_session2 = NewTraceWithCategories({"dynamic_2"});
1381 tracing_session2->get()->StartBlocking();
1382
1383 // Test naming dynamic categories with std::string.
1384 perfetto::DynamicCategory dynamic{"dynamic"};
1385 TRACE_EVENT_BEGIN(dynamic, "EventInDynamicCategory");
1386 perfetto::DynamicCategory dynamic_disabled{"dynamic_disabled"};
1387 TRACE_EVENT_BEGIN(dynamic_disabled, "EventInDisabledDynamicCategory");
1388
1389 // Test naming dynamic categories statically.
1390 TRACE_EVENT_BEGIN("dynamic", "EventInStaticallyNamedDynamicCategory");
1391
1392 perfetto::DynamicCategory dynamic_2{"dynamic_2"};
1393 TRACE_EVENT_BEGIN(dynamic_2, "EventInSecondDynamicCategory");
1394 TRACE_EVENT_BEGIN("dynamic_2", "EventInSecondStaticallyNamedDynamicCategory");
1395
1396 std::thread thread([] {
1397 // Make sure the category name can actually be computed at runtime.
1398 std::string name = "dyn";
1399 if (perfetto::base::GetThreadId())
1400 name += "amic";
1401 perfetto::DynamicCategory cat{name};
1402 TRACE_EVENT_BEGIN(cat, "DynamicFromOtherThread");
1403 perfetto::DynamicCategory cat2{"dynamic_disabled"};
1404 TRACE_EVENT_BEGIN(cat2, "EventInDisabledDynamicCategory");
1405 });
1406 thread.join();
1407
1408 perfetto::TrackEvent::Flush();
1409 tracing_session->get()->StopBlocking();
1410 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
1411 std::string trace(raw_trace.data(), raw_trace.size());
1412 EXPECT_THAT(trace, HasSubstr("EventInDynamicCategory"));
1413 EXPECT_THAT(trace, Not(HasSubstr("EventInDisabledDynamicCategory")));
1414 EXPECT_THAT(trace, HasSubstr("DynamicFromOtherThread"));
1415 EXPECT_THAT(trace, Not(HasSubstr("EventInSecondDynamicCategory")));
1416 EXPECT_THAT(trace, HasSubstr("EventInStaticallyNamedDynamicCategory"));
1417 EXPECT_THAT(trace,
1418 Not(HasSubstr("EventInSecondStaticallyNamedDynamicCategory")));
1419
1420 tracing_session2->get()->StopBlocking();
1421 raw_trace = tracing_session2->get()->ReadTraceBlocking();
1422 trace = std::string(raw_trace.data(), raw_trace.size());
1423 EXPECT_THAT(trace, Not(HasSubstr("EventInDynamicCategory")));
1424 EXPECT_THAT(trace, Not(HasSubstr("EventInDisabledDynamicCategory")));
1425 EXPECT_THAT(trace, Not(HasSubstr("DynamicFromOtherThread")));
1426 EXPECT_THAT(trace, HasSubstr("EventInSecondDynamicCategory"));
1427 EXPECT_THAT(trace, Not(HasSubstr("EventInStaticallyNamedDynamicCategory")));
1428 EXPECT_THAT(trace, HasSubstr("EventInSecondStaticallyNamedDynamicCategory"));
1429 }
1430
TEST_P(PerfettoApiTest,TrackEventConcurrentSessions)1431 TEST_P(PerfettoApiTest, TrackEventConcurrentSessions) {
1432 // Check that categories that are enabled and disabled in two parallel tracing
1433 // sessions don't interfere.
1434
1435 // Session #1 enables the "foo" category.
1436 auto* tracing_session = NewTraceWithCategories({"foo"});
1437 tracing_session->get()->StartBlocking();
1438
1439 // Session #2 enables the "bar" category.
1440 auto* tracing_session2 = NewTraceWithCategories({"bar"});
1441 tracing_session2->get()->StartBlocking();
1442
1443 // Emit some track events under both categories.
1444 TRACE_EVENT_BEGIN("foo", "Session1_First");
1445 TRACE_EVENT_END("foo");
1446 TRACE_EVENT_BEGIN("bar", "Session2_First");
1447 TRACE_EVENT_END("bar");
1448
1449 tracing_session->get()->StopBlocking();
1450 TRACE_EVENT_BEGIN("foo", "Session1_Second");
1451 TRACE_EVENT_END("foo");
1452 TRACE_EVENT_BEGIN("bar", "Session2_Second");
1453 TRACE_EVENT_END("bar");
1454
1455 tracing_session2->get()->StopBlocking();
1456 TRACE_EVENT_BEGIN("foo", "Session1_Third");
1457 TRACE_EVENT_END("foo");
1458 TRACE_EVENT_BEGIN("bar", "Session2_Third");
1459 TRACE_EVENT_END("bar");
1460
1461 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
1462 std::string trace(raw_trace.data(), raw_trace.size());
1463 EXPECT_THAT(trace, HasSubstr("Session1_First"));
1464 EXPECT_THAT(trace, Not(HasSubstr("Session1_Second")));
1465 EXPECT_THAT(trace, Not(HasSubstr("Session1_Third")));
1466 EXPECT_THAT(trace, Not(HasSubstr("Session2_First")));
1467 EXPECT_THAT(trace, Not(HasSubstr("Session2_Second")));
1468 EXPECT_THAT(trace, Not(HasSubstr("Session2_Third")));
1469
1470 std::vector<char> raw_trace2 = tracing_session2->get()->ReadTraceBlocking();
1471 std::string trace2(raw_trace2.data(), raw_trace2.size());
1472 EXPECT_THAT(trace2, Not(HasSubstr("Session1_First")));
1473 EXPECT_THAT(trace2, Not(HasSubstr("Session1_Second")));
1474 EXPECT_THAT(trace2, Not(HasSubstr("Session1_Third")));
1475 EXPECT_THAT(trace2, HasSubstr("Session2_First"));
1476 EXPECT_THAT(trace2, HasSubstr("Session2_Second"));
1477 EXPECT_THAT(trace2, Not(HasSubstr("Session2_Third")));
1478 }
1479
TEST_P(PerfettoApiTest,TrackEventProcessAndThreadDescriptors)1480 TEST_P(PerfettoApiTest, TrackEventProcessAndThreadDescriptors) {
1481 // Thread and process descriptors can be set before tracing is enabled.
1482 perfetto::TrackEvent::SetProcessDescriptor(
1483 [](perfetto::protos::pbzero::TrackDescriptor* desc) {
1484 desc->set_name("hello.exe");
1485 desc->set_chrome_process()->set_process_priority(1);
1486 });
1487
1488 // Erased tracks shouldn't show up anywhere.
1489 perfetto::Track erased(1234u);
1490 perfetto::TrackEvent::SetTrackDescriptor(
1491 erased, [](perfetto::protos::pbzero::TrackDescriptor* desc) {
1492 desc->set_name("ErasedTrack");
1493 });
1494 perfetto::TrackEvent::EraseTrackDescriptor(erased);
1495
1496 // Setup the trace config.
1497 perfetto::TraceConfig cfg;
1498 cfg.set_duration_ms(500);
1499 cfg.add_buffers()->set_size_kb(1024);
1500 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
1501 ds_cfg->set_name("track_event");
1502
1503 // Create a new trace session.
1504 auto* tracing_session = NewTrace(cfg);
1505 tracing_session->get()->StartBlocking();
1506 TRACE_EVENT_INSTANT("test", "MainThreadEvent");
1507
1508 std::thread thread([&] {
1509 perfetto::TrackEvent::SetThreadDescriptor(
1510 [](perfetto::protos::pbzero::TrackDescriptor* desc) {
1511 desc->set_name("TestThread");
1512 });
1513 TRACE_EVENT_INSTANT("test", "ThreadEvent");
1514 });
1515 thread.join();
1516
1517 // Update the process descriptor while tracing is enabled. It should be
1518 // immediately reflected in the trace.
1519 perfetto::TrackEvent::SetProcessDescriptor(
1520 [](perfetto::protos::pbzero::TrackDescriptor* desc) {
1521 desc->set_name("goodbye.exe");
1522 });
1523 perfetto::TrackEvent::Flush();
1524
1525 tracing_session->get()->StopBlocking();
1526
1527 // After tracing ends, setting the descriptor has no immediate effect.
1528 perfetto::TrackEvent::SetProcessDescriptor(
1529 [](perfetto::protos::pbzero::TrackDescriptor* desc) {
1530 desc->set_name("noop.exe");
1531 });
1532
1533 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
1534 perfetto::protos::gen::Trace trace;
1535 ASSERT_TRUE(trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
1536
1537 std::vector<perfetto::protos::gen::TrackDescriptor> descs;
1538 std::vector<perfetto::protos::gen::TrackDescriptor> thread_descs;
1539 uint32_t main_thread_sequence = GetMainThreadPacketSequenceId(trace);
1540 for (const auto& packet : trace.packet()) {
1541 if (packet.has_track_descriptor()) {
1542 if (packet.trusted_packet_sequence_id() == main_thread_sequence) {
1543 descs.push_back(packet.track_descriptor());
1544 } else if (packet.track_descriptor().has_thread()) {
1545 thread_descs.push_back(packet.track_descriptor());
1546 }
1547 }
1548 }
1549
1550 // The main thread records the initial process name as well as the one that's
1551 // set during tracing. Additionally it records a thread descriptor for the
1552 // main thread.
1553
1554 EXPECT_EQ(3u, descs.size());
1555
1556 // Default track for the main thread.
1557 EXPECT_EQ(0, descs[0].process().pid());
1558 EXPECT_NE(0, descs[0].thread().pid());
1559
1560 // First process descriptor.
1561 EXPECT_NE(0, descs[1].process().pid());
1562 EXPECT_EQ("hello.exe", descs[1].name());
1563
1564 // Second process descriptor.
1565 EXPECT_NE(0, descs[2].process().pid());
1566 EXPECT_EQ("goodbye.exe", descs[2].name());
1567
1568 // The child thread records only its own thread descriptor (twice, since it
1569 // was mutated).
1570 ASSERT_EQ(2u, thread_descs.size());
1571 EXPECT_EQ("TestThread", thread_descs[0].name());
1572 EXPECT_NE(0, thread_descs[0].thread().pid());
1573 EXPECT_NE(0, thread_descs[0].thread().tid());
1574 EXPECT_EQ("TestThread", thread_descs[1].name());
1575 EXPECT_NE(0, thread_descs[1].thread().pid());
1576 EXPECT_NE(0, thread_descs[1].thread().tid());
1577 EXPECT_NE(0, descs[2].process().pid());
1578 EXPECT_EQ("goodbye.exe", descs[2].name());
1579 }
1580
TEST_P(PerfettoApiTest,CustomTrackDescriptor)1581 TEST_P(PerfettoApiTest, CustomTrackDescriptor) {
1582 // Setup the trace config.
1583 perfetto::TraceConfig cfg;
1584 cfg.set_duration_ms(500);
1585 cfg.add_buffers()->set_size_kb(1024);
1586 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
1587 ds_cfg->set_name("track_event");
1588
1589 // Create a new trace session.
1590 auto* tracing_session = NewTrace(cfg);
1591 tracing_session->get()->StartBlocking();
1592
1593 auto track = perfetto::ProcessTrack::Current();
1594 auto desc = track.Serialize();
1595 desc.mutable_process()->set_process_name("testing.exe");
1596 desc.mutable_thread()->set_tid(
1597 static_cast<int32_t>(perfetto::base::GetThreadId()));
1598 desc.mutable_chrome_process()->set_process_priority(123);
1599 perfetto::TrackEvent::SetTrackDescriptor(track, std::move(desc));
1600 perfetto::TrackEvent::Flush();
1601
1602 tracing_session->get()->StopBlocking();
1603
1604 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
1605 perfetto::protos::gen::Trace trace;
1606 ASSERT_TRUE(trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
1607
1608 uint32_t main_thread_sequence = GetMainThreadPacketSequenceId(trace);
1609 bool found_desc = false;
1610 for (const auto& packet : trace.packet()) {
1611 if (packet.trusted_packet_sequence_id() != main_thread_sequence)
1612 continue;
1613 if (packet.has_track_descriptor()) {
1614 auto td = packet.track_descriptor();
1615 if (!td.has_process())
1616 continue;
1617 EXPECT_NE(0, td.process().pid());
1618 EXPECT_TRUE(td.has_chrome_process());
1619 EXPECT_EQ("testing.exe", td.process().process_name());
1620 EXPECT_EQ(123, td.chrome_process().process_priority());
1621 found_desc = true;
1622 }
1623 }
1624 EXPECT_TRUE(found_desc);
1625 }
1626
TEST_P(PerfettoApiTest,TrackEventCustomTrack)1627 TEST_P(PerfettoApiTest, TrackEventCustomTrack) {
1628 // Create a new trace session.
1629 auto* tracing_session = NewTraceWithCategories({"bar"});
1630 tracing_session->get()->StartBlocking();
1631
1632 // Declare a custom track and give it a name.
1633 uint64_t async_id = 123;
1634 perfetto::TrackEvent::SetTrackDescriptor(
1635 perfetto::Track(async_id),
1636 [](perfetto::protos::pbzero::TrackDescriptor* desc) {
1637 desc->set_name("MyCustomTrack");
1638 });
1639
1640 // Start events on one thread and end them on another.
1641 TRACE_EVENT_BEGIN("bar", "AsyncEvent", perfetto::Track(async_id), "debug_arg",
1642 123);
1643
1644 TRACE_EVENT_BEGIN("bar", "SubEvent", perfetto::Track(async_id),
1645 [](perfetto::EventContext) {});
1646 const auto main_thread_track =
1647 perfetto::Track(async_id, perfetto::ThreadTrack::Current());
1648 std::thread thread([&] {
1649 TRACE_EVENT_END("bar", perfetto::Track(async_id));
1650 TRACE_EVENT_END("bar", perfetto::Track(async_id), "arg1", false, "arg2",
1651 true);
1652 const auto thread_track =
1653 perfetto::Track(async_id, perfetto::ThreadTrack::Current());
1654 // Thread-scoped tracks will have different uuids on different thread even
1655 // if the id matches.
1656 ASSERT_NE(main_thread_track.uuid, thread_track.uuid);
1657 });
1658 thread.join();
1659
1660 perfetto::TrackEvent::Flush();
1661 tracing_session->get()->StopBlocking();
1662
1663 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
1664 perfetto::protos::gen::Trace trace;
1665 ASSERT_TRUE(trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
1666
1667 // Check that the track uuids match on the begin and end events.
1668 const auto track = perfetto::Track(async_id);
1669 uint32_t main_thread_sequence = GetMainThreadPacketSequenceId(trace);
1670 int event_count = 0;
1671 bool found_descriptor = false;
1672 for (const auto& packet : trace.packet()) {
1673 if (packet.has_track_descriptor() &&
1674 !packet.track_descriptor().has_process() &&
1675 !packet.track_descriptor().has_thread()) {
1676 auto td = packet.track_descriptor();
1677 EXPECT_EQ("MyCustomTrack", td.name());
1678 EXPECT_EQ(track.uuid, td.uuid());
1679 EXPECT_EQ(perfetto::ProcessTrack::Current().uuid, td.parent_uuid());
1680 found_descriptor = true;
1681 continue;
1682 }
1683
1684 if (!packet.has_track_event())
1685 continue;
1686 auto track_event = packet.track_event();
1687 if (track_event.type() ==
1688 perfetto::protos::gen::TrackEvent::TYPE_SLICE_BEGIN) {
1689 EXPECT_EQ(main_thread_sequence, packet.trusted_packet_sequence_id());
1690 EXPECT_EQ(track.uuid, track_event.track_uuid());
1691 } else {
1692 EXPECT_NE(main_thread_sequence, packet.trusted_packet_sequence_id());
1693 EXPECT_EQ(track.uuid, track_event.track_uuid());
1694 }
1695 event_count++;
1696 }
1697 EXPECT_TRUE(found_descriptor);
1698 EXPECT_EQ(4, event_count);
1699 perfetto::TrackEvent::EraseTrackDescriptor(track);
1700 }
1701
TEST_P(PerfettoApiTest,TrackEventCustomTimestampClock)1702 TEST_P(PerfettoApiTest, TrackEventCustomTimestampClock) {
1703 // Create a new trace session.
1704 auto* tracing_session = NewTraceWithCategories({"foo"});
1705 tracing_session->get()->StartBlocking();
1706
1707 const perfetto::protos::pbzero::BuiltinClock kMyClockId =
1708 static_cast<perfetto::protos::pbzero::BuiltinClock>(700);
1709 const uint64_t kTimestamp = 12345678;
1710
1711 // First emit a clock snapshot that maps our custom clock to regular trace
1712 // time. Note that the clock snapshot should come before any events
1713 // referencing that clock.
1714 perfetto::TrackEvent::Trace([](perfetto::TrackEvent::TraceContext ctx) {
1715 auto packet = ctx.NewTracePacket();
1716 packet->set_timestamp_clock_id(perfetto::TrackEvent::GetTraceClockId());
1717 packet->set_timestamp(perfetto::TrackEvent::GetTraceTimeNs());
1718 auto* clock_snapshot = packet->set_clock_snapshot();
1719 // First set the reference clock, i.e., the default trace clock in this
1720 // case.
1721 auto* clock = clock_snapshot->add_clocks();
1722 clock->set_clock_id(perfetto::TrackEvent::GetTraceClockId());
1723 clock->set_timestamp(perfetto::TrackEvent::GetTraceTimeNs());
1724 // Then set the value of our reference clock at the same point in time. We
1725 // pretend our clock is one second behind trace time.
1726 clock = clock_snapshot->add_clocks();
1727 clock->set_clock_id(kMyClockId);
1728 clock->set_timestamp(kTimestamp + 1000000000ull);
1729 });
1730
1731 // Next emit a trace event with a custom timestamp and a custom clock.
1732 TRACE_EVENT_INSTANT("foo", "EventWithCustomTime",
1733 perfetto::TraceTimestamp{kMyClockId, kTimestamp});
1734 TRACE_EVENT_INSTANT("foo", "EventWithNormalTime");
1735
1736 perfetto::TrackEvent::Flush();
1737 tracing_session->get()->StopBlocking();
1738
1739 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
1740 perfetto::protos::gen::Trace trace;
1741 ASSERT_TRUE(trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
1742
1743 // Check that both the clock id and the timestamp got written together with
1744 // the packet. Note that we don't check the actual clock sync behavior here
1745 // since that happens in the Trace Processor instead.
1746 bool found_clock_snapshot = false;
1747 bool found_event = false;
1748 for (const auto& packet : trace.packet()) {
1749 if (packet.has_clock_snapshot())
1750 found_clock_snapshot = true;
1751 if (!packet.has_track_event() || packet.timestamp() != kTimestamp)
1752 continue;
1753 found_event = true;
1754 EXPECT_EQ(static_cast<uint32_t>(kMyClockId), packet.timestamp_clock_id());
1755 EXPECT_EQ(kTimestamp, packet.timestamp());
1756 }
1757 EXPECT_TRUE(found_clock_snapshot);
1758 EXPECT_TRUE(found_event);
1759 }
1760
TEST_P(PerfettoApiTest,LegacyEventWithThreadOverride)1761 TEST_P(PerfettoApiTest, LegacyEventWithThreadOverride) {
1762 // Create a new trace session.
1763 auto* tracing_session = NewTraceWithCategories({"cat"});
1764 tracing_session->get()->StartBlocking();
1765
1766 TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0("cat", "Name", 1,
1767 MyThreadId(456), MyTimestamp{0});
1768 perfetto::TrackEvent::Flush();
1769 tracing_session->get()->StopBlocking();
1770
1771 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
1772 perfetto::protos::gen::Trace trace;
1773 ASSERT_TRUE(trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
1774
1775 // Check that we wrote a track descriptor for the custom thread track, and
1776 // that the event was associated with that track.
1777 const auto track = perfetto::ThreadTrack::ForThread(456);
1778 bool found_descriptor = false;
1779 bool found_event = false;
1780 for (const auto& packet : trace.packet()) {
1781 if (packet.has_track_descriptor() &&
1782 packet.track_descriptor().has_thread()) {
1783 auto td = packet.track_descriptor().thread();
1784 if (td.tid() == 456) {
1785 EXPECT_EQ(track.uuid, packet.track_descriptor().uuid());
1786 found_descriptor = true;
1787 }
1788 }
1789
1790 if (!packet.has_track_event())
1791 continue;
1792 auto track_event = packet.track_event();
1793 if (track_event.legacy_event().phase() == TRACE_EVENT_PHASE_ASYNC_BEGIN) {
1794 EXPECT_EQ(track.uuid, track_event.track_uuid());
1795 found_event = true;
1796 }
1797 }
1798 EXPECT_TRUE(found_descriptor);
1799 EXPECT_TRUE(found_event);
1800 perfetto::TrackEvent::EraseTrackDescriptor(track);
1801 }
1802
TEST_P(PerfettoApiTest,LegacyEventWithProcessOverride)1803 TEST_P(PerfettoApiTest, LegacyEventWithProcessOverride) {
1804 // Create a new trace session.
1805 auto* tracing_session = NewTraceWithCategories({"cat"});
1806 tracing_session->get()->StartBlocking();
1807
1808 // Note: there's no direct entrypoint for adding trace events for another
1809 // process, so we're using the internal support macro here.
1810 INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMP(
1811 TRACE_EVENT_PHASE_INSTANT, "cat", "Name", 0, MyThreadId{789},
1812 MyTimestamp{0}, TRACE_EVENT_FLAG_HAS_PROCESS_ID);
1813 perfetto::TrackEvent::Flush();
1814 tracing_session->get()->StopBlocking();
1815
1816 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
1817 perfetto::protos::gen::Trace trace;
1818 ASSERT_TRUE(trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
1819
1820 // Check that the event has a pid_override matching MyThread above.
1821 bool found_event = false;
1822 for (const auto& packet : trace.packet()) {
1823 if (!packet.has_track_event())
1824 continue;
1825 auto track_event = packet.track_event();
1826 if (track_event.type() == perfetto::protos::gen::TrackEvent::TYPE_INSTANT) {
1827 EXPECT_EQ(789, track_event.legacy_event().pid_override());
1828 EXPECT_EQ(-1, track_event.legacy_event().tid_override());
1829 found_event = true;
1830 }
1831 }
1832 EXPECT_TRUE(found_event);
1833 }
1834
TEST_P(PerfettoApiTest,TrackDescriptorWrittenBeforeEvent)1835 TEST_P(PerfettoApiTest, TrackDescriptorWrittenBeforeEvent) {
1836 // Create a new trace session.
1837 auto* tracing_session = NewTraceWithCategories({"bar"});
1838 tracing_session->get()->StartBlocking();
1839
1840 // Emit an event on a custom track.
1841 TRACE_EVENT_INSTANT("bar", "Event", perfetto::Track(8086));
1842 perfetto::TrackEvent::Flush();
1843 tracing_session->get()->StopBlocking();
1844
1845 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
1846 perfetto::protos::gen::Trace trace;
1847 ASSERT_TRUE(trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
1848
1849 // Check that the descriptor was written before the event.
1850 std::set<uint64_t> seen_descriptors;
1851 for (const auto& packet : trace.packet()) {
1852 if (packet.has_track_descriptor())
1853 seen_descriptors.insert(packet.track_descriptor().uuid());
1854
1855 if (!packet.has_track_event())
1856 continue;
1857 auto track_event = packet.track_event();
1858 EXPECT_TRUE(seen_descriptors.find(track_event.track_uuid()) !=
1859 seen_descriptors.end());
1860 }
1861 }
1862
TEST_P(PerfettoApiTest,TrackEventCustomTrackAndTimestamp)1863 TEST_P(PerfettoApiTest, TrackEventCustomTrackAndTimestamp) {
1864 // Create a new trace session.
1865 auto* tracing_session = NewTraceWithCategories({"bar"});
1866 tracing_session->get()->StartBlocking();
1867
1868 // Custom track.
1869 perfetto::Track track(789);
1870
1871 auto empty_lambda = [](perfetto::EventContext) {};
1872 constexpr uint64_t kBeginEventTime = 10;
1873 const MyTimestamp kEndEventTime{15};
1874 TRACE_EVENT_BEGIN("bar", "Event", track, kBeginEventTime, empty_lambda);
1875 TRACE_EVENT_END("bar", track, kEndEventTime, empty_lambda);
1876
1877 constexpr uint64_t kInstantEventTime = 1;
1878 TRACE_EVENT_INSTANT("bar", "InstantEvent", track, kInstantEventTime,
1879 empty_lambda);
1880
1881 perfetto::TrackEvent::Flush();
1882 tracing_session->get()->StopBlocking();
1883
1884 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
1885 perfetto::protos::gen::Trace trace;
1886 ASSERT_TRUE(trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
1887
1888 int event_count = 0;
1889 for (const auto& packet : trace.packet()) {
1890 if (!packet.has_track_event())
1891 continue;
1892
1893 EXPECT_EQ(packet.timestamp_clock_id(),
1894 static_cast<uint32_t>(perfetto::TrackEvent::GetTraceClockId()));
1895 event_count++;
1896 switch (packet.track_event().type()) {
1897 case perfetto::protos::gen::TrackEvent::TYPE_SLICE_BEGIN:
1898 EXPECT_EQ(packet.timestamp(), kBeginEventTime);
1899 break;
1900 case perfetto::protos::gen::TrackEvent::TYPE_SLICE_END:
1901 EXPECT_EQ(packet.timestamp(), kEndEventTime.ts);
1902 break;
1903 case perfetto::protos::gen::TrackEvent::TYPE_INSTANT:
1904 EXPECT_EQ(packet.timestamp(), kInstantEventTime);
1905 break;
1906 case perfetto::protos::gen::TrackEvent::TYPE_COUNTER:
1907 case perfetto::protos::gen::TrackEvent::TYPE_UNSPECIFIED:
1908 ADD_FAILURE();
1909 }
1910 }
1911 EXPECT_EQ(event_count, 3);
1912 perfetto::TrackEvent::EraseTrackDescriptor(track);
1913 }
1914
TEST_P(PerfettoApiTest,TrackEventCustomTrackAndTimestampNoLambda)1915 TEST_P(PerfettoApiTest, TrackEventCustomTrackAndTimestampNoLambda) {
1916 auto* tracing_session = NewTraceWithCategories({"bar"});
1917 tracing_session->get()->StartBlocking();
1918
1919 perfetto::Track track(789);
1920
1921 constexpr uint64_t kBeginEventTime = 10;
1922 constexpr uint64_t kEndEventTime = 15;
1923 TRACE_EVENT_BEGIN("bar", "Event", track, kBeginEventTime);
1924 TRACE_EVENT_END("bar", track, kEndEventTime);
1925
1926 perfetto::TrackEvent::Flush();
1927 tracing_session->get()->StopBlocking();
1928
1929 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
1930 perfetto::protos::gen::Trace trace;
1931 ASSERT_TRUE(trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
1932
1933 int event_count = 0;
1934 for (const auto& packet : trace.packet()) {
1935 if (!packet.has_track_event())
1936 continue;
1937 event_count++;
1938 switch (packet.track_event().type()) {
1939 case perfetto::protos::gen::TrackEvent::TYPE_SLICE_BEGIN:
1940 EXPECT_EQ(packet.timestamp(), kBeginEventTime);
1941 break;
1942 case perfetto::protos::gen::TrackEvent::TYPE_SLICE_END:
1943 EXPECT_EQ(packet.timestamp(), kEndEventTime);
1944 break;
1945 case perfetto::protos::gen::TrackEvent::TYPE_INSTANT:
1946 case perfetto::protos::gen::TrackEvent::TYPE_COUNTER:
1947 case perfetto::protos::gen::TrackEvent::TYPE_UNSPECIFIED:
1948 ADD_FAILURE();
1949 }
1950 }
1951
1952 EXPECT_EQ(event_count, 2);
1953 }
1954
TEST_P(PerfettoApiTest,TrackEventAnonymousCustomTrack)1955 TEST_P(PerfettoApiTest, TrackEventAnonymousCustomTrack) {
1956 // Create a new trace session.
1957 auto* tracing_session = NewTraceWithCategories({"bar"});
1958 tracing_session->get()->StartBlocking();
1959
1960 // Emit an async event without giving it an explicit descriptor.
1961 uint64_t async_id = 4004;
1962 auto track = perfetto::Track(async_id, perfetto::ThreadTrack::Current());
1963 TRACE_EVENT_BEGIN("bar", "AsyncEvent", track);
1964 std::thread thread([&] { TRACE_EVENT_END("bar", track); });
1965 thread.join();
1966
1967 perfetto::TrackEvent::Flush();
1968 tracing_session->get()->StopBlocking();
1969
1970 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
1971 perfetto::protos::gen::Trace trace;
1972 ASSERT_TRUE(trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
1973
1974 // Check that a descriptor for the track was emitted.
1975 bool found_descriptor = false;
1976 for (const auto& packet : trace.packet()) {
1977 if (packet.has_track_descriptor() &&
1978 !packet.track_descriptor().has_process() &&
1979 !packet.track_descriptor().has_thread()) {
1980 auto td = packet.track_descriptor();
1981 EXPECT_EQ(track.uuid, td.uuid());
1982 EXPECT_EQ(perfetto::ThreadTrack::Current().uuid, td.parent_uuid());
1983 found_descriptor = true;
1984 }
1985 }
1986 EXPECT_TRUE(found_descriptor);
1987 }
1988
TEST_P(PerfettoApiTest,TrackEventTypedArgs)1989 TEST_P(PerfettoApiTest, TrackEventTypedArgs) {
1990 // Create a new trace session.
1991 auto* tracing_session = NewTraceWithCategories({"foo"});
1992 tracing_session->get()->StartBlocking();
1993
1994 auto random_value = rand();
1995 TRACE_EVENT_BEGIN("foo", "EventWithTypedArg",
1996 [random_value](perfetto::EventContext ctx) {
1997 auto* log = ctx.event()->set_log_message();
1998 log->set_source_location_iid(1);
1999 log->set_body_iid(2);
2000 auto* dbg = ctx.event()->add_debug_annotations();
2001 dbg->set_name("random");
2002 dbg->set_int_value(random_value);
2003 });
2004 TRACE_EVENT_END("foo");
2005
2006 tracing_session->get()->StopBlocking();
2007 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
2008 std::string trace(raw_trace.data(), raw_trace.size());
2009
2010 perfetto::protos::gen::Trace parsed_trace;
2011 ASSERT_TRUE(parsed_trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
2012
2013 bool found_args = false;
2014 for (const auto& packet : parsed_trace.packet()) {
2015 if (!packet.has_track_event())
2016 continue;
2017 const auto& track_event = packet.track_event();
2018 if (track_event.type() !=
2019 perfetto::protos::gen::TrackEvent::TYPE_SLICE_BEGIN)
2020 continue;
2021
2022 EXPECT_TRUE(track_event.has_log_message());
2023 const auto& log = track_event.log_message();
2024 EXPECT_EQ(1u, log.source_location_iid());
2025 EXPECT_EQ(2u, log.body_iid());
2026
2027 const auto& dbg = track_event.debug_annotations()[0];
2028 EXPECT_EQ("random", dbg.name());
2029 EXPECT_EQ(random_value, dbg.int_value());
2030
2031 found_args = true;
2032 }
2033 EXPECT_TRUE(found_args);
2034 }
2035
TEST_P(PerfettoApiTest,InlineTrackEventTypedArgs_SimpleRepeated)2036 TEST_P(PerfettoApiTest, InlineTrackEventTypedArgs_SimpleRepeated) {
2037 // Create a new trace session.
2038 auto* tracing_session = NewTraceWithCategories({"foo"});
2039 tracing_session->get()->StartBlocking();
2040
2041 std::vector<uint64_t> flow_ids{1, 2, 3};
2042 TRACE_EVENT_BEGIN("foo", "EventWithTypedArg",
2043 perfetto::protos::pbzero::TrackEvent::kFlowIds, flow_ids);
2044 TRACE_EVENT_END("foo");
2045
2046 tracing_session->get()->StopBlocking();
2047 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
2048 std::string trace(raw_trace.data(), raw_trace.size());
2049
2050 perfetto::protos::gen::Trace parsed_trace;
2051 ASSERT_TRUE(parsed_trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
2052
2053 bool found_args = false;
2054 for (const auto& packet : parsed_trace.packet()) {
2055 if (!packet.has_track_event())
2056 continue;
2057 const auto& track_event = packet.track_event();
2058 if (track_event.type() !=
2059 perfetto::protos::gen::TrackEvent::TYPE_SLICE_BEGIN) {
2060 continue;
2061 }
2062
2063 EXPECT_THAT(track_event.flow_ids(), testing::ElementsAre(1, 2, 3));
2064 found_args = true;
2065 }
2066 EXPECT_TRUE(found_args);
2067 }
2068
2069 namespace {
2070
2071 struct LogMessage {
WriteIntoTrace__anon22b779c30111::__anon22b779c31511::LogMessage2072 void WriteIntoTrace(
2073 perfetto::TracedProto<perfetto::protos::pbzero::LogMessage> context)
2074 const {
2075 context->set_source_location_iid(1);
2076 context->set_body_iid(2);
2077 }
2078 };
2079
__anon22b779c31602() 2080 auto GetWriteLogMessageRefLambda = []() {
2081 return [](perfetto::EventContext& ctx) {
2082 auto* log = ctx.event()->set_log_message();
2083 log->set_source_location_iid(1);
2084 log->set_body_iid(2);
2085 };
2086 };
2087
CheckTypedArguments(const std::vector<char> & raw_trace,const char * event_name,perfetto::protos::gen::TrackEvent::Type type,std::function<void (const perfetto::protos::gen::TrackEvent &)> checker)2088 void CheckTypedArguments(
2089 const std::vector<char>& raw_trace,
2090 const char* event_name,
2091 perfetto::protos::gen::TrackEvent::Type type,
2092 std::function<void(const perfetto::protos::gen::TrackEvent&)> checker) {
2093 perfetto::protos::gen::Trace parsed_trace;
2094 ASSERT_TRUE(parsed_trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
2095
2096 bool found_slice = false;
2097 ParsedIncrementalState incremental_state;
2098
2099 for (const auto& packet : parsed_trace.packet()) {
2100 incremental_state.ClearIfNeeded(packet);
2101 incremental_state.Parse(packet);
2102
2103 if (!packet.has_track_event())
2104 continue;
2105 const auto& track_event = packet.track_event();
2106 if (track_event.type() != type) {
2107 continue;
2108 }
2109 if (event_name &&
2110 incremental_state.GetEventName(track_event) != event_name) {
2111 continue;
2112 }
2113
2114 checker(track_event);
2115 found_slice = true;
2116 }
2117 EXPECT_TRUE(found_slice);
2118 }
2119
CheckLogMessagePresent(const std::vector<char> & raw_trace)2120 void CheckLogMessagePresent(const std::vector<char>& raw_trace) {
2121 CheckTypedArguments(raw_trace, nullptr,
2122 perfetto::protos::gen::TrackEvent::TYPE_SLICE_BEGIN,
2123 [](const perfetto::protos::gen::TrackEvent& track_event) {
2124 EXPECT_TRUE(track_event.has_log_message());
2125 const auto& log = track_event.log_message();
2126 EXPECT_EQ(1u, log.source_location_iid());
2127 EXPECT_EQ(2u, log.body_iid());
2128 });
2129 }
2130
2131 } // namespace
2132
TEST_P(PerfettoApiTest,InlineTrackEventTypedArgs_NestedSingle)2133 TEST_P(PerfettoApiTest, InlineTrackEventTypedArgs_NestedSingle) {
2134 // Create a new trace session.
2135 auto* tracing_session = NewTraceWithCategories({"foo"});
2136 tracing_session->get()->StartBlocking();
2137
2138 TRACE_EVENT_BEGIN("foo", "EventWithTypedArg",
2139 perfetto::protos::pbzero::TrackEvent::kLogMessage,
2140 LogMessage());
2141 TRACE_EVENT_END("foo");
2142
2143 tracing_session->get()->StopBlocking();
2144 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
2145 }
2146
TEST_P(PerfettoApiTest,TrackEventArgs_TypedAndUntyped)2147 TEST_P(PerfettoApiTest, TrackEventArgs_TypedAndUntyped) {
2148 // Create a new trace session.
2149 auto* tracing_session = NewTraceWithCategories({"foo"});
2150 tracing_session->get()->StartBlocking();
2151
2152 TRACE_EVENT_BEGIN("foo", "E",
2153 perfetto::protos::pbzero::TrackEvent::kLogMessage,
2154 LogMessage(), "arg", "value");
2155 TRACE_EVENT_END("foo");
2156
2157 tracing_session->get()->StopBlocking();
2158
2159 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
2160 std::string trace(raw_trace.data(), raw_trace.size());
2161
2162 // Find typed argument.
2163 CheckLogMessagePresent(raw_trace);
2164
2165 // Find untyped argument.
2166 EXPECT_THAT(ReadSlicesFromTrace(raw_trace),
2167 ElementsAre("B:foo.E(arg=(string)value)"));
2168 }
2169
TEST_P(PerfettoApiTest,TrackEventArgs_UntypedAndTyped)2170 TEST_P(PerfettoApiTest, TrackEventArgs_UntypedAndTyped) {
2171 // Create a new trace session.
2172 auto* tracing_session = NewTraceWithCategories({"foo"});
2173 tracing_session->get()->StartBlocking();
2174
2175 TRACE_EVENT_BEGIN("foo", "E", "arg", "value",
2176 perfetto::protos::pbzero::TrackEvent::kLogMessage,
2177 LogMessage());
2178 TRACE_EVENT_END("foo");
2179
2180 tracing_session->get()->StopBlocking();
2181
2182 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
2183
2184 // Find typed argument.
2185 CheckLogMessagePresent(raw_trace);
2186
2187 // Find untyped argument.
2188 EXPECT_THAT(ReadSlicesFromTrace(raw_trace),
2189 ElementsAre("B:foo.E(arg=(string)value)"));
2190 }
2191
TEST_P(PerfettoApiTest,TrackEventArgs_UntypedAndRefLambda)2192 TEST_P(PerfettoApiTest, TrackEventArgs_UntypedAndRefLambda) {
2193 // Create a new trace session.
2194 auto* tracing_session = NewTraceWithCategories({"foo"});
2195 tracing_session->get()->StartBlocking();
2196
2197 TRACE_EVENT_BEGIN("foo", "E", "arg", "value", GetWriteLogMessageRefLambda());
2198 TRACE_EVENT_END("foo");
2199
2200 tracing_session->get()->StopBlocking();
2201
2202 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
2203
2204 // Find typed argument.
2205 CheckLogMessagePresent(raw_trace);
2206
2207 // Find untyped argument.
2208 EXPECT_THAT(ReadSlicesFromTrace(raw_trace),
2209 ElementsAre("B:foo.E(arg=(string)value)"));
2210 }
2211
TEST_P(PerfettoApiTest,TrackEventArgs_RefLambdaAndUntyped)2212 TEST_P(PerfettoApiTest, TrackEventArgs_RefLambdaAndUntyped) {
2213 // Create a new trace session.
2214 auto* tracing_session = NewTraceWithCategories({"foo"});
2215 tracing_session->get()->StartBlocking();
2216
2217 TRACE_EVENT_BEGIN("foo", "E", GetWriteLogMessageRefLambda(), "arg", "value");
2218 TRACE_EVENT_END("foo");
2219
2220 tracing_session->get()->StopBlocking();
2221
2222 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
2223
2224 // Find typed argument.
2225 CheckLogMessagePresent(raw_trace);
2226
2227 // Find untyped argument.
2228 EXPECT_THAT(ReadSlicesFromTrace(raw_trace),
2229 ElementsAre("B:foo.E(arg=(string)value)"));
2230 }
2231
TEST_P(PerfettoApiTest,TrackEventArgs_RefLambdaAndTyped)2232 TEST_P(PerfettoApiTest, TrackEventArgs_RefLambdaAndTyped) {
2233 // Create a new trace session.
2234 auto* tracing_session = NewTraceWithCategories({"foo"});
2235 tracing_session->get()->StartBlocking();
2236
2237 TRACE_EVENT_BEGIN(
2238 "foo", "E",
2239 [](perfetto::EventContext& ctx) {
2240 ctx.AddDebugAnnotation("arg", "value");
2241 },
2242 perfetto::protos::pbzero::TrackEvent::kLogMessage, LogMessage());
2243 TRACE_EVENT_END("foo");
2244
2245 tracing_session->get()->StopBlocking();
2246
2247 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
2248
2249 // Find typed argument.
2250 CheckLogMessagePresent(raw_trace);
2251
2252 // Find untyped argument.
2253 EXPECT_THAT(ReadSlicesFromTrace(raw_trace),
2254 ElementsAre("B:foo.E(arg=(string)value)"));
2255 }
2256
TEST_P(PerfettoApiTest,TrackEventArgs_TypedAndRefLambda)2257 TEST_P(PerfettoApiTest, TrackEventArgs_TypedAndRefLambda) {
2258 // Create a new trace session.
2259 auto* tracing_session = NewTraceWithCategories({"foo"});
2260 tracing_session->get()->StartBlocking();
2261
2262 TRACE_EVENT_BEGIN("foo", "E",
2263 perfetto::protos::pbzero::TrackEvent::kLogMessage,
2264 LogMessage(), [](perfetto::EventContext& ctx) {
2265 ctx.AddDebugAnnotation("arg", "value");
2266 });
2267 TRACE_EVENT_END("foo");
2268
2269 tracing_session->get()->StopBlocking();
2270
2271 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
2272
2273 // Find typed argument.
2274 CheckLogMessagePresent(raw_trace);
2275
2276 // Find untyped argument.
2277 EXPECT_THAT(ReadSlicesFromTrace(raw_trace),
2278 ElementsAre("B:foo.E(arg=(string)value)"));
2279 }
2280
TEST_P(PerfettoApiTest,TrackEventArgs_RefLambdaAndRefLambda)2281 TEST_P(PerfettoApiTest, TrackEventArgs_RefLambdaAndRefLambda) {
2282 // Create a new trace session.
2283 auto* tracing_session = NewTraceWithCategories({"foo"});
2284 tracing_session->get()->StartBlocking();
2285
2286 TRACE_EVENT_BEGIN(
2287 "foo", "E",
2288 [](perfetto::EventContext& ctx) {
2289 ctx.AddDebugAnnotation("arg1", "value1");
2290 },
2291 [](perfetto::EventContext& ctx) {
2292 ctx.AddDebugAnnotation("arg2", "value2");
2293 });
2294 TRACE_EVENT_END("foo");
2295
2296 tracing_session->get()->StopBlocking();
2297
2298 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
2299
2300 // Find untyped arguments.
2301 EXPECT_THAT(ReadSlicesFromTrace(raw_trace),
2302 ElementsAre("B:foo.E(arg1=(string)value1,arg2=(string)value2)"));
2303 }
2304
TEST_P(PerfettoApiTest,TrackEventArgs_RefLambdaAndLambda)2305 TEST_P(PerfettoApiTest, TrackEventArgs_RefLambdaAndLambda) {
2306 // Create a new trace session.
2307 auto* tracing_session = NewTraceWithCategories({"foo"});
2308 tracing_session->get()->StartBlocking();
2309
2310 TRACE_EVENT_BEGIN(
2311 "foo", "E",
2312 [](perfetto::EventContext& ctx) {
2313 ctx.AddDebugAnnotation("arg1", "value1");
2314 },
2315 [](perfetto::EventContext ctx) {
2316 ctx.AddDebugAnnotation("arg2", "value2");
2317 });
2318 TRACE_EVENT_END("foo");
2319
2320 tracing_session->get()->StopBlocking();
2321
2322 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
2323
2324 // Find untyped arguments.
2325 EXPECT_THAT(ReadSlicesFromTrace(raw_trace),
2326 ElementsAre("B:foo.E(arg1=(string)value1,arg2=(string)value2)"));
2327 }
2328
TEST_P(PerfettoApiTest,TrackEventArgs_RefLambda)2329 TEST_P(PerfettoApiTest, TrackEventArgs_RefLambda) {
2330 // Create a new trace session.
2331 auto* tracing_session = NewTraceWithCategories({"foo"});
2332 tracing_session->get()->StartBlocking();
2333
2334 TRACE_EVENT_BEGIN("foo", "E", [](perfetto::EventContext& ctx) {
2335 ctx.AddDebugAnnotation("arg", "value");
2336 });
2337 TRACE_EVENT_END("foo");
2338
2339 tracing_session->get()->StopBlocking();
2340
2341 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
2342
2343 // Find untyped argument.
2344 EXPECT_THAT(ReadSlicesFromTrace(raw_trace),
2345 ElementsAre("B:foo.E(arg=(string)value)"));
2346 }
2347
TEST_P(PerfettoApiTest,TrackEventArgs_Flow_Global)2348 TEST_P(PerfettoApiTest, TrackEventArgs_Flow_Global) {
2349 // Create a new trace session.
2350 auto* tracing_session = NewTraceWithCategories({"foo"});
2351 tracing_session->get()->StartBlocking();
2352
2353 TRACE_EVENT_INSTANT("foo", "E1", perfetto::Flow::Global(42));
2354 TRACE_EVENT_INSTANT("foo", "E2", perfetto::TerminatingFlow::Global(42));
2355
2356 tracing_session->get()->StopBlocking();
2357
2358 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
2359
2360 // Find typed argument.
2361 CheckTypedArguments(
2362 raw_trace, "E1", perfetto::protos::gen::TrackEvent::TYPE_INSTANT,
2363 [](const perfetto::protos::gen::TrackEvent& track_event) {
2364 EXPECT_THAT(track_event.flow_ids(), testing::ElementsAre(42));
2365 });
2366 }
2367
TEST_P(PerfettoApiTest,TrackEventArgs_MultipleFlows)2368 TEST_P(PerfettoApiTest, TrackEventArgs_MultipleFlows) {
2369 // Create a new trace session.
2370 auto* tracing_session = NewTraceWithCategories({"foo"});
2371 tracing_session->get()->StartBlocking();
2372
2373 {
2374 TRACE_EVENT("foo", "E1", perfetto::Flow::Global(1),
2375 perfetto::Flow::Global(2), perfetto::Flow::Global(3));
2376 }
2377 {
2378 TRACE_EVENT("foo", "E2", perfetto::Flow::Global(1),
2379 perfetto::TerminatingFlow::Global(2));
2380 }
2381 { TRACE_EVENT("foo", "E3", perfetto::TerminatingFlow::Global(3)); }
2382
2383 tracing_session->get()->StopBlocking();
2384
2385 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
2386 EXPECT_THAT(ReadSlicesFromTrace(raw_trace),
2387 ElementsAre("B:foo.E1(flow_ids=1,2,3)", "E",
2388 "B:foo.E2(flow_ids=1)(terminating_flow_ids=2)", "E",
2389 "B:foo.E3(terminating_flow_ids=3)"));
2390 }
2391
TEST_P(PerfettoApiTest,TrackEventArgs_Flow_ProcessScoped)2392 TEST_P(PerfettoApiTest, TrackEventArgs_Flow_ProcessScoped) {
2393 // Create a new trace session.
2394 auto* tracing_session = NewTraceWithCategories({"foo"});
2395 tracing_session->get()->StartBlocking();
2396
2397 TRACE_EVENT_INSTANT("foo", "E1", perfetto::Flow::ProcessScoped(1));
2398 TRACE_EVENT_INSTANT("foo", "E2", perfetto::TerminatingFlow::ProcessScoped(1));
2399 TRACE_EVENT_INSTANT("foo", "Flush");
2400
2401 tracing_session->get()->StopBlocking();
2402
2403 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
2404
2405 // Find typed arguments.
2406 CheckTypedArguments(raw_trace, "E1",
2407 perfetto::protos::gen::TrackEvent::TYPE_INSTANT,
2408 [](const perfetto::protos::gen::TrackEvent& track_event) {
2409 EXPECT_EQ(track_event.flow_ids_size(), 1);
2410 });
2411 CheckTypedArguments(raw_trace, "E2",
2412 perfetto::protos::gen::TrackEvent::TYPE_INSTANT,
2413 [](const perfetto::protos::gen::TrackEvent& track_event) {
2414 EXPECT_EQ(track_event.terminating_flow_ids_size(), 1);
2415 });
2416 }
2417
TEST_P(PerfettoApiTest,TrackEventArgs_Flow_FromPointer)2418 TEST_P(PerfettoApiTest, TrackEventArgs_Flow_FromPointer) {
2419 // Create a new trace session.
2420 auto* tracing_session = NewTraceWithCategories({"foo"});
2421 tracing_session->get()->StartBlocking();
2422
2423 int a;
2424 int* ptr = &a;
2425 TRACE_EVENT_INSTANT("foo", "E1", perfetto::Flow::FromPointer(ptr));
2426 TRACE_EVENT_INSTANT("foo", "E2", perfetto::TerminatingFlow::FromPointer(ptr));
2427 TRACE_EVENT_INSTANT("foo", "Flush");
2428
2429 tracing_session->get()->StopBlocking();
2430
2431 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
2432
2433 // Find typed arguments.
2434 CheckTypedArguments(raw_trace, "E1",
2435 perfetto::protos::gen::TrackEvent::TYPE_INSTANT,
2436 [](const perfetto::protos::gen::TrackEvent& track_event) {
2437 EXPECT_EQ(track_event.flow_ids_size(), 1);
2438 });
2439 CheckTypedArguments(raw_trace, "E2",
2440 perfetto::protos::gen::TrackEvent::TYPE_INSTANT,
2441 [](const perfetto::protos::gen::TrackEvent& track_event) {
2442 EXPECT_EQ(track_event.terminating_flow_ids_size(), 1);
2443 });
2444 }
2445
2446 struct InternedLogMessageBody
2447 : public perfetto::TrackEventInternedDataIndex<
2448 InternedLogMessageBody,
2449 perfetto::protos::pbzero::InternedData::kLogMessageBodyFieldNumber,
2450 std::string> {
Add__anon22b779c30111::InternedLogMessageBody2451 static void Add(perfetto::protos::pbzero::InternedData* interned_data,
2452 size_t iid,
2453 const std::string& value) {
2454 auto l = interned_data->add_log_message_body();
2455 l->set_iid(iid);
2456 l->set_body(value.data(), value.size());
2457 commit_count++;
2458 }
2459
2460 static int commit_count;
2461 };
2462
2463 int InternedLogMessageBody::commit_count = 0;
2464
TEST_P(PerfettoApiTest,TrackEventTypedArgsWithInterning)2465 TEST_P(PerfettoApiTest, TrackEventTypedArgsWithInterning) {
2466 // Create a new trace session.
2467 auto* tracing_session = NewTraceWithCategories({"foo"});
2468 tracing_session->get()->StartBlocking();
2469
2470 std::stringstream large_message;
2471 for (size_t i = 0; i < 512; i++)
2472 large_message << i << ". Something wicked this way comes. ";
2473
2474 size_t body_iid;
2475 InternedLogMessageBody::commit_count = 0;
2476 TRACE_EVENT_BEGIN("foo", "EventWithState", [&](perfetto::EventContext ctx) {
2477 EXPECT_EQ(0, InternedLogMessageBody::commit_count);
2478 body_iid = InternedLogMessageBody::Get(&ctx, "Alas, poor Yorick!");
2479 auto log = ctx.event()->set_log_message();
2480 log->set_body_iid(body_iid);
2481 EXPECT_EQ(1, InternedLogMessageBody::commit_count);
2482
2483 auto body_iid2 = InternedLogMessageBody::Get(&ctx, "Alas, poor Yorick!");
2484 EXPECT_EQ(body_iid, body_iid2);
2485 EXPECT_EQ(1, InternedLogMessageBody::commit_count);
2486 });
2487 TRACE_EVENT_END("foo");
2488
2489 TRACE_EVENT_BEGIN("foo", "EventWithState", [&](perfetto::EventContext ctx) {
2490 // Check that very large amounts of interned data works.
2491 auto log = ctx.event()->set_log_message();
2492 log->set_body_iid(InternedLogMessageBody::Get(&ctx, large_message.str()));
2493 EXPECT_EQ(2, InternedLogMessageBody::commit_count);
2494 });
2495 TRACE_EVENT_END("foo");
2496
2497 // Make sure interned data persists across trace points.
2498 TRACE_EVENT_BEGIN("foo", "EventWithState", [&](perfetto::EventContext ctx) {
2499 auto body_iid2 = InternedLogMessageBody::Get(&ctx, "Alas, poor Yorick!");
2500 EXPECT_EQ(body_iid, body_iid2);
2501
2502 auto body_iid3 = InternedLogMessageBody::Get(&ctx, "I knew him, Horatio");
2503 EXPECT_NE(body_iid, body_iid3);
2504 auto log = ctx.event()->set_log_message();
2505 log->set_body_iid(body_iid3);
2506 EXPECT_EQ(3, InternedLogMessageBody::commit_count);
2507 });
2508 TRACE_EVENT_END("foo");
2509
2510 tracing_session->get()->StopBlocking();
2511 auto log_messages = ReadLogMessagesFromTrace(tracing_session->get());
2512 EXPECT_THAT(log_messages,
2513 ElementsAre("Alas, poor Yorick!", large_message.str(),
2514 "I knew him, Horatio"));
2515 }
2516
2517 struct InternedLogMessageBodySmall
2518 : public perfetto::TrackEventInternedDataIndex<
2519 InternedLogMessageBodySmall,
2520 perfetto::protos::pbzero::InternedData::kLogMessageBodyFieldNumber,
2521 const char*,
2522 perfetto::SmallInternedDataTraits> {
Add__anon22b779c30111::InternedLogMessageBodySmall2523 static void Add(perfetto::protos::pbzero::InternedData* interned_data,
2524 size_t iid,
2525 const char* value) {
2526 auto l = interned_data->add_log_message_body();
2527 l->set_iid(iid);
2528 l->set_body(value);
2529 }
2530 };
2531
TEST_P(PerfettoApiTest,TrackEventTypedArgsWithInterningByValue)2532 TEST_P(PerfettoApiTest, TrackEventTypedArgsWithInterningByValue) {
2533 // Create a new trace session.
2534 auto* tracing_session = NewTraceWithCategories({"foo"});
2535 tracing_session->get()->StartBlocking();
2536
2537 size_t body_iid;
2538 TRACE_EVENT_BEGIN("foo", "EventWithState", [&](perfetto::EventContext ctx) {
2539 body_iid = InternedLogMessageBodySmall::Get(&ctx, "This above all:");
2540 auto log = ctx.event()->set_log_message();
2541 log->set_body_iid(body_iid);
2542
2543 auto body_iid2 = InternedLogMessageBodySmall::Get(&ctx, "This above all:");
2544 EXPECT_EQ(body_iid, body_iid2);
2545
2546 auto body_iid3 =
2547 InternedLogMessageBodySmall::Get(&ctx, "to thine own self be true");
2548 EXPECT_NE(body_iid, body_iid3);
2549 });
2550 TRACE_EVENT_END("foo");
2551
2552 tracing_session->get()->StopBlocking();
2553 auto log_messages = ReadLogMessagesFromTrace(tracing_session->get());
2554 EXPECT_THAT(log_messages, ElementsAre("This above all:"));
2555 }
2556
2557 struct InternedLogMessageBodyHashed
2558 : public perfetto::TrackEventInternedDataIndex<
2559 InternedLogMessageBodyHashed,
2560 perfetto::protos::pbzero::InternedData::kLogMessageBodyFieldNumber,
2561 std::string,
2562 perfetto::HashedInternedDataTraits> {
Add__anon22b779c30111::InternedLogMessageBodyHashed2563 static void Add(perfetto::protos::pbzero::InternedData* interned_data,
2564 size_t iid,
2565 const std::string& value) {
2566 auto l = interned_data->add_log_message_body();
2567 l->set_iid(iid);
2568 l->set_body(value.data(), value.size());
2569 }
2570 };
2571
TEST_P(PerfettoApiTest,TrackEventTypedArgsWithInterningByHashing)2572 TEST_P(PerfettoApiTest, TrackEventTypedArgsWithInterningByHashing) {
2573 // Create a new trace session.
2574 auto* tracing_session = NewTraceWithCategories({"foo"});
2575 tracing_session->get()->StartBlocking();
2576
2577 size_t body_iid;
2578 TRACE_EVENT_BEGIN("foo", "EventWithState", [&](perfetto::EventContext ctx) {
2579 // Test using a dynamically created interned value.
2580 body_iid = InternedLogMessageBodyHashed::Get(
2581 &ctx, std::string("Though this ") + "be madness,");
2582 auto log = ctx.event()->set_log_message();
2583 log->set_body_iid(body_iid);
2584
2585 auto body_iid2 =
2586 InternedLogMessageBodyHashed::Get(&ctx, "Though this be madness,");
2587 EXPECT_EQ(body_iid, body_iid2);
2588
2589 auto body_iid3 =
2590 InternedLogMessageBodyHashed::Get(&ctx, "yet there is method in’t");
2591 EXPECT_NE(body_iid, body_iid3);
2592 });
2593 TRACE_EVENT_END("foo");
2594
2595 tracing_session->get()->StopBlocking();
2596 auto log_messages = ReadLogMessagesFromTrace(tracing_session->get());
2597 EXPECT_THAT(log_messages, ElementsAre("Though this be madness,"));
2598 }
2599
2600 struct InternedSourceLocation
2601 : public perfetto::TrackEventInternedDataIndex<
2602 InternedSourceLocation,
2603 perfetto::protos::pbzero::InternedData::kSourceLocationsFieldNumber,
2604 SourceLocation> {
Add__anon22b779c30111::InternedSourceLocation2605 static void Add(perfetto::protos::pbzero::InternedData* interned_data,
2606 size_t iid,
2607 const SourceLocation& value) {
2608 auto l = interned_data->add_source_locations();
2609 auto file_name = std::get<0>(value);
2610 auto function_name = std::get<1>(value);
2611 auto line_number = std::get<2>(value);
2612 l->set_iid(iid);
2613 l->set_file_name(file_name);
2614 l->set_function_name(function_name);
2615 l->set_line_number(line_number);
2616 }
2617 };
2618
TEST_P(PerfettoApiTest,TrackEventTypedArgsWithInterningComplexValue)2619 TEST_P(PerfettoApiTest, TrackEventTypedArgsWithInterningComplexValue) {
2620 // Create a new trace session.
2621 auto* tracing_session = NewTraceWithCategories({"foo"});
2622 tracing_session->get()->StartBlocking();
2623
2624 TRACE_EVENT_BEGIN("foo", "EventWithState", [&](perfetto::EventContext ctx) {
2625 const SourceLocation location{"file.cc", "SomeFunction", 123};
2626 auto location_iid = InternedSourceLocation::Get(&ctx, location);
2627 auto body_iid = InternedLogMessageBody::Get(&ctx, "To be, or not to be");
2628 auto log = ctx.event()->set_log_message();
2629 log->set_source_location_iid(location_iid);
2630 log->set_body_iid(body_iid);
2631
2632 auto location_iid2 = InternedSourceLocation::Get(&ctx, location);
2633 EXPECT_EQ(location_iid, location_iid2);
2634
2635 const SourceLocation location2{"file.cc", "SomeFunction", 456};
2636 auto location_iid3 = InternedSourceLocation::Get(&ctx, location2);
2637 EXPECT_NE(location_iid, location_iid3);
2638 });
2639 TRACE_EVENT_END("foo");
2640
2641 tracing_session->get()->StopBlocking();
2642 auto log_messages = ReadLogMessagesFromTrace(tracing_session->get());
2643 EXPECT_THAT(log_messages,
2644 ElementsAre("SomeFunction(file.cc:123): To be, or not to be"));
2645 }
2646
TEST_P(PerfettoApiTest,TrackEventScoped)2647 TEST_P(PerfettoApiTest, TrackEventScoped) {
2648 // Create a new trace session.
2649 auto* tracing_session = NewTraceWithCategories({"test"});
2650 tracing_session->get()->StartBlocking();
2651
2652 {
2653 uint64_t arg = 123;
2654 TRACE_EVENT("test", "TestEventWithArgs", [&](perfetto::EventContext ctx) {
2655 ctx.event()->set_log_message()->set_body_iid(arg);
2656 });
2657 }
2658
2659 // Ensure a single line if statement counts as a valid scope for the macro.
2660 if (true)
2661 TRACE_EVENT("test", "SingleLineTestEvent");
2662
2663 {
2664 // Make sure you can have multiple scoped events in the same scope.
2665 TRACE_EVENT("test", "TestEvent");
2666 TRACE_EVENT("test", "AnotherEvent");
2667 TRACE_EVENT("foo", "DisabledEvent");
2668 }
2669 perfetto::TrackEvent::Flush();
2670
2671 tracing_session->get()->StopBlocking();
2672 auto slices = ReadSlicesFromTrace(tracing_session->get());
2673 EXPECT_THAT(
2674 slices,
2675 ElementsAre("B:test.TestEventWithArgs", "E", "B:test.SingleLineTestEvent",
2676 "E", "B:test.TestEvent", "B:test.AnotherEvent", "E", "E"));
2677 }
2678
2679 // A class similar to what Protozero generates for extended message.
2680 class TestTrackEvent : public perfetto::protos::pbzero::TrackEvent {
2681 public:
2682 static const int field_number = 9901;
2683
set_extension_value(int value)2684 void set_extension_value(int value) {
2685 // 9900-10000 is the range of extension field numbers reserved for testing.
2686 AppendTinyVarInt(field_number, value);
2687 }
2688 };
2689
TEST_P(PerfettoApiTest,ExtensionClass)2690 TEST_P(PerfettoApiTest, ExtensionClass) {
2691 auto* tracing_session = NewTraceWithCategories({"test"});
2692 tracing_session->get()->StartBlocking();
2693
2694 {
2695 TRACE_EVENT("test", "TestEventWithExtensionArgs",
2696 [&](perfetto::EventContext ctx) {
2697 ctx.event<perfetto::protos::pbzero::TestExtension>()
2698 ->add_int_extension_for_testing(42);
2699 });
2700 }
2701
2702 perfetto::TrackEvent::Flush();
2703 tracing_session->get()->StopBlocking();
2704
2705 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
2706 EXPECT_GE(raw_trace.size(), 0u);
2707
2708 bool found_extension = false;
2709 perfetto::protos::pbzero::Trace_Decoder trace(
2710 reinterpret_cast<uint8_t*>(raw_trace.data()), raw_trace.size());
2711
2712 for (auto it = trace.packet(); it; ++it) {
2713 perfetto::protos::pbzero::TracePacket_Decoder packet(it->data(),
2714 it->size());
2715
2716 if (!packet.has_track_event())
2717 continue;
2718
2719 auto track_event = packet.track_event();
2720 protozero::ProtoDecoder decoder(track_event.data, track_event.size);
2721
2722 for (protozero::Field f = decoder.ReadField(); f.valid();
2723 f = decoder.ReadField()) {
2724 if (f.id() == perfetto::protos::pbzero::TestExtension::
2725 FieldMetadata_IntExtensionForTesting::kFieldId) {
2726 found_extension = true;
2727 }
2728 }
2729 }
2730
2731 EXPECT_TRUE(found_extension);
2732 }
2733
TEST_P(PerfettoApiTest,InlineTypedExtensionField)2734 TEST_P(PerfettoApiTest, InlineTypedExtensionField) {
2735 auto* tracing_session = NewTraceWithCategories({"test"});
2736 tracing_session->get()->StartBlocking();
2737
2738 {
2739 TRACE_EVENT(
2740 "test", "TestEventWithExtensionArgs",
2741 perfetto::protos::pbzero::TestExtension::kIntExtensionForTesting,
2742 std::vector<int>{42});
2743 }
2744
2745 perfetto::TrackEvent::Flush();
2746 tracing_session->get()->StopBlocking();
2747
2748 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
2749 EXPECT_GE(raw_trace.size(), 0u);
2750
2751 bool found_extension = false;
2752 perfetto::protos::pbzero::Trace_Decoder trace(
2753 reinterpret_cast<uint8_t*>(raw_trace.data()), raw_trace.size());
2754
2755 for (auto it = trace.packet(); it; ++it) {
2756 perfetto::protos::pbzero::TracePacket_Decoder packet(it->data(),
2757 it->size());
2758
2759 if (!packet.has_track_event())
2760 continue;
2761
2762 auto track_event = packet.track_event();
2763 protozero::ProtoDecoder decoder(track_event.data, track_event.size);
2764
2765 for (protozero::Field f = decoder.ReadField(); f.valid();
2766 f = decoder.ReadField()) {
2767 if (f.id() == perfetto::protos::pbzero::TestExtension::
2768 FieldMetadata_IntExtensionForTesting::kFieldId) {
2769 found_extension = true;
2770 }
2771 }
2772 }
2773
2774 EXPECT_TRUE(found_extension);
2775 }
2776
TEST_P(PerfettoApiTest,TrackEventInstant)2777 TEST_P(PerfettoApiTest, TrackEventInstant) {
2778 // Create a new trace session.
2779 auto* tracing_session = NewTraceWithCategories({"test"});
2780 tracing_session->get()->StartBlocking();
2781
2782 TRACE_EVENT_INSTANT("test", "TestEvent");
2783 TRACE_EVENT_INSTANT("test", "AnotherEvent");
2784 perfetto::TrackEvent::Flush();
2785
2786 tracing_session->get()->StopBlocking();
2787 auto slices = ReadSlicesFromTrace(tracing_session->get());
2788 EXPECT_THAT(slices, ElementsAre("I:test.TestEvent", "I:test.AnotherEvent"));
2789 }
2790
TEST_P(PerfettoApiTest,TrackEventDefaultGlobalTrack)2791 TEST_P(PerfettoApiTest, TrackEventDefaultGlobalTrack) {
2792 // Create a new trace session.
2793 auto* tracing_session = NewTraceWithCategories({"test"});
2794 tracing_session->get()->StartBlocking();
2795
2796 TRACE_EVENT_INSTANT("test", "ThreadEvent");
2797 TRACE_EVENT_INSTANT("test", "GlobalEvent", perfetto::Track::Global(0u));
2798 perfetto::TrackEvent::Flush();
2799
2800 tracing_session->get()->StopBlocking();
2801 auto slices = ReadSlicesFromTrace(tracing_session->get());
2802 EXPECT_THAT(slices,
2803 ElementsAre("I:test.ThreadEvent", "[track=0]I:test.GlobalEvent"));
2804 }
2805
TEST_P(PerfettoApiTest,TrackEventTrackFromPointer)2806 TEST_P(PerfettoApiTest, TrackEventTrackFromPointer) {
2807 // Create a new trace session.
2808 auto* tracing_session = NewTraceWithCategories({"test"});
2809 tracing_session->get()->StartBlocking();
2810
2811 perfetto::Track parent_track(1);
2812 int* ptr = reinterpret_cast<int*>(2);
2813 TRACE_EVENT_INSTANT("test", "Event",
2814 perfetto::Track::FromPointer(ptr, parent_track));
2815 perfetto::TrackEvent::Flush();
2816
2817 perfetto::Track track(reinterpret_cast<uintptr_t>(ptr), parent_track);
2818
2819 tracing_session->get()->StopBlocking();
2820 auto slices = ReadSlicesFromTrace(tracing_session->get());
2821 EXPECT_THAT(slices, ElementsAre("[track=" + std::to_string(track.uuid) +
2822 "]I:test.Event"));
2823 }
2824
TEST_P(PerfettoApiTest,TrackEventTrackFromThreadScopedPointer)2825 TEST_P(PerfettoApiTest, TrackEventTrackFromThreadScopedPointer) {
2826 // Create a new trace session.
2827 auto* tracing_session = NewTraceWithCategories({"test"});
2828 tracing_session->get()->StartBlocking();
2829
2830 int num = 2;
2831 TRACE_EVENT_INSTANT("test", "Event0.1");
2832 TRACE_EVENT_INSTANT("test", "Event0.2");
2833 TRACE_EVENT_INSTANT("test", "Event1.1", perfetto::Track::ThreadScoped(&num));
2834 TRACE_EVENT_INSTANT("test", "Event1.2", perfetto::Track::ThreadScoped(&num));
2835 std::thread t1([&]() {
2836 TRACE_EVENT_INSTANT("test", "Event2.1",
2837 perfetto::Track::ThreadScoped(&num));
2838 TRACE_EVENT_INSTANT("test", "Event2.2",
2839 perfetto::Track::ThreadScoped(&num));
2840 });
2841 t1.join();
2842 std::thread t2([&]() {
2843 TRACE_EVENT_INSTANT("test", "Event3.1",
2844 perfetto::Track::ThreadScoped(&num));
2845 TRACE_EVENT_INSTANT("test", "Event3.2",
2846 perfetto::Track::ThreadScoped(&num));
2847 });
2848 t2.join();
2849 perfetto::TrackEvent::Flush();
2850 tracing_session->get()->StopBlocking();
2851 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
2852 perfetto::protos::gen::Trace parsed_trace;
2853 ASSERT_TRUE(parsed_trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
2854
2855 std::unordered_map<std::string, uint64_t> track_uuid_map;
2856 for (auto packet : parsed_trace.packet()) {
2857 if (packet.has_interned_data()) {
2858 for (auto& ename : packet.interned_data().event_names()) {
2859 track_uuid_map.emplace(ename.name(), packet.track_event().track_uuid());
2860 }
2861 }
2862 }
2863 EXPECT_EQ(track_uuid_map.at("Event0.1"), track_uuid_map.at("Event0.2"));
2864 EXPECT_EQ(track_uuid_map.at("Event1.1"), track_uuid_map.at("Event1.2"));
2865 EXPECT_EQ(track_uuid_map.at("Event2.1"), track_uuid_map.at("Event2.2"));
2866 EXPECT_EQ(track_uuid_map.at("Event3.1"), track_uuid_map.at("Event3.2"));
2867
2868 EXPECT_EQ(4u,
2869 (std::unordered_set<uint64_t>{
2870 track_uuid_map.at("Event0.1"), track_uuid_map.at("Event1.1"),
2871 track_uuid_map.at("Event2.1"), track_uuid_map.at("Event3.1")})
2872 .size());
2873 }
2874
TEST_P(PerfettoApiTest,FilterDebugAnnotations)2875 TEST_P(PerfettoApiTest, FilterDebugAnnotations) {
2876 for (auto flag : {false, true}) {
2877 // Create a new trace session.
2878 perfetto::protos::gen::TrackEventConfig te_cfg;
2879 te_cfg.set_filter_debug_annotations(flag);
2880 auto* tracing_session = NewTraceWithCategories({"test"}, te_cfg);
2881 tracing_session->get()->StartBlocking();
2882
2883 TRACE_EVENT_BEGIN("test", "Event1");
2884 TRACE_EVENT_BEGIN("test", "Event2", [&](perfetto::EventContext ctx) {
2885 ctx.AddDebugAnnotation("debug_name", "debug_value");
2886 });
2887 TRACE_EVENT_BEGIN("test", "Event3");
2888 perfetto::TrackEvent::Flush();
2889 tracing_session->get()->StopBlocking();
2890
2891 auto slices = ReadSlicesFromTrace(tracing_session->get());
2892 ASSERT_EQ(3u, slices.size());
2893 if (flag) {
2894 EXPECT_EQ("B:test.Event2", slices[1]);
2895 } else {
2896 EXPECT_EQ("B:test.Event2(debug_name=(string)debug_value)", slices[1]);
2897 }
2898 }
2899 }
2900
TEST_P(PerfettoApiTest,TrackEventDebugAnnotations)2901 TEST_P(PerfettoApiTest, TrackEventDebugAnnotations) {
2902 // Create a new trace session.
2903 auto* tracing_session = NewTraceWithCategories({"test"});
2904 tracing_session->get()->StartBlocking();
2905
2906 enum MyEnum : uint32_t { ENUM_FOO, ENUM_BAR };
2907 enum MySignedEnum : int32_t { SIGNED_ENUM_FOO = -1, SIGNED_ENUM_BAR };
2908 enum class MyClassEnum { VALUE };
2909
2910 TRACE_EVENT_BEGIN("test", "E", "bool_arg", false);
2911 TRACE_EVENT_BEGIN("test", "E", "int_arg", -123);
2912 TRACE_EVENT_BEGIN("test", "E", "uint_arg", 456u);
2913 TRACE_EVENT_BEGIN("test", "E", "float_arg", 3.14159262f);
2914 TRACE_EVENT_BEGIN("test", "E", "double_arg", 6.22);
2915 TRACE_EVENT_BEGIN("test", "E", "str_arg", "hello", "str_arg2",
2916 std::string("tracing"));
2917 TRACE_EVENT_BEGIN("test", "E", "ptr_arg",
2918 reinterpret_cast<void*>(static_cast<intptr_t>(0xbaadf00d)));
2919 TRACE_EVENT_BEGIN("test", "E", "size_t_arg", size_t{42});
2920 TRACE_EVENT_BEGIN("test", "E", "ptrdiff_t_arg", ptrdiff_t{-7});
2921 TRACE_EVENT_BEGIN("test", "E", "enum_arg", ENUM_BAR);
2922 TRACE_EVENT_BEGIN("test", "E", "signed_enum_arg", SIGNED_ENUM_FOO);
2923 TRACE_EVENT_BEGIN("test", "E", "class_enum_arg", MyClassEnum::VALUE);
2924 TRACE_EVENT_BEGIN("test", "E", "traced_value",
2925 [&](perfetto::TracedValue context) {
2926 std::move(context).WriteInt64(42);
2927 });
2928 TRACE_EVENT_BEGIN("test", "E", [&](perfetto::EventContext ctx) {
2929 ctx.AddDebugAnnotation("debug_annotation", "value");
2930 });
2931 perfetto::TrackEvent::Flush();
2932
2933 tracing_session->get()->StopBlocking();
2934 auto slices = ReadSlicesFromTrace(tracing_session->get());
2935 EXPECT_THAT(
2936 slices,
2937 ElementsAre(
2938 "B:test.E(bool_arg=(bool)0)", "B:test.E(int_arg=(int)-123)",
2939 "B:test.E(uint_arg=(uint)456)", "B:test.E(float_arg=(double)3.14159)",
2940 "B:test.E(double_arg=(double)6.22)",
2941 "B:test.E(str_arg=(string)hello,str_arg2=(string)tracing)",
2942 "B:test.E(ptr_arg=(pointer)baadf00d)",
2943 "B:test.E(size_t_arg=(uint)42)", "B:test.E(ptrdiff_t_arg=(int)-7)",
2944 "B:test.E(enum_arg=(uint)1)", "B:test.E(signed_enum_arg=(int)-1)",
2945 "B:test.E(class_enum_arg=(int)0)", "B:test.E(traced_value=(int)42)",
2946 "B:test.E(debug_annotation=(string)value)"));
2947 }
2948
TEST_P(PerfettoApiTest,TrackEventCustomDebugAnnotations)2949 TEST_P(PerfettoApiTest, TrackEventCustomDebugAnnotations) {
2950 // Create a new trace session.
2951 auto* tracing_session = NewTraceWithCategories({"test"});
2952 tracing_session->get()->StartBlocking();
2953
2954 std::unique_ptr<MyDebugAnnotation> owned_annotation(new MyDebugAnnotation());
2955
2956 TRACE_EVENT_BEGIN("test", "E", "custom_arg", MyDebugAnnotation());
2957 TRACE_EVENT_BEGIN("test", "E", "normal_arg", "x", "custom_arg",
2958 std::move(owned_annotation));
2959 perfetto::TrackEvent::Flush();
2960
2961 tracing_session->get()->StopBlocking();
2962 auto slices = ReadSlicesFromTrace(tracing_session->get());
2963 EXPECT_THAT(
2964 slices,
2965 ElementsAre(
2966 R"(B:test.E(custom_arg=(json){"key": 123}))",
2967 R"(B:test.E(normal_arg=(string)x,custom_arg=(json){"key": 123}))"));
2968 }
2969
TEST_P(PerfettoApiTest,TrackEventCustomRawDebugAnnotations)2970 TEST_P(PerfettoApiTest, TrackEventCustomRawDebugAnnotations) {
2971 // Note: this class is also testing a non-moveable and non-copiable argument.
2972 class MyRawDebugAnnotation : public perfetto::DebugAnnotation {
2973 public:
2974 MyRawDebugAnnotation() { msg_->set_string_value("nested_value"); }
2975 ~MyRawDebugAnnotation() = default;
2976
2977 // |msg_| already deletes these implicitly, but let's be explicit for safety
2978 // against future changes.
2979 MyRawDebugAnnotation(const MyRawDebugAnnotation&) = delete;
2980 MyRawDebugAnnotation(MyRawDebugAnnotation&&) = delete;
2981
2982 void Add(perfetto::protos::pbzero::DebugAnnotation* annotation) const {
2983 auto ranges = msg_.GetRanges();
2984 annotation->AppendScatteredBytes(
2985 perfetto::protos::pbzero::DebugAnnotation::kNestedValueFieldNumber,
2986 &ranges[0], ranges.size());
2987 }
2988
2989 private:
2990 mutable protozero::HeapBuffered<
2991 perfetto::protos::pbzero::DebugAnnotation::NestedValue>
2992 msg_;
2993 };
2994
2995 // Create a new trace session.
2996 auto* tracing_session = NewTraceWithCategories({"test"});
2997 tracing_session->get()->StartBlocking();
2998
2999 TRACE_EVENT_BEGIN("test", "E", "raw_arg", MyRawDebugAnnotation());
3000 TRACE_EVENT_BEGIN("test", "E", "plain_arg", 42, "raw_arg",
3001 MyRawDebugAnnotation());
3002 perfetto::TrackEvent::Flush();
3003
3004 tracing_session->get()->StopBlocking();
3005 auto slices = ReadSlicesFromTrace(tracing_session->get());
3006 EXPECT_THAT(
3007 slices,
3008 ElementsAre("B:test.E(raw_arg=(nested)nested_value)",
3009 "B:test.E(plain_arg=(int)42,raw_arg=(nested)nested_value)"));
3010 }
3011
TEST_P(PerfettoApiTest,ManyDebugAnnotations)3012 TEST_P(PerfettoApiTest, ManyDebugAnnotations) {
3013 // Create a new trace session.
3014 auto* tracing_session = NewTraceWithCategories({"test"});
3015 tracing_session->get()->StartBlocking();
3016
3017 TRACE_EVENT_BEGIN("test", "E", "arg1", 1, "arg2", 2, "arg3", 3);
3018 perfetto::TrackEvent::Flush();
3019
3020 tracing_session->get()->StopBlocking();
3021 auto slices = ReadSlicesFromTrace(tracing_session->get());
3022 EXPECT_THAT(slices,
3023 ElementsAre("B:test.E(arg1=(int)1,arg2=(int)2,arg3=(int)3)"));
3024 }
3025
TEST_P(PerfettoApiTest,DebugAnnotationAndLambda)3026 TEST_P(PerfettoApiTest, DebugAnnotationAndLambda) {
3027 // Create a new trace session.
3028 auto* tracing_session = NewTraceWithCategories({"test"});
3029 tracing_session->get()->StartBlocking();
3030
3031 enum MyEnum : uint32_t { ENUM_FOO, ENUM_BAR };
3032 enum MySignedEnum : int32_t { SIGNED_ENUM_FOO = -1, SIGNED_ENUM_BAR };
3033 enum class MyClassEnum { VALUE };
3034
3035 TRACE_EVENT_BEGIN(
3036 "test", "E", "key", "value", [](perfetto::EventContext ctx) {
3037 ctx.event()->set_log_message()->set_source_location_iid(42);
3038 });
3039 perfetto::TrackEvent::Flush();
3040
3041 tracing_session->get()->StopBlocking();
3042 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
3043 std::string trace(raw_trace.data(), raw_trace.size());
3044
3045 perfetto::protos::gen::Trace parsed_trace;
3046 ASSERT_TRUE(parsed_trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
3047
3048 bool found_args = false;
3049 for (const auto& packet : parsed_trace.packet()) {
3050 if (!packet.has_track_event())
3051 continue;
3052 const auto& track_event = packet.track_event();
3053 if (track_event.type() !=
3054 perfetto::protos::gen::TrackEvent::TYPE_SLICE_BEGIN)
3055 continue;
3056
3057 EXPECT_TRUE(track_event.has_log_message());
3058 const auto& log = track_event.log_message();
3059 EXPECT_EQ(42u, log.source_location_iid());
3060
3061 const auto& dbg = track_event.debug_annotations()[0];
3062 EXPECT_EQ("value", dbg.string_value());
3063
3064 found_args = true;
3065 }
3066 EXPECT_TRUE(found_args);
3067 }
3068
TEST_P(PerfettoApiTest,ProtoInsideDebugAnnotation)3069 TEST_P(PerfettoApiTest, ProtoInsideDebugAnnotation) {
3070 auto* tracing_session = NewTraceWithCategories({"test"});
3071 tracing_session->get()->StartBlocking();
3072
3073 TRACE_EVENT_INSTANT(
3074 "test", "E", "key",
3075 [](perfetto::TracedProto<perfetto::protos::pbzero::LogMessage> ctx) {
3076 ctx->set_source_location_iid(42);
3077 });
3078
3079 perfetto::TrackEvent::Flush();
3080
3081 tracing_session->get()->StopBlocking();
3082 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
3083 std::string trace(raw_trace.data(), raw_trace.size());
3084
3085 perfetto::protos::gen::Trace parsed_trace;
3086 ASSERT_TRUE(parsed_trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
3087
3088 std::vector<std::string> interned_debug_annotation_names;
3089 std::vector<std::string> interned_debug_annotation_proto_type_names;
3090
3091 bool found_args = false;
3092 for (const auto& packet : parsed_trace.packet()) {
3093 if (packet.has_interned_data()) {
3094 for (const auto& interned_name :
3095 packet.interned_data().debug_annotation_names()) {
3096 interned_debug_annotation_names.push_back(interned_name.name());
3097 }
3098 for (const auto& interned_type_name :
3099 packet.interned_data().debug_annotation_value_type_names()) {
3100 interned_debug_annotation_proto_type_names.push_back(
3101 interned_type_name.name());
3102 }
3103 }
3104
3105 if (!packet.has_track_event())
3106 continue;
3107 const auto& track_event = packet.track_event();
3108 if (track_event.type() != perfetto::protos::gen::TrackEvent::TYPE_INSTANT) {
3109 continue;
3110 }
3111
3112 EXPECT_EQ(track_event.debug_annotations_size(), 1);
3113 found_args = true;
3114 }
3115 // TODO(altimin): Use DebugAnnotationParser here to parse the debug
3116 // annotations.
3117 EXPECT_TRUE(found_args);
3118 EXPECT_THAT(interned_debug_annotation_names,
3119 testing::UnorderedElementsAre("key"));
3120 EXPECT_THAT(interned_debug_annotation_proto_type_names,
3121 testing::UnorderedElementsAre(".perfetto.protos.LogMessage"));
3122 }
3123
TEST_P(PerfettoApiTest,TrackEventComputedName)3124 TEST_P(PerfettoApiTest, TrackEventComputedName) {
3125 // Setup the trace config.
3126 perfetto::TraceConfig cfg;
3127 cfg.set_duration_ms(500);
3128 cfg.add_buffers()->set_size_kb(1024);
3129 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
3130 ds_cfg->set_name("track_event");
3131
3132 // Create a new trace session.
3133 auto* tracing_session = NewTrace(cfg);
3134 tracing_session->get()->StartBlocking();
3135
3136 // New macros require perfetto::StaticString{} annotation.
3137 for (int i = 0; i < 3; i++)
3138 TRACE_EVENT_BEGIN("test", perfetto::StaticString{i % 2 ? "Odd" : "Even"});
3139
3140 // Legacy macros assume all arguments are static strings.
3141 for (int i = 0; i < 3; i++)
3142 TRACE_EVENT_BEGIN0("test", i % 2 ? "Odd" : "Even");
3143
3144 perfetto::TrackEvent::Flush();
3145
3146 tracing_session->get()->StopBlocking();
3147 auto slices = ReadSlicesFromTrace(tracing_session->get());
3148 EXPECT_THAT(slices, ElementsAre("B:test.Even", "B:test.Odd", "B:test.Even",
3149 "B:test.Even", "B:test.Odd", "B:test.Even"));
3150 }
3151
TEST_P(PerfettoApiTest,TrackEventArgumentsNotEvaluatedWhenDisabled)3152 TEST_P(PerfettoApiTest, TrackEventArgumentsNotEvaluatedWhenDisabled) {
3153 // Create a new trace session.
3154 auto* tracing_session = NewTraceWithCategories({"foo"});
3155 tracing_session->get()->StartBlocking();
3156
3157 bool called = false;
3158 auto ArgumentFunction = [&] {
3159 called = true;
3160 return 123;
3161 };
3162
3163 TRACE_EVENT_BEGIN("test", "DisabledEvent", "arg", ArgumentFunction());
3164 { TRACE_EVENT("test", "DisabledScopedEvent", "arg", ArgumentFunction()); }
3165 perfetto::TrackEvent::Flush();
3166
3167 tracing_session->get()->StopBlocking();
3168 EXPECT_FALSE(called);
3169
3170 ArgumentFunction();
3171 EXPECT_TRUE(called);
3172 }
3173
TEST_P(PerfettoApiTest,TrackEventConfig)3174 TEST_P(PerfettoApiTest, TrackEventConfig) {
3175 auto check_config = [&](perfetto::protos::gen::TrackEventConfig te_cfg) {
3176 perfetto::TraceConfig cfg;
3177 cfg.set_duration_ms(500);
3178 cfg.add_buffers()->set_size_kb(1024);
3179 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
3180 ds_cfg->set_name("track_event");
3181 ds_cfg->set_track_event_config_raw(te_cfg.SerializeAsString());
3182
3183 auto* tracing_session = NewTrace(cfg);
3184 tracing_session->get()->StartBlocking();
3185
3186 TRACE_EVENT_BEGIN("foo", "FooEvent");
3187 TRACE_EVENT_BEGIN("bar", "BarEvent");
3188 TRACE_EVENT_BEGIN("foo,bar", "MultiFooBar");
3189 TRACE_EVENT_BEGIN("baz,bar,quux", "MultiBar");
3190 TRACE_EVENT_BEGIN("red,green,blue,foo", "MultiFoo");
3191 TRACE_EVENT_BEGIN("red,green,blue,yellow", "MultiNone");
3192 TRACE_EVENT_BEGIN("cat", "SlowEvent");
3193 TRACE_EVENT_BEGIN("cat.verbose", "DebugEvent");
3194 TRACE_EVENT_BEGIN("test", "TagEvent");
3195 TRACE_EVENT_BEGIN(TRACE_DISABLED_BY_DEFAULT("cat"), "SlowDisabledEvent");
3196 TRACE_EVENT_BEGIN("dynamic,foo", "DynamicGroupFooEvent");
3197 perfetto::DynamicCategory dyn{"dynamic,bar"};
3198 TRACE_EVENT_BEGIN(dyn, "DynamicGroupBarEvent");
3199
3200 perfetto::TrackEvent::Flush();
3201 tracing_session->get()->StopBlocking();
3202 auto slices = ReadSlicesFromTrace(tracing_session->get());
3203 tracing_session->session.reset();
3204 return slices;
3205 };
3206
3207 // Empty config should enable all categories except slow ones.
3208 {
3209 perfetto::protos::gen::TrackEventConfig te_cfg;
3210 auto slices = check_config(te_cfg);
3211 EXPECT_THAT(
3212 slices,
3213 ElementsAre("B:foo.FooEvent", "B:bar.BarEvent", "B:foo,bar.MultiFooBar",
3214 "B:baz,bar,quux.MultiBar", "B:red,green,blue,foo.MultiFoo",
3215 "B:red,green,blue,yellow.MultiNone", "B:test.TagEvent",
3216 "B:$dynamic,$foo.DynamicGroupFooEvent",
3217 "B:$dynamic,$bar.DynamicGroupBarEvent"));
3218 }
3219
3220 // Enable exactly one category.
3221 {
3222 perfetto::protos::gen::TrackEventConfig te_cfg;
3223 te_cfg.add_disabled_categories("*");
3224 te_cfg.add_enabled_categories("foo");
3225 auto slices = check_config(te_cfg);
3226 EXPECT_THAT(slices, ElementsAre("B:foo.FooEvent", "B:foo,bar.MultiFooBar",
3227 "B:red,green,blue,foo.MultiFoo",
3228 "B:$dynamic,$foo.DynamicGroupFooEvent"));
3229 }
3230
3231 // Enable exactly one dynamic category.
3232 {
3233 perfetto::protos::gen::TrackEventConfig te_cfg;
3234 te_cfg.add_disabled_categories("*");
3235 te_cfg.add_enabled_categories("dynamic");
3236 auto slices = check_config(te_cfg);
3237 EXPECT_THAT(slices, ElementsAre("B:$dynamic,$foo.DynamicGroupFooEvent",
3238 "B:$dynamic,$bar.DynamicGroupBarEvent"));
3239 }
3240
3241 // Enable two categories.
3242 {
3243 perfetto::protos::gen::TrackEventConfig te_cfg;
3244 te_cfg.add_disabled_categories("*");
3245 te_cfg.add_enabled_categories("foo");
3246 te_cfg.add_enabled_categories("baz");
3247 te_cfg.add_enabled_categories("bar");
3248 auto slices = check_config(te_cfg);
3249 EXPECT_THAT(
3250 slices,
3251 ElementsAre("B:foo.FooEvent", "B:bar.BarEvent", "B:foo,bar.MultiFooBar",
3252 "B:baz,bar,quux.MultiBar", "B:red,green,blue,foo.MultiFoo",
3253 "B:$dynamic,$foo.DynamicGroupFooEvent",
3254 "B:$dynamic,$bar.DynamicGroupBarEvent"));
3255 }
3256
3257 // Enabling all categories with a pattern doesn't enable slow ones.
3258 {
3259 perfetto::protos::gen::TrackEventConfig te_cfg;
3260 te_cfg.add_enabled_categories("*");
3261 auto slices = check_config(te_cfg);
3262 EXPECT_THAT(
3263 slices,
3264 ElementsAre("B:foo.FooEvent", "B:bar.BarEvent", "B:foo,bar.MultiFooBar",
3265 "B:baz,bar,quux.MultiBar", "B:red,green,blue,foo.MultiFoo",
3266 "B:red,green,blue,yellow.MultiNone", "B:test.TagEvent",
3267 "B:$dynamic,$foo.DynamicGroupFooEvent",
3268 "B:$dynamic,$bar.DynamicGroupBarEvent"));
3269 }
3270
3271 // Enable with a pattern.
3272 {
3273 perfetto::protos::gen::TrackEventConfig te_cfg;
3274 te_cfg.add_disabled_categories("*");
3275 te_cfg.add_enabled_categories("fo*");
3276 auto slices = check_config(te_cfg);
3277 EXPECT_THAT(slices, ElementsAre("B:foo.FooEvent", "B:foo,bar.MultiFooBar",
3278 "B:red,green,blue,foo.MultiFoo",
3279 "B:$dynamic,$foo.DynamicGroupFooEvent"));
3280 }
3281
3282 // Enable with a tag.
3283 {
3284 perfetto::protos::gen::TrackEventConfig te_cfg;
3285 te_cfg.add_disabled_categories("*");
3286 te_cfg.add_enabled_tags("tag");
3287 auto slices = check_config(te_cfg);
3288 EXPECT_THAT(slices, ElementsAre("B:test.TagEvent"));
3289 }
3290
3291 // Enable just slow categories.
3292 {
3293 perfetto::protos::gen::TrackEventConfig te_cfg;
3294 te_cfg.add_disabled_categories("*");
3295 te_cfg.add_enabled_tags("slow");
3296 auto slices = check_config(te_cfg);
3297 EXPECT_THAT(slices,
3298 ElementsAre("B:cat.SlowEvent",
3299 "B:disabled-by-default-cat.SlowDisabledEvent"));
3300 }
3301
3302 // Enable everything including slow/debug categories.
3303 {
3304 perfetto::protos::gen::TrackEventConfig te_cfg;
3305 te_cfg.add_enabled_categories("*");
3306 te_cfg.add_enabled_tags("slow");
3307 te_cfg.add_enabled_tags("debug");
3308 auto slices = check_config(te_cfg);
3309 EXPECT_THAT(
3310 slices,
3311 ElementsAre("B:foo.FooEvent", "B:bar.BarEvent", "B:foo,bar.MultiFooBar",
3312 "B:baz,bar,quux.MultiBar", "B:red,green,blue,foo.MultiFoo",
3313 "B:red,green,blue,yellow.MultiNone", "B:cat.SlowEvent",
3314 "B:cat.verbose.DebugEvent", "B:test.TagEvent",
3315 "B:disabled-by-default-cat.SlowDisabledEvent",
3316 "B:$dynamic,$foo.DynamicGroupFooEvent",
3317 "B:$dynamic,$bar.DynamicGroupBarEvent"));
3318 }
3319 }
3320
TEST_P(PerfettoApiTest,OneDataSourceOneEvent)3321 TEST_P(PerfettoApiTest, OneDataSourceOneEvent) {
3322 auto* data_source = &data_sources_["my_data_source"];
3323
3324 // Setup the trace config.
3325 perfetto::TraceConfig cfg;
3326 cfg.set_duration_ms(500);
3327 cfg.add_buffers()->set_size_kb(1024);
3328 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
3329 ds_cfg->set_name("my_data_source");
3330 ds_cfg->set_legacy_config("test config");
3331
3332 // Create a new trace session.
3333 auto* tracing_session = NewTrace(cfg);
3334
3335 MockDataSource::Trace([](MockDataSource::TraceContext) {
3336 FAIL() << "Should not be called because the trace was not started";
3337 });
3338 MockDataSource::CallIfEnabled([](uint32_t) {
3339 FAIL() << "Should not be called because the trace was not started";
3340 });
3341
3342 tracing_session->get()->Start();
3343 data_source->on_setup.Wait();
3344 EXPECT_EQ(data_source->config.legacy_config(), "test config");
3345 data_source->on_start.Wait();
3346
3347 // Emit one trace event.
3348 std::atomic<int> trace_lambda_calls{0};
3349 MockDataSource::Trace(
3350 [&trace_lambda_calls](MockDataSource::TraceContext ctx) {
3351 auto packet = ctx.NewTracePacket();
3352 packet->set_timestamp(42);
3353 packet->set_for_testing()->set_str("event 1");
3354 trace_lambda_calls++;
3355 packet->Finalize();
3356
3357 // The SMB scraping logic will skip the last packet because it cannot
3358 // guarantee it's finalized. Create an empty packet so we get the
3359 // previous one and this empty one is ignored.
3360 packet = ctx.NewTracePacket();
3361 });
3362
3363 uint32_t active_instances = 0;
3364 MockDataSource::CallIfEnabled([&active_instances](uint32_t instances) {
3365 active_instances = instances;
3366 });
3367 EXPECT_EQ(1u, active_instances);
3368
3369 data_source->on_stop.Wait();
3370 tracing_session->on_stop.Wait();
3371 EXPECT_EQ(trace_lambda_calls, 1);
3372
3373 MockDataSource::Trace([](MockDataSource::TraceContext) {
3374 FAIL() << "Should not be called because the trace is now stopped";
3375 });
3376 MockDataSource::CallIfEnabled([](uint32_t) {
3377 FAIL() << "Should not be called because the trace is now stopped";
3378 });
3379
3380 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
3381 ASSERT_GE(raw_trace.size(), 0u);
3382
3383 perfetto::protos::gen::Trace trace;
3384 ASSERT_TRUE(trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
3385 bool test_packet_found = false;
3386 for (const auto& packet : trace.packet()) {
3387 if (!packet.has_for_testing())
3388 continue;
3389 EXPECT_FALSE(test_packet_found);
3390 EXPECT_EQ(packet.timestamp(), 42U);
3391 EXPECT_EQ(packet.for_testing().str(), "event 1");
3392 test_packet_found = true;
3393 }
3394 EXPECT_TRUE(test_packet_found);
3395 }
3396
TEST_P(PerfettoApiTest,ReentrantTracing)3397 TEST_P(PerfettoApiTest, ReentrantTracing) {
3398 auto* data_source = &data_sources_["my_data_source"];
3399
3400 // Setup the trace config.
3401 perfetto::TraceConfig cfg;
3402 cfg.set_duration_ms(500);
3403 cfg.add_buffers()->set_size_kb(1024);
3404 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
3405 ds_cfg->set_name("my_data_source");
3406
3407 // Create a new trace session.
3408 auto* tracing_session = NewTrace(cfg);
3409 tracing_session->get()->Start();
3410 data_source->on_start.Wait();
3411
3412 // Check that only one level of trace lambda calls is allowed.
3413 std::atomic<int> trace_lambda_calls{0};
3414 MockDataSource::Trace([&trace_lambda_calls](MockDataSource::TraceContext) {
3415 trace_lambda_calls++;
3416 MockDataSource::Trace([&trace_lambda_calls](MockDataSource::TraceContext) {
3417 trace_lambda_calls++;
3418 });
3419 });
3420
3421 tracing_session->get()->StopBlocking();
3422 EXPECT_EQ(trace_lambda_calls, 1);
3423 }
3424
TEST_P(PerfettoApiTest,ConsumerFlush)3425 TEST_P(PerfettoApiTest, ConsumerFlush) {
3426 auto* data_source = &data_sources_["my_data_source"];
3427
3428 // Setup the trace config.
3429 perfetto::TraceConfig cfg;
3430 cfg.add_buffers()->set_size_kb(1024);
3431 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
3432 ds_cfg->set_name("my_data_source");
3433 ds_cfg->set_legacy_config("test config");
3434
3435 // Create a new trace session.
3436 auto* tracing_session = NewTrace(cfg);
3437
3438 tracing_session->get()->Start();
3439 data_source->on_start.Wait();
3440
3441 MockDataSource::Trace([&](MockDataSource::TraceContext ctx) {
3442 auto packet = ctx.NewTracePacket();
3443 packet->set_timestamp(42);
3444 packet->set_for_testing()->set_str("flushed event");
3445 packet->Finalize();
3446
3447 // The SMB scraping logic will skip the last packet because it cannot
3448 // guarantee it's finalized. Create an empty packet so we get the
3449 // previous one and this empty one is ignored.
3450 packet = ctx.NewTracePacket();
3451 });
3452
3453 EXPECT_TRUE(tracing_session->get()->FlushBlocking());
3454
3455 // Deliberately doing ReadTraceBlocking() before StopBlocking() to avoid
3456 // hitting the auto scrape-on-stop behavior of the service.
3457 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
3458 tracing_session->get()->StopBlocking();
3459
3460 ASSERT_GE(raw_trace.size(), 0u);
3461 perfetto::protos::gen::Trace trace;
3462 ASSERT_TRUE(trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
3463 bool test_packet_found = false;
3464 for (const auto& packet : trace.packet()) {
3465 if (!packet.has_for_testing())
3466 continue;
3467 EXPECT_FALSE(test_packet_found);
3468 EXPECT_EQ(packet.timestamp(), 42U);
3469 EXPECT_EQ(packet.for_testing().str(), "flushed event");
3470 test_packet_found = true;
3471 }
3472 EXPECT_TRUE(test_packet_found);
3473 }
3474
TEST_P(PerfettoApiTest,WithBatching)3475 TEST_P(PerfettoApiTest, WithBatching) {
3476 auto* data_source = &data_sources_["my_data_source"];
3477
3478 // Setup the trace config.
3479 perfetto::TraceConfig cfg;
3480 cfg.set_duration_ms(500);
3481 cfg.add_buffers()->set_size_kb(1024);
3482 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
3483 ds_cfg->set_name("my_data_source");
3484 ds_cfg->set_legacy_config("test config");
3485
3486 // Create a new trace session.
3487 auto* tracing_session = NewTrace(cfg);
3488
3489 tracing_session->get()->Start();
3490 data_source->on_setup.Wait();
3491 data_source->on_start.Wait();
3492
3493 std::stringstream first_large_message;
3494 for (size_t i = 0; i < 512; i++)
3495 first_large_message << i << ". Something wicked this way comes. ";
3496 auto first_large_message_str = first_large_message.str();
3497
3498 // Emit one trace event before we begin batching.
3499 MockDataSource::Trace(
3500 [&first_large_message_str](MockDataSource::TraceContext ctx) {
3501 auto packet = ctx.NewTracePacket();
3502 packet->set_timestamp(42);
3503 packet->set_for_testing()->set_str(first_large_message_str);
3504 packet->Finalize();
3505 });
3506
3507 // Simulate the start of a batching cycle by first setting the batching period
3508 // to a very large value and then force-flushing when we are done writing
3509 // data.
3510 ASSERT_TRUE(
3511 perfetto::test::EnableDirectSMBPatching(/*BackendType=*/GetParam()));
3512 perfetto::test::SetBatchCommitsDuration(UINT32_MAX,
3513 /*BackendType=*/GetParam());
3514
3515 std::stringstream second_large_message;
3516 for (size_t i = 0; i < 512; i++)
3517 second_large_message << i << ". Something else wicked this way comes. ";
3518 auto second_large_message_str = second_large_message.str();
3519
3520 // Emit another trace event.
3521 MockDataSource::Trace(
3522 [&second_large_message_str](MockDataSource::TraceContext ctx) {
3523 auto packet = ctx.NewTracePacket();
3524 packet->set_timestamp(43);
3525 packet->set_for_testing()->set_str(second_large_message_str);
3526 packet->Finalize();
3527
3528 // Simulate the end of the batching cycle.
3529 ctx.Flush();
3530 });
3531
3532 data_source->on_stop.Wait();
3533 tracing_session->on_stop.Wait();
3534
3535 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
3536 ASSERT_GE(raw_trace.size(), 0u);
3537
3538 perfetto::protos::gen::Trace trace;
3539 ASSERT_TRUE(trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
3540 bool test_packet_1_found = false;
3541 bool test_packet_2_found = false;
3542 for (const auto& packet : trace.packet()) {
3543 if (!packet.has_for_testing())
3544 continue;
3545 EXPECT_TRUE(packet.timestamp() == 42U || packet.timestamp() == 43U);
3546 if (packet.timestamp() == 42U) {
3547 EXPECT_FALSE(test_packet_1_found);
3548 EXPECT_EQ(packet.for_testing().str(), first_large_message_str);
3549 test_packet_1_found = true;
3550 } else {
3551 EXPECT_FALSE(test_packet_2_found);
3552 EXPECT_EQ(packet.for_testing().str(), second_large_message_str);
3553 test_packet_2_found = true;
3554 }
3555 }
3556 EXPECT_TRUE(test_packet_1_found && test_packet_2_found);
3557 }
3558
TEST_P(PerfettoApiTest,BlockingStartAndStop)3559 TEST_P(PerfettoApiTest, BlockingStartAndStop) {
3560 auto* data_source = &data_sources_["my_data_source"];
3561
3562 // Register a second data source to get a bit more coverage.
3563 perfetto::DataSourceDescriptor dsd;
3564 dsd.set_name("my_data_source2");
3565 MockDataSource2::Register(dsd, kTestDataSourceArg);
3566 perfetto::test::SyncProducers();
3567
3568 // Setup the trace config.
3569 perfetto::TraceConfig cfg;
3570 cfg.set_duration_ms(500);
3571 cfg.add_buffers()->set_size_kb(1024);
3572 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
3573 ds_cfg->set_name("my_data_source");
3574 ds_cfg = cfg.add_data_sources()->mutable_config();
3575 ds_cfg->set_name("my_data_source2");
3576
3577 // Create a new trace session.
3578 auto* tracing_session = NewTrace(cfg);
3579
3580 tracing_session->get()->StartBlocking();
3581 EXPECT_TRUE(data_source->on_setup.notified());
3582 EXPECT_TRUE(data_source->on_start.notified());
3583
3584 tracing_session->get()->StopBlocking();
3585 EXPECT_TRUE(data_source->on_stop.notified());
3586 EXPECT_TRUE(tracing_session->on_stop.notified());
3587 }
3588
TEST_P(PerfettoApiTest,BlockingStartAndStopOnEmptySession)3589 TEST_P(PerfettoApiTest, BlockingStartAndStopOnEmptySession) {
3590 // Setup the trace config.
3591 perfetto::TraceConfig cfg;
3592 cfg.set_duration_ms(500);
3593 cfg.add_buffers()->set_size_kb(1024);
3594 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
3595 ds_cfg->set_name("non_existent_data_source");
3596
3597 // Create a new trace session.
3598 auto* tracing_session = NewTrace(cfg);
3599 tracing_session->get()->StartBlocking();
3600 tracing_session->get()->StopBlocking();
3601 EXPECT_TRUE(tracing_session->on_stop.notified());
3602 }
3603
TEST_P(PerfettoApiTest,WriteEventsAfterDeferredStop)3604 TEST_P(PerfettoApiTest, WriteEventsAfterDeferredStop) {
3605 auto* data_source = &data_sources_["my_data_source"];
3606 data_source->handle_stop_asynchronously = true;
3607
3608 // Setup the trace config and start the tracing session.
3609 perfetto::TraceConfig cfg;
3610 cfg.set_duration_ms(500);
3611 cfg.add_buffers()->set_size_kb(1024);
3612 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
3613 ds_cfg->set_name("my_data_source");
3614 auto* tracing_session = NewTrace(cfg);
3615 tracing_session->get()->StartBlocking();
3616
3617 // Stop and wait for the producer to have seen the stop event.
3618 WaitableTestEvent consumer_stop_signal;
3619 tracing_session->get()->SetOnStopCallback(
3620 [&consumer_stop_signal] { consumer_stop_signal.Notify(); });
3621 tracing_session->get()->Stop();
3622 data_source->on_stop.Wait();
3623
3624 // At this point tracing should be still allowed because of the
3625 // HandleStopAsynchronously() call.
3626 bool lambda_called = false;
3627
3628 // This usleep is here just to prevent that we accidentally pass the test
3629 // just by virtue of hitting some race. We should be able to trace up until
3630 // 5 seconds after seeing the stop when using the deferred stop mechanism.
3631 std::this_thread::sleep_for(std::chrono::milliseconds(250));
3632
3633 MockDataSource::Trace([&lambda_called](MockDataSource::TraceContext ctx) {
3634 auto packet = ctx.NewTracePacket();
3635 packet->set_for_testing()->set_str("event written after OnStop");
3636 packet->Finalize();
3637 ctx.Flush();
3638 lambda_called = true;
3639 });
3640 ASSERT_TRUE(lambda_called);
3641
3642 // Now call the async stop closure. This acks the stop to the service and
3643 // disallows further Trace() calls.
3644 EXPECT_TRUE(data_source->async_stop_closure);
3645 data_source->async_stop_closure();
3646
3647 // Wait that the stop is propagated to the consumer.
3648 consumer_stop_signal.Wait();
3649
3650 MockDataSource::Trace([](MockDataSource::TraceContext) {
3651 FAIL() << "Should not be called after the stop is acked";
3652 });
3653
3654 // Check the contents of the trace.
3655 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
3656 ASSERT_GE(raw_trace.size(), 0u);
3657 perfetto::protos::gen::Trace trace;
3658 ASSERT_TRUE(trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
3659 int test_packet_found = 0;
3660 for (const auto& packet : trace.packet()) {
3661 if (!packet.has_for_testing())
3662 continue;
3663 EXPECT_EQ(packet.for_testing().str(), "event written after OnStop");
3664 test_packet_found++;
3665 }
3666 EXPECT_EQ(test_packet_found, 1);
3667 }
3668
TEST_P(PerfettoApiTest,RepeatedStartAndStop)3669 TEST_P(PerfettoApiTest, RepeatedStartAndStop) {
3670 perfetto::TraceConfig cfg;
3671 cfg.set_duration_ms(500);
3672 cfg.add_buffers()->set_size_kb(1024);
3673 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
3674 ds_cfg->set_name("my_data_source");
3675
3676 for (int i = 0; i < 5; i++) {
3677 auto* tracing_session = NewTrace(cfg);
3678 tracing_session->get()->Start();
3679 std::atomic<bool> stop_called{false};
3680 tracing_session->get()->SetOnStopCallback(
3681 [&stop_called] { stop_called = true; });
3682 tracing_session->get()->StopBlocking();
3683 EXPECT_TRUE(stop_called);
3684 }
3685 }
3686
TEST_P(PerfettoApiTest,SetupWithFile)3687 TEST_P(PerfettoApiTest, SetupWithFile) {
3688 #if PERFETTO_BUILDFLAG(PERFETTO_OS_WIN)
3689 if (GetParam() == perfetto::kSystemBackend)
3690 GTEST_SKIP() << "write_into_file + system mode is not supported on Windows";
3691 #endif
3692 auto temp_file = perfetto::test::CreateTempFile();
3693 perfetto::TraceConfig cfg;
3694 cfg.set_duration_ms(500);
3695 cfg.add_buffers()->set_size_kb(1024);
3696 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
3697 ds_cfg->set_name("my_data_source");
3698 // Write a trace into |fd|.
3699 auto* tracing_session = NewTrace(cfg, temp_file.fd);
3700 tracing_session->get()->StartBlocking();
3701 tracing_session->get()->StopBlocking();
3702 #if !PERFETTO_BUILDFLAG(PERFETTO_OS_WIN)
3703 // Check that |fd| didn't get closed.
3704 EXPECT_EQ(0, fcntl(temp_file.fd, F_GETFD, 0));
3705 #endif
3706 // Check that the trace got written.
3707 EXPECT_GT(lseek(temp_file.fd, 0, SEEK_END), 0);
3708 EXPECT_EQ(0, close(temp_file.fd));
3709 // Clean up.
3710 EXPECT_EQ(0, remove(temp_file.path.c_str()));
3711 }
3712
TEST_P(PerfettoApiTest,MultipleRegistrations)3713 TEST_P(PerfettoApiTest, MultipleRegistrations) {
3714 // Attempt to register the same data source again.
3715 perfetto::DataSourceDescriptor dsd;
3716 dsd.set_name("my_data_source");
3717 EXPECT_TRUE(MockDataSource::Register(dsd));
3718 perfetto::test::SyncProducers();
3719
3720 // Setup the trace config.
3721 perfetto::TraceConfig cfg;
3722 cfg.set_duration_ms(500);
3723 cfg.add_buffers()->set_size_kb(1024);
3724 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
3725 ds_cfg->set_name("my_data_source");
3726
3727 // Create a new trace session.
3728 auto* tracing_session = NewTrace(cfg);
3729 tracing_session->get()->StartBlocking();
3730
3731 // Emit one trace event.
3732 std::atomic<int> trace_lambda_calls{0};
3733 MockDataSource::Trace([&trace_lambda_calls](MockDataSource::TraceContext) {
3734 trace_lambda_calls++;
3735 });
3736
3737 // Make sure the data source got called only once.
3738 tracing_session->get()->StopBlocking();
3739 EXPECT_EQ(trace_lambda_calls, 1);
3740 }
3741
TEST_P(PerfettoApiTest,CustomIncrementalState)3742 TEST_P(PerfettoApiTest, CustomIncrementalState) {
3743 perfetto::DataSourceDescriptor dsd;
3744 dsd.set_name("incr_data_source");
3745 TestIncrementalDataSource::Register(dsd);
3746 perfetto::test::SyncProducers();
3747
3748 // Setup the trace config.
3749 perfetto::TraceConfig cfg;
3750 cfg.set_duration_ms(500);
3751 cfg.add_buffers()->set_size_kb(1024);
3752 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
3753 ds_cfg->set_name("incr_data_source");
3754
3755 // Create a new trace session.
3756 auto* tracing_session = NewTrace(cfg);
3757 tracing_session->get()->StartBlocking();
3758
3759 // First emit a no-op trace event that initializes the incremental state as a
3760 // side effect.
3761 TestIncrementalDataSource::Trace(
3762 [](TestIncrementalDataSource::TraceContext) {});
3763 EXPECT_TRUE(TestIncrementalState::constructed);
3764
3765 // Check that the incremental state is carried across trace events.
3766 TestIncrementalDataSource::Trace(
3767 [](TestIncrementalDataSource::TraceContext ctx) {
3768 auto* state = ctx.GetIncrementalState();
3769 EXPECT_TRUE(state);
3770 EXPECT_EQ(100, state->count);
3771 state->count++;
3772 });
3773
3774 TestIncrementalDataSource::Trace(
3775 [](TestIncrementalDataSource::TraceContext ctx) {
3776 auto* state = ctx.GetIncrementalState();
3777 EXPECT_EQ(101, state->count);
3778 });
3779
3780 // Make sure the incremental state gets cleaned up between sessions.
3781 tracing_session->get()->StopBlocking();
3782 tracing_session = NewTrace(cfg);
3783 tracing_session->get()->StartBlocking();
3784 TestIncrementalDataSource::Trace(
3785 [](TestIncrementalDataSource::TraceContext ctx) {
3786 auto* state = ctx.GetIncrementalState();
3787 EXPECT_TRUE(TestIncrementalState::destroyed);
3788 EXPECT_TRUE(state);
3789 EXPECT_EQ(100, state->count);
3790 });
3791 tracing_session->get()->StopBlocking();
3792 }
3793
3794 // Regression test for b/139110180. Checks that GetDataSourceLocked() can be
3795 // called from OnStart() and OnStop() callbacks without deadlocking.
TEST_P(PerfettoApiTest,GetDataSourceLockedFromCallbacks)3796 TEST_P(PerfettoApiTest, GetDataSourceLockedFromCallbacks) {
3797 auto* data_source = &data_sources_["my_data_source"];
3798
3799 // Setup the trace config.
3800 perfetto::TraceConfig cfg;
3801 cfg.set_duration_ms(1);
3802 cfg.add_buffers()->set_size_kb(1024);
3803 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
3804 ds_cfg->set_name("my_data_source");
3805
3806 // Create a new trace session.
3807 auto* tracing_session = NewTrace(cfg);
3808
3809 data_source->on_start_callback = [] {
3810 MockDataSource::Trace([](MockDataSource::TraceContext ctx) {
3811 ctx.NewTracePacket()->set_for_testing()->set_str("on-start");
3812 auto ds = ctx.GetDataSourceLocked();
3813 ASSERT_TRUE(!!ds);
3814 ctx.NewTracePacket()->set_for_testing()->set_str("on-start-locked");
3815 });
3816 };
3817
3818 data_source->on_stop_callback = [] {
3819 MockDataSource::Trace([](MockDataSource::TraceContext ctx) {
3820 ctx.NewTracePacket()->set_for_testing()->set_str("on-stop");
3821 auto ds = ctx.GetDataSourceLocked();
3822 ASSERT_TRUE(!!ds);
3823 ctx.NewTracePacket()->set_for_testing()->set_str("on-stop-locked");
3824 ctx.Flush();
3825 });
3826 };
3827
3828 tracing_session->get()->Start();
3829 data_source->on_stop.Wait();
3830 tracing_session->on_stop.Wait();
3831
3832 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
3833 ASSERT_GE(raw_trace.size(), 0u);
3834
3835 perfetto::protos::gen::Trace trace;
3836 ASSERT_TRUE(trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
3837 int packets_found = 0;
3838 for (const auto& packet : trace.packet()) {
3839 if (!packet.has_for_testing())
3840 continue;
3841 packets_found |= packet.for_testing().str() == "on-start" ? 1 : 0;
3842 packets_found |= packet.for_testing().str() == "on-start-locked" ? 2 : 0;
3843 packets_found |= packet.for_testing().str() == "on-stop" ? 4 : 0;
3844 packets_found |= packet.for_testing().str() == "on-stop-locked" ? 8 : 0;
3845 }
3846 EXPECT_EQ(packets_found, 1 | 2 | 4 | 8);
3847 }
3848
TEST_P(PerfettoApiTest,OnStartCallback)3849 TEST_P(PerfettoApiTest, OnStartCallback) {
3850 perfetto::TraceConfig cfg;
3851 cfg.set_duration_ms(60000);
3852 cfg.add_buffers()->set_size_kb(1024);
3853 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
3854 ds_cfg->set_name("track_event");
3855 auto* tracing_session = NewTrace(cfg);
3856
3857 WaitableTestEvent got_start;
3858 tracing_session->get()->SetOnStartCallback([&] { got_start.Notify(); });
3859 tracing_session->get()->Start();
3860 got_start.Wait();
3861
3862 tracing_session->get()->StopBlocking();
3863 }
3864
TEST_P(PerfettoApiTest,OnErrorCallback)3865 TEST_P(PerfettoApiTest, OnErrorCallback) {
3866 perfetto::TraceConfig cfg;
3867
3868 // Requesting too long |duration_ms| will cause EnableTracing() to fail.
3869 cfg.set_duration_ms(static_cast<uint32_t>(-1));
3870 cfg.add_buffers()->set_size_kb(1024);
3871 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
3872 ds_cfg->set_name("track_event");
3873 auto* tracing_session = NewTrace(cfg);
3874
3875 WaitableTestEvent got_error;
3876 tracing_session->get()->SetOnErrorCallback([&](perfetto::TracingError error) {
3877 EXPECT_EQ(perfetto::TracingError::kTracingFailed, error.code);
3878 EXPECT_FALSE(error.message.empty());
3879 got_error.Notify();
3880 });
3881
3882 tracing_session->get()->Start();
3883 got_error.Wait();
3884
3885 // Registered error callback will be triggered also by OnDisconnect()
3886 // function. This may happen after exiting this test what would result in
3887 // system crash (|got_error| will not exist at that time). To prevent that
3888 // scenario, error callback has to be cleared.
3889 tracing_session->get()->SetOnErrorCallback(nullptr);
3890 tracing_session->get()->StopBlocking();
3891 }
3892
TEST_P(PerfettoApiTest,UnsupportedBackend)3893 TEST_P(PerfettoApiTest, UnsupportedBackend) {
3894 // Create a new trace session with an invalid backend type specified.
3895 // Specifically, the custom backend isn't initialized for these tests.
3896 perfetto::TraceConfig cfg;
3897 cfg.add_buffers()->set_size_kb(1024);
3898 auto* tracing_session = NewTrace(cfg, perfetto::BackendType::kCustomBackend);
3899
3900 // Creating the consumer should cause an asynchronous disconnect error.
3901 WaitableTestEvent got_error;
3902 tracing_session->get()->SetOnErrorCallback([&](perfetto::TracingError error) {
3903 EXPECT_EQ(perfetto::TracingError::kDisconnected, error.code);
3904 EXPECT_FALSE(error.message.empty());
3905 got_error.Notify();
3906 });
3907 got_error.Wait();
3908
3909 // Clear the callback for test tear down.
3910 tracing_session->get()->SetOnErrorCallback(nullptr);
3911 // Synchronize the consumer channel to ensure the callback has propagated.
3912 tracing_session->get()->StopBlocking();
3913 }
3914
TEST_P(PerfettoApiTest,ForbiddenConsumer)3915 TEST_P(PerfettoApiTest, ForbiddenConsumer) {
3916 g_test_tracing_policy->should_allow_consumer_connection = false;
3917
3918 // Create a new trace session while consumer connections are forbidden.
3919 perfetto::TraceConfig cfg;
3920 cfg.add_buffers()->set_size_kb(1024);
3921 auto* tracing_session = NewTrace(cfg);
3922
3923 // Creating the consumer should cause an asynchronous disconnect error.
3924 WaitableTestEvent got_error;
3925 tracing_session->get()->SetOnErrorCallback([&](perfetto::TracingError error) {
3926 EXPECT_EQ(perfetto::TracingError::kDisconnected, error.code);
3927 EXPECT_FALSE(error.message.empty());
3928 got_error.Notify();
3929 });
3930 got_error.Wait();
3931
3932 // Clear the callback for test tear down.
3933 tracing_session->get()->SetOnErrorCallback(nullptr);
3934 // Synchronize the consumer channel to ensure the callback has propagated.
3935 tracing_session->get()->StopBlocking();
3936
3937 g_test_tracing_policy->should_allow_consumer_connection = true;
3938 }
3939
TEST_P(PerfettoApiTest,GetTraceStats)3940 TEST_P(PerfettoApiTest, GetTraceStats) {
3941 perfetto::TraceConfig cfg;
3942 cfg.set_duration_ms(500);
3943 cfg.add_buffers()->set_size_kb(1024);
3944 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
3945 ds_cfg->set_name("track_event");
3946 auto* tracing_session = NewTrace(cfg);
3947 tracing_session->get()->StartBlocking();
3948
3949 // Asynchronous read.
3950 WaitableTestEvent got_stats;
3951 tracing_session->get()->GetTraceStats(
3952 [&got_stats](perfetto::TracingSession::GetTraceStatsCallbackArgs args) {
3953 perfetto::protos::gen::TraceStats trace_stats;
3954 EXPECT_TRUE(args.success);
3955 EXPECT_TRUE(trace_stats.ParseFromArray(args.trace_stats_data.data(),
3956 args.trace_stats_data.size()));
3957 EXPECT_EQ(1, trace_stats.buffer_stats_size());
3958 got_stats.Notify();
3959 });
3960 got_stats.Wait();
3961
3962 // Blocking read.
3963 auto stats = tracing_session->get()->GetTraceStatsBlocking();
3964 perfetto::protos::gen::TraceStats trace_stats;
3965 EXPECT_TRUE(stats.success);
3966 EXPECT_TRUE(trace_stats.ParseFromArray(stats.trace_stats_data.data(),
3967 stats.trace_stats_data.size()));
3968 EXPECT_EQ(1, trace_stats.buffer_stats_size());
3969
3970 tracing_session->get()->StopBlocking();
3971 }
3972
TEST_P(PerfettoApiTest,QueryServiceState)3973 TEST_P(PerfettoApiTest, QueryServiceState) {
3974 class QueryTestDataSource : public perfetto::DataSource<QueryTestDataSource> {
3975 };
3976 RegisterDataSource<QueryTestDataSource>("query_test_data_source");
3977 perfetto::test::SyncProducers();
3978
3979 auto tracing_session =
3980 perfetto::Tracing::NewTrace(/*BackendType=*/GetParam());
3981 // Asynchronous read.
3982 WaitableTestEvent got_state;
3983 tracing_session->QueryServiceState(
3984 [&got_state](
3985 perfetto::TracingSession::QueryServiceStateCallbackArgs result) {
3986 perfetto::protos::gen::TracingServiceState state;
3987 EXPECT_TRUE(result.success);
3988 EXPECT_TRUE(state.ParseFromArray(result.service_state_data.data(),
3989 result.service_state_data.size()));
3990 EXPECT_EQ(1, state.producers_size());
3991 EXPECT_NE(std::string::npos,
3992 state.producers()[0].name().find("integrationtest"));
3993 bool found_ds = false;
3994 for (const auto& ds : state.data_sources())
3995 found_ds |= ds.ds_descriptor().name() == "query_test_data_source";
3996 EXPECT_TRUE(found_ds);
3997 got_state.Notify();
3998 });
3999 got_state.Wait();
4000
4001 // Blocking read.
4002 auto result = tracing_session->QueryServiceStateBlocking();
4003 perfetto::protos::gen::TracingServiceState state;
4004 EXPECT_TRUE(result.success);
4005 EXPECT_TRUE(state.ParseFromArray(result.service_state_data.data(),
4006 result.service_state_data.size()));
4007 EXPECT_EQ(1, state.producers_size());
4008 EXPECT_NE(std::string::npos,
4009 state.producers()[0].name().find("integrationtest"));
4010 bool found_ds = false;
4011 for (const auto& ds : state.data_sources())
4012 found_ds |= ds.ds_descriptor().name() == "query_test_data_source";
4013 EXPECT_TRUE(found_ds);
4014 }
4015
TEST_P(PerfettoApiTest,UpdateDataSource)4016 TEST_P(PerfettoApiTest, UpdateDataSource) {
4017 class UpdateTestDataSource
4018 : public perfetto::DataSource<UpdateTestDataSource> {};
4019
4020 perfetto::DataSourceDescriptor dsd;
4021 dsd.set_name("update_test_data_source");
4022
4023 RegisterDataSource<UpdateTestDataSource>(dsd);
4024
4025 {
4026 protozero::HeapBuffered<perfetto::protos::pbzero::TrackEventDescriptor> ted;
4027 auto cat = ted->add_available_categories();
4028 cat->set_name("new_cat");
4029 dsd.set_track_event_descriptor_raw(ted.SerializeAsString());
4030 }
4031
4032 UpdateDataSource<UpdateTestDataSource>(dsd);
4033
4034 perfetto::test::SyncProducers();
4035
4036 auto tracing_session =
4037 perfetto::Tracing::NewTrace(/*BackendType=*/GetParam());
4038 // Blocking read.
4039 auto result = tracing_session->QueryServiceStateBlocking();
4040 perfetto::protos::gen::TracingServiceState state;
4041 EXPECT_TRUE(result.success);
4042 EXPECT_TRUE(state.ParseFromArray(result.service_state_data.data(),
4043 result.service_state_data.size()));
4044 EXPECT_EQ(1, state.producers_size());
4045 EXPECT_NE(std::string::npos,
4046 state.producers()[0].name().find("integrationtest"));
4047 bool found_ds = false;
4048 for (const auto& ds : state.data_sources()) {
4049 if (ds.ds_descriptor().name() == "update_test_data_source") {
4050 found_ds = true;
4051 perfetto::protos::gen::TrackEventDescriptor ted;
4052 auto desc_raw = ds.ds_descriptor().track_event_descriptor_raw();
4053 EXPECT_TRUE(ted.ParseFromArray(desc_raw.data(), desc_raw.size()));
4054 EXPECT_EQ(ted.available_categories_size(), 1);
4055 EXPECT_EQ(ted.available_categories()[0].name(), "new_cat");
4056 }
4057 }
4058 EXPECT_TRUE(found_ds);
4059 }
4060
TEST_P(PerfettoApiTest,LegacyTraceEvents)4061 TEST_P(PerfettoApiTest, LegacyTraceEvents) {
4062 auto is_new_session = [] {
4063 bool result;
4064 TRACE_EVENT_IS_NEW_TRACE(&result);
4065 return result;
4066 };
4067
4068 // Create a new trace session.
4069 EXPECT_FALSE(is_new_session());
4070 auto* tracing_session =
4071 NewTraceWithCategories({"cat", TRACE_DISABLED_BY_DEFAULT("cat")});
4072 tracing_session->get()->StartBlocking();
4073 EXPECT_TRUE(is_new_session());
4074 EXPECT_FALSE(is_new_session());
4075
4076 // Basic events.
4077 TRACE_EVENT_INSTANT0("cat", "LegacyEvent", TRACE_EVENT_SCOPE_GLOBAL);
4078 TRACE_EVENT_BEGIN1("cat", "LegacyEvent", "arg", 123);
4079 TRACE_EVENT_END2("cat", "LegacyEvent", "arg", "string", "arg2", 0.123f);
4080
4081 // Scoped event.
4082 { TRACE_EVENT0("cat", "ScopedLegacyEvent"); }
4083
4084 // Event with flow (and disabled category).
4085 TRACE_EVENT_WITH_FLOW0(TRACE_DISABLED_BY_DEFAULT("cat"), "LegacyFlowEvent",
4086 0xdadacafe, TRACE_EVENT_FLAG_FLOW_IN);
4087
4088 // Event with timestamp.
4089 TRACE_EVENT_INSTANT_WITH_TIMESTAMP0("cat", "LegacyInstantEvent",
4090 TRACE_EVENT_SCOPE_GLOBAL,
4091 MyTimestamp{123456789ul});
4092
4093 // Event with id, thread id and timestamp (and dynamic name).
4094 TRACE_EVENT_COPY_BEGIN_WITH_ID_TID_AND_TIMESTAMP0(
4095 "cat", std::string("LegacyWithIdTidAndTimestamp").c_str(), 1,
4096 MyThreadId(123), MyTimestamp{3});
4097
4098 // Event with id.
4099 TRACE_COUNTER1("cat", "LegacyCounter", 1234);
4100 TRACE_COUNTER_ID1("cat", "LegacyCounterWithId", 1234, 9000);
4101
4102 // Metadata event.
4103 TRACE_EVENT_METADATA1("cat", "LegacyMetadata", "obsolete", true);
4104
4105 // Async events.
4106 TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP_AND_FLAGS0(
4107 "cat", "LegacyAsync", 5678, MyTimestamp{4}, TRACE_EVENT_FLAG_NONE);
4108 TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP0("cat", "LegacyAsync", 5678,
4109 MyTimestamp{5});
4110 TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_FLAGS0("cat", "LegacyAsync2", 9000,
4111 TRACE_EVENT_FLAG_NONE);
4112 TRACE_EVENT_NESTABLE_ASYNC_END_WITH_FLAGS0("cat", "LegacyAsync2", 9000,
4113 TRACE_EVENT_FLAG_NONE);
4114 TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_FLAGS0("cat", "LegacyAsync3", 9001,
4115 TRACE_EVENT_FLAG_NONE);
4116 TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP_AND_FLAGS0(
4117 "cat", "LegacyAsync3", 9001, MyTimestamp{6}, TRACE_EVENT_FLAG_NONE);
4118
4119 perfetto::TrackEvent::Flush();
4120 tracing_session->get()->StopBlocking();
4121 auto slices = ReadSlicesFromTrace(tracing_session->get());
4122 EXPECT_THAT(
4123 slices,
4124 ElementsAre(
4125 "[track=0]I:cat.LegacyEvent", "B:cat.LegacyEvent(arg=(int)123)",
4126 "E(arg=(string)string,arg2=(double)0.123)", "B:cat.ScopedLegacyEvent",
4127 "E",
4128 "B(bind_id=3671771902)(flow_direction=1):disabled-by-default-cat."
4129 "LegacyFlowEvent",
4130 "[track=0]I:cat.LegacyInstantEvent",
4131 std::string("[track=") +
4132 std::to_string(perfetto::ThreadTrack::ForThread(123).uuid) +
4133 "]Legacy_S(unscoped_id=1):cat.LegacyWithIdTidAndTimestamp",
4134 "Legacy_C:cat.LegacyCounter(value=(int)1234)",
4135 "Legacy_C(unscoped_id=1234):cat.LegacyCounterWithId(value=(int)9000)",
4136 "Legacy_M:cat.LegacyMetadata",
4137 "Legacy_b(unscoped_id=5678):cat.LegacyAsync",
4138 "Legacy_e(unscoped_id=5678):cat.LegacyAsync",
4139 "Legacy_b(unscoped_id=9000):cat.LegacyAsync2",
4140 "Legacy_e(unscoped_id=9000):cat.LegacyAsync2",
4141 "Legacy_b(unscoped_id=9001):cat.LegacyAsync3",
4142 "Legacy_e(unscoped_id=9001):cat.LegacyAsync3"));
4143 }
4144
TEST_P(PerfettoApiTest,LegacyTraceEventsWithCustomAnnotation)4145 TEST_P(PerfettoApiTest, LegacyTraceEventsWithCustomAnnotation) {
4146 // Create a new trace session.
4147 auto* tracing_session = NewTraceWithCategories({"cat"});
4148 tracing_session->get()->StartBlocking();
4149
4150 MyDebugAnnotation annotation;
4151 TRACE_EVENT_BEGIN1("cat", "LegacyEvent", "arg", annotation);
4152
4153 std::unique_ptr<MyDebugAnnotation> owned_annotation(new MyDebugAnnotation());
4154 TRACE_EVENT_BEGIN1("cat", "LegacyEvent", "arg", std::move(owned_annotation));
4155
4156 perfetto::TrackEvent::Flush();
4157 tracing_session->get()->StopBlocking();
4158 auto slices = ReadSlicesFromTrace(tracing_session->get());
4159 EXPECT_THAT(slices,
4160 ElementsAre("B:cat.LegacyEvent(arg=(json){\"key\": 123})",
4161 "B:cat.LegacyEvent(arg=(json){\"key\": 123})"));
4162 }
4163
TEST_P(PerfettoApiTest,LegacyTraceEventsWithConcurrentSessions)4164 TEST_P(PerfettoApiTest, LegacyTraceEventsWithConcurrentSessions) {
4165 // Make sure that a uniquely owned debug annotation can be written into
4166 // multiple concurrent tracing sessions.
4167
4168 auto* tracing_session = NewTraceWithCategories({"cat"});
4169 tracing_session->get()->StartBlocking();
4170
4171 auto* tracing_session2 = NewTraceWithCategories({"cat"});
4172 tracing_session2->get()->StartBlocking();
4173
4174 std::unique_ptr<MyDebugAnnotation> owned_annotation(new MyDebugAnnotation());
4175 TRACE_EVENT_BEGIN1("cat", "LegacyEvent", "arg", std::move(owned_annotation));
4176
4177 perfetto::TrackEvent::Flush();
4178 tracing_session->get()->StopBlocking();
4179 auto slices = ReadSlicesFromTrace(tracing_session->get());
4180 EXPECT_THAT(slices,
4181 ElementsAre("B:cat.LegacyEvent(arg=(json){\"key\": 123})"));
4182
4183 tracing_session2->get()->StopBlocking();
4184 slices = ReadSlicesFromTrace(tracing_session2->get());
4185 EXPECT_THAT(slices,
4186 ElementsAre("B:cat.LegacyEvent(arg=(json){\"key\": 123})"));
4187 }
4188
TEST_P(PerfettoApiTest,LegacyTraceEventsWithId)4189 TEST_P(PerfettoApiTest, LegacyTraceEventsWithId) {
4190 auto* tracing_session = NewTraceWithCategories({"cat"});
4191 tracing_session->get()->StartBlocking();
4192
4193 TRACE_EVENT_ASYNC_BEGIN0("cat", "UnscopedId", 0x1000);
4194 TRACE_EVENT_ASYNC_BEGIN0("cat", "LocalId", TRACE_ID_LOCAL(0x2000));
4195 TRACE_EVENT_ASYNC_BEGIN0("cat", "GlobalId", TRACE_ID_GLOBAL(0x3000));
4196 TRACE_EVENT_ASYNC_BEGIN0(
4197 "cat", "WithScope",
4198 TRACE_ID_WITH_SCOPE("scope string", TRACE_ID_GLOBAL(0x4000)));
4199
4200 perfetto::TrackEvent::Flush();
4201 tracing_session->get()->StopBlocking();
4202 auto slices = ReadSlicesFromTrace(tracing_session->get());
4203 EXPECT_THAT(slices, ElementsAre("Legacy_S(unscoped_id=4096):cat.UnscopedId",
4204 "Legacy_S(local_id=8192):cat.LocalId",
4205 "Legacy_S(global_id=12288):cat.GlobalId",
4206 "Legacy_S(global_id=16384)(id_scope=\"scope "
4207 "string\"):cat.WithScope"));
4208 }
4209
TEST_P(PerfettoApiTest,NestableAsyncTraceEvent)4210 TEST_P(PerfettoApiTest, NestableAsyncTraceEvent) {
4211 auto* tracing_session = NewTraceWithCategories({"cat"});
4212 tracing_session->get()->StartBlocking();
4213 TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("cat", "foo",
4214 TRACE_ID_WITH_SCOPE("foo", 1));
4215 // Same id, different scope.
4216 TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("cat", "bar",
4217 TRACE_ID_WITH_SCOPE("bar", 1));
4218 // Same scope, different id.
4219 TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("cat", "bar",
4220 TRACE_ID_WITH_SCOPE("bar", 2));
4221
4222 TRACE_EVENT_NESTABLE_ASYNC_END0("cat", "bar", TRACE_ID_WITH_SCOPE("bar", 2));
4223 TRACE_EVENT_NESTABLE_ASYNC_END0("cat", "bar", TRACE_ID_WITH_SCOPE("bar", 1));
4224 TRACE_EVENT_NESTABLE_ASYNC_END0("cat", "foo", TRACE_ID_WITH_SCOPE("foo", 1));
4225 perfetto::TrackEvent::Flush();
4226 tracing_session->get()->StopBlocking();
4227
4228 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
4229 perfetto::protos::gen::Trace parsed_trace;
4230 ASSERT_TRUE(parsed_trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
4231 using LegacyEvent = perfetto::protos::gen::TrackEvent::LegacyEvent;
4232 std::vector<const LegacyEvent*> legacy_events;
4233 for (const auto& packet : parsed_trace.packet()) {
4234 if (packet.has_track_event() && packet.track_event().has_legacy_event()) {
4235 legacy_events.push_back(&packet.track_event().legacy_event());
4236 }
4237 }
4238 ASSERT_EQ(6u, legacy_events.size());
4239 EXPECT_EQ("foo", legacy_events[0]->id_scope());
4240 EXPECT_EQ("bar", legacy_events[1]->id_scope());
4241 EXPECT_EQ("bar", legacy_events[2]->id_scope());
4242 EXPECT_EQ("bar", legacy_events[3]->id_scope());
4243 EXPECT_EQ("bar", legacy_events[4]->id_scope());
4244 EXPECT_EQ("foo", legacy_events[5]->id_scope());
4245
4246 EXPECT_EQ(legacy_events[0]->unscoped_id(), legacy_events[5]->unscoped_id());
4247 EXPECT_EQ(legacy_events[1]->unscoped_id(), legacy_events[4]->unscoped_id());
4248 EXPECT_EQ(legacy_events[2]->unscoped_id(), legacy_events[3]->unscoped_id());
4249
4250 EXPECT_NE(legacy_events[0]->unscoped_id(), legacy_events[1]->unscoped_id());
4251 EXPECT_NE(legacy_events[1]->unscoped_id(), legacy_events[2]->unscoped_id());
4252 EXPECT_NE(legacy_events[2]->unscoped_id(), legacy_events[0]->unscoped_id());
4253 }
4254
TEST_P(PerfettoApiTest,LegacyTraceEventsWithFlow)4255 TEST_P(PerfettoApiTest, LegacyTraceEventsWithFlow) {
4256 auto* tracing_session = NewTraceWithCategories({"cat"});
4257 tracing_session->get()->StartBlocking();
4258
4259 const uint64_t flow_id = 1234;
4260 {
4261 TRACE_EVENT_WITH_FLOW1("cat", "LatencyInfo.Flow", TRACE_ID_GLOBAL(flow_id),
4262 TRACE_EVENT_FLAG_FLOW_OUT, "step", "Begin");
4263 }
4264
4265 {
4266 TRACE_EVENT_WITH_FLOW2("cat", "LatencyInfo.Flow", TRACE_ID_GLOBAL(flow_id),
4267 TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT,
4268 "step", "Middle", "value", false);
4269 }
4270
4271 {
4272 TRACE_EVENT_WITH_FLOW1("cat", "LatencyInfo.Flow", TRACE_ID_GLOBAL(flow_id),
4273 TRACE_EVENT_FLAG_FLOW_IN, "step", "End");
4274 }
4275
4276 perfetto::TrackEvent::Flush();
4277 tracing_session->get()->StopBlocking();
4278 auto slices = ReadSlicesFromTrace(tracing_session->get());
4279 EXPECT_THAT(slices,
4280 ElementsAre("B(bind_id=1234)(flow_direction=2):cat.LatencyInfo."
4281 "Flow(step=(string)Begin)",
4282 "E",
4283 "B(bind_id=1234)(flow_direction=3):cat.LatencyInfo."
4284 "Flow(step=(string)Middle,value=(bool)0)",
4285 "E",
4286 "B(bind_id=1234)(flow_direction=1):cat.LatencyInfo."
4287 "Flow(step=(string)End)",
4288 "E"));
4289 }
4290
TEST_P(PerfettoApiTest,LegacyCategoryGroupEnabledState)4291 TEST_P(PerfettoApiTest, LegacyCategoryGroupEnabledState) {
4292 bool foo_status;
4293 bool bar_status;
4294 bool dynamic_status;
4295 TRACE_EVENT_CATEGORY_GROUP_ENABLED("foo", &foo_status);
4296 TRACE_EVENT_CATEGORY_GROUP_ENABLED("bar", &bar_status);
4297 TRACE_EVENT_CATEGORY_GROUP_ENABLED("dynamic", &dynamic_status);
4298 EXPECT_FALSE(foo_status);
4299 EXPECT_FALSE(bar_status);
4300 EXPECT_FALSE(dynamic_status);
4301
4302 const uint8_t* foo_enabled =
4303 TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED("foo");
4304 const uint8_t* bar_enabled =
4305 TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED("bar");
4306 EXPECT_FALSE(*foo_enabled);
4307 EXPECT_FALSE(*bar_enabled);
4308
4309 // The category group enabled pointer can also be retrieved with a
4310 // runtime-computed category name.
4311 std::string computed_cat("cat");
4312 const uint8_t* computed_enabled =
4313 TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED(computed_cat.c_str());
4314 EXPECT_FALSE(*computed_enabled);
4315
4316 // The enabled pointers can be converted back to category names.
4317 EXPECT_EQ("foo", TRACE_EVENT_API_GET_CATEGORY_GROUP_NAME(foo_enabled));
4318 EXPECT_EQ("bar", TRACE_EVENT_API_GET_CATEGORY_GROUP_NAME(bar_enabled));
4319 EXPECT_EQ("cat", TRACE_EVENT_API_GET_CATEGORY_GROUP_NAME(computed_enabled));
4320
4321 auto* tracing_session = NewTraceWithCategories({"foo", "dynamic", "cat"});
4322 tracing_session->get()->StartBlocking();
4323 TRACE_EVENT_CATEGORY_GROUP_ENABLED("foo", &foo_status);
4324 TRACE_EVENT_CATEGORY_GROUP_ENABLED("bar", &bar_status);
4325 TRACE_EVENT_CATEGORY_GROUP_ENABLED("dynamic", &dynamic_status);
4326 EXPECT_TRUE(foo_status);
4327 EXPECT_FALSE(bar_status);
4328 EXPECT_TRUE(dynamic_status);
4329
4330 EXPECT_TRUE(*foo_enabled);
4331 EXPECT_FALSE(*bar_enabled);
4332 EXPECT_TRUE(*computed_enabled);
4333
4334 tracing_session->get()->StopBlocking();
4335 TRACE_EVENT_CATEGORY_GROUP_ENABLED("foo", &foo_status);
4336 TRACE_EVENT_CATEGORY_GROUP_ENABLED("bar", &bar_status);
4337 TRACE_EVENT_CATEGORY_GROUP_ENABLED("dynamic", &dynamic_status);
4338 EXPECT_FALSE(foo_status);
4339 EXPECT_FALSE(bar_status);
4340 EXPECT_FALSE(dynamic_status);
4341 EXPECT_FALSE(*foo_enabled);
4342 EXPECT_FALSE(*bar_enabled);
4343 EXPECT_FALSE(*computed_enabled);
4344 }
4345
TEST_P(PerfettoApiTest,CategoryEnabledState)4346 TEST_P(PerfettoApiTest, CategoryEnabledState) {
4347 perfetto::DynamicCategory dynamic{"dynamic"};
4348 EXPECT_FALSE(TRACE_EVENT_CATEGORY_ENABLED("foo"));
4349 EXPECT_FALSE(TRACE_EVENT_CATEGORY_ENABLED("bar"));
4350 EXPECT_FALSE(TRACE_EVENT_CATEGORY_ENABLED("red,green,blue,foo"));
4351 EXPECT_FALSE(TRACE_EVENT_CATEGORY_ENABLED("dynamic"));
4352 EXPECT_FALSE(TRACE_EVENT_CATEGORY_ENABLED("dynamic_2"));
4353 EXPECT_FALSE(TRACE_EVENT_CATEGORY_ENABLED(dynamic));
4354
4355 auto* tracing_session = NewTraceWithCategories({"foo", "dynamic"});
4356 tracing_session->get()->StartBlocking();
4357 EXPECT_TRUE(TRACE_EVENT_CATEGORY_ENABLED("foo"));
4358 EXPECT_FALSE(TRACE_EVENT_CATEGORY_ENABLED("bar"));
4359 EXPECT_TRUE(TRACE_EVENT_CATEGORY_ENABLED("red,green,blue,foo"));
4360 EXPECT_TRUE(TRACE_EVENT_CATEGORY_ENABLED("dynamic"));
4361 EXPECT_FALSE(TRACE_EVENT_CATEGORY_ENABLED("dynamic_2"));
4362 EXPECT_TRUE(TRACE_EVENT_CATEGORY_ENABLED(dynamic));
4363
4364 tracing_session->get()->StopBlocking();
4365 EXPECT_FALSE(TRACE_EVENT_CATEGORY_ENABLED("foo"));
4366 EXPECT_FALSE(TRACE_EVENT_CATEGORY_ENABLED("bar"));
4367 EXPECT_FALSE(TRACE_EVENT_CATEGORY_ENABLED("red,green,blue,foo"));
4368 EXPECT_FALSE(TRACE_EVENT_CATEGORY_ENABLED("dynamic"));
4369 EXPECT_FALSE(TRACE_EVENT_CATEGORY_ENABLED("dynamic_2"));
4370 EXPECT_FALSE(TRACE_EVENT_CATEGORY_ENABLED(dynamic));
4371 }
4372
4373 class TestInterceptor : public perfetto::Interceptor<TestInterceptor> {
4374 public:
4375 static TestInterceptor* instance;
4376
4377 struct ThreadLocalState : public perfetto::InterceptorBase::ThreadLocalState {
ThreadLocalState__anon22b779c30111::TestInterceptor::ThreadLocalState4378 ThreadLocalState(ThreadLocalStateArgs& args) {
4379 // Test accessing instance state from the TLS constructor.
4380 if (auto self = args.GetInterceptorLocked()) {
4381 self->tls_initialized = true;
4382 }
4383 }
4384
4385 std::map<uint64_t, std::string> event_names;
4386 };
4387
TestInterceptor(const std::string & constructor_arg)4388 TestInterceptor(const std::string& constructor_arg) {
4389 EXPECT_EQ(constructor_arg, "Constructor argument");
4390 // Note: some tests in this suite register multiple track event data
4391 // sources. We only track data for the first in this test.
4392 if (!instance)
4393 instance = this;
4394 }
4395
~TestInterceptor()4396 ~TestInterceptor() override {
4397 if (instance != this)
4398 return;
4399 instance = nullptr;
4400 EXPECT_TRUE(setup_called);
4401 EXPECT_TRUE(start_called);
4402 EXPECT_TRUE(stop_called);
4403 EXPECT_TRUE(tls_initialized);
4404 }
4405
OnSetup(const SetupArgs &)4406 void OnSetup(const SetupArgs&) override {
4407 EXPECT_FALSE(setup_called);
4408 EXPECT_FALSE(start_called);
4409 EXPECT_FALSE(stop_called);
4410 setup_called = true;
4411 }
4412
OnStart(const StartArgs &)4413 void OnStart(const StartArgs&) override {
4414 EXPECT_TRUE(setup_called);
4415 EXPECT_FALSE(start_called);
4416 EXPECT_FALSE(stop_called);
4417 start_called = true;
4418 }
4419
OnStop(const StopArgs &)4420 void OnStop(const StopArgs&) override {
4421 EXPECT_TRUE(setup_called);
4422 EXPECT_TRUE(start_called);
4423 EXPECT_FALSE(stop_called);
4424 stop_called = true;
4425 }
4426
OnTracePacket(InterceptorContext context)4427 static void OnTracePacket(InterceptorContext context) {
4428 perfetto::protos::pbzero::TracePacket::Decoder packet(
4429 context.packet_data.data, context.packet_data.size);
4430 EXPECT_TRUE(packet.trusted_packet_sequence_id() > 0);
4431 {
4432 auto self = context.GetInterceptorLocked();
4433 ASSERT_TRUE(self);
4434 EXPECT_TRUE(self->setup_called);
4435 EXPECT_TRUE(self->start_called);
4436 EXPECT_FALSE(self->stop_called);
4437 EXPECT_TRUE(self->tls_initialized);
4438 }
4439
4440 auto& tls = context.GetThreadLocalState();
4441 if (packet.sequence_flags() &
4442 perfetto::protos::pbzero::TracePacket::SEQ_INCREMENTAL_STATE_CLEARED) {
4443 tls.event_names.clear();
4444 }
4445 if (packet.has_interned_data()) {
4446 perfetto::protos::pbzero::InternedData::Decoder interned_data(
4447 packet.interned_data());
4448 for (auto it = interned_data.event_names(); it; it++) {
4449 perfetto::protos::pbzero::EventName::Decoder entry(*it);
4450 tls.event_names[entry.iid()] = entry.name().ToStdString();
4451 }
4452 }
4453 if (packet.has_track_event()) {
4454 perfetto::protos::pbzero::TrackEvent::Decoder track_event(
4455 packet.track_event());
4456 uint64_t name_iid = track_event.name_iid();
4457 auto self = context.GetInterceptorLocked();
4458 self->events.push_back(tls.event_names[name_iid].c_str());
4459 }
4460 }
4461
4462 bool setup_called = false;
4463 bool start_called = false;
4464 bool stop_called = false;
4465 bool tls_initialized = false;
4466 std::vector<std::string> events;
4467 };
4468
4469 TestInterceptor* TestInterceptor::instance;
4470
TEST_P(PerfettoApiTest,TracePacketInterception)4471 TEST_P(PerfettoApiTest, TracePacketInterception) {
4472 perfetto::InterceptorDescriptor desc;
4473 desc.set_name("test_interceptor");
4474 TestInterceptor::Register(desc, std::string("Constructor argument"));
4475
4476 perfetto::TraceConfig cfg;
4477 cfg.set_duration_ms(500);
4478 cfg.add_buffers()->set_size_kb(1024);
4479 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
4480 ds_cfg->set_name("track_event");
4481 ds_cfg->mutable_interceptor_config()->set_name("test_interceptor");
4482
4483 auto* tracing_session = NewTrace(cfg);
4484 tracing_session->get()->StartBlocking();
4485 EXPECT_EQ(0u, TestInterceptor::instance->events.size());
4486
4487 // The interceptor should see an event immediately without any explicit
4488 // flushing.
4489 TRACE_EVENT_BEGIN("foo", "Hip");
4490 EXPECT_THAT(TestInterceptor::instance->events, ElementsAre("Hip"));
4491
4492 // Emit another event with the same title to test interning.
4493 TRACE_EVENT_BEGIN("foo", "Hip");
4494 EXPECT_THAT(TestInterceptor::instance->events, ElementsAre("Hip", "Hip"));
4495
4496 // Emit an event from another thread. It should still reach the same
4497 // interceptor instance.
4498 std::thread thread([] { TRACE_EVENT_BEGIN("foo", "Hooray"); });
4499 thread.join();
4500 EXPECT_THAT(TestInterceptor::instance->events,
4501 ElementsAre("Hip", "Hip", "Hooray"));
4502
4503 // Emit a packet that spans multiple segments and must be stitched together.
4504 TestInterceptor::instance->events.clear();
4505 static char long_title[8192];
4506 memset(long_title, 'a', sizeof(long_title) - 1);
4507 long_title[sizeof(long_title) - 1] = 0;
4508 TRACE_EVENT_BEGIN("foo", long_title);
4509 EXPECT_THAT(TestInterceptor::instance->events, ElementsAre(long_title));
4510
4511 tracing_session->get()->StopBlocking();
4512 }
4513
EmitConsoleEvents()4514 void EmitConsoleEvents() {
4515 TRACE_EVENT_INSTANT("foo", "Instant event");
4516 TRACE_EVENT("foo", "Scoped event");
4517 TRACE_EVENT_BEGIN("foo", "Nested event");
4518 TRACE_EVENT_INSTANT("foo", "Instant event");
4519 TRACE_EVENT_INSTANT("foo", "Annotated event", "foo", 1, "bar", "hello");
4520 TRACE_EVENT_END("foo");
4521 uint64_t async_id = 4004;
4522 auto track = perfetto::Track(async_id, perfetto::ThreadTrack::Current());
4523 perfetto::TrackEvent::SetTrackDescriptor(
4524 track, [](perfetto::protos::pbzero::TrackDescriptor* desc) {
4525 desc->set_name("AsyncTrack");
4526 });
4527 TRACE_EVENT_BEGIN("test", "AsyncEvent", track);
4528
4529 std::thread thread([&] {
4530 TRACE_EVENT("foo", "EventFromAnotherThread");
4531 TRACE_EVENT_INSTANT("foo", "Instant event");
4532 TRACE_EVENT_END("test", track);
4533 });
4534 thread.join();
4535
4536 TRACE_EVENT_INSTANT(
4537 "foo", "More annotations", "dict",
4538 [](perfetto::TracedValue context) {
4539 auto dict = std::move(context).WriteDictionary();
4540 dict.Add("key", 123);
4541 },
4542 "array",
4543 [](perfetto::TracedValue context) {
4544 auto array = std::move(context).WriteArray();
4545 array.Append("first");
4546 array.Append("second");
4547 });
4548 }
4549
TEST_P(PerfettoApiTest,ConsoleInterceptorPrint)4550 TEST_P(PerfettoApiTest, ConsoleInterceptorPrint) {
4551 perfetto::ConsoleInterceptor::Register();
4552
4553 perfetto::TraceConfig cfg;
4554 cfg.set_duration_ms(500);
4555 cfg.add_buffers()->set_size_kb(1024);
4556 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
4557 ds_cfg->set_name("track_event");
4558 ds_cfg->mutable_interceptor_config()->set_name("console");
4559
4560 auto* tracing_session = NewTrace(cfg);
4561 tracing_session->get()->StartBlocking();
4562 EmitConsoleEvents();
4563 tracing_session->get()->StopBlocking();
4564 }
4565
TEST_P(PerfettoApiTest,ConsoleInterceptorVerify)4566 TEST_P(PerfettoApiTest, ConsoleInterceptorVerify) {
4567 perfetto::ConsoleInterceptor::Register();
4568 auto temp_file = perfetto::test::CreateTempFile();
4569 perfetto::ConsoleInterceptor::SetOutputFdForTesting(temp_file.fd);
4570
4571 perfetto::TraceConfig cfg;
4572 cfg.set_duration_ms(500);
4573 cfg.add_buffers()->set_size_kb(1024);
4574 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
4575 ds_cfg->set_name("track_event");
4576 ds_cfg->mutable_interceptor_config()->set_name("console");
4577
4578 auto* tracing_session = NewTrace(cfg);
4579 tracing_session->get()->StartBlocking();
4580 EmitConsoleEvents();
4581 tracing_session->get()->StopBlocking();
4582 perfetto::ConsoleInterceptor::SetOutputFdForTesting(0);
4583
4584 std::vector<std::string> lines;
4585 FILE* f = fdopen(temp_file.fd, "r");
4586 fseek(f, 0u, SEEK_SET);
4587 std::array<char, 128> line{};
4588 while (fgets(line.data(), line.size(), f)) {
4589 // Ignore timestamps and process/thread ids.
4590 std::string s(line.data() + 28);
4591 // Filter out durations.
4592 s = std::regex_replace(s, std::regex(" [+][0-9]*ms"), "");
4593 lines.push_back(std::move(s));
4594 }
4595 fclose(f);
4596 EXPECT_EQ(0, remove(temp_file.path.c_str()));
4597
4598 // clang-format off
4599 std::vector<std::string> golden_lines = {
4600 "foo Instant event\n",
4601 "foo Scoped event {\n",
4602 "foo - Nested event {\n",
4603 "foo - - Instant event\n",
4604 "foo - - Annotated event(foo:1, bar:hello)\n",
4605 "foo - } Nested event\n",
4606 "test AsyncEvent {\n",
4607 "foo EventFromAnotherThread {\n",
4608 "foo - Instant event\n",
4609 "test } AsyncEvent\n",
4610 "foo } EventFromAnotherThread\n",
4611 "foo - More annotations(dict:{key:123}, array:[first, second])\n",
4612 "foo } Scoped event\n",
4613 };
4614 // clang-format on
4615 EXPECT_THAT(lines, ContainerEq(golden_lines));
4616 }
4617
TEST_P(PerfettoApiTest,TrackEventObserver)4618 TEST_P(PerfettoApiTest, TrackEventObserver) {
4619 class Observer : public perfetto::TrackEventSessionObserver {
4620 public:
4621 ~Observer() override = default;
4622
4623 void OnSetup(const perfetto::DataSourceBase::SetupArgs&) {
4624 // Since other tests here register multiple track event data sources,
4625 // ignore all but the first notifications.
4626 if (setup_called)
4627 return;
4628 setup_called = true;
4629 if (unsubscribe_at_setup)
4630 perfetto::TrackEvent::RemoveSessionObserver(this);
4631 // This event isn't recorded in the trace because tracing isn't active yet
4632 // when OnSetup is called.
4633 TRACE_EVENT_INSTANT("foo", "OnSetup");
4634 // However the active tracing categories have already been updated at this
4635 // point.
4636 EXPECT_TRUE(perfetto::TrackEvent::IsEnabled());
4637 EXPECT_TRUE(TRACE_EVENT_CATEGORY_ENABLED("foo"));
4638 }
4639
4640 void OnStart(const perfetto::DataSourceBase::StartArgs&) {
4641 if (start_called)
4642 return;
4643 start_called = true;
4644 EXPECT_TRUE(perfetto::TrackEvent::IsEnabled());
4645 EXPECT_TRUE(TRACE_EVENT_CATEGORY_ENABLED("foo"));
4646 TRACE_EVENT_INSTANT("foo", "OnStart");
4647 }
4648
4649 void OnStop(const perfetto::DataSourceBase::StopArgs&) {
4650 if (stop_called)
4651 return;
4652 stop_called = true;
4653 EXPECT_TRUE(perfetto::TrackEvent::IsEnabled());
4654 EXPECT_TRUE(TRACE_EVENT_CATEGORY_ENABLED("foo"));
4655 TRACE_EVENT_INSTANT("foo", "OnStop");
4656 perfetto::TrackEvent::Flush();
4657 }
4658
4659 bool setup_called{};
4660 bool start_called{};
4661 bool stop_called{};
4662 bool unsubscribe_at_setup{};
4663 };
4664
4665 EXPECT_FALSE(perfetto::TrackEvent::IsEnabled());
4666 {
4667 Observer observer;
4668 perfetto::TrackEvent::AddSessionObserver(&observer);
4669
4670 auto* tracing_session = NewTraceWithCategories({"foo"});
4671 tracing_session->get()->StartBlocking();
4672 EXPECT_TRUE(observer.setup_called);
4673 EXPECT_TRUE(observer.start_called);
4674 tracing_session->get()->StopBlocking();
4675 EXPECT_TRUE(observer.stop_called);
4676 perfetto::TrackEvent::RemoveSessionObserver(&observer);
4677 auto slices = ReadSlicesFromTrace(tracing_session->get());
4678 EXPECT_THAT(slices, ElementsAre("I:foo.OnStart", "I:foo.OnStop"));
4679 }
4680
4681 // No notifications after removing observer.
4682 {
4683 Observer observer;
4684 perfetto::TrackEvent::AddSessionObserver(&observer);
4685 perfetto::TrackEvent::RemoveSessionObserver(&observer);
4686 auto* tracing_session = NewTraceWithCategories({"foo"});
4687 tracing_session->get()->StartBlocking();
4688 EXPECT_FALSE(observer.setup_called);
4689 EXPECT_FALSE(observer.start_called);
4690 tracing_session->get()->StopBlocking();
4691 EXPECT_FALSE(observer.stop_called);
4692 }
4693
4694 // Removing observer in a callback.
4695 {
4696 Observer observer;
4697 observer.unsubscribe_at_setup = true;
4698 perfetto::TrackEvent::AddSessionObserver(&observer);
4699 auto* tracing_session = NewTraceWithCategories({"foo"});
4700 tracing_session->get()->StartBlocking();
4701 EXPECT_TRUE(observer.setup_called);
4702 EXPECT_FALSE(observer.start_called);
4703 tracing_session->get()->StopBlocking();
4704 EXPECT_FALSE(observer.stop_called);
4705 perfetto::TrackEvent::RemoveSessionObserver(&observer);
4706 }
4707
4708 // Multiple observers.
4709 {
4710 Observer observer1;
4711 Observer observer2;
4712 perfetto::TrackEvent::AddSessionObserver(&observer1);
4713 perfetto::TrackEvent::AddSessionObserver(&observer2);
4714 auto* tracing_session = NewTraceWithCategories({"foo"});
4715 tracing_session->get()->StartBlocking();
4716 tracing_session->get()->StopBlocking();
4717 perfetto::TrackEvent::RemoveSessionObserver(&observer1);
4718 perfetto::TrackEvent::RemoveSessionObserver(&observer2);
4719 auto slices = ReadSlicesFromTrace(tracing_session->get());
4720 EXPECT_THAT(slices, ElementsAre("I:foo.OnStart", "I:foo.OnStart",
4721 "I:foo.OnStop", "I:foo.OnStop"));
4722 }
4723
4724 // Multiple observers with one being removed midway.
4725 {
4726 Observer observer1;
4727 Observer observer2;
4728 perfetto::TrackEvent::AddSessionObserver(&observer1);
4729 perfetto::TrackEvent::AddSessionObserver(&observer2);
4730 auto* tracing_session = NewTraceWithCategories({"foo"});
4731 tracing_session->get()->StartBlocking();
4732 perfetto::TrackEvent::RemoveSessionObserver(&observer1);
4733 tracing_session->get()->StopBlocking();
4734 perfetto::TrackEvent::RemoveSessionObserver(&observer2);
4735 auto slices = ReadSlicesFromTrace(tracing_session->get());
4736 EXPECT_THAT(slices,
4737 ElementsAre("I:foo.OnStart", "I:foo.OnStart", "I:foo.OnStop"));
4738 }
4739 EXPECT_FALSE(perfetto::TrackEvent::IsEnabled());
4740 }
4741
4742 #if PERFETTO_BUILDFLAG(PERFETTO_COMPILER_CLANG)
4743 struct __attribute__((capability("mutex"))) MockMutex {
Lock__anon22b779c30111::MockMutex4744 void Lock() __attribute__((acquire_capability())) {}
Unlock__anon22b779c30111::MockMutex4745 void Unlock() __attribute__((release_capability())) {}
4746 };
4747
4748 struct AnnotatedObject {
4749 MockMutex mutex;
4750 int value __attribute__((guarded_by(mutex))) = {};
4751 };
4752
TEST_P(PerfettoApiTest,ThreadSafetyAnnotation)4753 TEST_P(PerfettoApiTest, ThreadSafetyAnnotation) {
4754 AnnotatedObject obj;
4755
4756 // Access to the locked field is only allowed while holding the mutex.
4757 obj.mutex.Lock();
4758 obj.value = 1;
4759 obj.mutex.Unlock();
4760
4761 auto* tracing_session = NewTraceWithCategories({"cat"});
4762 tracing_session->get()->StartBlocking();
4763
4764 // It should be possible to trace the field while holding the lock.
4765 obj.mutex.Lock();
4766 TRACE_EVENT_INSTANT("cat", "Instant", "value", obj.value);
4767 TRACE_EVENT_INSTANT1("cat", "InstantLegacy", 0, "value", obj.value);
4768 { TRACE_EVENT("cat", "Scoped", "value", obj.value); }
4769 { TRACE_EVENT1("cat", "ScopedLegacy", "value", obj.value); }
4770 obj.mutex.Unlock();
4771
4772 perfetto::TrackEvent::Flush();
4773 tracing_session->get()->StopBlocking();
4774 auto slices = ReadSlicesFromTrace(tracing_session->get());
4775 EXPECT_THAT(slices, ElementsAre("I:cat.Instant(value=(int)1)",
4776 "[track=0]I:cat.InstantLegacy(value=(int)1)",
4777 "B:cat.Scoped(value=(int)1)", "E",
4778 "B:cat.ScopedLegacy(value=(int)1)", "E"));
4779 }
4780 #endif // PERFETTO_BUILDFLAG(PERFETTO_COMPILER_CLANG)
4781
TEST_P(PerfettoApiTest,CountersDeltaEncoding)4782 TEST_P(PerfettoApiTest, CountersDeltaEncoding) {
4783 auto* tracing_session = NewTraceWithCategories({"cat"});
4784 tracing_session->get()->StartBlocking();
4785
4786 // Describe a counter track.
4787 perfetto::CounterTrack track1 =
4788 perfetto::CounterTrack("Framerate1", "fps1").set_is_incremental(true);
4789 // Global tracks can be constructed at build time.
4790 constexpr perfetto::CounterTrack track2 =
4791 perfetto::CounterTrack::Global("Framerate2", "fps2")
4792 .set_is_incremental(true);
4793 perfetto::CounterTrack track3 = perfetto::CounterTrack("Framerate3", "fps3");
4794
4795 TRACE_COUNTER("cat", track1, 120);
4796 TRACE_COUNTER("cat", track2, 1000);
4797 TRACE_COUNTER("cat", track3, 10009);
4798
4799 TRACE_COUNTER("cat", track1, 10);
4800 TRACE_COUNTER("cat", track1, 1200);
4801 TRACE_COUNTER("cat", track1, 34);
4802
4803 TRACE_COUNTER("cat", track3, 975);
4804 TRACE_COUNTER("cat", track2, 449);
4805 TRACE_COUNTER("cat", track2, 2);
4806
4807 TRACE_COUNTER("cat", track3, 1091);
4808 TRACE_COUNTER("cat", track3, 110);
4809 TRACE_COUNTER("cat", track3, 1081);
4810
4811 TRACE_COUNTER("cat", track1, 98);
4812 TRACE_COUNTER("cat", track2, 1084);
4813
4814 perfetto::TrackEvent::Flush();
4815
4816 tracing_session->get()->StopBlocking();
4817 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
4818 perfetto::protos::gen::Trace trace;
4819 ASSERT_TRUE(trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
4820 std::unordered_map<uint64_t, std::string> counter_names;
4821 // Map(Counter name -> counter values)
4822 std::unordered_map<std::string, std::vector<int64_t>> values;
4823 for (const auto& packet : trace.packet()) {
4824 if (packet.has_track_descriptor()) {
4825 auto& desc = packet.track_descriptor();
4826 if (!desc.has_counter())
4827 continue;
4828 counter_names[desc.uuid()] = desc.name();
4829 EXPECT_EQ((desc.name() != "Framerate3"), desc.counter().is_incremental());
4830 }
4831 if (packet.has_track_event()) {
4832 auto event = packet.track_event();
4833 EXPECT_EQ(perfetto::protos::gen::TrackEvent_Type_TYPE_COUNTER,
4834 event.type());
4835 auto& counter_name = counter_names.at(event.track_uuid());
4836 values[counter_name].push_back(event.counter_value());
4837 }
4838 }
4839 ASSERT_EQ(3u, values.size());
4840 using IntVector = std::vector<int64_t>;
4841 EXPECT_EQ((IntVector{120, -110, 1190, -1166, 64}), values.at("Framerate1"));
4842 EXPECT_EQ((IntVector{1000, -551, -447, 1082}), values.at("Framerate2"));
4843 EXPECT_EQ((IntVector{10009, 975, 1091, 110, 1081}), values.at("Framerate3"));
4844 }
4845
TEST_P(PerfettoApiTest,Counters)4846 TEST_P(PerfettoApiTest, Counters) {
4847 auto* tracing_session = NewTraceWithCategories({"cat"});
4848 tracing_session->get()->StartBlocking();
4849
4850 // Describe a counter track.
4851 perfetto::CounterTrack fps_track = perfetto::CounterTrack("Framerate", "fps");
4852
4853 // Emit an integer sample.
4854 TRACE_COUNTER("cat", fps_track, 120);
4855
4856 // Global tracks can be constructed at build time.
4857 constexpr auto goats_track =
4858 perfetto::CounterTrack::Global("Goats teleported", "goats x 1000")
4859 .set_unit_multiplier(1000);
4860 static_assert(goats_track.uuid == 0x6072fc234f82df11,
4861 "Counter track uuid mismatch");
4862
4863 // Emit some floating point samples.
4864 TRACE_COUNTER("cat", goats_track, 0.25);
4865 TRACE_COUNTER("cat", goats_track, 0.5);
4866 TRACE_COUNTER("cat", goats_track, 0.75);
4867
4868 // Emit a sample using an inline track name.
4869 TRACE_COUNTER("cat", "Voltage", 220);
4870
4871 // Emit sample with a custom timestamp.
4872 TRACE_COUNTER("cat",
4873 perfetto::CounterTrack("Power", "GW").set_category("dmc"),
4874 MyTimestamp(1985u), 1.21f);
4875 perfetto::TrackEvent::Flush();
4876
4877 tracing_session->get()->StopBlocking();
4878 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
4879
4880 perfetto::protos::gen::Trace trace;
4881 ASSERT_TRUE(trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
4882 std::map<uint64_t, std::string> counter_names;
4883 std::vector<std::string> counter_samples;
4884 for (const auto& packet : trace.packet()) {
4885 if (packet.has_track_event()) {
4886 auto event = packet.track_event();
4887 EXPECT_EQ(perfetto::protos::gen::TrackEvent_Type_TYPE_COUNTER,
4888 event.type());
4889 std::stringstream sample;
4890 std::string counter_name = counter_names[event.track_uuid()];
4891 sample << counter_name << " = ";
4892 if (event.has_counter_value()) {
4893 sample << event.counter_value();
4894 } else if (event.has_double_counter_value()) {
4895 sample << event.double_counter_value();
4896 }
4897 if (counter_name == "Power") {
4898 EXPECT_EQ(1985u, packet.timestamp());
4899 }
4900 counter_samples.push_back(sample.str());
4901 }
4902
4903 if (!packet.has_track_descriptor() ||
4904 !packet.track_descriptor().has_counter()) {
4905 continue;
4906 }
4907 auto desc = packet.track_descriptor();
4908 counter_names[desc.uuid()] = desc.name();
4909 if (desc.name() == "Framerate") {
4910 EXPECT_EQ("fps", desc.counter().unit_name());
4911 } else if (desc.name() == "Goats teleported") {
4912 EXPECT_EQ("goats x 1000", desc.counter().unit_name());
4913 EXPECT_EQ(1000, desc.counter().unit_multiplier());
4914 } else if (desc.name() == "Power") {
4915 EXPECT_EQ("GW", desc.counter().unit_name());
4916 EXPECT_EQ("dmc", desc.counter().categories()[0]);
4917 }
4918 }
4919 EXPECT_EQ(4u, counter_names.size());
4920 EXPECT_THAT(counter_samples,
4921 ElementsAre("Framerate = 120", "Goats teleported = 0.25",
4922 "Goats teleported = 0.5", "Goats teleported = 0.75",
4923 "Voltage = 220", "Power = 1.21"));
4924 }
4925
TEST_P(PerfettoApiTest,EmptyEvent)4926 TEST_P(PerfettoApiTest, EmptyEvent) {
4927 auto* tracing_session = NewTraceWithCategories({"cat"});
4928 tracing_session->get()->StartBlocking();
4929
4930 // Emit an empty event.
4931 PERFETTO_INTERNAL_ADD_EMPTY_EVENT();
4932 perfetto::TrackEvent::Flush();
4933
4934 tracing_session->get()->StopBlocking();
4935 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
4936
4937 perfetto::protos::gen::Trace trace;
4938 ASSERT_TRUE(trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
4939 auto it = std::find_if(trace.packet().begin(), trace.packet().end(),
4940 [](const perfetto::protos::gen::TracePacket& packet) {
4941 return packet.has_trace_stats();
4942 });
4943 EXPECT_NE(it, trace.packet().end());
4944 // The empty event required a trace chunk.
4945 EXPECT_EQ(it->trace_stats().buffer_stats()[0].chunks_read(), 1u);
4946 // But it isn't in the trace, because empty packets are skipped when reading
4947 // from TraceBuffer.
4948 it = std::find_if(trace.packet().begin(), trace.packet().end(),
4949 [](const perfetto::protos::gen::TracePacket& packet) {
4950 return packet.has_track_event();
4951 });
4952 EXPECT_EQ(it, trace.packet().end());
4953 }
4954
4955 struct BackendTypeAsString {
operator ()__anon22b779c30111::BackendTypeAsString4956 std::string operator()(
4957 const ::testing::TestParamInfo<perfetto::BackendType>& info) const {
4958 switch (info.param) {
4959 case perfetto::kInProcessBackend:
4960 return "InProc";
4961 case perfetto::kSystemBackend:
4962 return "System";
4963 case perfetto::kCustomBackend:
4964 return "Custom";
4965 case perfetto::kUnspecifiedBackend:
4966 return "Unspec";
4967 }
4968 return nullptr;
4969 }
4970 };
4971
4972 INSTANTIATE_TEST_SUITE_P(PerfettoApiTest,
4973 PerfettoApiTest,
4974 ::testing::Values(perfetto::kInProcessBackend,
4975 perfetto::kSystemBackend),
4976 BackendTypeAsString());
4977
4978 } // namespace
4979
4980 PERFETTO_DECLARE_DATA_SOURCE_STATIC_MEMBERS(MockDataSource);
4981 PERFETTO_DECLARE_DATA_SOURCE_STATIC_MEMBERS(MockDataSource2);
4982 PERFETTO_DECLARE_DATA_SOURCE_STATIC_MEMBERS(TestIncrementalDataSource,
4983 TestIncrementalDataSourceTraits);
4984
4985 PERFETTO_DEFINE_DATA_SOURCE_STATIC_MEMBERS(MockDataSource);
4986 PERFETTO_DEFINE_DATA_SOURCE_STATIC_MEMBERS(MockDataSource2);
4987 PERFETTO_DEFINE_DATA_SOURCE_STATIC_MEMBERS(TestIncrementalDataSource,
4988 TestIncrementalDataSourceTraits);
4989