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/base/time.h"
49 #include "perfetto/protozero/scattered_heap_buffer.h"
50 #include "perfetto/tracing/core/data_source_descriptor.h"
51 #include "perfetto/tracing/core/trace_config.h"
52
53 // xxx.pbzero.h includes are for the writing path (the code that pretends to be
54 // production code).
55 // yyy.gen.h includes are for the test readback path (the code in the test that
56 // checks that the results are valid).
57 #include "protos/perfetto/common/builtin_clock.pbzero.h"
58 #include "protos/perfetto/common/interceptor_descriptor.gen.h"
59 #include "protos/perfetto/common/trace_stats.gen.h"
60 #include "protos/perfetto/common/tracing_service_state.gen.h"
61 #include "protos/perfetto/common/track_event_descriptor.gen.h"
62 #include "protos/perfetto/common/track_event_descriptor.pbzero.h"
63 #include "protos/perfetto/config/interceptor_config.gen.h"
64 #include "protos/perfetto/config/track_event/track_event_config.gen.h"
65 #include "protos/perfetto/trace/clock_snapshot.gen.h"
66 #include "protos/perfetto/trace/clock_snapshot.pbzero.h"
67 #include "protos/perfetto/trace/gpu/gpu_render_stage_event.gen.h"
68 #include "protos/perfetto/trace/gpu/gpu_render_stage_event.pbzero.h"
69 #include "protos/perfetto/trace/interned_data/interned_data.gen.h"
70 #include "protos/perfetto/trace/interned_data/interned_data.pbzero.h"
71 #include "protos/perfetto/trace/profiling/profile_common.gen.h"
72 #include "protos/perfetto/trace/test_event.gen.h"
73 #include "protos/perfetto/trace/test_event.pbzero.h"
74 #include "protos/perfetto/trace/test_extensions.pbzero.h"
75 #include "protos/perfetto/trace/trace.gen.h"
76 #include "protos/perfetto/trace/trace.pbzero.h"
77 #include "protos/perfetto/trace/trace_packet.gen.h"
78 #include "protos/perfetto/trace/trace_packet.pbzero.h"
79 #include "protos/perfetto/trace/trace_packet_defaults.gen.h"
80 #include "protos/perfetto/trace/track_event/chrome_process_descriptor.gen.h"
81 #include "protos/perfetto/trace/track_event/chrome_process_descriptor.pbzero.h"
82 #include "protos/perfetto/trace/track_event/counter_descriptor.gen.h"
83 #include "protos/perfetto/trace/track_event/debug_annotation.gen.h"
84 #include "protos/perfetto/trace/track_event/debug_annotation.pbzero.h"
85 #include "protos/perfetto/trace/track_event/log_message.gen.h"
86 #include "protos/perfetto/trace/track_event/log_message.pbzero.h"
87 #include "protos/perfetto/trace/track_event/process_descriptor.gen.h"
88 #include "protos/perfetto/trace/track_event/process_descriptor.pbzero.h"
89 #include "protos/perfetto/trace/track_event/source_location.gen.h"
90 #include "protos/perfetto/trace/track_event/source_location.pbzero.h"
91 #include "protos/perfetto/trace/track_event/thread_descriptor.gen.h"
92 #include "protos/perfetto/trace/track_event/thread_descriptor.pbzero.h"
93 #include "protos/perfetto/trace/track_event/track_descriptor.gen.h"
94 #include "protos/perfetto/trace/track_event/track_event.gen.h"
95 #include "protos/perfetto/trace/trigger.gen.h"
96
97 // Events in categories starting with "dynamic" will use dynamic category
98 // lookup.
99 PERFETTO_DEFINE_TEST_CATEGORY_PREFIXES("dynamic");
100
101 // Trace categories used in the tests.
102 PERFETTO_DEFINE_CATEGORIES(
103 perfetto::Category("test")
104 .SetDescription("This is a test category")
105 .SetTags("tag"),
106 perfetto::Category("foo"),
107 perfetto::Category("bar"),
108 perfetto::Category("cat").SetTags("slow"),
109 perfetto::Category("cat.verbose").SetTags("debug"),
110 perfetto::Category("cat-with-dashes"),
111 perfetto::Category::Group("foo,bar"),
112 perfetto::Category::Group("baz,bar,quux"),
113 perfetto::Category::Group("red,green,blue,foo"),
114 perfetto::Category::Group("red,green,blue,yellow"),
115 perfetto::Category(TRACE_DISABLED_BY_DEFAULT("cat")));
116 PERFETTO_TRACK_EVENT_STATIC_STORAGE();
117
118 // Test declaring an extra set of categories in a namespace in addition to the
119 // default one.
120 PERFETTO_DEFINE_CATEGORIES_IN_NAMESPACE(other_ns,
121 perfetto::Category("other_ns"));
122 PERFETTO_TRACK_EVENT_STATIC_STORAGE_IN_NAMESPACE(other_ns);
123
124 // For testing interning of complex objects.
125 using SourceLocation = std::tuple<const char* /* file_name */,
126 const char* /* function_name */,
127 uint32_t /* line_number */>;
128
129 template <>
130 struct std::hash<SourceLocation> {
operator ()std::hash131 size_t operator()(const SourceLocation& value) const {
132 auto hasher = hash<size_t>();
133 return hasher(reinterpret_cast<size_t>(get<0>(value))) ^
134 hasher(reinterpret_cast<size_t>(get<1>(value))) ^
135 hasher(get<2>(value));
136 }
137 };
138
WriteFile(const std::string & file_name,const char * content,size_t len)139 static void WriteFile(const std::string& file_name,
140 const char* content,
141 size_t len) {
142 std::ofstream output;
143 output.open(file_name.c_str(), std::ios::out | std::ios::binary);
144 output.write(content, static_cast<std::streamsize>(len));
145 output.close();
146 }
147
148 // Unused in merged code, but very handy for debugging when trace generated in
149 // a test needs to be exported, to understand it further with other tools.
WriteFile(const std::string & file_name,const std::vector<char> & data)150 PERFETTO_UNUSED static void WriteFile(const std::string& file_name,
151 const std::vector<char>& data) {
152 return WriteFile(file_name, data.data(), data.size());
153 }
154
155 // Returns true if the |key| is present in |container|.
156 template <typename ContainerType, class KeyType>
ContainsKey(const ContainerType & container,const KeyType & key)157 bool ContainsKey(const ContainerType& container, const KeyType& key) {
158 return container.find(key) != container.end();
159 }
160
161 // Represents an opaque (from Perfetto's point of view) thread identifier (e.g.,
162 // base::PlatformThreadId in Chromium).
163 struct MyThreadId {
MyThreadIdMyThreadId164 explicit MyThreadId(int tid_) : tid(tid_) {}
165
166 const int tid = 0;
167 };
168
169 // Represents an opaque timestamp (e.g., base::TimeTicks in Chromium).
170 class MyTimestamp {
171 public:
MyTimestamp(uint64_t ts_)172 explicit MyTimestamp(uint64_t ts_) : ts(ts_) {}
173
174 const uint64_t ts;
175 };
176
177 namespace perfetto {
178 namespace legacy {
179
180 template <>
ConvertThreadId(const MyThreadId & thread)181 ThreadTrack ConvertThreadId(const MyThreadId& thread) {
182 return perfetto::ThreadTrack::ForThread(
183 static_cast<base::PlatformThreadId>(thread.tid));
184 }
185
186 } // namespace legacy
187
188 template <>
189 struct TraceTimestampTraits<MyTimestamp> {
ConvertTimestampToTraceTimeNsperfetto::TraceTimestampTraits190 static TraceTimestamp ConvertTimestampToTraceTimeNs(
191 const MyTimestamp& timestamp) {
192 return {static_cast<uint32_t>(TrackEvent::GetTraceClockId()), timestamp.ts};
193 }
194 };
195
196 } // namespace perfetto
197
198 namespace {
199
200 using perfetto::TracingInitArgs;
201 using perfetto::internal::TrackEventIncrementalState;
202 using perfetto::internal::TrackEventInternal;
203 using ::perfetto::test::DataSourceInternalForTest;
204 using ::testing::_;
205 using ::testing::AllOf;
206 using ::testing::ContainerEq;
207 using ::testing::Contains;
208 using ::testing::Each;
209 using ::testing::ElementsAre;
210 using ::testing::HasSubstr;
211 using ::testing::Invoke;
212 using ::testing::InvokeWithoutArgs;
213 using ::testing::IsEmpty;
214 using ::testing::NiceMock;
215 using ::testing::Not;
216 using ::testing::Property;
217 using ::testing::StrEq;
218
219 // ------------------------------
220 // Declarations of helper classes
221 // ------------------------------
222
223 class WaitableTestEvent {
224 public:
notified()225 bool notified() {
226 std::unique_lock<std::mutex> lock(mutex_);
227 return notified_;
228 }
229
Wait()230 void Wait() {
231 std::unique_lock<std::mutex> lock(mutex_);
232 // TSAN gets confused by wait_for, which we would use here in a perfect
233 // world.
234 cv_.wait(lock, [this] { return notified_; });
235 }
236
Notify()237 void Notify() {
238 std::lock_guard<std::mutex> lock(mutex_);
239 notified_ = true;
240 cv_.notify_one();
241 }
242
243 private:
244 std::mutex mutex_;
245 std::condition_variable cv_;
246 bool notified_ = false;
247 };
248
249 template <typename Func>
250 class Cleanup {
251 public:
Cleanup(Func f)252 explicit Cleanup(Func f) : f_(std::move(f)) {}
~Cleanup()253 ~Cleanup() { f_(); }
254 Cleanup(Cleanup&&) noexcept = default;
255 Cleanup& operator=(Cleanup&&) noexcept = default;
256 Cleanup(const Cleanup&) = delete;
257 Cleanup& operator=(const Cleanup&) = delete;
258
259 private:
260 Func f_;
261 };
262 template <typename Func>
MakeCleanup(Func f)263 Cleanup<Func> MakeCleanup(Func f) {
264 return Cleanup<Func>(std::move(f));
265 }
266
267 class CustomDataSource : public perfetto::DataSource<CustomDataSource> {};
268
269 class MockDataSource;
270
271 // We can't easily use gmock here because instances of data sources are lazily
272 // created by the service and are not owned by the test fixture.
273 struct TestDataSourceHandle {
274 WaitableTestEvent on_create;
275 WaitableTestEvent on_setup;
276 WaitableTestEvent on_start;
277 WaitableTestEvent on_stop;
278 WaitableTestEvent on_flush;
279 MockDataSource* instance;
280 perfetto::DataSourceConfig config;
281 bool handle_stop_asynchronously = false;
282 bool handle_flush_asynchronously = false;
283 std::function<void()> on_start_callback;
284 std::function<void()> on_stop_callback;
285 std::function<void()> on_flush_callback;
286 std::function<void()> async_stop_closure;
287 std::function<void()> async_flush_closure;
288 };
289
290 class MockDataSource : public perfetto::DataSource<MockDataSource> {
291 public:
292 void OnSetup(const SetupArgs&) override;
293 void OnStart(const StartArgs&) override;
294 void OnStop(const StopArgs&) override;
295 void OnFlush(const FlushArgs&) override;
296 TestDataSourceHandle* handle_ = nullptr;
297 };
298
299 constexpr int kTestDataSourceArg = 123;
300
301 class MockDataSource2 : public perfetto::DataSource<MockDataSource2> {
302 public:
MockDataSource2(int arg)303 MockDataSource2(int arg) { EXPECT_EQ(arg, kTestDataSourceArg); }
OnSetup(const SetupArgs &)304 void OnSetup(const SetupArgs&) override {}
OnStart(const StartArgs &)305 void OnStart(const StartArgs&) override {}
OnStop(const StopArgs &)306 void OnStop(const StopArgs&) override {}
307 };
308
309 // Used to verify that track event data sources in different namespaces register
310 // themselves correctly in the muxer.
311 class MockTracingMuxer : public perfetto::internal::TracingMuxer {
312 public:
313 struct DataSource {
314 perfetto::DataSourceDescriptor dsd;
315 perfetto::internal::DataSourceStaticState* static_state;
316 };
317
MockTracingMuxer()318 MockTracingMuxer() : TracingMuxer(nullptr), prev_instance_(instance_) {
319 instance_ = this;
320 }
~MockTracingMuxer()321 ~MockTracingMuxer() override { instance_ = prev_instance_; }
322
RegisterDataSource(const perfetto::DataSourceDescriptor & dsd,DataSourceFactory,perfetto::internal::DataSourceParams,perfetto::internal::DataSourceStaticState * static_state)323 bool RegisterDataSource(
324 const perfetto::DataSourceDescriptor& dsd,
325 DataSourceFactory,
326 perfetto::internal::DataSourceParams,
327 perfetto::internal::DataSourceStaticState* static_state) override {
328 data_sources.emplace_back(DataSource{dsd, static_state});
329 return true;
330 }
331
UpdateDataSourceDescriptor(const perfetto::DataSourceDescriptor & dsd,const perfetto::internal::DataSourceStaticState * static_state)332 void UpdateDataSourceDescriptor(
333 const perfetto::DataSourceDescriptor& dsd,
334 const perfetto::internal::DataSourceStaticState* static_state) override {
335 for (auto& rds : data_sources) {
336 if (rds.static_state == static_state) {
337 rds.dsd = dsd;
338 return;
339 }
340 }
341 }
342
CreateTraceWriter(perfetto::internal::DataSourceStaticState *,uint32_t,perfetto::internal::DataSourceState *,perfetto::BufferExhaustedPolicy)343 std::unique_ptr<perfetto::TraceWriterBase> CreateTraceWriter(
344 perfetto::internal::DataSourceStaticState*,
345 uint32_t,
346 perfetto::internal::DataSourceState*,
347 perfetto::BufferExhaustedPolicy) override {
348 return nullptr;
349 }
350
DestroyStoppedTraceWritersForCurrentThread()351 void DestroyStoppedTraceWritersForCurrentThread() override {}
RegisterInterceptor(const perfetto::InterceptorDescriptor &,InterceptorFactory,perfetto::InterceptorBase::TLSFactory,perfetto::InterceptorBase::TracePacketCallback)352 void RegisterInterceptor(
353 const perfetto::InterceptorDescriptor&,
354 InterceptorFactory,
355 perfetto::InterceptorBase::TLSFactory,
356 perfetto::InterceptorBase::TracePacketCallback) override {}
357
ActivateTriggers(const std::vector<std::string> &,uint32_t)358 void ActivateTriggers(const std::vector<std::string>&, uint32_t) override {}
359
360 std::vector<DataSource> data_sources;
361
362 private:
363 TracingMuxer* prev_instance_;
364 };
365
366 struct TestIncrementalState {
TestIncrementalState__anon78e5bb3c0111::TestIncrementalState367 TestIncrementalState() { constructed = true; }
368 // Note: a virtual destructor is not required for incremental state.
~TestIncrementalState__anon78e5bb3c0111::TestIncrementalState369 ~TestIncrementalState() { destroyed = true; }
370
371 int count = 100;
372 bool flag = false;
373 static bool constructed;
374 static bool destroyed;
375 };
376
377 bool TestIncrementalState::constructed;
378 bool TestIncrementalState::destroyed;
379
380 struct TestIncrementalDataSourceTraits
381 : public perfetto::DefaultDataSourceTraits {
382 using IncrementalStateType = TestIncrementalState;
383 using CustomTlsState = void;
384 };
385
386 class TestIncrementalDataSource
387 : public perfetto::DataSource<TestIncrementalDataSource,
388 TestIncrementalDataSourceTraits> {
389 public:
OnSetup(const SetupArgs &)390 void OnSetup(const SetupArgs&) override {}
OnStart(const StartArgs &)391 void OnStart(const StartArgs&) override {}
OnStop(const StopArgs &)392 void OnStop(const StopArgs&) override {}
393 };
394
395 // A convenience wrapper around TracingSession that allows to do block on
396 //
397 struct TestTracingSessionHandle {
get__anon78e5bb3c0111::TestTracingSessionHandle398 perfetto::TracingSession* get() { return session.get(); }
399 std::unique_ptr<perfetto::TracingSession> session;
400 WaitableTestEvent on_stop;
401 };
402
403 class MyDebugAnnotation : public perfetto::DebugAnnotation {
404 public:
405 ~MyDebugAnnotation() override = default;
406
Add(perfetto::protos::pbzero::DebugAnnotation * annotation) const407 void Add(
408 perfetto::protos::pbzero::DebugAnnotation* annotation) const override {
409 annotation->set_legacy_json_value(R"({"key": 123})");
410 }
411 };
412
413 class TestTracingPolicy : public perfetto::TracingPolicy {
414 public:
ShouldAllowConsumerSession(const ShouldAllowConsumerSessionArgs & args)415 void ShouldAllowConsumerSession(
416 const ShouldAllowConsumerSessionArgs& args) override {
417 EXPECT_NE(args.backend_type, perfetto::BackendType::kUnspecifiedBackend);
418 args.result_callback(should_allow_consumer_connection);
419 }
420
421 bool should_allow_consumer_connection = true;
422 };
423
424 TestTracingPolicy* g_test_tracing_policy = new TestTracingPolicy(); // Leaked.
425
426 class ParsedIncrementalState {
427 public:
ClearIfNeeded(const perfetto::protos::gen::TracePacket & packet)428 void ClearIfNeeded(const perfetto::protos::gen::TracePacket& packet) {
429 if (packet.sequence_flags() &
430 perfetto::protos::pbzero::TracePacket::SEQ_INCREMENTAL_STATE_CLEARED) {
431 incremental_state_was_cleared_ = true;
432 categories_.clear();
433 event_names_.clear();
434 debug_annotation_names_.clear();
435 seen_tracks_.clear();
436 }
437 }
438
Parse(const perfetto::protos::gen::TracePacket & packet)439 void Parse(const perfetto::protos::gen::TracePacket& packet) {
440 // Update incremental state.
441 if (packet.has_interned_data()) {
442 const auto& interned_data = packet.interned_data();
443 for (const auto& it : interned_data.event_categories()) {
444 EXPECT_EQ(categories_.find(it.iid()), categories_.end());
445 categories_[it.iid()] = it.name();
446 }
447 for (const auto& it : interned_data.event_names()) {
448 EXPECT_EQ(event_names_.find(it.iid()), event_names_.end());
449 event_names_[it.iid()] = it.name();
450 }
451 for (const auto& it : interned_data.debug_annotation_names()) {
452 EXPECT_EQ(debug_annotation_names_.find(it.iid()),
453 debug_annotation_names_.end());
454 debug_annotation_names_[it.iid()] = it.name();
455 }
456 }
457 }
458
HasSeenTrack(uint64_t uuid) const459 bool HasSeenTrack(uint64_t uuid) const {
460 return seen_tracks_.count(uuid) != 0;
461 }
462
InsertTrack(uint64_t uuid)463 void InsertTrack(uint64_t uuid) { seen_tracks_.insert(uuid); }
464
GetCategory(uint64_t iid)465 std::string GetCategory(uint64_t iid) { return categories_[iid]; }
466
GetEventName(const perfetto::protos::gen::TrackEvent & event)467 std::string GetEventName(const perfetto::protos::gen::TrackEvent& event) {
468 if (event.has_name_iid())
469 return event_names_[event.name_iid()];
470 return event.name();
471 }
472
GetDebugAnnotationName(uint64_t iid)473 std::string GetDebugAnnotationName(uint64_t iid) {
474 return debug_annotation_names_[iid];
475 }
476
WasCleared() const477 bool WasCleared() const { return incremental_state_was_cleared_; }
478
479 private:
480 bool incremental_state_was_cleared_ = false;
481 std::map<uint64_t, std::string> categories_;
482 std::map<uint64_t, std::string> event_names_;
483 std::map<uint64_t, std::string> debug_annotation_names_;
484 std::set<uint64_t> seen_tracks_;
485 };
486
ReadSlicesFromTrace(const perfetto::protos::gen::Trace & parsed_trace,bool expect_incremental_state_cleared=true)487 std::vector<std::string> ReadSlicesFromTrace(
488 const perfetto::protos::gen::Trace& parsed_trace,
489 bool expect_incremental_state_cleared = true) {
490 // Read back the trace, maintaining interning tables as we go.
491 std::vector<std::string> slices;
492 if (parsed_trace.packet().size() == 0)
493 return slices;
494 ParsedIncrementalState incremental_state;
495
496 uint32_t sequence_id = 0;
497 for (const auto& packet : parsed_trace.packet()) {
498 incremental_state.ClearIfNeeded(packet);
499
500 if (packet.has_track_descriptor()) {
501 // Make sure we haven't seen any events on this track before the
502 // descriptor was written.
503 EXPECT_FALSE(
504 incremental_state.HasSeenTrack(packet.track_descriptor().uuid()));
505 }
506
507 if (!packet.has_track_event())
508 continue;
509
510 // Make sure we only see track events on one sequence.
511 if (packet.trusted_packet_sequence_id()) {
512 if (!sequence_id)
513 sequence_id = packet.trusted_packet_sequence_id();
514 EXPECT_EQ(sequence_id, packet.trusted_packet_sequence_id());
515 }
516
517 incremental_state.Parse(packet);
518
519 const auto& track_event = packet.track_event();
520 std::string slice;
521
522 if (track_event.has_track_uuid()) {
523 incremental_state.InsertTrack(track_event.track_uuid());
524 std::stringstream track;
525 track << "[track=" << track_event.track_uuid() << "]";
526 slice += track.str();
527 }
528
529 switch (track_event.type()) {
530 case perfetto::protos::gen::TrackEvent::TYPE_SLICE_BEGIN:
531 slice += "B";
532 break;
533 case perfetto::protos::gen::TrackEvent::TYPE_SLICE_END:
534 slice += "E";
535 break;
536 case perfetto::protos::gen::TrackEvent::TYPE_INSTANT:
537 slice += "I";
538 break;
539 case perfetto::protos::gen::TrackEvent::TYPE_UNSPECIFIED: {
540 EXPECT_TRUE(track_event.has_legacy_event());
541 EXPECT_FALSE(track_event.type());
542 auto legacy_event = track_event.legacy_event();
543 slice +=
544 "Legacy_" + std::string(1, static_cast<char>(legacy_event.phase()));
545 break;
546 }
547 case perfetto::protos::gen::TrackEvent::TYPE_COUNTER:
548 slice += "C";
549 break;
550 default:
551 ADD_FAILURE();
552 }
553 if (track_event.has_legacy_event()) {
554 auto legacy_event = track_event.legacy_event();
555 std::stringstream id;
556 if (legacy_event.has_unscoped_id()) {
557 id << "(unscoped_id=" << legacy_event.unscoped_id() << ")";
558 } else if (legacy_event.has_local_id()) {
559 id << "(local_id=" << legacy_event.local_id() << ")";
560 } else if (legacy_event.has_global_id()) {
561 id << "(global_id=" << legacy_event.global_id() << ")";
562 } else if (legacy_event.has_bind_id()) {
563 id << "(bind_id=" << legacy_event.bind_id() << ")";
564 }
565 if (legacy_event.has_id_scope())
566 id << "(id_scope=\"" << legacy_event.id_scope() << "\")";
567 if (legacy_event.use_async_tts())
568 id << "(use_async_tts)";
569 if (legacy_event.bind_to_enclosing())
570 id << "(bind_to_enclosing)";
571 if (legacy_event.has_flow_direction())
572 id << "(flow_direction=" << legacy_event.flow_direction() << ")";
573 if (legacy_event.has_pid_override())
574 id << "(pid_override=" << legacy_event.pid_override() << ")";
575 if (legacy_event.has_tid_override())
576 id << "(tid_override=" << legacy_event.tid_override() << ")";
577 slice += id.str();
578 }
579 size_t category_count = 0;
580 for (const auto& it : track_event.category_iids())
581 slice +=
582 (category_count++ ? "," : ":") + incremental_state.GetCategory(it);
583 for (const auto& it : track_event.categories())
584 slice += (category_count++ ? ",$" : ":$") + it;
585 if (track_event.has_name() || track_event.has_name_iid())
586 slice += "." + incremental_state.GetEventName(track_event);
587
588 if (track_event.debug_annotations_size()) {
589 slice += "(";
590 bool first_annotation = true;
591 for (const auto& it : track_event.debug_annotations()) {
592 if (!first_annotation) {
593 slice += ",";
594 }
595 if (it.has_name_iid()) {
596 slice += incremental_state.GetDebugAnnotationName(it.name_iid());
597 } else {
598 slice += it.name();
599 }
600 slice += "=";
601 std::stringstream value;
602 if (it.has_bool_value()) {
603 value << "(bool)" << it.bool_value();
604 } else if (it.has_uint_value()) {
605 value << "(uint)" << it.uint_value();
606 } else if (it.has_int_value()) {
607 value << "(int)" << it.int_value();
608 } else if (it.has_double_value()) {
609 value << "(double)" << it.double_value();
610 } else if (it.has_string_value()) {
611 value << "(string)" << it.string_value();
612 } else if (it.has_pointer_value()) {
613 value << "(pointer)" << std::hex << it.pointer_value();
614 } else if (it.has_legacy_json_value()) {
615 value << "(json)" << it.legacy_json_value();
616 } else if (it.has_nested_value()) {
617 value << "(nested)" << it.nested_value().string_value();
618 }
619 slice += value.str();
620 first_annotation = false;
621 }
622 slice += ")";
623 }
624
625 if (track_event.flow_ids_old_size()) {
626 slice += "(flow_ids_old=";
627 std::stringstream value;
628 bool first_annotation = true;
629 for (uint64_t id : track_event.flow_ids_old()) {
630 if (!first_annotation) {
631 value << ",";
632 }
633 first_annotation = false;
634 value << id;
635 }
636 slice += value.str() + ")";
637 }
638
639 if (track_event.flow_ids_size()) {
640 slice += "(flow_ids=";
641 std::stringstream value;
642 bool first_annotation = true;
643 for (uint64_t id : track_event.flow_ids()) {
644 if (!first_annotation) {
645 value << ",";
646 }
647 first_annotation = false;
648 value << id;
649 }
650 slice += value.str() + ")";
651 }
652
653 if (track_event.terminating_flow_ids_old_size()) {
654 slice += "(terminating_flow_ids_old=";
655 std::stringstream value;
656 bool first_annotation = true;
657 for (uint64_t id : track_event.terminating_flow_ids_old()) {
658 if (!first_annotation) {
659 value << ",";
660 }
661 value << id;
662 first_annotation = false;
663 }
664 slice += value.str() + ")";
665 }
666
667 if (track_event.terminating_flow_ids_size()) {
668 slice += "(terminating_flow_ids=";
669 std::stringstream value;
670 bool first_annotation = true;
671 for (uint64_t id : track_event.terminating_flow_ids()) {
672 if (!first_annotation) {
673 value << ",";
674 }
675 value << id;
676 first_annotation = false;
677 }
678 slice += value.str() + ")";
679 }
680
681 slices.push_back(slice);
682 }
683 if (expect_incremental_state_cleared) {
684 EXPECT_TRUE(incremental_state.WasCleared());
685 }
686 return slices;
687 }
688
ReadSlicesFromTrace(const std::vector<char> & raw_trace,bool expect_incremental_state_cleared=true)689 std::vector<std::string> ReadSlicesFromTrace(
690 const std::vector<char>& raw_trace,
691 bool expect_incremental_state_cleared = true) {
692 EXPECT_GE(raw_trace.size(), 0u);
693
694 perfetto::protos::gen::Trace parsed_trace;
695 EXPECT_TRUE(parsed_trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
696 return ReadSlicesFromTrace(parsed_trace, expect_incremental_state_cleared);
697 }
698
699 // -------------------------
700 // Declaration of test class
701 // -------------------------
702 class PerfettoApiTest : public ::testing::TestWithParam<perfetto::BackendType> {
703 public:
704 static PerfettoApiTest* instance;
705
SetUp()706 void SetUp() override {
707 instance = this;
708 g_test_tracing_policy->should_allow_consumer_connection = true;
709
710 // Start a fresh system service for this test, tearing down any previous
711 // service that was running.
712 if (GetParam() == perfetto::kSystemBackend) {
713 system_service_ = perfetto::test::SystemService::Start();
714 // If the system backend isn't supported, skip all system backend tests.
715 if (!system_service_.valid()) {
716 GTEST_SKIP();
717 }
718 }
719
720 EXPECT_FALSE(perfetto::Tracing::IsInitialized());
721 TracingInitArgs args;
722 args.backends = GetParam();
723 args.tracing_policy = g_test_tracing_policy;
724 perfetto::Tracing::Initialize(args);
725 RegisterDataSource<MockDataSource>("my_data_source");
726 {
727 perfetto::DataSourceDescriptor dsd;
728 dsd.set_name("CustomDataSource");
729 CustomDataSource::Register(dsd);
730 }
731 perfetto::TrackEvent::Register();
732
733 // Make sure our data source always has a valid handle.
734 data_sources_["my_data_source"];
735
736 // If this wasn't the first test to run in this process, any producers
737 // connected to the old system service will have been disconnected by the
738 // service restarting above. Wait for all producers to connect again before
739 // proceeding with the test.
740 perfetto::test::SyncProducers();
741
742 perfetto::test::DisableReconnectLimit();
743 }
744
TearDown()745 void TearDown() override {
746 instance = nullptr;
747 sessions_.clear();
748 perfetto::test::TracingMuxerImplInternalsForTest::
749 ClearDataSourceTlsStateOnReset<MockDataSource>();
750 perfetto::test::TracingMuxerImplInternalsForTest::
751 ClearDataSourceTlsStateOnReset<CustomDataSource>();
752 perfetto::test::TracingMuxerImplInternalsForTest::
753 ClearDataSourceTlsStateOnReset<perfetto::TrackEvent>();
754 perfetto::Tracing::ResetForTesting();
755 }
756
757 template <typename DerivedDataSource>
RegisterDataSource(std::string name)758 TestDataSourceHandle* RegisterDataSource(std::string name) {
759 perfetto::DataSourceDescriptor dsd;
760 dsd.set_name(name);
761 return RegisterDataSource<DerivedDataSource>(dsd);
762 }
763
764 template <typename DerivedDataSource>
RegisterDataSource(const perfetto::DataSourceDescriptor & dsd)765 TestDataSourceHandle* RegisterDataSource(
766 const perfetto::DataSourceDescriptor& dsd) {
767 EXPECT_EQ(data_sources_.count(dsd.name()), 0u);
768 TestDataSourceHandle* handle = &data_sources_[dsd.name()];
769 DerivedDataSource::Register(dsd);
770 return handle;
771 }
772
773 template <typename DerivedDataSource>
UpdateDataSource(const perfetto::DataSourceDescriptor & dsd)774 TestDataSourceHandle* UpdateDataSource(
775 const perfetto::DataSourceDescriptor& dsd) {
776 EXPECT_EQ(data_sources_.count(dsd.name()), 1u);
777 TestDataSourceHandle* handle = &data_sources_[dsd.name()];
778 DerivedDataSource::UpdateDescriptor(dsd);
779 return handle;
780 }
781
NewTrace(const perfetto::TraceConfig & cfg,int fd=-1)782 TestTracingSessionHandle* NewTrace(const perfetto::TraceConfig& cfg,
783 int fd = -1) {
784 return NewTrace(cfg, /*backend_type=*/GetParam(), fd);
785 }
786
NewTrace(const perfetto::TraceConfig & cfg,perfetto::BackendType backend_type,int fd=-1)787 TestTracingSessionHandle* NewTrace(const perfetto::TraceConfig& cfg,
788 perfetto::BackendType backend_type,
789 int fd = -1) {
790 sessions_.emplace_back();
791 TestTracingSessionHandle* handle = &sessions_.back();
792 handle->session = perfetto::Tracing::NewTrace(backend_type);
793 handle->session->SetOnStopCallback([handle] { handle->on_stop.Notify(); });
794 handle->session->Setup(cfg, fd);
795 return handle;
796 }
797
NewTraceWithCategories(std::vector<std::string> categories,perfetto::protos::gen::TrackEventConfig te_cfg={},perfetto::TraceConfig cfg={})798 TestTracingSessionHandle* NewTraceWithCategories(
799 std::vector<std::string> categories,
800 perfetto::protos::gen::TrackEventConfig te_cfg = {},
801 perfetto::TraceConfig cfg = {}) {
802 cfg.set_duration_ms(500);
803 cfg.add_buffers()->set_size_kb(1024);
804 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
805 ds_cfg->set_name("track_event");
806 te_cfg.add_disabled_categories("*");
807 for (const auto& category : categories)
808 te_cfg.add_enabled_categories(category);
809 ds_cfg->set_track_event_config_raw(te_cfg.SerializeAsString());
810
811 return NewTrace(cfg);
812 }
813
ReadLogMessagesFromTrace(perfetto::TracingSession * tracing_session)814 std::vector<std::string> ReadLogMessagesFromTrace(
815 perfetto::TracingSession* tracing_session) {
816 std::vector<char> raw_trace = tracing_session->ReadTraceBlocking();
817 EXPECT_GE(raw_trace.size(), 0u);
818
819 // Read back the trace, maintaining interning tables as we go.
820 std::vector<std::string> log_messages;
821 std::map<uint64_t, std::string> log_message_bodies;
822 std::map<uint64_t, perfetto::protos::gen::SourceLocation> source_locations;
823 perfetto::protos::gen::Trace parsed_trace;
824 EXPECT_TRUE(
825 parsed_trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
826
827 for (const auto& packet : parsed_trace.packet()) {
828 if (!packet.has_track_event())
829 continue;
830
831 if (packet.has_interned_data()) {
832 const auto& interned_data = packet.interned_data();
833 for (const auto& it : interned_data.log_message_body()) {
834 EXPECT_GE(it.iid(), 1u);
835 EXPECT_EQ(log_message_bodies.find(it.iid()),
836 log_message_bodies.end());
837 log_message_bodies[it.iid()] = it.body();
838 }
839 for (const auto& it : interned_data.source_locations()) {
840 EXPECT_GE(it.iid(), 1u);
841 EXPECT_EQ(source_locations.find(it.iid()), source_locations.end());
842 source_locations[it.iid()] = it;
843 }
844 }
845 const auto& track_event = packet.track_event();
846 if (track_event.type() !=
847 perfetto::protos::gen::TrackEvent::TYPE_SLICE_BEGIN)
848 continue;
849
850 EXPECT_TRUE(track_event.has_log_message());
851 const auto& log = track_event.log_message();
852 if (log.source_location_iid()) {
853 std::stringstream msg;
854 const auto& source_location =
855 source_locations[log.source_location_iid()];
856 msg << source_location.function_name() << "("
857 << source_location.file_name() << ":"
858 << source_location.line_number()
859 << "): " << log_message_bodies[log.body_iid()];
860 log_messages.emplace_back(msg.str());
861 } else {
862 log_messages.emplace_back(log_message_bodies[log.body_iid()]);
863 }
864 }
865 return log_messages;
866 }
867
ReadSlicesFromTraceSession(perfetto::TracingSession * tracing_session)868 std::vector<std::string> ReadSlicesFromTraceSession(
869 perfetto::TracingSession* tracing_session) {
870 return ReadSlicesFromTrace(tracing_session->ReadTraceBlocking());
871 }
872
StopSessionAndReadSlicesFromTrace(TestTracingSessionHandle * tracing_session)873 std::vector<std::string> StopSessionAndReadSlicesFromTrace(
874 TestTracingSessionHandle* tracing_session) {
875 return ReadSlicesFromTrace(StopSessionAndReturnBytes(tracing_session));
876 }
877
GetMainThreadPacketSequenceId(const perfetto::protos::gen::Trace & trace)878 uint32_t GetMainThreadPacketSequenceId(
879 const perfetto::protos::gen::Trace& trace) {
880 for (const auto& packet : trace.packet()) {
881 if (packet.has_track_descriptor() &&
882 packet.track_descriptor().thread().tid() ==
883 static_cast<int32_t>(perfetto::base::GetThreadId())) {
884 return packet.trusted_packet_sequence_id();
885 }
886 }
887 ADD_FAILURE() << "Main thread not found";
888 return 0;
889 }
890
StopSessionAndReturnBytes(TestTracingSessionHandle * tracing_session)891 static std::vector<char> StopSessionAndReturnBytes(
892 TestTracingSessionHandle* tracing_session) {
893 perfetto::TrackEvent::Flush();
894 tracing_session->get()->StopBlocking();
895 return tracing_session->get()->ReadTraceBlocking();
896 }
897
StopSessionAndReturnParsedTrace(TestTracingSessionHandle * tracing_session)898 static perfetto::protos::gen::Trace StopSessionAndReturnParsedTrace(
899 TestTracingSessionHandle* tracing_session) {
900 std::vector<char> raw_trace = StopSessionAndReturnBytes(tracing_session);
901 perfetto::protos::gen::Trace trace;
902 if (trace.ParseFromArray(raw_trace.data(), raw_trace.size())) {
903 return trace;
904 } else {
905 ADD_FAILURE() << "trace.ParseFromArray failed";
906 return perfetto::protos::gen::Trace();
907 }
908 }
909
910 perfetto::test::SystemService system_service_;
911 std::map<std::string, TestDataSourceHandle> data_sources_;
912 std::list<TestTracingSessionHandle> sessions_; // Needs stable pointers.
913 };
914
915 // ---------------------------------------------
916 // Definitions for non-inlineable helper methods
917 // ---------------------------------------------
918 PerfettoApiTest* PerfettoApiTest::instance;
919
OnSetup(const SetupArgs & args)920 void MockDataSource::OnSetup(const SetupArgs& args) {
921 EXPECT_EQ(handle_, nullptr);
922 auto it = PerfettoApiTest::instance->data_sources_.find(args.config->name());
923
924 // We should not see an OnSetup for a data source that we didn't register
925 // before via PerfettoApiTest::RegisterDataSource().
926 EXPECT_NE(it, PerfettoApiTest::instance->data_sources_.end());
927 handle_ = &it->second;
928 handle_->config = *args.config; // Deliberate copy.
929 handle_->on_setup.Notify();
930 }
931
OnStart(const StartArgs &)932 void MockDataSource::OnStart(const StartArgs&) {
933 EXPECT_NE(handle_, nullptr);
934 if (handle_->on_start_callback)
935 handle_->on_start_callback();
936 handle_->on_start.Notify();
937 }
938
OnStop(const StopArgs & args)939 void MockDataSource::OnStop(const StopArgs& args) {
940 EXPECT_NE(handle_, nullptr);
941 if (handle_->handle_stop_asynchronously)
942 handle_->async_stop_closure = args.HandleStopAsynchronously();
943 if (handle_->on_stop_callback)
944 handle_->on_stop_callback();
945 handle_->on_stop.Notify();
946 }
947
OnFlush(const FlushArgs & args)948 void MockDataSource::OnFlush(const FlushArgs& args) {
949 EXPECT_NE(handle_, nullptr);
950 if (handle_->handle_flush_asynchronously)
951 handle_->async_flush_closure = args.HandleFlushAsynchronously();
952 if (handle_->on_flush_callback)
953 handle_->on_flush_callback();
954 handle_->on_flush.Notify();
955 }
956
957 // -------------
958 // Test fixtures
959 // -------------
960
TEST_P(PerfettoApiTest,StartAndStopWithoutDataSources)961 TEST_P(PerfettoApiTest, StartAndStopWithoutDataSources) {
962 // Create a new trace session without any data sources configured.
963 perfetto::TraceConfig cfg;
964 cfg.add_buffers()->set_size_kb(1024);
965 auto* tracing_session = NewTrace(cfg);
966 // This should not timeout.
967 tracing_session->get()->StartBlocking();
968 tracing_session->get()->StopBlocking();
969 }
970
971 // Disabled by default because it leaks tracing sessions into subsequent tests,
972 // which can result in the per-uid tracing session limit (5) to be hit in later
973 // tests.
974 // TODO(b/261493947): fix or remove.
TEST_P(PerfettoApiTest,DISABLED_TrackEventStartStopAndDestroy)975 TEST_P(PerfettoApiTest, DISABLED_TrackEventStartStopAndDestroy) {
976 // This test used to cause a use after free as the tracing session got
977 // destroyed. It needed to be run approximately 2000 times to catch it so test
978 // with --gtest_repeat=3000 (less if running under GDB).
979
980 // Setup the trace config.
981 perfetto::TraceConfig cfg;
982 cfg.set_duration_ms(500);
983 cfg.add_buffers()->set_size_kb(1024);
984 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
985 ds_cfg->set_name("track_event");
986
987 // Create five new trace sessions.
988 std::vector<std::unique_ptr<perfetto::TracingSession>> sessions;
989 for (size_t i = 0; i < 5; ++i) {
990 sessions.push_back(perfetto::Tracing::NewTrace(/*BackendType=*/GetParam()));
991 sessions[i]->Setup(cfg);
992 sessions[i]->Start();
993 sessions[i]->Stop();
994 }
995 }
996
TEST_P(PerfettoApiTest,TrackEventStartStopAndStopBlocking)997 TEST_P(PerfettoApiTest, TrackEventStartStopAndStopBlocking) {
998 // This test used to cause a deadlock (due to StopBlocking() after the session
999 // already stopped). This usually occurred within 1 or 2 runs of the test so
1000 // use --gtest_repeat=10
1001
1002 // Setup the trace config.
1003 perfetto::TraceConfig cfg;
1004 cfg.set_duration_ms(500);
1005 cfg.add_buffers()->set_size_kb(1024);
1006 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
1007 ds_cfg->set_name("track_event");
1008
1009 // Create five new trace sessions.
1010 std::vector<std::unique_ptr<perfetto::TracingSession>> sessions;
1011 for (size_t i = 0; i < 5; ++i) {
1012 sessions.push_back(perfetto::Tracing::NewTrace(/*BackendType=*/GetParam()));
1013 sessions[i]->Setup(cfg);
1014 sessions[i]->Start();
1015 sessions[i]->Stop();
1016 }
1017 for (auto& session : sessions) {
1018 session->StopBlocking();
1019 }
1020 }
1021
TEST_P(PerfettoApiTest,ChangeTraceConfiguration)1022 TEST_P(PerfettoApiTest, ChangeTraceConfiguration) {
1023 // Setup the trace config.
1024 perfetto::TraceConfig trace_config;
1025 trace_config.set_duration_ms(2000);
1026 trace_config.add_buffers()->set_size_kb(1024);
1027 auto* data_source = trace_config.add_data_sources();
1028
1029 // Configure track events with category "foo".
1030 auto* ds_cfg = data_source->mutable_config();
1031 ds_cfg->set_name("track_event");
1032 perfetto::protos::gen::TrackEventConfig te_cfg;
1033 te_cfg.add_disabled_categories("*");
1034 te_cfg.add_enabled_categories("foo");
1035 ds_cfg->set_track_event_config_raw(te_cfg.SerializeAsString());
1036
1037 // Initially, exclude all producers (the client library's producer is named
1038 // after current process's name, which will not match
1039 // "all_producers_excluded").
1040 data_source->add_producer_name_filter("all_producers_excluded");
1041
1042 auto* tracing_session = NewTrace(trace_config);
1043
1044 tracing_session->get()->StartBlocking();
1045
1046 // Emit a first trace event, this one should be filtered out due
1047 // to the mismatching producer name filter.
1048 TRACE_EVENT_BEGIN("foo", "EventFilteredOut");
1049 TRACE_EVENT_END("foo");
1050
1051 // Remove the producer name filter by changing configs.
1052 data_source->clear_producer_name_filter();
1053 tracing_session->get()->ChangeTraceConfig(trace_config);
1054
1055 // We don't have a blocking version of ChangeTraceConfig, because there is
1056 // currently no response to it from producers or the service. Instead, we sync
1057 // the consumer and producer IPC streams for this test, to ensure that the
1058 // producer_name_filter change has propagated.
1059 tracing_session->get()->GetTraceStatsBlocking(); // sync consumer stream.
1060 perfetto::test::SyncProducers(); // sync producer stream.
1061
1062 // Emit a second trace event, this one should be included because
1063 // the producer name filter was cleared.
1064 TRACE_EVENT_BEGIN("foo", "EventIncluded");
1065 TRACE_EVENT_END("foo");
1066
1067 // Verify that only the second event is in the trace data.
1068 std::vector<char> raw_trace = StopSessionAndReturnBytes(tracing_session);
1069 std::string trace(raw_trace.data(), raw_trace.size());
1070 EXPECT_THAT(trace, Not(HasSubstr("EventFilteredOut")));
1071 EXPECT_THAT(trace, HasSubstr("EventIncluded"));
1072 }
1073
1074 // This is a build-only regression test that checks you can have a track event
1075 // inside a template.
1076 template <typename T>
TestTrackEventInsideTemplate(T)1077 void TestTrackEventInsideTemplate(T) {
1078 TRACE_EVENT_BEGIN("cat", "Name");
1079 }
1080
1081 // This is a build-only regression test that checks you can specify the tracing
1082 // category as a template argument.
1083 constexpr const char kTestCategory[] = "foo";
1084 template <const char* category>
TestCategoryAsTemplateParameter()1085 void TestCategoryAsTemplateParameter() {
1086 TRACE_EVENT_BEGIN(category, "Name");
1087 }
1088
1089 // Sleep for |nano_seconds| in a way that this duration is counted in
1090 // thread_time. i.e. sleep without using OS's sleep method, which blocks the
1091 // thread and OS doesn't schedule it until expected wake-up-time.
SpinForThreadTimeNanos(int64_t nano_seconds)1092 void SpinForThreadTimeNanos(int64_t nano_seconds) {
1093 auto time_now = perfetto::base::GetThreadCPUTimeNs().count();
1094 auto goal_time = time_now + nano_seconds;
1095 while (perfetto::base::GetThreadCPUTimeNs().count() < goal_time) {
1096 }
1097 }
1098
TEST_P(PerfettoApiTest,TrackEventTimestampUnitAbsolute)1099 TEST_P(PerfettoApiTest, TrackEventTimestampUnitAbsolute) {
1100 for (auto unit_multiplier : {1u, 1000u}) {
1101 perfetto::protos::gen::TrackEventConfig te_cfg;
1102 te_cfg.set_disable_incremental_timestamps(true);
1103 te_cfg.set_timestamp_unit_multiplier(unit_multiplier);
1104 auto* tracing_session = NewTraceWithCategories({"foo"}, te_cfg);
1105 tracing_session->get()->StartBlocking();
1106 int64_t t_before = static_cast<int64_t>(TrackEventInternal::GetTimeNs());
1107 TRACE_EVENT_BEGIN("foo", "Event1");
1108 SpinForThreadTimeNanos(1000000);
1109 TRACE_EVENT_BEGIN("foo", "Event2");
1110 SpinForThreadTimeNanos(1000000);
1111 TRACE_EVENT_BEGIN("foo", "Event3");
1112 int64_t t_after = static_cast<int64_t>(TrackEventInternal::GetTimeNs());
1113 auto trace = StopSessionAndReturnParsedTrace(tracing_session);
1114 std::unordered_map<std::string, int64_t> event_map;
1115 bool found_absolute_clock = false;
1116 for (const auto& packet : trace.packet()) {
1117 if (packet.has_interned_data()) {
1118 if (packet.interned_data().event_names().size() == 1) {
1119 auto& event_name = packet.interned_data().event_names()[0].name();
1120 event_map[event_name] = static_cast<int64_t>(packet.timestamp());
1121 }
1122 }
1123 if (packet.has_trace_packet_defaults()) {
1124 auto clock_id = packet.trace_packet_defaults().timestamp_clock_id();
1125 EXPECT_EQ(unit_multiplier == 1
1126 ? static_cast<uint32_t>(TrackEventInternal::GetClockId())
1127 : TrackEventIncrementalState::kClockIdAbsolute,
1128 clock_id);
1129 if (packet.has_clock_snapshot()) {
1130 for (auto& clock : packet.clock_snapshot().clocks()) {
1131 if (clock.clock_id() ==
1132 TrackEventIncrementalState::kClockIdAbsolute) {
1133 found_absolute_clock = true;
1134 EXPECT_EQ(unit_multiplier, clock.unit_multiplier_ns());
1135 EXPECT_FALSE(clock.is_incremental());
1136 }
1137 }
1138 }
1139 }
1140 }
1141
1142 EXPECT_EQ((unit_multiplier == 1000), found_absolute_clock);
1143
1144 auto e1_t = event_map.at("Event1");
1145 auto e2_t = event_map.at("Event2");
1146 auto e3_t = event_map.at("Event3");
1147
1148 int64_t min_delta = 1000000 / unit_multiplier;
1149 int64_t max_delta = (t_after - t_before) / unit_multiplier;
1150
1151 EXPECT_LE(t_before / unit_multiplier, e1_t);
1152 EXPECT_LE(e3_t, t_after / unit_multiplier);
1153
1154 EXPECT_GE(e2_t - e1_t, min_delta);
1155 EXPECT_GE(e3_t - e2_t, min_delta);
1156
1157 EXPECT_LE(e2_t - e1_t, max_delta);
1158 EXPECT_LE(e3_t - e2_t, max_delta);
1159 }
1160 }
1161
TEST_P(PerfettoApiTest,TrackEventTimestampUnitIncremental)1162 TEST_P(PerfettoApiTest, TrackEventTimestampUnitIncremental) {
1163 for (auto unit_multiplier : {1u, 1000u}) {
1164 perfetto::protos::gen::TrackEventConfig te_cfg;
1165 te_cfg.set_enable_thread_time_sampling(true);
1166 te_cfg.set_timestamp_unit_multiplier(unit_multiplier);
1167 auto* tracing_session = NewTraceWithCategories({"foo"}, te_cfg);
1168 tracing_session->get()->StartBlocking();
1169 SpinForThreadTimeNanos(1000000);
1170 TRACE_EVENT_BEGIN("foo", "Event1");
1171 SpinForThreadTimeNanos(1000000);
1172 TRACE_EVENT_BEGIN("foo", "Event2");
1173 SpinForThreadTimeNanos(1000000);
1174 TRACE_EVENT_BEGIN("foo", "Event3");
1175 auto trace = StopSessionAndReturnParsedTrace(tracing_session);
1176 struct TimeInfo {
1177 int64_t timestamp;
1178 int64_t thread_time;
1179 };
1180 std::unordered_map<std::string, TimeInfo> event_map;
1181 for (const auto& packet : trace.packet()) {
1182 if (packet.has_interned_data()) {
1183 if (packet.interned_data().event_names().size() == 1) {
1184 auto& event_name = packet.interned_data().event_names()[0].name();
1185 if (packet.has_track_event() &&
1186 packet.track_event().extra_counter_values().size() > 0) {
1187 auto thread_time = packet.track_event().extra_counter_values()[0];
1188 event_map[event_name] = {static_cast<int64_t>(packet.timestamp()),
1189 thread_time};
1190 }
1191 }
1192 }
1193 }
1194 int min_delta = 1000 * (unit_multiplier == 1 ? 1000 : 1);
1195
1196 EXPECT_EQ(0, event_map.at("Event1").timestamp);
1197 EXPECT_GT(event_map.at("Event2").timestamp, min_delta);
1198 EXPECT_GT(event_map.at("Event3").timestamp, min_delta);
1199
1200 EXPECT_GT(event_map.at("Event2").thread_time, min_delta);
1201 EXPECT_GT(event_map.at("Event3").thread_time, min_delta);
1202 }
1203 }
1204
1205 // Tests that we don't accumulate error when using incremental timestamps with
1206 // timestamp unit multiplier.
TEST_P(PerfettoApiTest,TrackEventTimestampIncrementalAccumulatedError)1207 TEST_P(PerfettoApiTest, TrackEventTimestampIncrementalAccumulatedError) {
1208 constexpr uint64_t kUnitMultiplier = 100000;
1209 constexpr uint64_t kNumberOfEvents = 1000;
1210 constexpr uint64_t kTimeBetweenEventsNs = 50000;
1211
1212 perfetto::protos::gen::TrackEventConfig te_cfg;
1213 te_cfg.set_timestamp_unit_multiplier(kUnitMultiplier);
1214 auto* tracing_session = NewTraceWithCategories({"foo"}, te_cfg);
1215 tracing_session->get()->StartBlocking();
1216 auto start = perfetto::TrackEvent::GetTraceTimeNs();
1217 TRACE_EVENT_BEGIN("foo", "Start");
1218 for (uint64_t i = 0; i < kNumberOfEvents; ++i) {
1219 SpinForThreadTimeNanos(kTimeBetweenEventsNs);
1220 TRACE_EVENT_BEGIN("foo", "Event");
1221 }
1222 auto end = perfetto::TrackEvent::GetTraceTimeNs();
1223 auto trace = StopSessionAndReturnParsedTrace(tracing_session);
1224 uint64_t accumulated_timestamp = 0;
1225 for (const auto& packet : trace.packet()) {
1226 if (packet.has_track_event()) {
1227 accumulated_timestamp += packet.timestamp() * kUnitMultiplier;
1228 }
1229 }
1230
1231 EXPECT_GE(accumulated_timestamp, kNumberOfEvents * kTimeBetweenEventsNs);
1232 EXPECT_LE(accumulated_timestamp, end - start);
1233 }
1234
TEST_P(PerfettoApiTest,TrackEvent)1235 TEST_P(PerfettoApiTest, TrackEvent) {
1236 // Create a new trace session.
1237 auto* tracing_session = NewTraceWithCategories({"test"});
1238 tracing_session->get()->StartBlocking();
1239
1240 // Emit one complete track event.
1241 TRACE_EVENT_BEGIN("test", "TestEvent");
1242 TRACE_EVENT_END("test");
1243 perfetto::TrackEvent::Flush();
1244
1245 tracing_session->on_stop.Wait();
1246 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
1247 ASSERT_GE(raw_trace.size(), 0u);
1248
1249 // Read back the trace, maintaining interning tables as we go.
1250 perfetto::protos::gen::Trace trace;
1251 std::map<uint64_t, std::string> categories;
1252 std::map<uint64_t, std::string> event_names;
1253 ASSERT_TRUE(trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
1254
1255 auto now = perfetto::TrackEvent::GetTraceTimeNs();
1256 #if !PERFETTO_BUILDFLAG(PERFETTO_OS_APPLE) && \
1257 !PERFETTO_BUILDFLAG(PERFETTO_OS_WIN)
1258 auto clock_id = perfetto::protos::pbzero::BUILTIN_CLOCK_BOOTTIME;
1259 #else
1260 auto clock_id = perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC;
1261 #endif
1262 EXPECT_EQ(clock_id, perfetto::TrackEvent::GetTraceClockId());
1263
1264 bool incremental_state_was_cleared = false;
1265 bool begin_found = false;
1266 bool end_found = false;
1267 bool process_descriptor_found = false;
1268 uint32_t sequence_id = 0;
1269 int32_t cur_pid = perfetto::test::GetCurrentProcessId();
1270 uint64_t recent_absolute_time_ns = 0;
1271 bool found_incremental_clock = false;
1272 constexpr auto kClockIdIncremental =
1273 TrackEventIncrementalState::kClockIdIncremental;
1274
1275 for (const auto& packet : trace.packet()) {
1276 if (packet.has_track_descriptor()) {
1277 const auto& desc = packet.track_descriptor();
1278 if (desc.has_process()) {
1279 EXPECT_FALSE(process_descriptor_found);
1280 const auto& pd = desc.process();
1281 EXPECT_EQ(cur_pid, pd.pid());
1282 process_descriptor_found = true;
1283 }
1284 }
1285 if (packet.sequence_flags() &
1286 perfetto::protos::pbzero::TracePacket::SEQ_INCREMENTAL_STATE_CLEARED) {
1287 EXPECT_TRUE(packet.has_trace_packet_defaults());
1288 incremental_state_was_cleared = true;
1289 categories.clear();
1290 event_names.clear();
1291 EXPECT_EQ(kClockIdIncremental,
1292 packet.trace_packet_defaults().timestamp_clock_id());
1293 }
1294 if (packet.has_clock_snapshot()) {
1295 for (auto& clock : packet.clock_snapshot().clocks()) {
1296 if (clock.is_incremental()) {
1297 found_incremental_clock = true;
1298 recent_absolute_time_ns = clock.timestamp();
1299 EXPECT_EQ(kClockIdIncremental, clock.clock_id());
1300 }
1301 }
1302 }
1303
1304 if (!packet.has_track_event())
1305 continue;
1306 EXPECT_TRUE(
1307 packet.sequence_flags() &
1308 (perfetto::protos::pbzero::TracePacket::SEQ_INCREMENTAL_STATE_CLEARED |
1309 perfetto::protos::pbzero::TracePacket::SEQ_NEEDS_INCREMENTAL_STATE));
1310 const auto& track_event = packet.track_event();
1311
1312 // Make sure we only see track events on one sequence.
1313 if (packet.trusted_packet_sequence_id()) {
1314 if (!sequence_id)
1315 sequence_id = packet.trusted_packet_sequence_id();
1316 EXPECT_EQ(sequence_id, packet.trusted_packet_sequence_id());
1317 }
1318
1319 // Update incremental state.
1320 if (packet.has_interned_data()) {
1321 const auto& interned_data = packet.interned_data();
1322 for (const auto& it : interned_data.event_categories()) {
1323 EXPECT_EQ(categories.find(it.iid()), categories.end());
1324 categories[it.iid()] = it.name();
1325 }
1326 for (const auto& it : interned_data.event_names()) {
1327 EXPECT_EQ(event_names.find(it.iid()), event_names.end());
1328 event_names[it.iid()] = it.name();
1329 }
1330 }
1331 EXPECT_TRUE(found_incremental_clock);
1332 uint64_t absolute_timestamp = packet.timestamp() + recent_absolute_time_ns;
1333 recent_absolute_time_ns = absolute_timestamp;
1334 EXPECT_GT(absolute_timestamp, 0u);
1335 EXPECT_LE(absolute_timestamp, now);
1336 // Packet uses default (incremental) clock.
1337 EXPECT_FALSE(packet.has_timestamp_clock_id());
1338 if (track_event.type() ==
1339 perfetto::protos::gen::TrackEvent::TYPE_SLICE_BEGIN) {
1340 EXPECT_FALSE(begin_found);
1341 EXPECT_EQ(track_event.category_iids().size(), 1u);
1342 EXPECT_GE(track_event.category_iids()[0], 1u);
1343 EXPECT_EQ("test", categories[track_event.category_iids()[0]]);
1344 EXPECT_EQ("TestEvent", event_names[track_event.name_iid()]);
1345 begin_found = true;
1346 } else if (track_event.type() ==
1347 perfetto::protos::gen::TrackEvent::TYPE_SLICE_END) {
1348 EXPECT_FALSE(end_found);
1349 EXPECT_EQ(track_event.category_iids().size(), 0u);
1350 EXPECT_EQ(0u, track_event.name_iid());
1351 end_found = true;
1352 }
1353 }
1354 EXPECT_TRUE(incremental_state_was_cleared);
1355 EXPECT_TRUE(process_descriptor_found);
1356 EXPECT_TRUE(begin_found);
1357 EXPECT_TRUE(end_found);
1358
1359 // Dummy instantiation of test templates.
1360 TestTrackEventInsideTemplate(true);
1361 TestCategoryAsTemplateParameter<kTestCategory>();
1362 }
1363
TEST_P(PerfettoApiTest,TrackEventWithIncrementalTimestamp)1364 TEST_P(PerfettoApiTest, TrackEventWithIncrementalTimestamp) {
1365 for (auto disable_incremental_timestamps : {false, true}) {
1366 // Create a new trace session.
1367 perfetto::protos::gen::TrackEventConfig te_cfg;
1368 te_cfg.set_disable_incremental_timestamps(disable_incremental_timestamps);
1369 auto* tracing_session = NewTraceWithCategories({"bar"}, te_cfg);
1370 constexpr auto kClockIdIncremental =
1371 TrackEventIncrementalState::kClockIdIncremental;
1372 tracing_session->get()->StartBlocking();
1373
1374 std::map<uint64_t, std::string> event_names;
1375
1376 auto empty_lambda = [](perfetto::EventContext) {};
1377
1378 constexpr uint64_t kInstantEvent1Time = 92718891479583;
1379 TRACE_EVENT_INSTANT(
1380 "bar", "InstantEvent1",
1381 perfetto::TraceTimestamp{kClockIdIncremental, kInstantEvent1Time},
1382 empty_lambda);
1383
1384 constexpr uint64_t kInstantEvent2Time = 92718891618959;
1385 TRACE_EVENT_INSTANT(
1386 "bar", "InstantEvent2",
1387 perfetto::TraceTimestamp{kClockIdIncremental, kInstantEvent2Time},
1388 empty_lambda);
1389
1390 auto trace = StopSessionAndReturnParsedTrace(tracing_session);
1391 uint64_t absolute_timestamp = 0;
1392 uint64_t prv_timestamp = 0;
1393 int event_count = 0;
1394 // Go through the packets and add the timestamps of those packets that use
1395 // the incremental clock - in order to get the absolute timestamps of the
1396 // track events.
1397
1398 uint64_t default_clock_id = 0;
1399 bool is_incremental = false;
1400
1401 for (const auto& packet : trace.packet()) {
1402 if (!packet.has_track_event() && !packet.has_clock_snapshot())
1403 continue;
1404 if (packet.has_trace_packet_defaults()) {
1405 auto& defaults = packet.trace_packet_defaults();
1406 if (defaults.has_timestamp_clock_id()) {
1407 default_clock_id = defaults.timestamp_clock_id();
1408 }
1409 }
1410 if (packet.has_clock_snapshot()) {
1411 for (auto& clock : packet.clock_snapshot().clocks()) {
1412 if (clock.is_incremental()) {
1413 is_incremental = true;
1414 absolute_timestamp = clock.timestamp();
1415 EXPECT_EQ(clock.clock_id(), kClockIdIncremental);
1416 EXPECT_FALSE(disable_incremental_timestamps);
1417 }
1418 }
1419 } else {
1420 auto clock_id = packet.has_timestamp_clock_id()
1421 ? packet.timestamp_clock_id()
1422 : default_clock_id;
1423 if (clock_id == kClockIdIncremental) {
1424 absolute_timestamp = prv_timestamp + packet.timestamp();
1425 EXPECT_FALSE(disable_incremental_timestamps);
1426 } else {
1427 absolute_timestamp = packet.timestamp();
1428 EXPECT_TRUE(disable_incremental_timestamps);
1429 }
1430 }
1431 prv_timestamp = absolute_timestamp;
1432
1433 if (packet.sequence_flags() & perfetto::protos::pbzero::TracePacket::
1434 SEQ_INCREMENTAL_STATE_CLEARED) {
1435 event_names.clear();
1436 }
1437
1438 // Update incremental state.
1439 if (packet.has_interned_data()) {
1440 const auto& interned_data = packet.interned_data();
1441 for (const auto& it : interned_data.event_names()) {
1442 EXPECT_EQ(event_names.find(it.iid()), event_names.end());
1443 event_names[it.iid()] = it.name();
1444 }
1445 }
1446
1447 if (event_names[packet.track_event().name_iid()] == "InstantEvent1") {
1448 event_count++;
1449 EXPECT_EQ(absolute_timestamp, kInstantEvent1Time);
1450 } else if (event_names[packet.track_event().name_iid()] ==
1451 "InstantEvent2") {
1452 event_count++;
1453 EXPECT_EQ(absolute_timestamp, kInstantEvent2Time);
1454 }
1455 }
1456 EXPECT_NE(is_incremental, disable_incremental_timestamps);
1457 EXPECT_EQ(event_count, 2);
1458 }
1459 }
1460
TEST_P(PerfettoApiTest,TrackEventCategories)1461 TEST_P(PerfettoApiTest, TrackEventCategories) {
1462 // Create a new trace session.
1463 auto* tracing_session = NewTraceWithCategories({"bar"});
1464 tracing_session->get()->StartBlocking();
1465
1466 // Emit some track events.
1467 TRACE_EVENT_BEGIN("foo", "NotEnabled");
1468 TRACE_EVENT_END("foo");
1469 TRACE_EVENT_BEGIN("bar", "Enabled");
1470 TRACE_EVENT_END("bar");
1471
1472 std::vector<char> raw_trace = StopSessionAndReturnBytes(tracing_session);
1473 std::string trace(raw_trace.data(), raw_trace.size());
1474 // TODO(skyostil): Come up with a nicer way to verify trace contents.
1475 EXPECT_THAT(trace, HasSubstr("Enabled"));
1476 EXPECT_THAT(trace, Not(HasSubstr("NotEnabled")));
1477 }
1478
TEST_P(PerfettoApiTest,ClearIncrementalState)1479 TEST_P(PerfettoApiTest, ClearIncrementalState) {
1480 perfetto::DataSourceDescriptor dsd;
1481 dsd.set_name("incr_data_source");
1482 TestIncrementalDataSource::Register(dsd);
1483 perfetto::test::SyncProducers();
1484
1485 // Setup the trace config with an incremental state clearing period.
1486 perfetto::TraceConfig cfg;
1487 cfg.set_duration_ms(500);
1488 cfg.add_buffers()->set_size_kb(1024);
1489 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
1490 ds_cfg->set_name("incr_data_source");
1491 auto* is_cfg = cfg.mutable_incremental_state_config();
1492 is_cfg->set_clear_period_ms(10);
1493
1494 // Create a new trace session.
1495 auto* tracing_session = NewTrace(cfg);
1496 tracing_session->get()->StartBlocking();
1497
1498 // Observe at least 5 incremental state resets.
1499 constexpr size_t kMaxLoops = 100;
1500 size_t loops = 0;
1501 size_t times_cleared = 0;
1502 while (times_cleared < 5) {
1503 ASSERT_LT(loops++, kMaxLoops);
1504 TestIncrementalDataSource::Trace(
1505 [&](TestIncrementalDataSource::TraceContext ctx) {
1506 auto* incr_state = ctx.GetIncrementalState();
1507 if (!incr_state->flag) {
1508 incr_state->flag = true;
1509 times_cleared++;
1510 }
1511 });
1512 std::this_thread::sleep_for(std::chrono::milliseconds(10));
1513 }
1514 tracing_session->get()->StopBlocking();
1515 perfetto::test::TracingMuxerImplInternalsForTest::
1516 ClearDataSourceTlsStateOnReset<TestIncrementalDataSource>();
1517 }
1518
TEST_P(PerfettoApiTest,TrackEventRegistrationWithModule)1519 TEST_P(PerfettoApiTest, TrackEventRegistrationWithModule) {
1520 MockTracingMuxer muxer;
1521
1522 // Each track event namespace registers its own data source.
1523 perfetto::TrackEvent::Register();
1524 EXPECT_EQ(1u, muxer.data_sources.size());
1525
1526 tracing_module::InitializeCategories();
1527 EXPECT_EQ(3u, muxer.data_sources.size());
1528
1529 // Both data sources have the same name but distinct static data (i.e.,
1530 // individual instance states).
1531 EXPECT_EQ("track_event", muxer.data_sources[0].dsd.name());
1532 EXPECT_EQ("track_event", muxer.data_sources[1].dsd.name());
1533 EXPECT_EQ("track_event", muxer.data_sources[2].dsd.name());
1534 EXPECT_NE(muxer.data_sources[0].static_state,
1535 muxer.data_sources[1].static_state);
1536 EXPECT_NE(muxer.data_sources[0].static_state,
1537 muxer.data_sources[2].static_state);
1538 }
1539
TEST_P(PerfettoApiTest,TrackEventDescriptor)1540 TEST_P(PerfettoApiTest, TrackEventDescriptor) {
1541 MockTracingMuxer muxer;
1542
1543 perfetto::TrackEvent::Register();
1544 EXPECT_EQ(1u, muxer.data_sources.size());
1545 EXPECT_EQ("track_event", muxer.data_sources[0].dsd.name());
1546
1547 perfetto::protos::gen::TrackEventDescriptor desc;
1548 auto desc_raw = muxer.data_sources[0].dsd.track_event_descriptor_raw();
1549 EXPECT_TRUE(desc.ParseFromArray(desc_raw.data(), desc_raw.size()));
1550
1551 // Check that the advertised categories match PERFETTO_DEFINE_CATEGORIES (see
1552 // above).
1553 EXPECT_EQ(7, desc.available_categories_size());
1554 EXPECT_EQ("test", desc.available_categories()[0].name());
1555 EXPECT_EQ("This is a test category",
1556 desc.available_categories()[0].description());
1557 EXPECT_EQ("tag", desc.available_categories()[0].tags()[0]);
1558 EXPECT_EQ("foo", desc.available_categories()[1].name());
1559 EXPECT_EQ("bar", desc.available_categories()[2].name());
1560 EXPECT_EQ("cat", desc.available_categories()[3].name());
1561 EXPECT_EQ("slow", desc.available_categories()[3].tags()[0]);
1562 EXPECT_EQ("cat.verbose", desc.available_categories()[4].name());
1563 EXPECT_EQ("debug", desc.available_categories()[4].tags()[0]);
1564 EXPECT_EQ("cat-with-dashes", desc.available_categories()[5].name());
1565 EXPECT_EQ("disabled-by-default-cat", desc.available_categories()[6].name());
1566 EXPECT_EQ("slow", desc.available_categories()[6].tags()[0]);
1567 }
1568
TEST_P(PerfettoApiTest,TrackEventSharedIncrementalState)1569 TEST_P(PerfettoApiTest, TrackEventSharedIncrementalState) {
1570 tracing_module::InitializeCategories();
1571
1572 // Setup the trace config.
1573 perfetto::TraceConfig cfg;
1574 cfg.set_duration_ms(500);
1575 cfg.add_buffers()->set_size_kb(1024);
1576 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
1577 ds_cfg->set_name("track_event");
1578 auto* tracing_session = NewTrace(cfg);
1579 tracing_session->get()->StartBlocking();
1580
1581 perfetto::internal::TrackEventIncrementalState* main_state = nullptr;
1582 perfetto::TrackEvent::Trace(
1583 [&main_state](perfetto::TrackEvent::TraceContext ctx) {
1584 main_state = ctx.GetIncrementalState();
1585 });
1586 perfetto::internal::TrackEventIncrementalState* module_state =
1587 tracing_module::GetIncrementalState();
1588
1589 // Both track event data sources should use the same incremental state (thanks
1590 // to sharing TLS).
1591 EXPECT_NE(nullptr, main_state);
1592 EXPECT_EQ(main_state, module_state);
1593 tracing_session->get()->StopBlocking();
1594 }
1595
TEST_P(PerfettoApiTest,TrackEventCategoriesWithModule)1596 TEST_P(PerfettoApiTest, TrackEventCategoriesWithModule) {
1597 // Check that categories defined in two different category registries are
1598 // enabled and disabled correctly.
1599 tracing_module::InitializeCategories();
1600
1601 // Create a new trace session. Only the "foo" category is enabled. It also
1602 // exists both locally and in the existing module.
1603 auto* tracing_session = NewTraceWithCategories({"foo"});
1604 tracing_session->get()->StartBlocking();
1605
1606 // Emit some track events locally and from the test module.
1607 TRACE_EVENT_BEGIN("foo", "FooEventFromMain");
1608 TRACE_EVENT_END("foo");
1609 tracing_module::EmitTrackEvents();
1610 tracing_module::EmitTrackEvents2();
1611 TRACE_EVENT_BEGIN("bar", "DisabledEventFromMain");
1612 TRACE_EVENT_END("bar");
1613
1614 std::vector<char> raw_trace = StopSessionAndReturnBytes(tracing_session);
1615 std::string trace(raw_trace.data(), raw_trace.size());
1616 EXPECT_THAT(trace, HasSubstr("FooEventFromMain"));
1617 EXPECT_THAT(trace, Not(HasSubstr("DisabledEventFromMain")));
1618 EXPECT_THAT(trace, HasSubstr("FooEventFromModule"));
1619 EXPECT_THAT(trace, Not(HasSubstr("DisabledEventFromModule")));
1620 EXPECT_THAT(trace, HasSubstr("FooEventFromModule2"));
1621 EXPECT_THAT(trace, Not(HasSubstr("DisabledEventFromModule2")));
1622
1623 perfetto::protos::gen::Trace parsed_trace;
1624 ASSERT_TRUE(parsed_trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
1625
1626 uint32_t sequence_id = 0;
1627 for (const auto& packet : parsed_trace.packet()) {
1628 if (!packet.has_track_event())
1629 continue;
1630
1631 // Make sure we only see track events on one sequence. This means all track
1632 // event modules are sharing the same trace writer (by using the same TLS
1633 // index).
1634 if (packet.trusted_packet_sequence_id()) {
1635 if (!sequence_id)
1636 sequence_id = packet.trusted_packet_sequence_id();
1637 EXPECT_EQ(sequence_id, packet.trusted_packet_sequence_id());
1638 }
1639 }
1640 }
1641
TEST_P(PerfettoApiTest,TrackEventNamespaces)1642 TEST_P(PerfettoApiTest, TrackEventNamespaces) {
1643 perfetto::TrackEvent::Register();
1644 other_ns::TrackEvent::Register();
1645 tracing_module::InitializeCategories();
1646
1647 auto* tracing_session =
1648 NewTraceWithCategories({"test", "cat1", "extra", "other_ns"});
1649 tracing_session->get()->StartBlocking();
1650
1651 // Default namespace.
1652 TRACE_EVENT_INSTANT("test", "MainNamespaceEvent");
1653 EXPECT_TRUE(TRACE_EVENT_CATEGORY_ENABLED("test"));
1654
1655 // Other namespace in a block scope.
1656 {
1657 PERFETTO_USE_CATEGORIES_FROM_NAMESPACE_SCOPED(other_ns);
1658 TRACE_EVENT_INSTANT("other_ns", "OtherNamespaceEvent");
1659 EXPECT_TRUE(TRACE_EVENT_CATEGORY_ENABLED("other_ns"));
1660 }
1661
1662 // Back to the default namespace.
1663 TRACE_EVENT_INSTANT("test", "MainNamespaceEvent2");
1664
1665 // More namespaces defined in another module.
1666 tracing_module::EmitTrackEventsFromAllNamespaces();
1667
1668 auto slices = StopSessionAndReadSlicesFromTrace(tracing_session);
1669 EXPECT_THAT(
1670 slices,
1671 ElementsAre("I:test.MainNamespaceEvent", "I:other_ns.OtherNamespaceEvent",
1672 "I:test.MainNamespaceEvent2",
1673 "B:cat1.DefaultNamespaceFromModule",
1674 "B:extra.ExtraNamespaceFromModule",
1675 "B:extra.OverrideNamespaceFromModule",
1676 "B:extra.DefaultNamespace", "B:cat1.DefaultNamespace"));
1677 }
1678
TEST_P(PerfettoApiTest,TrackEventDynamicCategories)1679 TEST_P(PerfettoApiTest, TrackEventDynamicCategories) {
1680 // Setup the trace config.
1681 perfetto::TraceConfig cfg;
1682 cfg.set_duration_ms(500);
1683 cfg.add_buffers()->set_size_kb(1024);
1684 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
1685 ds_cfg->set_name("track_event");
1686
1687 // Session #1 enabled the "dynamic" category.
1688 auto* tracing_session = NewTraceWithCategories({"dynamic"});
1689 tracing_session->get()->StartBlocking();
1690
1691 EXPECT_TRUE(TRACE_EVENT_CATEGORY_ENABLED("dynamic"));
1692 EXPECT_FALSE(TRACE_EVENT_CATEGORY_ENABLED("dynamic_2"));
1693
1694 // Session #2 enables "dynamic_2".
1695 auto* tracing_session2 = NewTraceWithCategories({"dynamic_2"});
1696 tracing_session2->get()->StartBlocking();
1697
1698 // Test naming dynamic categories with std::string.
1699 perfetto::DynamicCategory dynamic{"dynamic"};
1700 TRACE_EVENT_BEGIN(dynamic, "EventInDynamicCategory");
1701 perfetto::DynamicCategory dynamic_disabled{"dynamic_disabled"};
1702 TRACE_EVENT_BEGIN(dynamic_disabled, "EventInDisabledDynamicCategory");
1703
1704 // Test naming dynamic categories statically.
1705 TRACE_EVENT_BEGIN("dynamic", "EventInStaticallyNamedDynamicCategory");
1706
1707 perfetto::DynamicCategory dynamic_2{"dynamic_2"};
1708 TRACE_EVENT_BEGIN(dynamic_2, "EventInSecondDynamicCategory");
1709 TRACE_EVENT_BEGIN("dynamic_2", "EventInSecondStaticallyNamedDynamicCategory");
1710
1711 EXPECT_TRUE(TRACE_EVENT_CATEGORY_ENABLED(dynamic));
1712 EXPECT_TRUE(TRACE_EVENT_CATEGORY_ENABLED(dynamic_2));
1713
1714 std::thread thread([] {
1715 // Make sure the category name can actually be computed at runtime.
1716 std::string name = "dyn";
1717 if (perfetto::base::GetThreadId())
1718 name += "amic";
1719 perfetto::DynamicCategory cat{name};
1720 TRACE_EVENT_BEGIN(cat, "DynamicFromOtherThread");
1721 perfetto::DynamicCategory cat2{"dynamic_disabled"};
1722 TRACE_EVENT_BEGIN(cat2, "EventInDisabledDynamicCategory");
1723 });
1724 thread.join();
1725
1726 std::vector<char> raw_trace = StopSessionAndReturnBytes(tracing_session);
1727 std::string trace(raw_trace.data(), raw_trace.size());
1728 EXPECT_THAT(trace, HasSubstr("EventInDynamicCategory"));
1729 EXPECT_THAT(trace, Not(HasSubstr("EventInDisabledDynamicCategory")));
1730 EXPECT_THAT(trace, HasSubstr("DynamicFromOtherThread"));
1731 EXPECT_THAT(trace, Not(HasSubstr("EventInSecondDynamicCategory")));
1732 EXPECT_THAT(trace, HasSubstr("EventInStaticallyNamedDynamicCategory"));
1733 EXPECT_THAT(trace,
1734 Not(HasSubstr("EventInSecondStaticallyNamedDynamicCategory")));
1735
1736 raw_trace = StopSessionAndReturnBytes(tracing_session2);
1737 trace = std::string(raw_trace.data(), raw_trace.size());
1738 EXPECT_THAT(trace, Not(HasSubstr("EventInDynamicCategory")));
1739 EXPECT_THAT(trace, Not(HasSubstr("EventInDisabledDynamicCategory")));
1740 EXPECT_THAT(trace, Not(HasSubstr("DynamicFromOtherThread")));
1741 EXPECT_THAT(trace, HasSubstr("EventInSecondDynamicCategory"));
1742 EXPECT_THAT(trace, Not(HasSubstr("EventInStaticallyNamedDynamicCategory")));
1743 EXPECT_THAT(trace, HasSubstr("EventInSecondStaticallyNamedDynamicCategory"));
1744 }
1745
TEST_P(PerfettoApiTest,TrackEventConcurrentSessions)1746 TEST_P(PerfettoApiTest, TrackEventConcurrentSessions) {
1747 // Check that categories that are enabled and disabled in two parallel tracing
1748 // sessions don't interfere.
1749
1750 // Session #1 enables the "foo" category.
1751 auto* tracing_session = NewTraceWithCategories({"foo"});
1752 tracing_session->get()->StartBlocking();
1753
1754 // Session #2 enables the "bar" category.
1755 auto* tracing_session2 = NewTraceWithCategories({"bar"});
1756 tracing_session2->get()->StartBlocking();
1757
1758 // Emit some track events under both categories.
1759 TRACE_EVENT_BEGIN("foo", "Session1_First");
1760 TRACE_EVENT_END("foo");
1761 TRACE_EVENT_BEGIN("bar", "Session2_First");
1762 TRACE_EVENT_END("bar");
1763
1764 tracing_session->get()->StopBlocking();
1765 TRACE_EVENT_BEGIN("foo", "Session1_Second");
1766 TRACE_EVENT_END("foo");
1767 TRACE_EVENT_BEGIN("bar", "Session2_Second");
1768 TRACE_EVENT_END("bar");
1769
1770 tracing_session2->get()->StopBlocking();
1771 TRACE_EVENT_BEGIN("foo", "Session1_Third");
1772 TRACE_EVENT_END("foo");
1773 TRACE_EVENT_BEGIN("bar", "Session2_Third");
1774 TRACE_EVENT_END("bar");
1775
1776 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
1777 std::string trace(raw_trace.data(), raw_trace.size());
1778 EXPECT_THAT(trace, HasSubstr("Session1_First"));
1779 EXPECT_THAT(trace, Not(HasSubstr("Session1_Second")));
1780 EXPECT_THAT(trace, Not(HasSubstr("Session1_Third")));
1781 EXPECT_THAT(trace, Not(HasSubstr("Session2_First")));
1782 EXPECT_THAT(trace, Not(HasSubstr("Session2_Second")));
1783 EXPECT_THAT(trace, Not(HasSubstr("Session2_Third")));
1784
1785 std::vector<char> raw_trace2 = tracing_session2->get()->ReadTraceBlocking();
1786 std::string trace2(raw_trace2.data(), raw_trace2.size());
1787 EXPECT_THAT(trace2, Not(HasSubstr("Session1_First")));
1788 EXPECT_THAT(trace2, Not(HasSubstr("Session1_Second")));
1789 EXPECT_THAT(trace2, Not(HasSubstr("Session1_Third")));
1790 EXPECT_THAT(trace2, HasSubstr("Session2_First"));
1791 EXPECT_THAT(trace2, HasSubstr("Session2_Second"));
1792 EXPECT_THAT(trace2, Not(HasSubstr("Session2_Third")));
1793 }
1794
TEST_P(PerfettoApiTest,TrackEventProcessAndThreadDescriptors)1795 TEST_P(PerfettoApiTest, TrackEventProcessAndThreadDescriptors) {
1796 // Thread and process descriptors can be set before tracing is enabled.
1797 perfetto::TrackEvent::SetProcessDescriptor(
1798 [](perfetto::protos::pbzero::TrackDescriptor* desc) {
1799 desc->set_name("hello.exe");
1800 desc->set_chrome_process()->set_process_priority(1);
1801 });
1802
1803 // Erased tracks shouldn't show up anywhere.
1804 perfetto::Track erased(1234u);
1805 perfetto::TrackEvent::SetTrackDescriptor(
1806 erased, [](perfetto::protos::pbzero::TrackDescriptor* desc) {
1807 desc->set_name("ErasedTrack");
1808 });
1809 perfetto::TrackEvent::EraseTrackDescriptor(erased);
1810
1811 // Setup the trace config.
1812 perfetto::TraceConfig cfg;
1813 cfg.set_duration_ms(500);
1814 cfg.add_buffers()->set_size_kb(1024);
1815 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
1816 ds_cfg->set_name("track_event");
1817
1818 // Create a new trace session.
1819 auto* tracing_session = NewTrace(cfg);
1820 tracing_session->get()->StartBlocking();
1821 TRACE_EVENT_INSTANT("test", "MainThreadEvent");
1822
1823 std::thread thread([&] {
1824 perfetto::TrackEvent::SetThreadDescriptor(
1825 [](perfetto::protos::pbzero::TrackDescriptor* desc) {
1826 desc->set_name("TestThread");
1827 });
1828 TRACE_EVENT_INSTANT("test", "ThreadEvent");
1829 });
1830 thread.join();
1831
1832 // Update the process descriptor while tracing is enabled. It should be
1833 // immediately reflected in the trace.
1834 perfetto::TrackEvent::SetProcessDescriptor(
1835 [](perfetto::protos::pbzero::TrackDescriptor* desc) {
1836 desc->set_name("goodbye.exe");
1837 });
1838 perfetto::TrackEvent::Flush();
1839
1840 tracing_session->get()->StopBlocking();
1841
1842 // After tracing ends, setting the descriptor has no immediate effect.
1843 perfetto::TrackEvent::SetProcessDescriptor(
1844 [](perfetto::protos::pbzero::TrackDescriptor* desc) {
1845 desc->set_name("noop.exe");
1846 });
1847
1848 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
1849 perfetto::protos::gen::Trace trace;
1850 ASSERT_TRUE(trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
1851
1852 std::vector<perfetto::protos::gen::TrackDescriptor> descs;
1853 std::vector<perfetto::protos::gen::TrackDescriptor> thread_descs;
1854 uint32_t main_thread_sequence = GetMainThreadPacketSequenceId(trace);
1855 for (const auto& packet : trace.packet()) {
1856 if (packet.has_track_descriptor()) {
1857 if (packet.trusted_packet_sequence_id() == main_thread_sequence) {
1858 descs.push_back(packet.track_descriptor());
1859 } else if (packet.track_descriptor().has_thread()) {
1860 thread_descs.push_back(packet.track_descriptor());
1861 }
1862 }
1863 }
1864
1865 // The main thread records the initial process name as well as the one that's
1866 // set during tracing. Additionally it records a thread descriptor for the
1867 // main thread.
1868
1869 EXPECT_EQ(3u, descs.size());
1870
1871 // Default track for the main thread.
1872 EXPECT_EQ(0, descs[0].process().pid());
1873 EXPECT_NE(0, descs[0].thread().pid());
1874
1875 // First process descriptor.
1876 EXPECT_NE(0, descs[1].process().pid());
1877 EXPECT_EQ("hello.exe", descs[1].name());
1878
1879 // Second process descriptor.
1880 EXPECT_NE(0, descs[2].process().pid());
1881 EXPECT_EQ("goodbye.exe", descs[2].name());
1882
1883 // The child thread records only its own thread descriptor (twice, since it
1884 // was mutated).
1885 ASSERT_EQ(2u, thread_descs.size());
1886 EXPECT_EQ("TestThread", thread_descs[0].name());
1887 EXPECT_NE(0, thread_descs[0].thread().pid());
1888 EXPECT_NE(0, thread_descs[0].thread().tid());
1889 EXPECT_EQ("TestThread", thread_descs[1].name());
1890 EXPECT_NE(0, thread_descs[1].thread().pid());
1891 EXPECT_NE(0, thread_descs[1].thread().tid());
1892 EXPECT_NE(0, descs[2].process().pid());
1893 EXPECT_EQ("goodbye.exe", descs[2].name());
1894 }
1895
TEST_P(PerfettoApiTest,CustomTrackDescriptor)1896 TEST_P(PerfettoApiTest, CustomTrackDescriptor) {
1897 // Setup the trace config.
1898 perfetto::TraceConfig cfg;
1899 cfg.set_duration_ms(500);
1900 cfg.add_buffers()->set_size_kb(1024);
1901 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
1902 ds_cfg->set_name("track_event");
1903
1904 // Create a new trace session.
1905 auto* tracing_session = NewTrace(cfg);
1906 tracing_session->get()->StartBlocking();
1907
1908 auto track = perfetto::ProcessTrack::Current();
1909 auto desc = track.Serialize();
1910 desc.mutable_process()->set_process_name("testing.exe");
1911 desc.mutable_thread()->set_tid(
1912 static_cast<int32_t>(perfetto::base::GetThreadId()));
1913 desc.mutable_chrome_process()->set_process_priority(123);
1914 perfetto::TrackEvent::SetTrackDescriptor(track, std::move(desc));
1915
1916 auto trace = StopSessionAndReturnParsedTrace(tracing_session);
1917
1918 uint32_t main_thread_sequence = GetMainThreadPacketSequenceId(trace);
1919 bool found_desc = false;
1920 for (const auto& packet : trace.packet()) {
1921 if (packet.trusted_packet_sequence_id() != main_thread_sequence)
1922 continue;
1923 if (packet.has_track_descriptor()) {
1924 auto td = packet.track_descriptor();
1925 if (!td.has_process())
1926 continue;
1927 EXPECT_NE(0, td.process().pid());
1928 EXPECT_TRUE(td.has_chrome_process());
1929 EXPECT_EQ("testing.exe", td.process().process_name());
1930 EXPECT_EQ(123, td.chrome_process().process_priority());
1931 found_desc = true;
1932 }
1933 }
1934 EXPECT_TRUE(found_desc);
1935 }
1936
TEST_P(PerfettoApiTest,TrackEventCustomTrack)1937 TEST_P(PerfettoApiTest, TrackEventCustomTrack) {
1938 // Create a new trace session.
1939 auto* tracing_session = NewTraceWithCategories({"bar"});
1940 tracing_session->get()->StartBlocking();
1941
1942 // Declare a custom track and give it a name.
1943 uint64_t async_id = 123;
1944 perfetto::TrackEvent::SetTrackDescriptor(
1945 perfetto::Track(async_id),
1946 [](perfetto::protos::pbzero::TrackDescriptor* desc) {
1947 desc->set_name("MyCustomTrack");
1948 });
1949
1950 // Start events on one thread and end them on another.
1951 TRACE_EVENT_BEGIN("bar", "AsyncEvent", perfetto::Track(async_id), "debug_arg",
1952 123);
1953
1954 TRACE_EVENT_BEGIN("bar", "SubEvent", perfetto::Track(async_id),
1955 [](perfetto::EventContext) {});
1956 const auto main_thread_track =
1957 perfetto::Track(async_id, perfetto::ThreadTrack::Current());
1958 std::thread thread([&] {
1959 TRACE_EVENT_END("bar", perfetto::Track(async_id));
1960 TRACE_EVENT_END("bar", perfetto::Track(async_id), "arg1", false, "arg2",
1961 true);
1962 const auto thread_track =
1963 perfetto::Track(async_id, perfetto::ThreadTrack::Current());
1964 // Thread-scoped tracks will have different uuids on different thread even
1965 // if the id matches.
1966 ASSERT_NE(main_thread_track.uuid, thread_track.uuid);
1967 });
1968 thread.join();
1969
1970 auto trace = StopSessionAndReturnParsedTrace(tracing_session);
1971
1972 // Check that the track uuids match on the begin and end events.
1973 const auto track = perfetto::Track(async_id);
1974 uint32_t main_thread_sequence = GetMainThreadPacketSequenceId(trace);
1975 int event_count = 0;
1976 bool found_descriptor = false;
1977 for (const auto& packet : trace.packet()) {
1978 if (packet.has_track_descriptor() &&
1979 !packet.track_descriptor().has_process() &&
1980 !packet.track_descriptor().has_thread()) {
1981 auto td = packet.track_descriptor();
1982 EXPECT_EQ("MyCustomTrack", td.name());
1983 EXPECT_EQ(track.uuid, td.uuid());
1984 EXPECT_EQ(perfetto::ProcessTrack::Current().uuid, td.parent_uuid());
1985 found_descriptor = true;
1986 continue;
1987 }
1988
1989 if (!packet.has_track_event())
1990 continue;
1991 auto track_event = packet.track_event();
1992 if (track_event.type() ==
1993 perfetto::protos::gen::TrackEvent::TYPE_SLICE_BEGIN) {
1994 EXPECT_EQ(main_thread_sequence, packet.trusted_packet_sequence_id());
1995 EXPECT_EQ(track.uuid, track_event.track_uuid());
1996 } else {
1997 EXPECT_NE(main_thread_sequence, packet.trusted_packet_sequence_id());
1998 EXPECT_EQ(track.uuid, track_event.track_uuid());
1999 }
2000 event_count++;
2001 }
2002 EXPECT_TRUE(found_descriptor);
2003 EXPECT_EQ(4, event_count);
2004 perfetto::TrackEvent::EraseTrackDescriptor(track);
2005 }
2006
TEST_P(PerfettoApiTest,TrackEventCustomTimestampClock)2007 TEST_P(PerfettoApiTest, TrackEventCustomTimestampClock) {
2008 // Create a new trace session.
2009 auto* tracing_session = NewTraceWithCategories({"foo"});
2010 tracing_session->get()->StartBlocking();
2011
2012 static constexpr perfetto::protos::pbzero::BuiltinClock kMyClockId =
2013 static_cast<perfetto::protos::pbzero::BuiltinClock>(700);
2014 static constexpr uint64_t kTimestamp = 12345678;
2015
2016 // First emit a clock snapshot that maps our custom clock to regular trace
2017 // time. Note that the clock snapshot should come before any events
2018 // referencing that clock.
2019 perfetto::TrackEvent::Trace([](perfetto::TrackEvent::TraceContext ctx) {
2020 auto packet = ctx.NewTracePacket();
2021 packet->set_timestamp_clock_id(
2022 static_cast<uint32_t>(perfetto::TrackEvent::GetTraceClockId()));
2023 packet->set_timestamp(perfetto::TrackEvent::GetTraceTimeNs());
2024 auto* clock_snapshot = packet->set_clock_snapshot();
2025 // First set the reference clock, i.e., the default trace clock in this
2026 // case.
2027 auto* clock = clock_snapshot->add_clocks();
2028 clock->set_clock_id(
2029 static_cast<uint32_t>(perfetto::TrackEvent::GetTraceClockId()));
2030 clock->set_timestamp(perfetto::TrackEvent::GetTraceTimeNs());
2031 // Then set the value of our reference clock at the same point in time. We
2032 // pretend our clock is one second behind trace time.
2033 clock = clock_snapshot->add_clocks();
2034 clock->set_clock_id(kMyClockId);
2035 clock->set_timestamp(kTimestamp + 1000000000ull);
2036 });
2037
2038 // Next emit a trace event with a custom timestamp and a custom clock.
2039 TRACE_EVENT_INSTANT("foo", "EventWithCustomTime",
2040 perfetto::TraceTimestamp{kMyClockId, kTimestamp});
2041 TRACE_EVENT_INSTANT("foo", "EventWithNormalTime");
2042
2043 auto trace = StopSessionAndReturnParsedTrace(tracing_session);
2044
2045 // Check that both the clock id and the timestamp got written together with
2046 // the packet. Note that we don't check the actual clock sync behavior here
2047 // since that happens in the Trace Processor instead.
2048 bool found_clock_snapshot = false;
2049 bool found_event = false;
2050 for (const auto& packet : trace.packet()) {
2051 if (packet.has_clock_snapshot())
2052 found_clock_snapshot = true;
2053 if (!packet.has_track_event() || packet.timestamp() != kTimestamp)
2054 continue;
2055 found_event = true;
2056 EXPECT_EQ(static_cast<uint32_t>(kMyClockId), packet.timestamp_clock_id());
2057 EXPECT_EQ(kTimestamp, packet.timestamp());
2058 }
2059 EXPECT_TRUE(found_clock_snapshot);
2060 EXPECT_TRUE(found_event);
2061 }
2062
2063 // Only synchronous phases are supported for other threads. Hence disabled this
2064 // test.
2065 // TODO(b/261493947): fix or remove.
TEST_P(PerfettoApiTest,DISABLED_LegacyEventWithThreadOverride)2066 TEST_P(PerfettoApiTest, DISABLED_LegacyEventWithThreadOverride) {
2067 // Create a new trace session.
2068 auto* tracing_session = NewTraceWithCategories({"cat"});
2069 tracing_session->get()->StartBlocking();
2070
2071 TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0("cat", "Name", 1,
2072 MyThreadId(456), MyTimestamp{0});
2073 auto trace = StopSessionAndReturnParsedTrace(tracing_session);
2074
2075 // Check that we wrote a track descriptor for the custom thread track, and
2076 // that the event was associated with that track.
2077 const auto track = perfetto::ThreadTrack::ForThread(456);
2078 bool found_descriptor = false;
2079 bool found_event = false;
2080 for (const auto& packet : trace.packet()) {
2081 if (packet.has_track_descriptor() &&
2082 packet.track_descriptor().has_thread()) {
2083 auto td = packet.track_descriptor().thread();
2084 if (td.tid() == 456) {
2085 EXPECT_EQ(track.uuid, packet.track_descriptor().uuid());
2086 found_descriptor = true;
2087 }
2088 }
2089
2090 if (!packet.has_track_event())
2091 continue;
2092 auto track_event = packet.track_event();
2093 if (track_event.legacy_event().phase() == TRACE_EVENT_PHASE_ASYNC_BEGIN) {
2094 EXPECT_EQ(0u, track_event.track_uuid());
2095 found_event = true;
2096 }
2097 }
2098 EXPECT_TRUE(found_descriptor);
2099 EXPECT_TRUE(found_event);
2100 perfetto::TrackEvent::EraseTrackDescriptor(track);
2101 }
2102
2103 // Only synchronous phases are supported for other threads. Hence disabled this
2104 // test.
TEST_P(PerfettoApiTest,DISABLED_LegacyEventWithProcessOverride)2105 TEST_P(PerfettoApiTest, DISABLED_LegacyEventWithProcessOverride) {
2106 // Create a new trace session.
2107 auto* tracing_session = NewTraceWithCategories({"cat"});
2108 tracing_session->get()->StartBlocking();
2109
2110 // Note: there's no direct entrypoint for adding trace events for another
2111 // process, so we're using the internal support macro here.
2112 INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMP(
2113 TRACE_EVENT_PHASE_INSTANT, "cat", "Name", 0, MyThreadId{789},
2114 MyTimestamp{0}, TRACE_EVENT_FLAG_HAS_PROCESS_ID);
2115 auto trace = StopSessionAndReturnParsedTrace(tracing_session);
2116
2117 // Check that the event has a pid_override matching MyThread above.
2118 bool found_event = false;
2119 for (const auto& packet : trace.packet()) {
2120 if (!packet.has_track_event())
2121 continue;
2122 auto track_event = packet.track_event();
2123 if (track_event.type() == perfetto::protos::gen::TrackEvent::TYPE_INSTANT) {
2124 EXPECT_EQ(789, track_event.legacy_event().pid_override());
2125 EXPECT_EQ(-1, track_event.legacy_event().tid_override());
2126 found_event = true;
2127 }
2128 }
2129 EXPECT_TRUE(found_event);
2130 }
2131
TEST_P(PerfettoApiTest,TrackDescriptorWrittenBeforeEvent)2132 TEST_P(PerfettoApiTest, TrackDescriptorWrittenBeforeEvent) {
2133 // Create a new trace session.
2134 auto* tracing_session = NewTraceWithCategories({"bar"});
2135 tracing_session->get()->StartBlocking();
2136
2137 // Emit an event on a custom track.
2138 TRACE_EVENT_INSTANT("bar", "Event", perfetto::Track(8086));
2139 auto trace = StopSessionAndReturnParsedTrace(tracing_session);
2140
2141 // Check that the descriptor was written before the event.
2142 std::set<uint64_t> seen_descriptors;
2143 for (const auto& packet : trace.packet()) {
2144 if (packet.has_track_descriptor())
2145 seen_descriptors.insert(packet.track_descriptor().uuid());
2146
2147 if (!packet.has_track_event())
2148 continue;
2149 auto track_event = packet.track_event();
2150 EXPECT_TRUE(seen_descriptors.find(track_event.track_uuid()) !=
2151 seen_descriptors.end());
2152 }
2153 }
2154
TEST_P(PerfettoApiTest,TrackEventCustomTrackAndTimestamp)2155 TEST_P(PerfettoApiTest, TrackEventCustomTrackAndTimestamp) {
2156 // Create a new trace session.
2157 auto* tracing_session = NewTraceWithCategories({"bar"});
2158 tracing_session->get()->StartBlocking();
2159
2160 // Custom track.
2161 perfetto::Track track(789);
2162
2163 auto empty_lambda = [](perfetto::EventContext) {};
2164 constexpr uint64_t kBeginEventTime = 10;
2165 const MyTimestamp kEndEventTime{15};
2166 TRACE_EVENT_BEGIN("bar", "Event", track, kBeginEventTime, empty_lambda);
2167 TRACE_EVENT_END("bar", track, kEndEventTime, empty_lambda);
2168
2169 constexpr uint64_t kInstantEventTime = 1;
2170 TRACE_EVENT_INSTANT("bar", "InstantEvent", track, kInstantEventTime,
2171 empty_lambda);
2172
2173 auto trace = StopSessionAndReturnParsedTrace(tracing_session);
2174
2175 int event_count = 0;
2176 for (const auto& packet : trace.packet()) {
2177 if (!packet.has_track_event())
2178 continue;
2179
2180 EXPECT_EQ(packet.timestamp_clock_id(),
2181 static_cast<uint32_t>(perfetto::TrackEvent::GetTraceClockId()));
2182 event_count++;
2183 switch (packet.track_event().type()) {
2184 case perfetto::protos::gen::TrackEvent::TYPE_SLICE_BEGIN:
2185 EXPECT_EQ(packet.timestamp(), kBeginEventTime);
2186 break;
2187 case perfetto::protos::gen::TrackEvent::TYPE_SLICE_END:
2188 EXPECT_EQ(packet.timestamp(), kEndEventTime.ts);
2189 break;
2190 case perfetto::protos::gen::TrackEvent::TYPE_INSTANT:
2191 EXPECT_EQ(packet.timestamp(), kInstantEventTime);
2192 break;
2193 case perfetto::protos::gen::TrackEvent::TYPE_COUNTER:
2194 case perfetto::protos::gen::TrackEvent::TYPE_UNSPECIFIED:
2195 ADD_FAILURE();
2196 }
2197 }
2198 EXPECT_EQ(event_count, 3);
2199 perfetto::TrackEvent::EraseTrackDescriptor(track);
2200 }
2201
TEST_P(PerfettoApiTest,TrackEventCustomTrackAndTimestampNoLambda)2202 TEST_P(PerfettoApiTest, TrackEventCustomTrackAndTimestampNoLambda) {
2203 auto* tracing_session = NewTraceWithCategories({"bar"});
2204 tracing_session->get()->StartBlocking();
2205
2206 perfetto::Track track(789);
2207
2208 constexpr uint64_t kBeginEventTime = 10;
2209 constexpr uint64_t kEndEventTime = 15;
2210 TRACE_EVENT_BEGIN("bar", "Event", track, kBeginEventTime);
2211 TRACE_EVENT_END("bar", track, kEndEventTime);
2212
2213 auto trace = StopSessionAndReturnParsedTrace(tracing_session);
2214
2215 int event_count = 0;
2216 for (const auto& packet : trace.packet()) {
2217 if (!packet.has_track_event())
2218 continue;
2219 event_count++;
2220 switch (packet.track_event().type()) {
2221 case perfetto::protos::gen::TrackEvent::TYPE_SLICE_BEGIN:
2222 EXPECT_EQ(packet.timestamp(), kBeginEventTime);
2223 break;
2224 case perfetto::protos::gen::TrackEvent::TYPE_SLICE_END:
2225 EXPECT_EQ(packet.timestamp(), kEndEventTime);
2226 break;
2227 case perfetto::protos::gen::TrackEvent::TYPE_INSTANT:
2228 case perfetto::protos::gen::TrackEvent::TYPE_COUNTER:
2229 case perfetto::protos::gen::TrackEvent::TYPE_UNSPECIFIED:
2230 ADD_FAILURE();
2231 }
2232 }
2233
2234 EXPECT_EQ(event_count, 2);
2235 }
2236
TEST_P(PerfettoApiTest,TrackEventAnonymousCustomTrack)2237 TEST_P(PerfettoApiTest, TrackEventAnonymousCustomTrack) {
2238 // Create a new trace session.
2239 auto* tracing_session = NewTraceWithCategories({"bar"});
2240 tracing_session->get()->StartBlocking();
2241
2242 // Emit an async event without giving it an explicit descriptor.
2243 uint64_t async_id = 4004;
2244 auto track = perfetto::Track(async_id, perfetto::ThreadTrack::Current());
2245 TRACE_EVENT_BEGIN("bar", "AsyncEvent", track);
2246 std::thread thread([&] { TRACE_EVENT_END("bar", track); });
2247 thread.join();
2248
2249 auto trace = StopSessionAndReturnParsedTrace(tracing_session);
2250
2251 // Check that a descriptor for the track was emitted.
2252 bool found_descriptor = false;
2253 for (const auto& packet : trace.packet()) {
2254 if (packet.has_track_descriptor() &&
2255 !packet.track_descriptor().has_process() &&
2256 !packet.track_descriptor().has_thread()) {
2257 auto td = packet.track_descriptor();
2258 EXPECT_EQ(track.uuid, td.uuid());
2259 EXPECT_EQ(perfetto::ThreadTrack::Current().uuid, td.parent_uuid());
2260 found_descriptor = true;
2261 }
2262 }
2263 EXPECT_TRUE(found_descriptor);
2264 }
2265
TEST_P(PerfettoApiTest,TrackEventTypedArgs)2266 TEST_P(PerfettoApiTest, TrackEventTypedArgs) {
2267 // Create a new trace session.
2268 auto* tracing_session = NewTraceWithCategories({"foo"});
2269 tracing_session->get()->StartBlocking();
2270
2271 auto random_value = rand();
2272 TRACE_EVENT_BEGIN("foo", "EventWithTypedArg",
2273 [random_value](perfetto::EventContext ctx) {
2274 auto* log = ctx.event()->set_log_message();
2275 log->set_source_location_iid(1);
2276 log->set_body_iid(2);
2277 auto* dbg = ctx.event()->add_debug_annotations();
2278 dbg->set_name("random");
2279 dbg->set_int_value(random_value);
2280 });
2281 TRACE_EVENT_END("foo");
2282
2283 auto trace = StopSessionAndReturnParsedTrace(tracing_session);
2284
2285 bool found_args = false;
2286 for (const auto& packet : trace.packet()) {
2287 if (!packet.has_track_event())
2288 continue;
2289 const auto& track_event = packet.track_event();
2290 if (track_event.type() !=
2291 perfetto::protos::gen::TrackEvent::TYPE_SLICE_BEGIN)
2292 continue;
2293
2294 EXPECT_TRUE(track_event.has_log_message());
2295 const auto& log = track_event.log_message();
2296 EXPECT_EQ(1u, log.source_location_iid());
2297 EXPECT_EQ(2u, log.body_iid());
2298
2299 const auto& dbg = track_event.debug_annotations()[0];
2300 EXPECT_EQ("random", dbg.name());
2301 EXPECT_EQ(random_value, dbg.int_value());
2302
2303 found_args = true;
2304 }
2305 EXPECT_TRUE(found_args);
2306 }
2307
TEST_P(PerfettoApiTest,InlineTrackEventTypedArgs_SimpleRepeated)2308 TEST_P(PerfettoApiTest, InlineTrackEventTypedArgs_SimpleRepeated) {
2309 // Create a new trace session.
2310 auto* tracing_session = NewTraceWithCategories({"foo"});
2311 tracing_session->get()->StartBlocking();
2312
2313 std::vector<uint64_t> flow_ids_old{1, 2, 3};
2314 std::vector<uint64_t> flow_ids{4, 5, 6};
2315 TRACE_EVENT_BEGIN("foo", "EventWithTypedArg",
2316 perfetto::protos::pbzero::TrackEvent::kFlowIdsOld,
2317 flow_ids_old,
2318 perfetto::protos::pbzero::TrackEvent::kFlowIds, flow_ids);
2319 TRACE_EVENT_END("foo");
2320
2321 auto trace = StopSessionAndReturnParsedTrace(tracing_session);
2322
2323 bool found_args = false;
2324 for (const auto& packet : trace.packet()) {
2325 if (!packet.has_track_event())
2326 continue;
2327 const auto& track_event = packet.track_event();
2328 if (track_event.type() !=
2329 perfetto::protos::gen::TrackEvent::TYPE_SLICE_BEGIN) {
2330 continue;
2331 }
2332
2333 EXPECT_THAT(track_event.flow_ids_old(), testing::ElementsAre(1u, 2u, 3u));
2334 EXPECT_THAT(track_event.flow_ids(), testing::ElementsAre(4u, 5u, 6u));
2335 found_args = true;
2336 }
2337 EXPECT_TRUE(found_args);
2338 }
2339
2340 namespace {
2341
2342 struct LogMessage {
WriteIntoTrace__anon78e5bb3c0111::__anon78e5bb3c1511::LogMessage2343 void WriteIntoTrace(
2344 perfetto::TracedProto<perfetto::protos::pbzero::LogMessage> context)
2345 const {
2346 context->set_source_location_iid(1);
2347 context->set_body_iid(2);
2348 }
2349 };
2350
__anon78e5bb3c1602() 2351 auto GetWriteLogMessageRefLambda = []() {
2352 return [](perfetto::EventContext& ctx) {
2353 auto* log = ctx.event()->set_log_message();
2354 log->set_source_location_iid(1);
2355 log->set_body_iid(2);
2356 };
2357 };
2358
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)2359 void CheckTypedArguments(
2360 const std::vector<char>& raw_trace,
2361 const char* event_name,
2362 perfetto::protos::gen::TrackEvent::Type type,
2363 std::function<void(const perfetto::protos::gen::TrackEvent&)> checker) {
2364 perfetto::protos::gen::Trace parsed_trace;
2365 ASSERT_TRUE(parsed_trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
2366
2367 bool found_slice = false;
2368 ParsedIncrementalState incremental_state;
2369
2370 for (const auto& packet : parsed_trace.packet()) {
2371 incremental_state.ClearIfNeeded(packet);
2372 incremental_state.Parse(packet);
2373
2374 if (!packet.has_track_event())
2375 continue;
2376 const auto& track_event = packet.track_event();
2377 if (track_event.type() != type) {
2378 continue;
2379 }
2380 if (event_name &&
2381 incremental_state.GetEventName(track_event) != event_name) {
2382 continue;
2383 }
2384
2385 checker(track_event);
2386 found_slice = true;
2387 }
2388 EXPECT_TRUE(found_slice);
2389 }
2390
CheckLogMessagePresent(const std::vector<char> & raw_trace)2391 void CheckLogMessagePresent(const std::vector<char>& raw_trace) {
2392 CheckTypedArguments(raw_trace, nullptr,
2393 perfetto::protos::gen::TrackEvent::TYPE_SLICE_BEGIN,
2394 [](const perfetto::protos::gen::TrackEvent& track_event) {
2395 EXPECT_TRUE(track_event.has_log_message());
2396 const auto& log = track_event.log_message();
2397 EXPECT_EQ(1u, log.source_location_iid());
2398 EXPECT_EQ(2u, log.body_iid());
2399 });
2400 }
2401
2402 } // namespace
2403
TEST_P(PerfettoApiTest,InlineTrackEventTypedArgs_NestedSingle)2404 TEST_P(PerfettoApiTest, InlineTrackEventTypedArgs_NestedSingle) {
2405 // Create a new trace session.
2406 auto* tracing_session = NewTraceWithCategories({"foo"});
2407 tracing_session->get()->StartBlocking();
2408
2409 TRACE_EVENT_BEGIN("foo", "EventWithTypedArg",
2410 perfetto::protos::pbzero::TrackEvent::kLogMessage,
2411 LogMessage());
2412 TRACE_EVENT_END("foo");
2413
2414 std::vector<char> raw_trace = StopSessionAndReturnBytes(tracing_session);
2415 }
2416
TEST_P(PerfettoApiTest,TrackEventThreadTime)2417 TEST_P(PerfettoApiTest, TrackEventThreadTime) {
2418 for (auto enable_thread_time : {true, false}) {
2419 perfetto::protos::gen::TrackEventConfig te_cfg;
2420 te_cfg.set_enable_thread_time_sampling(enable_thread_time);
2421 auto* tracing_session = NewTraceWithCategories({"foo"}, te_cfg);
2422
2423 tracing_session->get()->StartBlocking();
2424
2425 perfetto::Track custom_track(1);
2426
2427 TRACE_EVENT_BEGIN("foo", "event1");
2428 TRACE_EVENT_BEGIN("foo", "event2");
2429 TRACE_EVENT_BEGIN("foo", "event3");
2430 TRACE_EVENT_BEGIN("foo", "event4", custom_track);
2431 TRACE_EVENT_END("foo");
2432 TRACE_EVENT_END("foo");
2433 TRACE_EVENT_END("foo");
2434 TRACE_EVENT_END("foo");
2435
2436 auto trace = StopSessionAndReturnParsedTrace(tracing_session);
2437
2438 bool found_counter_track_descriptor = false;
2439 uint64_t thread_time_counter_uuid = 0;
2440 uint64_t default_counter_uuid = 0;
2441 std::unordered_set<std::string> event_names;
2442 for (const auto& packet : trace.packet()) {
2443 if (packet.has_track_descriptor() &&
2444 packet.track_descriptor().has_counter()) {
2445 EXPECT_FALSE(found_counter_track_descriptor);
2446 found_counter_track_descriptor = true;
2447 thread_time_counter_uuid = packet.track_descriptor().uuid();
2448 EXPECT_EQ("thread_time", packet.track_descriptor().name());
2449 auto counter = packet.track_descriptor().counter();
2450 EXPECT_EQ(
2451 perfetto::protos::gen::
2452 CounterDescriptor_BuiltinCounterType_COUNTER_THREAD_TIME_NS,
2453 counter.type());
2454 EXPECT_TRUE(counter.is_incremental());
2455 }
2456 if (packet.has_trace_packet_defaults()) {
2457 auto& defaults = packet.trace_packet_defaults().track_event_defaults();
2458 ASSERT_EQ(enable_thread_time ? 1u : 0u,
2459 defaults.extra_counter_track_uuids().size());
2460 if (enable_thread_time) {
2461 default_counter_uuid = defaults.extra_counter_track_uuids().at(0);
2462 }
2463 }
2464 if (packet.has_track_event()) {
2465 std::string event_name;
2466 if (packet.has_interned_data()) {
2467 auto& event_names_info = packet.interned_data().event_names();
2468 if (event_names_info.size() > 0) {
2469 event_name = event_names_info[0].name();
2470 }
2471 }
2472 event_names.insert(event_name);
2473 EXPECT_EQ((enable_thread_time && event_name != "event4") ? 1u : 0u,
2474 packet.track_event().extra_counter_values().size());
2475 }
2476 }
2477 EXPECT_TRUE(ContainsKey(event_names, "event1"));
2478 EXPECT_TRUE(ContainsKey(event_names, "event2"));
2479 EXPECT_TRUE(ContainsKey(event_names, "event3"));
2480 EXPECT_TRUE(ContainsKey(event_names, "event4"));
2481 EXPECT_EQ(enable_thread_time, found_counter_track_descriptor);
2482 EXPECT_EQ(default_counter_uuid, thread_time_counter_uuid);
2483 if (enable_thread_time) {
2484 EXPECT_GT(thread_time_counter_uuid, 0u);
2485 } else {
2486 EXPECT_EQ(thread_time_counter_uuid, 0u);
2487 }
2488 }
2489 }
2490
TEST_P(PerfettoApiTest,TrackEventArgs_TypedAndUntyped)2491 TEST_P(PerfettoApiTest, TrackEventArgs_TypedAndUntyped) {
2492 // Create a new trace session.
2493 auto* tracing_session = NewTraceWithCategories({"foo"});
2494 tracing_session->get()->StartBlocking();
2495
2496 TRACE_EVENT_BEGIN("foo", "E",
2497 perfetto::protos::pbzero::TrackEvent::kLogMessage,
2498 LogMessage(), "arg", "value");
2499 TRACE_EVENT_END("foo");
2500
2501 std::vector<char> raw_trace = StopSessionAndReturnBytes(tracing_session);
2502 std::string trace(raw_trace.data(), raw_trace.size());
2503
2504 // Find typed argument.
2505 CheckLogMessagePresent(raw_trace);
2506
2507 // Find untyped argument.
2508 EXPECT_THAT(ReadSlicesFromTrace(raw_trace),
2509 ElementsAre("B:foo.E(arg=(string)value)", "E"));
2510 }
2511
TEST_P(PerfettoApiTest,TrackEventArgs_UntypedAndTyped)2512 TEST_P(PerfettoApiTest, TrackEventArgs_UntypedAndTyped) {
2513 // Create a new trace session.
2514 auto* tracing_session = NewTraceWithCategories({"foo"});
2515 tracing_session->get()->StartBlocking();
2516
2517 TRACE_EVENT_BEGIN("foo", "E", "arg", "value",
2518 perfetto::protos::pbzero::TrackEvent::kLogMessage,
2519 LogMessage());
2520 TRACE_EVENT_END("foo");
2521
2522 std::vector<char> raw_trace = StopSessionAndReturnBytes(tracing_session);
2523
2524 // Find typed argument.
2525 CheckLogMessagePresent(raw_trace);
2526
2527 // Find untyped argument.
2528 EXPECT_THAT(ReadSlicesFromTrace(raw_trace),
2529 ElementsAre("B:foo.E(arg=(string)value)", "E"));
2530 }
2531
TEST_P(PerfettoApiTest,TrackEventArgs_UntypedAndRefLambda)2532 TEST_P(PerfettoApiTest, TrackEventArgs_UntypedAndRefLambda) {
2533 // Create a new trace session.
2534 auto* tracing_session = NewTraceWithCategories({"foo"});
2535 tracing_session->get()->StartBlocking();
2536
2537 TRACE_EVENT_BEGIN("foo", "E", "arg", "value", GetWriteLogMessageRefLambda());
2538 TRACE_EVENT_END("foo");
2539
2540 std::vector<char> raw_trace = StopSessionAndReturnBytes(tracing_session);
2541
2542 // Find typed argument.
2543 CheckLogMessagePresent(raw_trace);
2544
2545 // Find untyped argument.
2546 EXPECT_THAT(ReadSlicesFromTrace(raw_trace),
2547 ElementsAre("B:foo.E(arg=(string)value)", "E"));
2548 }
2549
TEST_P(PerfettoApiTest,TrackEventArgs_RefLambdaAndUntyped)2550 TEST_P(PerfettoApiTest, TrackEventArgs_RefLambdaAndUntyped) {
2551 // Create a new trace session.
2552 auto* tracing_session = NewTraceWithCategories({"foo"});
2553 tracing_session->get()->StartBlocking();
2554
2555 TRACE_EVENT_BEGIN("foo", "E", GetWriteLogMessageRefLambda(), "arg", "value");
2556 TRACE_EVENT_END("foo");
2557
2558 std::vector<char> raw_trace = StopSessionAndReturnBytes(tracing_session);
2559
2560 // Find typed argument.
2561 CheckLogMessagePresent(raw_trace);
2562
2563 // Find untyped argument.
2564 EXPECT_THAT(ReadSlicesFromTrace(raw_trace),
2565 ElementsAre("B:foo.E(arg=(string)value)", "E"));
2566 }
2567
TEST_P(PerfettoApiTest,TrackEventArgs_RefLambdaAndTyped)2568 TEST_P(PerfettoApiTest, TrackEventArgs_RefLambdaAndTyped) {
2569 // Create a new trace session.
2570 auto* tracing_session = NewTraceWithCategories({"foo"});
2571 tracing_session->get()->StartBlocking();
2572
2573 TRACE_EVENT_BEGIN(
2574 "foo", "E",
2575 [](perfetto::EventContext& ctx) {
2576 ctx.AddDebugAnnotation("arg", "value");
2577 },
2578 perfetto::protos::pbzero::TrackEvent::kLogMessage, LogMessage());
2579 TRACE_EVENT_END("foo");
2580
2581 std::vector<char> raw_trace = StopSessionAndReturnBytes(tracing_session);
2582
2583 // Find typed argument.
2584 CheckLogMessagePresent(raw_trace);
2585
2586 // Find untyped argument.
2587 EXPECT_THAT(ReadSlicesFromTrace(raw_trace),
2588 ElementsAre("B:foo.E(arg=(string)value)", "E"));
2589 }
2590
TEST_P(PerfettoApiTest,TrackEventArgs_TypedAndRefLambda)2591 TEST_P(PerfettoApiTest, TrackEventArgs_TypedAndRefLambda) {
2592 // Create a new trace session.
2593 auto* tracing_session = NewTraceWithCategories({"foo"});
2594 tracing_session->get()->StartBlocking();
2595
2596 TRACE_EVENT_BEGIN("foo", "E",
2597 perfetto::protos::pbzero::TrackEvent::kLogMessage,
2598 LogMessage(), [](perfetto::EventContext& ctx) {
2599 ctx.AddDebugAnnotation("arg", "value");
2600 });
2601 TRACE_EVENT_END("foo");
2602
2603 std::vector<char> raw_trace = StopSessionAndReturnBytes(tracing_session);
2604
2605 // Find typed argument.
2606 CheckLogMessagePresent(raw_trace);
2607
2608 // Find untyped argument.
2609 EXPECT_THAT(ReadSlicesFromTrace(raw_trace),
2610 ElementsAre("B:foo.E(arg=(string)value)", "E"));
2611 }
2612
TEST_P(PerfettoApiTest,TrackEventArgs_RefLambdaAndRefLambda)2613 TEST_P(PerfettoApiTest, TrackEventArgs_RefLambdaAndRefLambda) {
2614 // Create a new trace session.
2615 auto* tracing_session = NewTraceWithCategories({"foo"});
2616 tracing_session->get()->StartBlocking();
2617
2618 TRACE_EVENT_BEGIN(
2619 "foo", "E",
2620 [](perfetto::EventContext& ctx) {
2621 ctx.AddDebugAnnotation("arg1", "value1");
2622 },
2623 [](perfetto::EventContext& ctx) {
2624 ctx.AddDebugAnnotation("arg2", "value2");
2625 });
2626 TRACE_EVENT_END("foo");
2627
2628 std::vector<char> raw_trace = StopSessionAndReturnBytes(tracing_session);
2629
2630 // Find untyped arguments.
2631 EXPECT_THAT(
2632 ReadSlicesFromTrace(raw_trace),
2633 ElementsAre("B:foo.E(arg1=(string)value1,arg2=(string)value2)", "E"));
2634 }
2635
TEST_P(PerfettoApiTest,TrackEventArgs_RefLambdaAndLambda)2636 TEST_P(PerfettoApiTest, TrackEventArgs_RefLambdaAndLambda) {
2637 // Create a new trace session.
2638 auto* tracing_session = NewTraceWithCategories({"foo"});
2639 tracing_session->get()->StartBlocking();
2640
2641 TRACE_EVENT_BEGIN(
2642 "foo", "E",
2643 [](perfetto::EventContext& ctx) {
2644 ctx.AddDebugAnnotation("arg1", "value1");
2645 },
2646 [](perfetto::EventContext ctx) {
2647 ctx.AddDebugAnnotation("arg2", "value2");
2648 });
2649 TRACE_EVENT_END("foo");
2650
2651 std::vector<char> raw_trace = StopSessionAndReturnBytes(tracing_session);
2652
2653 // Find untyped arguments.
2654 EXPECT_THAT(
2655 ReadSlicesFromTrace(raw_trace),
2656 ElementsAre("B:foo.E(arg1=(string)value1,arg2=(string)value2)", "E"));
2657 }
2658
TEST_P(PerfettoApiTest,TrackEventArgs_RefLambda)2659 TEST_P(PerfettoApiTest, TrackEventArgs_RefLambda) {
2660 // Create a new trace session.
2661 auto* tracing_session = NewTraceWithCategories({"foo"});
2662 tracing_session->get()->StartBlocking();
2663
2664 TRACE_EVENT_BEGIN("foo", "E", [](perfetto::EventContext& ctx) {
2665 ctx.AddDebugAnnotation("arg", "value");
2666 });
2667 TRACE_EVENT_END("foo");
2668
2669 std::vector<char> raw_trace = StopSessionAndReturnBytes(tracing_session);
2670
2671 // Find untyped argument.
2672 EXPECT_THAT(ReadSlicesFromTrace(raw_trace),
2673 ElementsAre("B:foo.E(arg=(string)value)", "E"));
2674 }
2675
TEST_P(PerfettoApiTest,TrackEventArgs_Flow_Global)2676 TEST_P(PerfettoApiTest, TrackEventArgs_Flow_Global) {
2677 // Create a new trace session.
2678 auto* tracing_session = NewTraceWithCategories({"foo"});
2679 tracing_session->get()->StartBlocking();
2680
2681 TRACE_EVENT_INSTANT("foo", "E1", perfetto::Flow::Global(42));
2682 TRACE_EVENT_INSTANT("foo", "E2", perfetto::TerminatingFlow::Global(42));
2683
2684 std::vector<char> raw_trace = StopSessionAndReturnBytes(tracing_session);
2685
2686 // Find typed argument.
2687 CheckTypedArguments(
2688 raw_trace, "E1", perfetto::protos::gen::TrackEvent::TYPE_INSTANT,
2689 [](const perfetto::protos::gen::TrackEvent& track_event) {
2690 EXPECT_TRUE(track_event.flow_ids_old().empty());
2691 EXPECT_THAT(track_event.flow_ids(), testing::ElementsAre(42u));
2692 });
2693 }
2694
TEST_P(PerfettoApiTest,TrackEventArgs_Lambda_Multisession)2695 TEST_P(PerfettoApiTest, TrackEventArgs_Lambda_Multisession) {
2696 // Create two simultaneous tracing sessions.
2697 auto* tracing_session = NewTraceWithCategories({"foo"});
2698 auto* tracing_session2 = NewTraceWithCategories({"foo"});
2699 tracing_session->get()->StartBlocking();
2700 tracing_session2->get()->StartBlocking();
2701
2702 // Emit an event in both sessions using an argument function.
2703 auto make_arg = []() -> std::function<void(perfetto::EventContext&)> {
2704 return [](perfetto::EventContext& ctx) {
2705 ctx.event()->set_type(perfetto::protos::pbzero::TrackEvent::TYPE_INSTANT);
2706 ctx.event()->add_flow_ids(42);
2707 };
2708 };
2709 TRACE_EVENT_INSTANT("foo", "E1", make_arg());
2710
2711 std::vector<char> raw_trace = StopSessionAndReturnBytes(tracing_session);
2712 std::vector<char> raw_trace2 = StopSessionAndReturnBytes(tracing_session2);
2713
2714 // Check that the event was output twice.
2715 CheckTypedArguments(
2716 raw_trace, "E1", perfetto::protos::gen::TrackEvent::TYPE_INSTANT,
2717 [](const perfetto::protos::gen::TrackEvent& track_event) {
2718 EXPECT_TRUE(track_event.flow_ids_old().empty());
2719 EXPECT_THAT(track_event.flow_ids(), testing::ElementsAre(42u));
2720 });
2721 CheckTypedArguments(
2722 raw_trace2, "E1", perfetto::protos::gen::TrackEvent::TYPE_INSTANT,
2723 [](const perfetto::protos::gen::TrackEvent& track_event) {
2724 EXPECT_TRUE(track_event.flow_ids_old().empty());
2725 EXPECT_THAT(track_event.flow_ids(), testing::ElementsAre(42u));
2726 });
2727 }
2728
TEST_P(PerfettoApiTest,TrackEventArgs_MultipleFlows)2729 TEST_P(PerfettoApiTest, TrackEventArgs_MultipleFlows) {
2730 // Create a new trace session.
2731 auto* tracing_session = NewTraceWithCategories({"foo"});
2732 tracing_session->get()->StartBlocking();
2733
2734 {
2735 TRACE_EVENT("foo", "E1", perfetto::Flow::Global(1),
2736 perfetto::Flow::Global(2), perfetto::Flow::Global(3));
2737 }
2738 {
2739 TRACE_EVENT("foo", "E2", perfetto::Flow::Global(1),
2740 perfetto::TerminatingFlow::Global(2));
2741 }
2742 { TRACE_EVENT("foo", "E3", perfetto::TerminatingFlow::Global(3)); }
2743
2744 std::vector<char> raw_trace = StopSessionAndReturnBytes(tracing_session);
2745 EXPECT_THAT(ReadSlicesFromTrace(raw_trace),
2746 ElementsAre("B:foo.E1(flow_ids=1,2,3)", "E",
2747 "B:foo.E2(flow_ids=1)(terminating_flow_ids=2)", "E",
2748 "B:foo.E3(terminating_flow_ids=3)", "E"));
2749 }
2750
TEST_P(PerfettoApiTest,TrackEventArgs_Flow_ProcessScoped)2751 TEST_P(PerfettoApiTest, TrackEventArgs_Flow_ProcessScoped) {
2752 // Create a new trace session.
2753 auto* tracing_session = NewTraceWithCategories({"foo"});
2754 tracing_session->get()->StartBlocking();
2755
2756 TRACE_EVENT_INSTANT("foo", "E1", perfetto::Flow::ProcessScoped(1));
2757 TRACE_EVENT_INSTANT("foo", "E2", perfetto::TerminatingFlow::ProcessScoped(1));
2758 TRACE_EVENT_INSTANT("foo", "Flush");
2759
2760 std::vector<char> raw_trace = StopSessionAndReturnBytes(tracing_session);
2761
2762 // Find typed arguments.
2763 CheckTypedArguments(raw_trace, "E1",
2764 perfetto::protos::gen::TrackEvent::TYPE_INSTANT,
2765 [](const perfetto::protos::gen::TrackEvent& track_event) {
2766 EXPECT_EQ(track_event.flow_ids_old_size(), 0);
2767 EXPECT_EQ(track_event.flow_ids_size(), 1);
2768 });
2769 CheckTypedArguments(
2770 raw_trace, "E2", perfetto::protos::gen::TrackEvent::TYPE_INSTANT,
2771 [](const perfetto::protos::gen::TrackEvent& track_event) {
2772 EXPECT_EQ(track_event.terminating_flow_ids_old_size(), 0);
2773 EXPECT_EQ(track_event.terminating_flow_ids_size(), 1);
2774 });
2775 }
2776
TEST_P(PerfettoApiTest,TrackEventArgs_Flow_FromPointer)2777 TEST_P(PerfettoApiTest, TrackEventArgs_Flow_FromPointer) {
2778 // Create a new trace session.
2779 auto* tracing_session = NewTraceWithCategories({"foo"});
2780 tracing_session->get()->StartBlocking();
2781
2782 int a;
2783 int* ptr = &a;
2784 TRACE_EVENT_INSTANT("foo", "E1", perfetto::Flow::FromPointer(ptr));
2785 TRACE_EVENT_INSTANT("foo", "E2", perfetto::TerminatingFlow::FromPointer(ptr));
2786 TRACE_EVENT_INSTANT("foo", "Flush");
2787
2788 std::vector<char> raw_trace = StopSessionAndReturnBytes(tracing_session);
2789
2790 // Find typed arguments.
2791 CheckTypedArguments(raw_trace, "E1",
2792 perfetto::protos::gen::TrackEvent::TYPE_INSTANT,
2793 [](const perfetto::protos::gen::TrackEvent& track_event) {
2794 EXPECT_EQ(track_event.flow_ids_old_size(), 0);
2795 EXPECT_EQ(track_event.flow_ids_size(), 1);
2796 });
2797 CheckTypedArguments(
2798 raw_trace, "E2", perfetto::protos::gen::TrackEvent::TYPE_INSTANT,
2799 [](const perfetto::protos::gen::TrackEvent& track_event) {
2800 EXPECT_EQ(track_event.terminating_flow_ids_old_size(), 0);
2801 EXPECT_EQ(track_event.terminating_flow_ids_size(), 1);
2802 });
2803 }
2804
2805 struct InternedLogMessageBody
2806 : public perfetto::TrackEventInternedDataIndex<
2807 InternedLogMessageBody,
2808 perfetto::protos::pbzero::InternedData::kLogMessageBodyFieldNumber,
2809 std::string> {
Add__anon78e5bb3c0111::InternedLogMessageBody2810 static void Add(perfetto::protos::pbzero::InternedData* interned_data,
2811 size_t iid,
2812 const std::string& value) {
2813 auto l = interned_data->add_log_message_body();
2814 l->set_iid(iid);
2815 l->set_body(value.data(), value.size());
2816 commit_count++;
2817 }
2818
2819 static int commit_count;
2820 };
2821
2822 int InternedLogMessageBody::commit_count = 0;
2823
TEST_P(PerfettoApiTest,TrackEventTypedArgsWithInterning)2824 TEST_P(PerfettoApiTest, TrackEventTypedArgsWithInterning) {
2825 // Create a new trace session.
2826 auto* tracing_session = NewTraceWithCategories({"foo"});
2827 tracing_session->get()->StartBlocking();
2828
2829 std::stringstream large_message;
2830 for (size_t i = 0; i < 512; i++)
2831 large_message << i << ". Something wicked this way comes. ";
2832
2833 size_t body_iid;
2834 InternedLogMessageBody::commit_count = 0;
2835 TRACE_EVENT_BEGIN("foo", "EventWithState", [&](perfetto::EventContext ctx) {
2836 EXPECT_EQ(0, InternedLogMessageBody::commit_count);
2837 body_iid = InternedLogMessageBody::Get(&ctx, "Alas, poor Yorick!");
2838 auto log = ctx.event()->set_log_message();
2839 log->set_body_iid(body_iid);
2840 EXPECT_EQ(1, InternedLogMessageBody::commit_count);
2841
2842 auto body_iid2 = InternedLogMessageBody::Get(&ctx, "Alas, poor Yorick!");
2843 EXPECT_EQ(body_iid, body_iid2);
2844 EXPECT_EQ(1, InternedLogMessageBody::commit_count);
2845 });
2846 TRACE_EVENT_END("foo");
2847
2848 TRACE_EVENT_BEGIN("foo", "EventWithState", [&](perfetto::EventContext ctx) {
2849 // Check that very large amounts of interned data works.
2850 auto log = ctx.event()->set_log_message();
2851 log->set_body_iid(InternedLogMessageBody::Get(&ctx, large_message.str()));
2852 EXPECT_EQ(2, InternedLogMessageBody::commit_count);
2853 });
2854 TRACE_EVENT_END("foo");
2855
2856 // Make sure interned data persists across trace points.
2857 TRACE_EVENT_BEGIN("foo", "EventWithState", [&](perfetto::EventContext ctx) {
2858 auto body_iid2 = InternedLogMessageBody::Get(&ctx, "Alas, poor Yorick!");
2859 EXPECT_EQ(body_iid, body_iid2);
2860
2861 auto body_iid3 = InternedLogMessageBody::Get(&ctx, "I knew him, Horatio");
2862 EXPECT_NE(body_iid, body_iid3);
2863 auto log = ctx.event()->set_log_message();
2864 log->set_body_iid(body_iid3);
2865 EXPECT_EQ(3, InternedLogMessageBody::commit_count);
2866 });
2867 TRACE_EVENT_END("foo");
2868
2869 tracing_session->get()->StopBlocking();
2870 auto log_messages = ReadLogMessagesFromTrace(tracing_session->get());
2871 EXPECT_THAT(log_messages,
2872 ElementsAre("Alas, poor Yorick!", large_message.str(),
2873 "I knew him, Horatio"));
2874 }
2875
2876 struct InternedLogMessageBodySmall
2877 : public perfetto::TrackEventInternedDataIndex<
2878 InternedLogMessageBodySmall,
2879 perfetto::protos::pbzero::InternedData::kLogMessageBodyFieldNumber,
2880 const char*,
2881 perfetto::SmallInternedDataTraits> {
Add__anon78e5bb3c0111::InternedLogMessageBodySmall2882 static void Add(perfetto::protos::pbzero::InternedData* interned_data,
2883 size_t iid,
2884 const char* value) {
2885 auto l = interned_data->add_log_message_body();
2886 l->set_iid(iid);
2887 l->set_body(value);
2888 }
2889 };
2890
TEST_P(PerfettoApiTest,TrackEventTypedArgsWithInterningByValue)2891 TEST_P(PerfettoApiTest, TrackEventTypedArgsWithInterningByValue) {
2892 // Create a new trace session.
2893 auto* tracing_session = NewTraceWithCategories({"foo"});
2894 tracing_session->get()->StartBlocking();
2895
2896 size_t body_iid;
2897 TRACE_EVENT_BEGIN("foo", "EventWithState", [&](perfetto::EventContext ctx) {
2898 body_iid = InternedLogMessageBodySmall::Get(&ctx, "This above all:");
2899 auto log = ctx.event()->set_log_message();
2900 log->set_body_iid(body_iid);
2901
2902 auto body_iid2 = InternedLogMessageBodySmall::Get(&ctx, "This above all:");
2903 EXPECT_EQ(body_iid, body_iid2);
2904
2905 auto body_iid3 =
2906 InternedLogMessageBodySmall::Get(&ctx, "to thine own self be true");
2907 EXPECT_NE(body_iid, body_iid3);
2908 });
2909 TRACE_EVENT_END("foo");
2910
2911 tracing_session->get()->StopBlocking();
2912 auto log_messages = ReadLogMessagesFromTrace(tracing_session->get());
2913 EXPECT_THAT(log_messages, ElementsAre("This above all:"));
2914 }
2915
2916 struct InternedLogMessageBodyHashed
2917 : public perfetto::TrackEventInternedDataIndex<
2918 InternedLogMessageBodyHashed,
2919 perfetto::protos::pbzero::InternedData::kLogMessageBodyFieldNumber,
2920 std::string,
2921 perfetto::HashedInternedDataTraits> {
Add__anon78e5bb3c0111::InternedLogMessageBodyHashed2922 static void Add(perfetto::protos::pbzero::InternedData* interned_data,
2923 size_t iid,
2924 const std::string& value) {
2925 auto l = interned_data->add_log_message_body();
2926 l->set_iid(iid);
2927 l->set_body(value.data(), value.size());
2928 }
2929 };
2930
TEST_P(PerfettoApiTest,TrackEventTypedArgsWithInterningByHashing)2931 TEST_P(PerfettoApiTest, TrackEventTypedArgsWithInterningByHashing) {
2932 // Create a new trace session.
2933 auto* tracing_session = NewTraceWithCategories({"foo"});
2934 tracing_session->get()->StartBlocking();
2935
2936 size_t body_iid;
2937 TRACE_EVENT_BEGIN("foo", "EventWithState", [&](perfetto::EventContext ctx) {
2938 // Test using a dynamically created interned value.
2939 body_iid = InternedLogMessageBodyHashed::Get(
2940 &ctx, std::string("Though this ") + "be madness,");
2941 auto log = ctx.event()->set_log_message();
2942 log->set_body_iid(body_iid);
2943
2944 auto body_iid2 =
2945 InternedLogMessageBodyHashed::Get(&ctx, "Though this be madness,");
2946 EXPECT_EQ(body_iid, body_iid2);
2947
2948 auto body_iid3 =
2949 InternedLogMessageBodyHashed::Get(&ctx, "yet there is method in’t");
2950 EXPECT_NE(body_iid, body_iid3);
2951 });
2952 TRACE_EVENT_END("foo");
2953
2954 tracing_session->get()->StopBlocking();
2955 auto log_messages = ReadLogMessagesFromTrace(tracing_session->get());
2956 EXPECT_THAT(log_messages, ElementsAre("Though this be madness,"));
2957 }
2958
2959 struct InternedSourceLocation
2960 : public perfetto::TrackEventInternedDataIndex<
2961 InternedSourceLocation,
2962 perfetto::protos::pbzero::InternedData::kSourceLocationsFieldNumber,
2963 SourceLocation> {
Add__anon78e5bb3c0111::InternedSourceLocation2964 static void Add(perfetto::protos::pbzero::InternedData* interned_data,
2965 size_t iid,
2966 const SourceLocation& value) {
2967 auto l = interned_data->add_source_locations();
2968 auto file_name = std::get<0>(value);
2969 auto function_name = std::get<1>(value);
2970 auto line_number = std::get<2>(value);
2971 l->set_iid(iid);
2972 l->set_file_name(file_name);
2973 l->set_function_name(function_name);
2974 l->set_line_number(line_number);
2975 }
2976 };
2977
TEST_P(PerfettoApiTest,TrackEventTypedArgsWithInterningComplexValue)2978 TEST_P(PerfettoApiTest, TrackEventTypedArgsWithInterningComplexValue) {
2979 // Create a new trace session.
2980 auto* tracing_session = NewTraceWithCategories({"foo"});
2981 tracing_session->get()->StartBlocking();
2982
2983 TRACE_EVENT_BEGIN("foo", "EventWithState", [&](perfetto::EventContext ctx) {
2984 const SourceLocation location{"file.cc", "SomeFunction", 123};
2985 auto location_iid = InternedSourceLocation::Get(&ctx, location);
2986 auto body_iid = InternedLogMessageBody::Get(&ctx, "To be, or not to be");
2987 auto log = ctx.event()->set_log_message();
2988 log->set_source_location_iid(location_iid);
2989 log->set_body_iid(body_iid);
2990
2991 auto location_iid2 = InternedSourceLocation::Get(&ctx, location);
2992 EXPECT_EQ(location_iid, location_iid2);
2993
2994 const SourceLocation location2{"file.cc", "SomeFunction", 456};
2995 auto location_iid3 = InternedSourceLocation::Get(&ctx, location2);
2996 EXPECT_NE(location_iid, location_iid3);
2997 });
2998 TRACE_EVENT_END("foo");
2999
3000 tracing_session->get()->StopBlocking();
3001 auto log_messages = ReadLogMessagesFromTrace(tracing_session->get());
3002 EXPECT_THAT(log_messages,
3003 ElementsAre("SomeFunction(file.cc:123): To be, or not to be"));
3004 }
3005
TEST_P(PerfettoApiTest,TrackEventScoped)3006 TEST_P(PerfettoApiTest, TrackEventScoped) {
3007 // Create a new trace session.
3008 auto* tracing_session = NewTraceWithCategories({"test"});
3009 tracing_session->get()->StartBlocking();
3010
3011 {
3012 uint64_t arg = 123;
3013 TRACE_EVENT("test", "TestEventWithArgs", [&](perfetto::EventContext ctx) {
3014 ctx.event()->set_log_message()->set_body_iid(arg);
3015 });
3016 }
3017
3018 // Ensure a single line if statement counts as a valid scope for the macro.
3019 if (true)
3020 TRACE_EVENT("test", "SingleLineTestEvent");
3021
3022 {
3023 // Make sure you can have multiple scoped events in the same scope.
3024 TRACE_EVENT("test", "TestEvent");
3025 TRACE_EVENT("test", "AnotherEvent");
3026 TRACE_EVENT("foo", "DisabledEvent");
3027 }
3028 auto slices = StopSessionAndReadSlicesFromTrace(tracing_session);
3029 EXPECT_THAT(
3030 slices,
3031 ElementsAre("B:test.TestEventWithArgs", "E", "B:test.SingleLineTestEvent",
3032 "E", "B:test.TestEvent", "B:test.AnotherEvent", "E", "E"));
3033 }
3034
3035 // A class similar to what Protozero generates for extended message.
3036 class TestTrackEvent : public perfetto::protos::pbzero::TrackEvent {
3037 public:
3038 static const int field_number = 9901;
3039
set_extension_value(int value)3040 void set_extension_value(int value) {
3041 // 9900-10000 is the range of extension field numbers reserved for testing.
3042 AppendTinyVarInt(field_number, value);
3043 }
3044 };
3045
TEST_P(PerfettoApiTest,ExtensionClass)3046 TEST_P(PerfettoApiTest, ExtensionClass) {
3047 auto* tracing_session = NewTraceWithCategories({"test"});
3048 tracing_session->get()->StartBlocking();
3049
3050 {
3051 TRACE_EVENT("test", "TestEventWithExtensionArgs",
3052 [&](perfetto::EventContext ctx) {
3053 ctx.event<perfetto::protos::pbzero::TestExtension>()
3054 ->add_int_extension_for_testing(42);
3055 });
3056 }
3057
3058 std::vector<char> raw_trace = StopSessionAndReturnBytes(tracing_session);
3059 EXPECT_GE(raw_trace.size(), 0u);
3060
3061 bool found_extension = false;
3062 perfetto::protos::pbzero::Trace_Decoder trace(
3063 reinterpret_cast<uint8_t*>(raw_trace.data()), raw_trace.size());
3064
3065 for (auto it = trace.packet(); it; ++it) {
3066 perfetto::protos::pbzero::TracePacket_Decoder packet(it->data(),
3067 it->size());
3068
3069 if (!packet.has_track_event())
3070 continue;
3071
3072 auto track_event = packet.track_event();
3073 protozero::ProtoDecoder decoder(track_event.data, track_event.size);
3074
3075 for (protozero::Field f = decoder.ReadField(); f.valid();
3076 f = decoder.ReadField()) {
3077 if (f.id() == perfetto::protos::pbzero::TestExtension::
3078 FieldMetadata_IntExtensionForTesting::kFieldId) {
3079 found_extension = true;
3080 }
3081 }
3082 }
3083
3084 EXPECT_TRUE(found_extension);
3085 }
3086
TEST_P(PerfettoApiTest,InlineTypedExtensionField)3087 TEST_P(PerfettoApiTest, InlineTypedExtensionField) {
3088 auto* tracing_session = NewTraceWithCategories({"test"});
3089 tracing_session->get()->StartBlocking();
3090
3091 {
3092 TRACE_EVENT(
3093 "test", "TestEventWithExtensionArgs",
3094 perfetto::protos::pbzero::TestExtension::kIntExtensionForTesting,
3095 std::vector<int>{42});
3096 }
3097
3098 std::vector<char> raw_trace = StopSessionAndReturnBytes(tracing_session);
3099 EXPECT_GE(raw_trace.size(), 0u);
3100
3101 bool found_extension = false;
3102 perfetto::protos::pbzero::Trace_Decoder trace(
3103 reinterpret_cast<uint8_t*>(raw_trace.data()), raw_trace.size());
3104
3105 for (auto it = trace.packet(); it; ++it) {
3106 perfetto::protos::pbzero::TracePacket_Decoder packet(it->data(),
3107 it->size());
3108
3109 if (!packet.has_track_event())
3110 continue;
3111
3112 auto track_event = packet.track_event();
3113 protozero::ProtoDecoder decoder(track_event.data, track_event.size);
3114
3115 for (protozero::Field f = decoder.ReadField(); f.valid();
3116 f = decoder.ReadField()) {
3117 if (f.id() == perfetto::protos::pbzero::TestExtension::
3118 FieldMetadata_IntExtensionForTesting::kFieldId) {
3119 found_extension = true;
3120 }
3121 }
3122 }
3123
3124 EXPECT_TRUE(found_extension);
3125 }
3126
TEST_P(PerfettoApiTest,TrackEventInstant)3127 TEST_P(PerfettoApiTest, TrackEventInstant) {
3128 // Create a new trace session.
3129 auto* tracing_session = NewTraceWithCategories({"test"});
3130 tracing_session->get()->StartBlocking();
3131
3132 TRACE_EVENT_INSTANT("test", "TestEvent");
3133 TRACE_EVENT_INSTANT("test", "AnotherEvent");
3134 auto slices = StopSessionAndReadSlicesFromTrace(tracing_session);
3135 EXPECT_THAT(slices, ElementsAre("I:test.TestEvent", "I:test.AnotherEvent"));
3136 }
3137
TEST_P(PerfettoApiTest,TrackEventDefaultGlobalTrack)3138 TEST_P(PerfettoApiTest, TrackEventDefaultGlobalTrack) {
3139 // Create a new trace session.
3140 auto* tracing_session = NewTraceWithCategories({"test"});
3141 tracing_session->get()->StartBlocking();
3142
3143 TRACE_EVENT_INSTANT("test", "ThreadEvent");
3144 TRACE_EVENT_INSTANT("test", "GlobalEvent", perfetto::Track::Global(0u));
3145 auto slices = StopSessionAndReadSlicesFromTrace(tracing_session);
3146 EXPECT_THAT(slices,
3147 ElementsAre("I:test.ThreadEvent", "[track=0]I:test.GlobalEvent"));
3148 }
3149
TEST_P(PerfettoApiTest,TrackEventTrackFromPointer)3150 TEST_P(PerfettoApiTest, TrackEventTrackFromPointer) {
3151 // Create a new trace session.
3152 auto* tracing_session = NewTraceWithCategories({"test"});
3153 tracing_session->get()->StartBlocking();
3154
3155 perfetto::Track parent_track(1);
3156 int* ptr = reinterpret_cast<int*>(2);
3157 TRACE_EVENT_INSTANT("test", "Event",
3158 perfetto::Track::FromPointer(ptr, parent_track));
3159
3160 perfetto::Track track(reinterpret_cast<uintptr_t>(ptr), parent_track);
3161
3162 auto slices = StopSessionAndReadSlicesFromTrace(tracing_session);
3163 EXPECT_THAT(slices, ElementsAre("[track=" + std::to_string(track.uuid) +
3164 "]I:test.Event"));
3165 }
3166
TEST_P(PerfettoApiTest,TrackEventTrackFromThreadScopedPointer)3167 TEST_P(PerfettoApiTest, TrackEventTrackFromThreadScopedPointer) {
3168 // Create a new trace session.
3169 auto* tracing_session = NewTraceWithCategories({"test"});
3170 tracing_session->get()->StartBlocking();
3171
3172 int num = 2;
3173 TRACE_EVENT_INSTANT("test", "Event0.1");
3174 TRACE_EVENT_INSTANT("test", "Event0.2");
3175 TRACE_EVENT_INSTANT("test", "Event1.1", perfetto::Track::ThreadScoped(&num));
3176 TRACE_EVENT_INSTANT("test", "Event1.2", perfetto::Track::ThreadScoped(&num));
3177 std::thread t1([&]() {
3178 TRACE_EVENT_INSTANT("test", "Event2.1",
3179 perfetto::Track::ThreadScoped(&num));
3180 TRACE_EVENT_INSTANT("test", "Event2.2",
3181 perfetto::Track::ThreadScoped(&num));
3182 });
3183 t1.join();
3184 std::thread t2([&]() {
3185 TRACE_EVENT_INSTANT("test", "Event3.1",
3186 perfetto::Track::ThreadScoped(&num));
3187 TRACE_EVENT_INSTANT("test", "Event3.2",
3188 perfetto::Track::ThreadScoped(&num));
3189 });
3190 t2.join();
3191
3192 auto trace = StopSessionAndReturnParsedTrace(tracing_session);
3193
3194 std::unordered_map<std::string, uint64_t> track_uuid_map;
3195 for (auto packet : trace.packet()) {
3196 if (packet.has_interned_data()) {
3197 for (auto& ename : packet.interned_data().event_names()) {
3198 track_uuid_map.emplace(ename.name(), packet.track_event().track_uuid());
3199 }
3200 }
3201 }
3202 EXPECT_EQ(track_uuid_map.at("Event0.1"), track_uuid_map.at("Event0.2"));
3203 EXPECT_EQ(track_uuid_map.at("Event1.1"), track_uuid_map.at("Event1.2"));
3204 EXPECT_EQ(track_uuid_map.at("Event2.1"), track_uuid_map.at("Event2.2"));
3205 EXPECT_EQ(track_uuid_map.at("Event3.1"), track_uuid_map.at("Event3.2"));
3206
3207 EXPECT_EQ(4u,
3208 (std::unordered_set<uint64_t>{
3209 track_uuid_map.at("Event0.1"), track_uuid_map.at("Event1.1"),
3210 track_uuid_map.at("Event2.1"), track_uuid_map.at("Event3.1")})
3211 .size());
3212 }
3213
TEST_P(PerfettoApiTest,FilterDebugAnnotations)3214 TEST_P(PerfettoApiTest, FilterDebugAnnotations) {
3215 for (auto flag : {false, true}) {
3216 // Create a new trace session.
3217 perfetto::protos::gen::TrackEventConfig te_cfg;
3218 te_cfg.set_filter_debug_annotations(flag);
3219 auto* tracing_session = NewTraceWithCategories({"test"}, te_cfg);
3220 tracing_session->get()->StartBlocking();
3221
3222 TRACE_EVENT_BEGIN("test", "Event1");
3223 TRACE_EVENT_BEGIN("test", "Event2", [&](perfetto::EventContext ctx) {
3224 ctx.AddDebugAnnotation("debug_name", "debug_value");
3225 });
3226 TRACE_EVENT_BEGIN("test", "Event3");
3227 auto slices = StopSessionAndReadSlicesFromTrace(tracing_session);
3228 ASSERT_EQ(3u, slices.size());
3229 if (flag) {
3230 EXPECT_EQ("B:test.Event2", slices[1]);
3231 } else {
3232 EXPECT_EQ("B:test.Event2(debug_name=(string)debug_value)", slices[1]);
3233 }
3234 }
3235 }
3236
TEST_P(PerfettoApiTest,TrackEventDebugAnnotations)3237 TEST_P(PerfettoApiTest, TrackEventDebugAnnotations) {
3238 // Create a new trace session.
3239 auto* tracing_session = NewTraceWithCategories({"test"});
3240 tracing_session->get()->StartBlocking();
3241
3242 enum MyEnum : uint32_t { ENUM_FOO, ENUM_BAR };
3243 enum MySignedEnum : int32_t { SIGNED_ENUM_FOO = -1, SIGNED_ENUM_BAR };
3244 enum class MyClassEnum { VALUE };
3245
3246 TRACE_EVENT_BEGIN("test", "E", "bool_arg", false);
3247 TRACE_EVENT_BEGIN("test", "E", "int_arg", -123);
3248 TRACE_EVENT_BEGIN("test", "E", "uint_arg", 456u);
3249 TRACE_EVENT_BEGIN("test", "E", "float_arg", 3.14159262f);
3250 TRACE_EVENT_BEGIN("test", "E", "double_arg", 6.22);
3251 TRACE_EVENT_BEGIN("test", "E", "str_arg", "hello", "str_arg2",
3252 std::string("tracing"));
3253 TRACE_EVENT_BEGIN("test", "E", "ptr_arg",
3254 reinterpret_cast<void*>(static_cast<intptr_t>(0xbaadf00d)));
3255 TRACE_EVENT_BEGIN("test", "E", "size_t_arg", size_t{42});
3256 TRACE_EVENT_BEGIN("test", "E", "ptrdiff_t_arg", ptrdiff_t{-7});
3257 TRACE_EVENT_BEGIN("test", "E", "enum_arg", ENUM_BAR);
3258 TRACE_EVENT_BEGIN("test", "E", "signed_enum_arg", SIGNED_ENUM_FOO);
3259 TRACE_EVENT_BEGIN("test", "E", "class_enum_arg", MyClassEnum::VALUE);
3260 TRACE_EVENT_BEGIN("test", "E", "traced_value",
3261 [&](perfetto::TracedValue context) {
3262 std::move(context).WriteInt64(42);
3263 });
3264 TRACE_EVENT_BEGIN("test", "E", [&](perfetto::EventContext ctx) {
3265 ctx.AddDebugAnnotation("debug_annotation", "value");
3266 });
3267 auto slices = StopSessionAndReadSlicesFromTrace(tracing_session);
3268 EXPECT_THAT(
3269 slices,
3270 ElementsAre(
3271 "B:test.E(bool_arg=(bool)0)", "B:test.E(int_arg=(int)-123)",
3272 "B:test.E(uint_arg=(uint)456)", "B:test.E(float_arg=(double)3.14159)",
3273 "B:test.E(double_arg=(double)6.22)",
3274 "B:test.E(str_arg=(string)hello,str_arg2=(string)tracing)",
3275 "B:test.E(ptr_arg=(pointer)baadf00d)",
3276 "B:test.E(size_t_arg=(uint)42)", "B:test.E(ptrdiff_t_arg=(int)-7)",
3277 "B:test.E(enum_arg=(uint)1)", "B:test.E(signed_enum_arg=(int)-1)",
3278 "B:test.E(class_enum_arg=(int)0)", "B:test.E(traced_value=(int)42)",
3279 "B:test.E(debug_annotation=(string)value)"));
3280 }
3281
TEST_P(PerfettoApiTest,TrackEventCustomDebugAnnotations)3282 TEST_P(PerfettoApiTest, TrackEventCustomDebugAnnotations) {
3283 // Create a new trace session.
3284 auto* tracing_session = NewTraceWithCategories({"test"});
3285 tracing_session->get()->StartBlocking();
3286
3287 std::unique_ptr<MyDebugAnnotation> owned_annotation(new MyDebugAnnotation());
3288
3289 TRACE_EVENT_BEGIN("test", "E", "custom_arg", MyDebugAnnotation());
3290 TRACE_EVENT_BEGIN("test", "E", "normal_arg", "x", "custom_arg",
3291 std::move(owned_annotation));
3292 auto slices = StopSessionAndReadSlicesFromTrace(tracing_session);
3293 EXPECT_THAT(
3294 slices,
3295 ElementsAre(
3296 R"(B:test.E(custom_arg=(json){"key": 123}))",
3297 R"(B:test.E(normal_arg=(string)x,custom_arg=(json){"key": 123}))"));
3298 }
3299
TEST_P(PerfettoApiTest,TrackEventCustomRawDebugAnnotations)3300 TEST_P(PerfettoApiTest, TrackEventCustomRawDebugAnnotations) {
3301 // Note: this class is also testing a non-moveable and non-copiable argument.
3302 class MyRawDebugAnnotation : public perfetto::DebugAnnotation {
3303 public:
3304 MyRawDebugAnnotation() { msg_->set_string_value("nested_value"); }
3305 ~MyRawDebugAnnotation() = default;
3306
3307 // |msg_| already deletes these implicitly, but let's be explicit for safety
3308 // against future changes.
3309 MyRawDebugAnnotation(const MyRawDebugAnnotation&) = delete;
3310 MyRawDebugAnnotation(MyRawDebugAnnotation&&) = delete;
3311
3312 void Add(perfetto::protos::pbzero::DebugAnnotation* annotation) const {
3313 auto ranges = msg_.GetRanges();
3314 annotation->AppendScatteredBytes(
3315 perfetto::protos::pbzero::DebugAnnotation::kNestedValueFieldNumber,
3316 &ranges[0], ranges.size());
3317 }
3318
3319 private:
3320 mutable protozero::HeapBuffered<
3321 perfetto::protos::pbzero::DebugAnnotation::NestedValue>
3322 msg_;
3323 };
3324
3325 // Create a new trace session.
3326 auto* tracing_session = NewTraceWithCategories({"test"});
3327 tracing_session->get()->StartBlocking();
3328
3329 TRACE_EVENT_BEGIN("test", "E", "raw_arg", MyRawDebugAnnotation());
3330 TRACE_EVENT_BEGIN("test", "E", "plain_arg", 42, "raw_arg",
3331 MyRawDebugAnnotation());
3332 auto slices = StopSessionAndReadSlicesFromTrace(tracing_session);
3333 EXPECT_THAT(
3334 slices,
3335 ElementsAre("B:test.E(raw_arg=(nested)nested_value)",
3336 "B:test.E(plain_arg=(int)42,raw_arg=(nested)nested_value)"));
3337 }
3338
TEST_P(PerfettoApiTest,ManyDebugAnnotations)3339 TEST_P(PerfettoApiTest, ManyDebugAnnotations) {
3340 // Create a new trace session.
3341 auto* tracing_session = NewTraceWithCategories({"test"});
3342 tracing_session->get()->StartBlocking();
3343
3344 TRACE_EVENT_BEGIN("test", "E", "arg1", 1, "arg2", 2, "arg3", 3);
3345 auto slices = StopSessionAndReadSlicesFromTrace(tracing_session);
3346 EXPECT_THAT(slices,
3347 ElementsAre("B:test.E(arg1=(int)1,arg2=(int)2,arg3=(int)3)"));
3348 }
3349
TEST_P(PerfettoApiTest,DebugAnnotationAndLambda)3350 TEST_P(PerfettoApiTest, DebugAnnotationAndLambda) {
3351 // Create a new trace session.
3352 auto* tracing_session = NewTraceWithCategories({"test"});
3353 tracing_session->get()->StartBlocking();
3354
3355 enum MyEnum : uint32_t { ENUM_FOO, ENUM_BAR };
3356 enum MySignedEnum : int32_t { SIGNED_ENUM_FOO = -1, SIGNED_ENUM_BAR };
3357 enum class MyClassEnum { VALUE };
3358
3359 TRACE_EVENT_BEGIN(
3360 "test", "E", "key", "value", [](perfetto::EventContext ctx) {
3361 ctx.event()->set_log_message()->set_source_location_iid(42);
3362 });
3363 auto trace = StopSessionAndReturnParsedTrace(tracing_session);
3364
3365 bool found_args = false;
3366 for (const auto& packet : trace.packet()) {
3367 if (!packet.has_track_event())
3368 continue;
3369 const auto& track_event = packet.track_event();
3370 if (track_event.type() !=
3371 perfetto::protos::gen::TrackEvent::TYPE_SLICE_BEGIN)
3372 continue;
3373
3374 EXPECT_TRUE(track_event.has_log_message());
3375 const auto& log = track_event.log_message();
3376 EXPECT_EQ(42u, log.source_location_iid());
3377
3378 const auto& dbg = track_event.debug_annotations()[0];
3379 EXPECT_EQ("value", dbg.string_value());
3380
3381 found_args = true;
3382 }
3383 EXPECT_TRUE(found_args);
3384 }
3385
TEST_P(PerfettoApiTest,ProtoInsideDebugAnnotation)3386 TEST_P(PerfettoApiTest, ProtoInsideDebugAnnotation) {
3387 auto* tracing_session = NewTraceWithCategories({"test"});
3388 tracing_session->get()->StartBlocking();
3389
3390 TRACE_EVENT_INSTANT(
3391 "test", "E", "key",
3392 [](perfetto::TracedProto<perfetto::protos::pbzero::LogMessage> ctx) {
3393 ctx->set_source_location_iid(42);
3394 });
3395
3396 auto trace = StopSessionAndReturnParsedTrace(tracing_session);
3397
3398 std::vector<std::string> interned_debug_annotation_names;
3399 std::vector<std::string> interned_debug_annotation_proto_type_names;
3400
3401 bool found_args = false;
3402 for (const auto& packet : trace.packet()) {
3403 if (packet.has_interned_data()) {
3404 for (const auto& interned_name :
3405 packet.interned_data().debug_annotation_names()) {
3406 interned_debug_annotation_names.push_back(interned_name.name());
3407 }
3408 for (const auto& interned_type_name :
3409 packet.interned_data().debug_annotation_value_type_names()) {
3410 interned_debug_annotation_proto_type_names.push_back(
3411 interned_type_name.name());
3412 }
3413 }
3414
3415 if (!packet.has_track_event())
3416 continue;
3417 const auto& track_event = packet.track_event();
3418 if (track_event.type() != perfetto::protos::gen::TrackEvent::TYPE_INSTANT) {
3419 continue;
3420 }
3421
3422 EXPECT_EQ(track_event.debug_annotations_size(), 1);
3423 found_args = true;
3424 }
3425 // TODO(altimin): Use DebugAnnotationParser here to parse the debug
3426 // annotations.
3427 EXPECT_TRUE(found_args);
3428 EXPECT_THAT(interned_debug_annotation_names,
3429 testing::UnorderedElementsAre("key"));
3430 EXPECT_THAT(interned_debug_annotation_proto_type_names,
3431 testing::UnorderedElementsAre(".perfetto.protos.LogMessage"));
3432 }
3433
TEST_P(PerfettoApiTest,TrackEventComputedName)3434 TEST_P(PerfettoApiTest, TrackEventComputedName) {
3435 // Setup the trace config.
3436 perfetto::TraceConfig cfg;
3437 cfg.set_duration_ms(500);
3438 cfg.add_buffers()->set_size_kb(1024);
3439 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
3440 ds_cfg->set_name("track_event");
3441
3442 // Create a new trace session.
3443 auto* tracing_session = NewTrace(cfg);
3444 tracing_session->get()->StartBlocking();
3445
3446 // New macros require perfetto::StaticString{} annotation.
3447 for (int i = 0; i < 3; i++)
3448 TRACE_EVENT_BEGIN("test", perfetto::StaticString{i % 2 ? "Odd" : "Even"});
3449
3450 // Legacy macros assume all arguments are static strings.
3451 for (int i = 0; i < 3; i++)
3452 TRACE_EVENT_BEGIN0("test", i % 2 ? "Odd" : "Even");
3453
3454 auto slices = StopSessionAndReadSlicesFromTrace(tracing_session);
3455 EXPECT_THAT(slices, ElementsAre("B:test.Even", "B:test.Odd", "B:test.Even",
3456 "B:test.Even", "B:test.Odd", "B:test.Even"));
3457 }
3458
TEST_P(PerfettoApiTest,TrackEventEventNameDynamicString)3459 TEST_P(PerfettoApiTest, TrackEventEventNameDynamicString) {
3460 // Create a new trace session.
3461 auto* tracing_session = NewTraceWithCategories({"foo"});
3462 tracing_session->get()->StartBlocking();
3463 TRACE_EVENT_BEGIN("foo", perfetto::DynamicString{std::string("Event1")});
3464 TRACE_EVENT_BEGIN("foo", perfetto::DynamicString{std::string("Event2")});
3465
3466 TRACE_EVENT0("foo", TRACE_STR_COPY(std::string("Event3")));
3467 const char* event4 = "Event4";
3468 TRACE_EVENT0("foo", event4);
3469
3470 // Ensure that event-name is not emitted in case of `_END` events.
3471 PERFETTO_INTERNAL_TRACK_EVENT(
3472 "foo", perfetto::DynamicString{std::string("Event5")},
3473 ::perfetto::protos::pbzero::TrackEvent::TYPE_SLICE_END);
3474 PERFETTO_INTERNAL_TRACK_EVENT(
3475 "foo", "Event6", ::perfetto::protos::pbzero::TrackEvent::TYPE_SLICE_END);
3476
3477 auto slices = StopSessionAndReadSlicesFromTrace(tracing_session);
3478 ASSERT_EQ(6u, slices.size());
3479 EXPECT_EQ("B:foo.Event1", slices[0]);
3480 EXPECT_EQ("B:foo.Event2", slices[1]);
3481 EXPECT_EQ("B:foo.Event3", slices[2]);
3482 EXPECT_EQ("B:foo.Event4", slices[3]);
3483 EXPECT_EQ("E", slices[4]);
3484 EXPECT_EQ("E", slices[5]);
3485 }
3486
TEST_P(PerfettoApiTest,TrackEventDynamicStringInDebugArgs)3487 TEST_P(PerfettoApiTest, TrackEventDynamicStringInDebugArgs) {
3488 auto* tracing_session = NewTraceWithCategories({"foo"});
3489 tracing_session->get()->StartBlocking();
3490
3491 TRACE_EVENT1("foo", "Event1", "arg1",
3492 TRACE_STR_COPY(std::string("arg1_value1")));
3493 const char* value2 = "arg1_value2";
3494 TRACE_EVENT1("foo", "Event2", "arg1", value2);
3495 const char* value4 = "arg1_value4";
3496 TRACE_EVENT1("foo", "Event3", "arg1",
3497 perfetto::DynamicString(std::string("arg1_value3")));
3498 TRACE_EVENT1("foo", "Event4", "arg1", perfetto::StaticString(value4));
3499
3500 TRACE_EVENT_BEGIN("foo", "Event5", "arg1",
3501 TRACE_STR_COPY(std::string("arg1_value5")));
3502 TRACE_EVENT_BEGIN("foo", "Event6", "arg1",
3503 perfetto::DynamicString(std::string("arg1_value6")));
3504 const char* value7 = "arg1_value7";
3505 TRACE_EVENT_BEGIN("foo", "Event7", "arg1", perfetto::StaticString(value7));
3506 const char* arg_name = "new_arg1";
3507 TRACE_EVENT_BEGIN("foo", "Event8", perfetto::DynamicString{arg_name}, 5);
3508
3509 auto slices = StopSessionAndReadSlicesFromTrace(tracing_session);
3510 ASSERT_EQ(8u, slices.size());
3511 EXPECT_EQ("B:foo.Event1(arg1=(string)arg1_value1)", slices[0]);
3512 EXPECT_EQ("B:foo.Event2(arg1=(string)arg1_value2)", slices[1]);
3513 EXPECT_EQ("B:foo.Event3(arg1=(string)arg1_value3)", slices[2]);
3514 EXPECT_EQ("B:foo.Event4(arg1=(string)arg1_value4)", slices[3]);
3515 EXPECT_EQ("B:foo.Event5(arg1=(string)arg1_value5)", slices[4]);
3516 EXPECT_EQ("B:foo.Event6(arg1=(string)arg1_value6)", slices[5]);
3517 EXPECT_EQ("B:foo.Event7(arg1=(string)arg1_value7)", slices[6]);
3518 EXPECT_EQ("B:foo.Event8(new_arg1=(int)5)", slices[7]);
3519 }
3520
TEST_P(PerfettoApiTest,TrackEventLegacyNullStringInArgs)3521 TEST_P(PerfettoApiTest, TrackEventLegacyNullStringInArgs) {
3522 auto* tracing_session = NewTraceWithCategories({"foo"});
3523 tracing_session->get()->StartBlocking();
3524
3525 const char* null_str = nullptr;
3526
3527 TRACE_EVENT1("foo", "Event1", "arg1", null_str);
3528 TRACE_EVENT1("foo", "Event2", "arg1", TRACE_STR_COPY(null_str));
3529
3530 auto slices = StopSessionAndReadSlicesFromTrace(tracing_session);
3531 ASSERT_EQ(2u, slices.size());
3532 EXPECT_EQ("B:foo.Event1(arg1=(string)NULL)", slices[0]);
3533 EXPECT_EQ("B:foo.Event2(arg1=(string)NULL)", slices[1]);
3534 }
3535
TEST_P(PerfettoApiTest,FilterDynamicEventName)3536 TEST_P(PerfettoApiTest, FilterDynamicEventName) {
3537 for (auto filter_dynamic_names : {false, true}) {
3538 // Create a new trace session.
3539 perfetto::protos::gen::TrackEventConfig te_cfg;
3540 te_cfg.set_filter_dynamic_event_names(filter_dynamic_names);
3541 auto* tracing_session = NewTraceWithCategories({"test"}, te_cfg);
3542 tracing_session->get()->StartBlocking();
3543
3544 TRACE_EVENT_BEGIN("test", "Event1");
3545 TRACE_EVENT_BEGIN("test", perfetto::DynamicString("Event2"));
3546 const char* event3 = "Event3";
3547 TRACE_EVENT_BEGIN("test", perfetto::StaticString(event3));
3548 auto slices = StopSessionAndReadSlicesFromTrace(tracing_session);
3549 ASSERT_EQ(3u, slices.size());
3550 EXPECT_EQ("B:test.Event1", slices[0]);
3551 EXPECT_EQ(filter_dynamic_names ? "B:test" : "B:test.Event2", slices[1]);
3552 EXPECT_EQ("B:test.Event3", slices[2]);
3553 }
3554 }
3555
TEST_P(PerfettoApiTest,TrackEventArgumentsNotEvaluatedWhenDisabled)3556 TEST_P(PerfettoApiTest, TrackEventArgumentsNotEvaluatedWhenDisabled) {
3557 // Create a new trace session.
3558 auto* tracing_session = NewTraceWithCategories({"foo"});
3559 tracing_session->get()->StartBlocking();
3560
3561 bool called = false;
3562 auto ArgumentFunction = [&] {
3563 called = true;
3564 return 123;
3565 };
3566
3567 TRACE_EVENT_BEGIN("test", "DisabledEvent", "arg", ArgumentFunction());
3568 { TRACE_EVENT("test", "DisabledScopedEvent", "arg", ArgumentFunction()); }
3569 perfetto::TrackEvent::Flush();
3570
3571 tracing_session->get()->StopBlocking();
3572 EXPECT_FALSE(called);
3573
3574 ArgumentFunction();
3575 EXPECT_TRUE(called);
3576 }
3577
TEST_P(PerfettoApiTest,TrackEventConfig)3578 TEST_P(PerfettoApiTest, TrackEventConfig) {
3579 auto check_config = [&](perfetto::protos::gen::TrackEventConfig te_cfg) {
3580 perfetto::TraceConfig cfg;
3581 cfg.set_duration_ms(500);
3582 cfg.add_buffers()->set_size_kb(1024);
3583 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
3584 ds_cfg->set_name("track_event");
3585 ds_cfg->set_track_event_config_raw(te_cfg.SerializeAsString());
3586
3587 auto* tracing_session = NewTrace(cfg);
3588 tracing_session->get()->StartBlocking();
3589
3590 TRACE_EVENT_BEGIN("foo", "FooEvent");
3591 TRACE_EVENT_BEGIN("bar", "BarEvent");
3592 TRACE_EVENT_BEGIN("foo,bar", "MultiFooBar");
3593 TRACE_EVENT_BEGIN("baz,bar,quux", "MultiBar");
3594 TRACE_EVENT_BEGIN("red,green,blue,foo", "MultiFoo");
3595 TRACE_EVENT_BEGIN("red,green,blue,yellow", "MultiNone");
3596 TRACE_EVENT_BEGIN("cat", "SlowEvent");
3597 TRACE_EVENT_BEGIN("cat.verbose", "DebugEvent");
3598 TRACE_EVENT_BEGIN("test", "TagEvent");
3599 TRACE_EVENT_BEGIN(TRACE_DISABLED_BY_DEFAULT("cat"), "SlowDisabledEvent");
3600 TRACE_EVENT_BEGIN("dynamic,foo", "DynamicGroupFooEvent");
3601 perfetto::DynamicCategory dyn{"dynamic,bar"};
3602 TRACE_EVENT_BEGIN(dyn, "DynamicGroupBarEvent");
3603
3604 auto slices = StopSessionAndReadSlicesFromTrace(tracing_session);
3605 tracing_session->session.reset();
3606 return slices;
3607 };
3608
3609 // Empty config should enable all categories except slow ones.
3610 {
3611 perfetto::protos::gen::TrackEventConfig te_cfg;
3612 auto slices = check_config(te_cfg);
3613 EXPECT_THAT(
3614 slices,
3615 ElementsAre("B:foo.FooEvent", "B:bar.BarEvent", "B:foo,bar.MultiFooBar",
3616 "B:baz,bar,quux.MultiBar", "B:red,green,blue,foo.MultiFoo",
3617 "B:red,green,blue,yellow.MultiNone", "B:test.TagEvent",
3618 "B:$dynamic,$foo.DynamicGroupFooEvent",
3619 "B:$dynamic,$bar.DynamicGroupBarEvent"));
3620 }
3621
3622 // Enable exactly one category.
3623 {
3624 perfetto::protos::gen::TrackEventConfig te_cfg;
3625 te_cfg.add_disabled_categories("*");
3626 te_cfg.add_enabled_categories("foo");
3627 auto slices = check_config(te_cfg);
3628 EXPECT_THAT(slices, ElementsAre("B:foo.FooEvent", "B:foo,bar.MultiFooBar",
3629 "B:red,green,blue,foo.MultiFoo",
3630 "B:$dynamic,$foo.DynamicGroupFooEvent"));
3631 }
3632
3633 // Enable exactly one dynamic category.
3634 {
3635 perfetto::protos::gen::TrackEventConfig te_cfg;
3636 te_cfg.add_disabled_categories("*");
3637 te_cfg.add_enabled_categories("dynamic");
3638 auto slices = check_config(te_cfg);
3639 EXPECT_THAT(slices, ElementsAre("B:$dynamic,$foo.DynamicGroupFooEvent",
3640 "B:$dynamic,$bar.DynamicGroupBarEvent"));
3641 }
3642
3643 // Enable two categories.
3644 {
3645 perfetto::protos::gen::TrackEventConfig te_cfg;
3646 te_cfg.add_disabled_categories("*");
3647 te_cfg.add_enabled_categories("foo");
3648 te_cfg.add_enabled_categories("baz");
3649 te_cfg.add_enabled_categories("bar");
3650 auto slices = check_config(te_cfg);
3651 EXPECT_THAT(
3652 slices,
3653 ElementsAre("B:foo.FooEvent", "B:bar.BarEvent", "B:foo,bar.MultiFooBar",
3654 "B:baz,bar,quux.MultiBar", "B:red,green,blue,foo.MultiFoo",
3655 "B:$dynamic,$foo.DynamicGroupFooEvent",
3656 "B:$dynamic,$bar.DynamicGroupBarEvent"));
3657 }
3658
3659 // Enabling all categories with a pattern doesn't enable slow ones.
3660 {
3661 perfetto::protos::gen::TrackEventConfig te_cfg;
3662 te_cfg.add_enabled_categories("*");
3663 auto slices = check_config(te_cfg);
3664 EXPECT_THAT(
3665 slices,
3666 ElementsAre("B:foo.FooEvent", "B:bar.BarEvent", "B:foo,bar.MultiFooBar",
3667 "B:baz,bar,quux.MultiBar", "B:red,green,blue,foo.MultiFoo",
3668 "B:red,green,blue,yellow.MultiNone", "B:test.TagEvent",
3669 "B:$dynamic,$foo.DynamicGroupFooEvent",
3670 "B:$dynamic,$bar.DynamicGroupBarEvent"));
3671 }
3672
3673 // Enable with a pattern.
3674 {
3675 perfetto::protos::gen::TrackEventConfig te_cfg;
3676 te_cfg.add_disabled_categories("*");
3677 te_cfg.add_enabled_categories("fo*");
3678 auto slices = check_config(te_cfg);
3679 EXPECT_THAT(slices, ElementsAre("B:foo.FooEvent", "B:foo,bar.MultiFooBar",
3680 "B:red,green,blue,foo.MultiFoo",
3681 "B:$dynamic,$foo.DynamicGroupFooEvent"));
3682 }
3683
3684 // Enable with a tag.
3685 {
3686 perfetto::protos::gen::TrackEventConfig te_cfg;
3687 te_cfg.add_disabled_categories("*");
3688 te_cfg.add_enabled_tags("tag");
3689 auto slices = check_config(te_cfg);
3690 EXPECT_THAT(slices, ElementsAre("B:test.TagEvent"));
3691 }
3692
3693 // Enable just slow categories.
3694 {
3695 perfetto::protos::gen::TrackEventConfig te_cfg;
3696 te_cfg.add_disabled_categories("*");
3697 te_cfg.add_enabled_tags("slow");
3698 auto slices = check_config(te_cfg);
3699 EXPECT_THAT(slices,
3700 ElementsAre("B:cat.SlowEvent",
3701 "B:disabled-by-default-cat.SlowDisabledEvent"));
3702 }
3703
3704 // Enable all legacy disabled-by-default categories by a pattern
3705 {
3706 perfetto::protos::gen::TrackEventConfig te_cfg;
3707 te_cfg.add_disabled_categories("*");
3708 te_cfg.add_enabled_categories("disabled-by-default-*");
3709 auto slices = check_config(te_cfg);
3710 EXPECT_THAT(slices,
3711 ElementsAre("B:disabled-by-default-cat.SlowDisabledEvent"));
3712 }
3713
3714 // Enable everything including slow/debug categories.
3715 {
3716 perfetto::protos::gen::TrackEventConfig te_cfg;
3717 te_cfg.add_enabled_categories("*");
3718 te_cfg.add_enabled_tags("slow");
3719 te_cfg.add_enabled_tags("debug");
3720 auto slices = check_config(te_cfg);
3721 EXPECT_THAT(
3722 slices,
3723 ElementsAre("B:foo.FooEvent", "B:bar.BarEvent", "B:foo,bar.MultiFooBar",
3724 "B:baz,bar,quux.MultiBar", "B:red,green,blue,foo.MultiFoo",
3725 "B:red,green,blue,yellow.MultiNone", "B:cat.SlowEvent",
3726 "B:cat.verbose.DebugEvent", "B:test.TagEvent",
3727 "B:disabled-by-default-cat.SlowDisabledEvent",
3728 "B:$dynamic,$foo.DynamicGroupFooEvent",
3729 "B:$dynamic,$bar.DynamicGroupBarEvent"));
3730 }
3731 }
3732
TEST_P(PerfettoApiTest,OneDataSourceOneEvent)3733 TEST_P(PerfettoApiTest, OneDataSourceOneEvent) {
3734 auto* data_source = &data_sources_["my_data_source"];
3735
3736 // Setup the trace config.
3737 perfetto::TraceConfig cfg;
3738 cfg.set_duration_ms(500);
3739 cfg.add_buffers()->set_size_kb(1024);
3740 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
3741 ds_cfg->set_name("my_data_source");
3742 ds_cfg->set_legacy_config("test config");
3743
3744 // Create a new trace session.
3745 auto* tracing_session = NewTrace(cfg);
3746
3747 MockDataSource::Trace([](MockDataSource::TraceContext) {
3748 FAIL() << "Should not be called because the trace was not started";
3749 });
3750 MockDataSource::CallIfEnabled([](uint32_t) {
3751 FAIL() << "Should not be called because the trace was not started";
3752 });
3753
3754 tracing_session->get()->Start();
3755 data_source->on_setup.Wait();
3756 EXPECT_EQ(data_source->config.legacy_config(), "test config");
3757 data_source->on_start.Wait();
3758
3759 // Emit one trace event.
3760 std::atomic<int> trace_lambda_calls{0};
3761 MockDataSource::Trace(
3762 [&trace_lambda_calls](MockDataSource::TraceContext ctx) {
3763 auto packet = ctx.NewTracePacket();
3764 packet->set_timestamp(42);
3765 packet->set_for_testing()->set_str("event 1");
3766 trace_lambda_calls++;
3767 packet->Finalize();
3768
3769 // The SMB scraping logic will skip the last packet because it cannot
3770 // guarantee it's finalized. Create an empty packet so we get the
3771 // previous one and this empty one is ignored.
3772 packet = ctx.NewTracePacket();
3773 });
3774
3775 uint32_t active_instances = 0;
3776 MockDataSource::CallIfEnabled([&active_instances](uint32_t instances) {
3777 active_instances = instances;
3778 });
3779 EXPECT_EQ(1u, active_instances);
3780
3781 data_source->on_stop.Wait();
3782 tracing_session->on_stop.Wait();
3783 EXPECT_EQ(trace_lambda_calls, 1);
3784
3785 MockDataSource::Trace([](MockDataSource::TraceContext) {
3786 FAIL() << "Should not be called because the trace is now stopped";
3787 });
3788 MockDataSource::CallIfEnabled([](uint32_t) {
3789 FAIL() << "Should not be called because the trace is now stopped";
3790 });
3791
3792 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
3793 ASSERT_GE(raw_trace.size(), 0u);
3794
3795 perfetto::protos::gen::Trace trace;
3796 ASSERT_TRUE(trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
3797 bool test_packet_found = false;
3798 for (const auto& packet : trace.packet()) {
3799 if (!packet.has_for_testing())
3800 continue;
3801 EXPECT_FALSE(test_packet_found);
3802 EXPECT_EQ(packet.timestamp(), 42U);
3803 EXPECT_EQ(packet.for_testing().str(), "event 1");
3804 test_packet_found = true;
3805 }
3806 EXPECT_TRUE(test_packet_found);
3807 }
3808
TEST_P(PerfettoApiTest,ReentrantTracing)3809 TEST_P(PerfettoApiTest, ReentrantTracing) {
3810 auto* data_source = &data_sources_["my_data_source"];
3811
3812 // Setup the trace config.
3813 perfetto::TraceConfig cfg;
3814 cfg.set_duration_ms(500);
3815 cfg.add_buffers()->set_size_kb(1024);
3816 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
3817 ds_cfg->set_name("my_data_source");
3818
3819 // Create a new trace session.
3820 auto* tracing_session = NewTrace(cfg);
3821 tracing_session->get()->Start();
3822 data_source->on_start.Wait();
3823
3824 // Check that only one level of trace lambda calls is allowed.
3825 std::atomic<int> trace_lambda_calls{0};
3826 MockDataSource::Trace([&trace_lambda_calls](MockDataSource::TraceContext) {
3827 trace_lambda_calls++;
3828 MockDataSource::Trace([&trace_lambda_calls](MockDataSource::TraceContext) {
3829 trace_lambda_calls++;
3830 });
3831 });
3832
3833 tracing_session->get()->StopBlocking();
3834 EXPECT_EQ(trace_lambda_calls, 1);
3835 }
3836
TEST_P(PerfettoApiTest,ConsumerFlush)3837 TEST_P(PerfettoApiTest, ConsumerFlush) {
3838 auto* data_source = &data_sources_["my_data_source"];
3839
3840 // Setup the trace config.
3841 perfetto::TraceConfig cfg;
3842 cfg.add_buffers()->set_size_kb(1024);
3843 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
3844 ds_cfg->set_name("my_data_source");
3845 ds_cfg->set_legacy_config("test config");
3846
3847 // Create a new trace session.
3848 auto* tracing_session = NewTrace(cfg);
3849
3850 tracing_session->get()->Start();
3851 data_source->on_start.Wait();
3852
3853 MockDataSource::Trace([&](MockDataSource::TraceContext ctx) {
3854 auto packet = ctx.NewTracePacket();
3855 packet->set_timestamp(42);
3856 packet->set_for_testing()->set_str("flushed event");
3857 packet->Finalize();
3858
3859 // The SMB scraping logic will skip the last packet because it cannot
3860 // guarantee it's finalized. Create an empty packet so we get the
3861 // previous one and this empty one is ignored.
3862 packet = ctx.NewTracePacket();
3863 });
3864
3865 auto trace = StopSessionAndReturnParsedTrace(tracing_session);
3866
3867 bool test_packet_found = false;
3868 for (const auto& packet : trace.packet()) {
3869 if (!packet.has_for_testing())
3870 continue;
3871 EXPECT_FALSE(test_packet_found);
3872 EXPECT_EQ(packet.timestamp(), 42U);
3873 EXPECT_EQ(packet.for_testing().str(), "flushed event");
3874 test_packet_found = true;
3875 }
3876 EXPECT_TRUE(test_packet_found);
3877 }
3878
TEST_P(PerfettoApiTest,WithBatching)3879 TEST_P(PerfettoApiTest, WithBatching) {
3880 auto* data_source = &data_sources_["my_data_source"];
3881
3882 // Setup the trace config.
3883 perfetto::TraceConfig cfg;
3884 cfg.set_duration_ms(500);
3885 cfg.add_buffers()->set_size_kb(1024);
3886 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
3887 ds_cfg->set_name("my_data_source");
3888 ds_cfg->set_legacy_config("test config");
3889
3890 // Create a new trace session.
3891 auto* tracing_session = NewTrace(cfg);
3892
3893 tracing_session->get()->Start();
3894 data_source->on_setup.Wait();
3895 data_source->on_start.Wait();
3896
3897 std::stringstream first_large_message;
3898 for (size_t i = 0; i < 512; i++)
3899 first_large_message << i << ". Something wicked this way comes. ";
3900 auto first_large_message_str = first_large_message.str();
3901
3902 // Emit one trace event before we begin batching.
3903 MockDataSource::Trace(
3904 [&first_large_message_str](MockDataSource::TraceContext ctx) {
3905 auto packet = ctx.NewTracePacket();
3906 packet->set_timestamp(42);
3907 packet->set_for_testing()->set_str(first_large_message_str);
3908 packet->Finalize();
3909 });
3910
3911 // Simulate the start of a batching cycle by first setting the batching period
3912 // to a very large value and then force-flushing when we are done writing
3913 // data.
3914 ASSERT_TRUE(
3915 perfetto::test::EnableDirectSMBPatching(/*BackendType=*/GetParam()));
3916 perfetto::test::SetBatchCommitsDuration(UINT32_MAX,
3917 /*BackendType=*/GetParam());
3918
3919 std::stringstream second_large_message;
3920 for (size_t i = 0; i < 512; i++)
3921 second_large_message << i << ". Something else wicked this way comes. ";
3922 auto second_large_message_str = second_large_message.str();
3923
3924 // Emit another trace event.
3925 MockDataSource::Trace(
3926 [&second_large_message_str](MockDataSource::TraceContext ctx) {
3927 auto packet = ctx.NewTracePacket();
3928 packet->set_timestamp(43);
3929 packet->set_for_testing()->set_str(second_large_message_str);
3930 packet->Finalize();
3931
3932 // Simulate the end of the batching cycle.
3933 ctx.Flush();
3934 });
3935
3936 data_source->on_stop.Wait();
3937 tracing_session->on_stop.Wait();
3938
3939 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
3940 ASSERT_GE(raw_trace.size(), 0u);
3941
3942 perfetto::protos::gen::Trace trace;
3943 ASSERT_TRUE(trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
3944 bool test_packet_1_found = false;
3945 bool test_packet_2_found = false;
3946 for (const auto& packet : trace.packet()) {
3947 if (!packet.has_for_testing())
3948 continue;
3949 EXPECT_TRUE(packet.timestamp() == 42U || packet.timestamp() == 43U);
3950 if (packet.timestamp() == 42U) {
3951 EXPECT_FALSE(test_packet_1_found);
3952 EXPECT_EQ(packet.for_testing().str(), first_large_message_str);
3953 test_packet_1_found = true;
3954 } else {
3955 EXPECT_FALSE(test_packet_2_found);
3956 EXPECT_EQ(packet.for_testing().str(), second_large_message_str);
3957 test_packet_2_found = true;
3958 }
3959 }
3960 EXPECT_TRUE(test_packet_1_found && test_packet_2_found);
3961 }
3962
TEST_P(PerfettoApiTest,BlockingStartAndStop)3963 TEST_P(PerfettoApiTest, BlockingStartAndStop) {
3964 auto* data_source = &data_sources_["my_data_source"];
3965
3966 // Register a second data source to get a bit more coverage.
3967 perfetto::DataSourceDescriptor dsd;
3968 dsd.set_name("my_data_source2");
3969 MockDataSource2::Register(dsd, kTestDataSourceArg);
3970 perfetto::test::SyncProducers();
3971
3972 // Setup the trace config.
3973 perfetto::TraceConfig cfg;
3974 cfg.set_duration_ms(500);
3975 cfg.add_buffers()->set_size_kb(1024);
3976 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
3977 ds_cfg->set_name("my_data_source");
3978 ds_cfg = cfg.add_data_sources()->mutable_config();
3979 ds_cfg->set_name("my_data_source2");
3980
3981 // Create a new trace session.
3982 auto* tracing_session = NewTrace(cfg);
3983
3984 tracing_session->get()->StartBlocking();
3985 EXPECT_TRUE(data_source->on_setup.notified());
3986 EXPECT_TRUE(data_source->on_start.notified());
3987
3988 tracing_session->get()->StopBlocking();
3989 EXPECT_TRUE(data_source->on_stop.notified());
3990 EXPECT_TRUE(tracing_session->on_stop.notified());
3991 perfetto::test::TracingMuxerImplInternalsForTest::
3992 ClearDataSourceTlsStateOnReset<MockDataSource2>();
3993 }
3994
TEST_P(PerfettoApiTest,BlockingStartAndStopOnEmptySession)3995 TEST_P(PerfettoApiTest, BlockingStartAndStopOnEmptySession) {
3996 // Setup the trace config.
3997 perfetto::TraceConfig cfg;
3998 cfg.set_duration_ms(500);
3999 cfg.add_buffers()->set_size_kb(1024);
4000 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
4001 ds_cfg->set_name("non_existent_data_source");
4002
4003 // Create a new trace session.
4004 auto* tracing_session = NewTrace(cfg);
4005 tracing_session->get()->StartBlocking();
4006 tracing_session->get()->StopBlocking();
4007 EXPECT_TRUE(tracing_session->on_stop.notified());
4008 }
4009
TEST_P(PerfettoApiTest,WriteEventsAfterDeferredStop)4010 TEST_P(PerfettoApiTest, WriteEventsAfterDeferredStop) {
4011 auto* data_source = &data_sources_["my_data_source"];
4012 data_source->handle_stop_asynchronously = true;
4013
4014 // Setup the trace config and start the tracing session.
4015 perfetto::TraceConfig cfg;
4016 cfg.set_duration_ms(500);
4017 cfg.add_buffers()->set_size_kb(1024);
4018 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
4019 ds_cfg->set_name("my_data_source");
4020 auto* tracing_session = NewTrace(cfg);
4021 tracing_session->get()->StartBlocking();
4022
4023 // Stop and wait for the producer to have seen the stop event.
4024 WaitableTestEvent consumer_stop_signal;
4025 tracing_session->get()->SetOnStopCallback(
4026 [&consumer_stop_signal] { consumer_stop_signal.Notify(); });
4027 tracing_session->get()->Stop();
4028 data_source->on_stop.Wait();
4029
4030 // At this point tracing should be still allowed because of the
4031 // HandleStopAsynchronously() call.
4032 bool lambda_called = false;
4033
4034 // This usleep is here just to prevent that we accidentally pass the test
4035 // just by virtue of hitting some race. We should be able to trace up until
4036 // 5 seconds after seeing the stop when using the deferred stop mechanism.
4037 std::this_thread::sleep_for(std::chrono::milliseconds(250));
4038
4039 MockDataSource::Trace([&lambda_called](MockDataSource::TraceContext ctx) {
4040 auto packet = ctx.NewTracePacket();
4041 packet->set_for_testing()->set_str("event written after OnStop");
4042 packet->Finalize();
4043 ctx.Flush();
4044 lambda_called = true;
4045 });
4046 ASSERT_TRUE(lambda_called);
4047
4048 // Now call the async stop closure. This acks the stop to the service and
4049 // disallows further Trace() calls.
4050 EXPECT_TRUE(data_source->async_stop_closure);
4051 data_source->async_stop_closure();
4052
4053 // Wait that the stop is propagated to the consumer.
4054 consumer_stop_signal.Wait();
4055
4056 MockDataSource::Trace([](MockDataSource::TraceContext) {
4057 FAIL() << "Should not be called after the stop is acked";
4058 });
4059
4060 // Check the contents of the trace.
4061 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
4062 ASSERT_GE(raw_trace.size(), 0u);
4063 perfetto::protos::gen::Trace trace;
4064 ASSERT_TRUE(trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
4065 int test_packet_found = 0;
4066 for (const auto& packet : trace.packet()) {
4067 if (!packet.has_for_testing())
4068 continue;
4069 EXPECT_EQ(packet.for_testing().str(), "event written after OnStop");
4070 test_packet_found++;
4071 }
4072 EXPECT_EQ(test_packet_found, 1);
4073 }
4074
TEST_P(PerfettoApiTest,RepeatedStartAndStop)4075 TEST_P(PerfettoApiTest, RepeatedStartAndStop) {
4076 perfetto::TraceConfig cfg;
4077 cfg.set_duration_ms(500);
4078 cfg.add_buffers()->set_size_kb(1024);
4079 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
4080 ds_cfg->set_name("my_data_source");
4081
4082 for (int i = 0; i < 5; i++) {
4083 auto* tracing_session = NewTrace(cfg);
4084 tracing_session->get()->Start();
4085 std::atomic<bool> stop_called{false};
4086 tracing_session->get()->SetOnStopCallback(
4087 [&stop_called] { stop_called = true; });
4088 tracing_session->get()->StopBlocking();
4089 EXPECT_TRUE(stop_called);
4090 }
4091 }
4092
TEST_P(PerfettoApiTest,SetupWithFile)4093 TEST_P(PerfettoApiTest, SetupWithFile) {
4094 #if PERFETTO_BUILDFLAG(PERFETTO_OS_WIN)
4095 if (GetParam() == perfetto::kSystemBackend)
4096 GTEST_SKIP() << "write_into_file + system mode is not supported on Windows";
4097 #endif
4098 auto temp_file = perfetto::test::CreateTempFile();
4099 perfetto::TraceConfig cfg;
4100 cfg.set_duration_ms(500);
4101 cfg.add_buffers()->set_size_kb(1024);
4102 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
4103 ds_cfg->set_name("my_data_source");
4104 // Write a trace into |fd|.
4105 auto* tracing_session = NewTrace(cfg, temp_file.fd);
4106 tracing_session->get()->StartBlocking();
4107 tracing_session->get()->StopBlocking();
4108 #if !PERFETTO_BUILDFLAG(PERFETTO_OS_WIN)
4109 // Check that |fd| didn't get closed.
4110 EXPECT_EQ(0, fcntl(temp_file.fd, F_GETFD, 0));
4111 #endif
4112 // Check that the trace got written.
4113 EXPECT_GT(lseek(temp_file.fd, 0, SEEK_END), 0);
4114 EXPECT_EQ(0, close(temp_file.fd));
4115 // Clean up.
4116 EXPECT_EQ(0, remove(temp_file.path.c_str()));
4117 }
4118
TEST_P(PerfettoApiTest,MultipleRegistrations)4119 TEST_P(PerfettoApiTest, MultipleRegistrations) {
4120 // Attempt to register the same data source again.
4121 perfetto::DataSourceDescriptor dsd;
4122 dsd.set_name("my_data_source");
4123 EXPECT_TRUE(MockDataSource::Register(dsd));
4124 perfetto::test::SyncProducers();
4125
4126 // Setup the trace config.
4127 perfetto::TraceConfig cfg;
4128 cfg.set_duration_ms(500);
4129 cfg.add_buffers()->set_size_kb(1024);
4130 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
4131 ds_cfg->set_name("my_data_source");
4132
4133 // Create a new trace session.
4134 auto* tracing_session = NewTrace(cfg);
4135 tracing_session->get()->StartBlocking();
4136
4137 // Emit one trace event.
4138 std::atomic<int> trace_lambda_calls{0};
4139 MockDataSource::Trace([&trace_lambda_calls](MockDataSource::TraceContext) {
4140 trace_lambda_calls++;
4141 });
4142
4143 // Make sure the data source got called only once.
4144 tracing_session->get()->StopBlocking();
4145 EXPECT_EQ(trace_lambda_calls, 1);
4146 }
4147
TEST_P(PerfettoApiTest,CustomIncrementalState)4148 TEST_P(PerfettoApiTest, CustomIncrementalState) {
4149 perfetto::DataSourceDescriptor dsd;
4150 dsd.set_name("incr_data_source");
4151 TestIncrementalDataSource::Register(dsd);
4152 perfetto::test::SyncProducers();
4153
4154 // Setup the trace config.
4155 perfetto::TraceConfig cfg;
4156 cfg.set_duration_ms(500);
4157 cfg.add_buffers()->set_size_kb(1024);
4158 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
4159 ds_cfg->set_name("incr_data_source");
4160
4161 // Create a new trace session.
4162 auto* tracing_session = NewTrace(cfg);
4163 tracing_session->get()->StartBlocking();
4164
4165 // First emit a no-op trace event that initializes the incremental state as a
4166 // side effect.
4167 TestIncrementalDataSource::Trace(
4168 [](TestIncrementalDataSource::TraceContext) {});
4169 EXPECT_TRUE(TestIncrementalState::constructed);
4170
4171 // Check that the incremental state is carried across trace events.
4172 TestIncrementalDataSource::Trace(
4173 [](TestIncrementalDataSource::TraceContext ctx) {
4174 auto* state = ctx.GetIncrementalState();
4175 EXPECT_TRUE(state);
4176 EXPECT_EQ(100, state->count);
4177 state->count++;
4178 });
4179
4180 TestIncrementalDataSource::Trace(
4181 [](TestIncrementalDataSource::TraceContext ctx) {
4182 auto* state = ctx.GetIncrementalState();
4183 EXPECT_EQ(101, state->count);
4184 });
4185
4186 // Make sure the incremental state gets cleaned up between sessions.
4187 tracing_session->get()->StopBlocking();
4188 tracing_session = NewTrace(cfg);
4189 tracing_session->get()->StartBlocking();
4190 TestIncrementalDataSource::Trace(
4191 [](TestIncrementalDataSource::TraceContext ctx) {
4192 auto* state = ctx.GetIncrementalState();
4193 EXPECT_TRUE(TestIncrementalState::destroyed);
4194 EXPECT_TRUE(state);
4195 EXPECT_EQ(100, state->count);
4196 });
4197 tracing_session->get()->StopBlocking();
4198 perfetto::test::TracingMuxerImplInternalsForTest::
4199 ClearDataSourceTlsStateOnReset<TestIncrementalDataSource>();
4200 }
4201
TEST_P(PerfettoApiTest,OnFlush)4202 TEST_P(PerfettoApiTest, OnFlush) {
4203 auto* data_source = &data_sources_["my_data_source"];
4204
4205 // Setup the trace config.
4206 perfetto::TraceConfig cfg;
4207 cfg.add_buffers()->set_size_kb(1024);
4208 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
4209 ds_cfg->set_name("my_data_source");
4210
4211 // Create a new trace session.
4212 auto* tracing_session = NewTrace(cfg);
4213
4214 tracing_session->get()->StartBlocking();
4215
4216 WaitableTestEvent producer_on_flush;
4217 WaitableTestEvent consumer_flush_done;
4218
4219 data_source->on_flush_callback = [&] {
4220 EXPECT_FALSE(consumer_flush_done.notified());
4221 producer_on_flush.Notify();
4222 MockDataSource::Trace([](MockDataSource::TraceContext ctx) {
4223 ctx.NewTracePacket()->set_for_testing()->set_str("on-flush");
4224 ctx.Flush();
4225 });
4226 };
4227
4228 tracing_session->get()->Flush([&](bool success) {
4229 EXPECT_TRUE(success);
4230 EXPECT_TRUE(producer_on_flush.notified());
4231 consumer_flush_done.Notify();
4232 });
4233
4234 producer_on_flush.Wait();
4235 consumer_flush_done.Wait();
4236
4237 tracing_session->get()->StopBlocking();
4238
4239 data_source->on_stop.Wait();
4240
4241 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
4242 ASSERT_GE(raw_trace.size(), 0u);
4243
4244 perfetto::protos::gen::Trace trace;
4245 ASSERT_TRUE(trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
4246 EXPECT_THAT(
4247 trace.packet(),
4248 Contains(Property(
4249 &perfetto::protos::gen::TracePacket::for_testing,
4250 Property(&perfetto::protos::gen::TestEvent::str, "on-flush"))));
4251 }
4252
TEST_P(PerfettoApiTest,OnFlushAsync)4253 TEST_P(PerfettoApiTest, OnFlushAsync) {
4254 auto* data_source = &data_sources_["my_data_source"];
4255
4256 // Setup the trace config.
4257 perfetto::TraceConfig cfg;
4258 cfg.add_buffers()->set_size_kb(1024);
4259 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
4260 ds_cfg->set_name("my_data_source");
4261
4262 // Create a new trace session.
4263 auto* tracing_session = NewTrace(cfg);
4264
4265 tracing_session->get()->StartBlocking();
4266
4267 WaitableTestEvent consumer_flush_done;
4268
4269 data_source->handle_flush_asynchronously = true;
4270 data_source->on_flush_callback = [&] {
4271 EXPECT_FALSE(consumer_flush_done.notified());
4272 };
4273
4274 tracing_session->get()->Flush([&](bool success) {
4275 EXPECT_TRUE(success);
4276 consumer_flush_done.Notify();
4277 });
4278
4279 data_source->on_flush.Wait();
4280 perfetto::test::SyncProducers();
4281 EXPECT_FALSE(consumer_flush_done.notified());
4282
4283 // Finish the flush asynchronously
4284 MockDataSource::Trace([](MockDataSource::TraceContext ctx) {
4285 ctx.NewTracePacket()->set_for_testing()->set_str("on-flush");
4286 ctx.Flush();
4287 });
4288 data_source->async_flush_closure();
4289
4290 consumer_flush_done.Wait();
4291
4292 tracing_session->get()->StopBlocking();
4293
4294 data_source->on_stop.Wait();
4295
4296 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
4297 ASSERT_GE(raw_trace.size(), 0u);
4298
4299 perfetto::protos::gen::Trace trace;
4300 ASSERT_TRUE(trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
4301 EXPECT_THAT(
4302 trace.packet(),
4303 Contains(Property(
4304 &perfetto::protos::gen::TracePacket::for_testing,
4305 Property(&perfetto::protos::gen::TestEvent::str, "on-flush"))));
4306 }
4307
4308 // Regression test for b/139110180. Checks that GetDataSourceLocked() can be
4309 // called from OnStart() and OnStop() callbacks without deadlocking.
TEST_P(PerfettoApiTest,GetDataSourceLockedFromCallbacks)4310 TEST_P(PerfettoApiTest, GetDataSourceLockedFromCallbacks) {
4311 auto* data_source = &data_sources_["my_data_source"];
4312
4313 // Setup the trace config.
4314 perfetto::TraceConfig cfg;
4315 cfg.set_duration_ms(1);
4316 cfg.add_buffers()->set_size_kb(1024);
4317 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
4318 ds_cfg->set_name("my_data_source");
4319
4320 // Create a new trace session.
4321 auto* tracing_session = NewTrace(cfg);
4322
4323 data_source->on_start_callback = [] {
4324 MockDataSource::Trace([](MockDataSource::TraceContext ctx) {
4325 ctx.NewTracePacket()->set_for_testing()->set_str("on-start");
4326 auto ds = ctx.GetDataSourceLocked();
4327 ASSERT_TRUE(!!ds);
4328 ctx.NewTracePacket()->set_for_testing()->set_str("on-start-locked");
4329 });
4330 };
4331
4332 data_source->on_stop_callback = [] {
4333 MockDataSource::Trace([](MockDataSource::TraceContext ctx) {
4334 ctx.NewTracePacket()->set_for_testing()->set_str("on-stop");
4335 auto ds = ctx.GetDataSourceLocked();
4336 ASSERT_TRUE(!!ds);
4337 ctx.NewTracePacket()->set_for_testing()->set_str("on-stop-locked");
4338 ctx.Flush();
4339 });
4340 };
4341
4342 tracing_session->get()->Start();
4343 data_source->on_stop.Wait();
4344 tracing_session->on_stop.Wait();
4345
4346 std::vector<char> raw_trace = tracing_session->get()->ReadTraceBlocking();
4347 ASSERT_GE(raw_trace.size(), 0u);
4348
4349 perfetto::protos::gen::Trace trace;
4350 ASSERT_TRUE(trace.ParseFromArray(raw_trace.data(), raw_trace.size()));
4351 int packets_found = 0;
4352 for (const auto& packet : trace.packet()) {
4353 if (!packet.has_for_testing())
4354 continue;
4355 packets_found |= packet.for_testing().str() == "on-start" ? 1 : 0;
4356 packets_found |= packet.for_testing().str() == "on-start-locked" ? 2 : 0;
4357 packets_found |= packet.for_testing().str() == "on-stop" ? 4 : 0;
4358 packets_found |= packet.for_testing().str() == "on-stop-locked" ? 8 : 0;
4359 }
4360 EXPECT_EQ(packets_found, 1 | 2 | 4 | 8);
4361 }
4362
TEST_P(PerfettoApiTest,OnStartCallback)4363 TEST_P(PerfettoApiTest, OnStartCallback) {
4364 perfetto::TraceConfig cfg;
4365 cfg.set_duration_ms(60000);
4366 cfg.add_buffers()->set_size_kb(1024);
4367 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
4368 ds_cfg->set_name("track_event");
4369 auto* tracing_session = NewTrace(cfg);
4370
4371 WaitableTestEvent got_start;
4372 tracing_session->get()->SetOnStartCallback([&] { got_start.Notify(); });
4373 tracing_session->get()->Start();
4374 got_start.Wait();
4375
4376 tracing_session->get()->StopBlocking();
4377 }
4378
TEST_P(PerfettoApiTest,OnErrorCallback)4379 TEST_P(PerfettoApiTest, OnErrorCallback) {
4380 perfetto::TraceConfig cfg;
4381
4382 // Requesting too long |duration_ms| will cause EnableTracing() to fail.
4383 cfg.set_duration_ms(static_cast<uint32_t>(-1));
4384 cfg.add_buffers()->set_size_kb(1024);
4385 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
4386 ds_cfg->set_name("track_event");
4387 auto* tracing_session = NewTrace(cfg);
4388
4389 WaitableTestEvent got_error;
4390 tracing_session->get()->SetOnErrorCallback([&](perfetto::TracingError error) {
4391 EXPECT_EQ(perfetto::TracingError::kTracingFailed, error.code);
4392 EXPECT_FALSE(error.message.empty());
4393 got_error.Notify();
4394 });
4395
4396 tracing_session->get()->Start();
4397 got_error.Wait();
4398
4399 // Registered error callback will be triggered also by OnDisconnect()
4400 // function. This may happen after exiting this test what would result in
4401 // system crash (|got_error| will not exist at that time). To prevent that
4402 // scenario, error callback has to be cleared.
4403 tracing_session->get()->SetOnErrorCallback(nullptr);
4404 tracing_session->get()->StopBlocking();
4405 }
4406
TEST_P(PerfettoApiTest,UnsupportedBackend)4407 TEST_P(PerfettoApiTest, UnsupportedBackend) {
4408 // Create a new trace session with an invalid backend type specified.
4409 // Specifically, the custom backend isn't initialized for these tests.
4410 perfetto::TraceConfig cfg;
4411 cfg.add_buffers()->set_size_kb(1024);
4412 auto* tracing_session = NewTrace(cfg, perfetto::BackendType::kCustomBackend);
4413
4414 // Creating the consumer should cause an asynchronous disconnect error.
4415 WaitableTestEvent got_error;
4416 tracing_session->get()->SetOnErrorCallback([&](perfetto::TracingError error) {
4417 EXPECT_EQ(perfetto::TracingError::kDisconnected, error.code);
4418 EXPECT_FALSE(error.message.empty());
4419 got_error.Notify();
4420 });
4421 got_error.Wait();
4422
4423 // Clear the callback for test tear down.
4424 tracing_session->get()->SetOnErrorCallback(nullptr);
4425 // Synchronize the consumer channel to ensure the callback has propagated.
4426 tracing_session->get()->StopBlocking();
4427 }
4428
TEST_P(PerfettoApiTest,ForbiddenConsumer)4429 TEST_P(PerfettoApiTest, ForbiddenConsumer) {
4430 g_test_tracing_policy->should_allow_consumer_connection = false;
4431
4432 // Create a new trace session while consumer connections are forbidden.
4433 perfetto::TraceConfig cfg;
4434 cfg.add_buffers()->set_size_kb(1024);
4435 auto* tracing_session = NewTrace(cfg);
4436
4437 // Creating the consumer should cause an asynchronous disconnect error.
4438 WaitableTestEvent got_error;
4439 tracing_session->get()->SetOnErrorCallback([&](perfetto::TracingError error) {
4440 EXPECT_EQ(perfetto::TracingError::kDisconnected, error.code);
4441 EXPECT_FALSE(error.message.empty());
4442 got_error.Notify();
4443 });
4444 got_error.Wait();
4445
4446 // Clear the callback for test tear down.
4447 tracing_session->get()->SetOnErrorCallback(nullptr);
4448 // Synchronize the consumer channel to ensure the callback has propagated.
4449 tracing_session->get()->StopBlocking();
4450
4451 g_test_tracing_policy->should_allow_consumer_connection = true;
4452 }
4453
TEST_P(PerfettoApiTest,GetTraceStats)4454 TEST_P(PerfettoApiTest, GetTraceStats) {
4455 perfetto::TraceConfig cfg;
4456 cfg.set_duration_ms(500);
4457 cfg.add_buffers()->set_size_kb(1024);
4458 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
4459 ds_cfg->set_name("track_event");
4460 auto* tracing_session = NewTrace(cfg);
4461 tracing_session->get()->StartBlocking();
4462
4463 // Asynchronous read.
4464 WaitableTestEvent got_stats;
4465 tracing_session->get()->GetTraceStats(
4466 [&got_stats](perfetto::TracingSession::GetTraceStatsCallbackArgs args) {
4467 perfetto::protos::gen::TraceStats trace_stats;
4468 EXPECT_TRUE(args.success);
4469 EXPECT_TRUE(trace_stats.ParseFromArray(args.trace_stats_data.data(),
4470 args.trace_stats_data.size()));
4471 EXPECT_EQ(1, trace_stats.buffer_stats_size());
4472 got_stats.Notify();
4473 });
4474 got_stats.Wait();
4475
4476 // Blocking read.
4477 auto stats = tracing_session->get()->GetTraceStatsBlocking();
4478 perfetto::protos::gen::TraceStats trace_stats;
4479 EXPECT_TRUE(stats.success);
4480 EXPECT_TRUE(trace_stats.ParseFromArray(stats.trace_stats_data.data(),
4481 stats.trace_stats_data.size()));
4482 EXPECT_EQ(1, trace_stats.buffer_stats_size());
4483
4484 tracing_session->get()->StopBlocking();
4485 }
4486
TEST_P(PerfettoApiTest,CustomDataSource)4487 TEST_P(PerfettoApiTest, CustomDataSource) {
4488 perfetto::TraceConfig cfg;
4489 cfg.add_buffers()->set_size_kb(1024);
4490 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
4491 ds_cfg->set_name("CustomDataSource");
4492 auto* tracing_session = NewTrace(cfg);
4493 tracing_session->get()->StartBlocking();
4494 CustomDataSource::Trace([](CustomDataSource::TraceContext ctx) {
4495 auto packet = ctx.NewTracePacket();
4496 packet->set_timestamp(4200000);
4497 packet->set_for_testing()->set_str("Test String");
4498 });
4499 CustomDataSource::Trace(
4500 [](CustomDataSource::TraceContext ctx) { ctx.Flush(); });
4501
4502 tracing_session->get()->StopBlocking();
4503 auto bytes = tracing_session->get()->ReadTraceBlocking();
4504 perfetto::protos::gen::Trace parsed_trace;
4505 EXPECT_TRUE(parsed_trace.ParseFromArray(bytes.data(), bytes.size()));
4506 bool found_for_testing = false;
4507 for (auto& packet : parsed_trace.packet()) {
4508 if (packet.has_for_testing()) {
4509 EXPECT_FALSE(found_for_testing);
4510 found_for_testing = true;
4511 EXPECT_EQ(4200000u, packet.timestamp());
4512 EXPECT_EQ("Test String", packet.for_testing().str());
4513 }
4514 }
4515 EXPECT_TRUE(found_for_testing);
4516 }
4517
TEST_P(PerfettoApiTest,QueryServiceState)4518 TEST_P(PerfettoApiTest, QueryServiceState) {
4519 class QueryTestDataSource : public perfetto::DataSource<QueryTestDataSource> {
4520 };
4521 RegisterDataSource<QueryTestDataSource>("query_test_data_source");
4522 perfetto::test::SyncProducers();
4523
4524 auto tracing_session =
4525 perfetto::Tracing::NewTrace(/*BackendType=*/GetParam());
4526 // Asynchronous read.
4527 WaitableTestEvent got_state;
4528 tracing_session->QueryServiceState(
4529 [&got_state](
4530 perfetto::TracingSession::QueryServiceStateCallbackArgs result) {
4531 perfetto::protos::gen::TracingServiceState state;
4532 EXPECT_TRUE(result.success);
4533 EXPECT_TRUE(state.ParseFromArray(result.service_state_data.data(),
4534 result.service_state_data.size()));
4535 EXPECT_EQ(1, state.producers_size());
4536 EXPECT_NE(std::string::npos,
4537 state.producers()[0].name().find("integrationtest"));
4538 bool found_ds = false;
4539 for (const auto& ds : state.data_sources())
4540 found_ds |= ds.ds_descriptor().name() == "query_test_data_source";
4541 EXPECT_TRUE(found_ds);
4542 got_state.Notify();
4543 });
4544 got_state.Wait();
4545
4546 // Blocking read.
4547 auto result = tracing_session->QueryServiceStateBlocking();
4548 perfetto::protos::gen::TracingServiceState state;
4549 EXPECT_TRUE(result.success);
4550 EXPECT_TRUE(state.ParseFromArray(result.service_state_data.data(),
4551 result.service_state_data.size()));
4552 EXPECT_EQ(1, state.producers_size());
4553 EXPECT_NE(std::string::npos,
4554 state.producers()[0].name().find("integrationtest"));
4555 bool found_ds = false;
4556 for (const auto& ds : state.data_sources())
4557 found_ds |= ds.ds_descriptor().name() == "query_test_data_source";
4558 EXPECT_TRUE(found_ds);
4559 perfetto::test::TracingMuxerImplInternalsForTest::
4560 ClearDataSourceTlsStateOnReset<QueryTestDataSource>();
4561 }
4562
TEST_P(PerfettoApiTest,UpdateDataSource)4563 TEST_P(PerfettoApiTest, UpdateDataSource) {
4564 class UpdateTestDataSource
4565 : public perfetto::DataSource<UpdateTestDataSource> {};
4566
4567 perfetto::DataSourceDescriptor dsd;
4568 dsd.set_name("update_test_data_source");
4569
4570 RegisterDataSource<UpdateTestDataSource>(dsd);
4571
4572 {
4573 protozero::HeapBuffered<perfetto::protos::pbzero::TrackEventDescriptor> ted;
4574 auto cat = ted->add_available_categories();
4575 cat->set_name("new_cat");
4576 dsd.set_track_event_descriptor_raw(ted.SerializeAsString());
4577 }
4578
4579 UpdateDataSource<UpdateTestDataSource>(dsd);
4580
4581 perfetto::test::SyncProducers();
4582
4583 auto tracing_session =
4584 perfetto::Tracing::NewTrace(/*BackendType=*/GetParam());
4585 // Blocking read.
4586 auto result = tracing_session->QueryServiceStateBlocking();
4587 perfetto::protos::gen::TracingServiceState state;
4588 EXPECT_TRUE(result.success);
4589 EXPECT_TRUE(state.ParseFromArray(result.service_state_data.data(),
4590 result.service_state_data.size()));
4591 EXPECT_EQ(1, state.producers_size());
4592 EXPECT_NE(std::string::npos,
4593 state.producers()[0].name().find("integrationtest"));
4594 bool found_ds = false;
4595 for (const auto& ds : state.data_sources()) {
4596 if (ds.ds_descriptor().name() == "update_test_data_source") {
4597 found_ds = true;
4598 perfetto::protos::gen::TrackEventDescriptor ted;
4599 auto desc_raw = ds.ds_descriptor().track_event_descriptor_raw();
4600 EXPECT_TRUE(ted.ParseFromArray(desc_raw.data(), desc_raw.size()));
4601 EXPECT_EQ(ted.available_categories_size(), 1);
4602 EXPECT_EQ(ted.available_categories()[0].name(), "new_cat");
4603 }
4604 }
4605 EXPECT_TRUE(found_ds);
4606 perfetto::test::TracingMuxerImplInternalsForTest::
4607 ClearDataSourceTlsStateOnReset<UpdateTestDataSource>();
4608 }
4609
TEST_P(PerfettoApiTest,LegacyTraceEventsCopyDynamicString)4610 TEST_P(PerfettoApiTest, LegacyTraceEventsCopyDynamicString) {
4611 char ptr1[] = "A1";
4612 char ptr2[] = "B1";
4613 char arg_name1[] = "C1";
4614 char arg_name2[] = "D1";
4615 auto* tracing_session = NewTraceWithCategories({"cat"});
4616 tracing_session->get()->StartBlocking();
4617 {
4618 TRACE_EVENT_MARK_WITH_TIMESTAMP0("cat", ptr1, MyTimestamp{0});
4619 ptr1[1] = '3';
4620 // Old value of event name ("A1") is recorded here in trace.
4621 // The reason being, in legacy macros, event name was expected to be static
4622 // by default unless `_COPY` version of these macro is used.
4623 // Perfetto is caching pointer values and if a event-name-pointer matches an
4624 // existing pointer, it ASSUMES the string-value of new pointer is same as
4625 // string-value of the cached pointer when it was cached.
4626 // and hence it assign the same intern-id to second event.
4627 TRACE_EVENT_MARK_WITH_TIMESTAMP0("cat", ptr1, MyTimestamp{0});
4628 }
4629 {
4630 TRACE_EVENT_COPY_MARK_WITH_TIMESTAMP("cat", ptr2, MyTimestamp{0});
4631 ptr2[1] = '4';
4632 TRACE_EVENT_COPY_MARK_WITH_TIMESTAMP("cat", ptr2, MyTimestamp{0});
4633 }
4634 {
4635 TRACE_EVENT_INSTANT1("cat", "event_name", TRACE_EVENT_FLAG_NONE, arg_name1,
4636 /*arg_value=*/5);
4637 arg_name1[1] = '5';
4638 // Since we don't use the _COPY version here, this event will record the old
4639 // value of arg_name1 (see earlier comment for full explanation).
4640 TRACE_EVENT_INSTANT1("cat", "event_name", TRACE_EVENT_FLAG_NONE, arg_name1,
4641 /*arg_value=*/5);
4642 }
4643 {
4644 TRACE_EVENT_COPY_INSTANT1("cat", "event_name", TRACE_EVENT_FLAG_NONE,
4645 arg_name2, /*arg_value=*/5);
4646 arg_name2[1] = '6';
4647 TRACE_EVENT_COPY_INSTANT1("cat", "event_name", TRACE_EVENT_FLAG_NONE,
4648 arg_name2, /*arg_value=*/5);
4649 }
4650 auto slices = StopSessionAndReadSlicesFromTrace(tracing_session);
4651 EXPECT_THAT(
4652 slices,
4653 ElementsAre("[track=0]Legacy_R:cat.A1", "[track=0]Legacy_R:cat.A1",
4654 "[track=0]Legacy_R:cat.B1", "[track=0]Legacy_R:cat.B4",
4655 "[track=0]I:cat.event_name(C1=(int)5)",
4656 "[track=0]I:cat.event_name(C1=(int)5)",
4657 "[track=0]I:cat.event_name(D1=(int)5)",
4658 "[track=0]I:cat.event_name(D6=(int)5)"));
4659 }
4660
TEST_P(PerfettoApiTest,LegacyTraceEvents)4661 TEST_P(PerfettoApiTest, LegacyTraceEvents) {
4662 auto is_new_session = [] {
4663 bool result;
4664 TRACE_EVENT_IS_NEW_TRACE(&result);
4665 return result;
4666 };
4667
4668 // Create a new trace session.
4669 EXPECT_FALSE(is_new_session());
4670 auto* tracing_session =
4671 NewTraceWithCategories({"cat", TRACE_DISABLED_BY_DEFAULT("cat")});
4672 tracing_session->get()->StartBlocking();
4673 EXPECT_TRUE(is_new_session());
4674 EXPECT_FALSE(is_new_session());
4675
4676 // Basic events.
4677 TRACE_EVENT_INSTANT0("cat", "LegacyEvent", TRACE_EVENT_SCOPE_GLOBAL);
4678 TRACE_EVENT_BEGIN1("cat", "LegacyEvent", "arg", 123);
4679 TRACE_EVENT_END2("cat", "LegacyEvent", "arg", "string", "arg2", 0.123f);
4680
4681 // Scoped event.
4682 { TRACE_EVENT0("cat", "ScopedLegacyEvent"); }
4683
4684 // Event with flow (and disabled category).
4685 TRACE_EVENT_WITH_FLOW0(TRACE_DISABLED_BY_DEFAULT("cat"), "LegacyFlowEvent",
4686 0xdadacafe, TRACE_EVENT_FLAG_FLOW_IN);
4687
4688 // Event with timestamp.
4689 TRACE_EVENT_INSTANT_WITH_TIMESTAMP0("cat", "LegacyInstantEvent",
4690 TRACE_EVENT_SCOPE_GLOBAL,
4691 MyTimestamp{123456789ul});
4692
4693 // Event with id.
4694 TRACE_COUNTER1("cat", "LegacyCounter", 1234);
4695 TRACE_COUNTER_ID1("cat", "LegacyCounterWithId", 1234, 9000);
4696
4697 // Metadata event.
4698 TRACE_EVENT_METADATA1("cat", "LegacyMetadata", "obsolete", true);
4699
4700 // Async events.
4701 TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP_AND_FLAGS0(
4702 "cat", "LegacyAsync", 5678, MyTimestamp{4}, TRACE_EVENT_FLAG_NONE);
4703 TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP0("cat", "LegacyAsync", 5678,
4704 MyTimestamp{5});
4705 TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_FLAGS0("cat", "LegacyAsync2", 9000,
4706 TRACE_EVENT_FLAG_NONE);
4707 TRACE_EVENT_NESTABLE_ASYNC_END_WITH_FLAGS0("cat", "LegacyAsync2", 9000,
4708 TRACE_EVENT_FLAG_NONE);
4709 TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_FLAGS0("cat", "LegacyAsync3", 9001,
4710 TRACE_EVENT_FLAG_NONE);
4711 TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP_AND_FLAGS0(
4712 "cat", "LegacyAsync3", 9001, MyTimestamp{6}, TRACE_EVENT_FLAG_NONE);
4713
4714 auto slices = StopSessionAndReadSlicesFromTrace(tracing_session);
4715 EXPECT_THAT(
4716 slices,
4717 ElementsAre(
4718 "[track=0]I:cat.LegacyEvent", "B:cat.LegacyEvent(arg=(int)123)",
4719 "E(arg=(string)string,arg2=(double)0.123)", "B:cat.ScopedLegacyEvent",
4720 "E",
4721 "B(bind_id=3671771902)(flow_direction=1):disabled-by-default-cat."
4722 "LegacyFlowEvent",
4723 "[track=0]I:cat.LegacyInstantEvent",
4724 "[track=0]Legacy_C:cat.LegacyCounter(value=(int)1234)",
4725 "[track=0]Legacy_C(unscoped_id=1234):cat.LegacyCounterWithId(value=("
4726 "int)9000)",
4727 "[track=0]Legacy_M:cat.LegacyMetadata",
4728 "[track=0]Legacy_b(unscoped_id=5678):cat.LegacyAsync",
4729 "[track=0]Legacy_e(unscoped_id=5678):cat.LegacyAsync",
4730 "[track=0]Legacy_b(unscoped_id=9000):cat.LegacyAsync2",
4731 "[track=0]Legacy_e(unscoped_id=9000):cat.LegacyAsync2",
4732 "[track=0]Legacy_b(unscoped_id=9001):cat.LegacyAsync3",
4733 "[track=0]Legacy_e(unscoped_id=9001):cat.LegacyAsync3"));
4734 }
4735
TEST_P(PerfettoApiTest,LegacyTraceEventsAndClockSnapshots)4736 TEST_P(PerfettoApiTest, LegacyTraceEventsAndClockSnapshots) {
4737 auto* tracing_session = NewTraceWithCategories({"cat"});
4738 tracing_session->get()->StartBlocking();
4739
4740 {
4741 TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("cat", "LegacyAsync", 5678);
4742
4743 perfetto::test::TracingMuxerImplInternalsForTest::ClearIncrementalState();
4744
4745 TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0(
4746 "cat", "LegacyAsyncWithTimestamp", 5678, MyTimestamp{1});
4747 TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP0(
4748 "cat", "LegacyAsyncWithTimestamp", 5678, MyTimestamp{2});
4749
4750 perfetto::test::TracingMuxerImplInternalsForTest::ClearIncrementalState();
4751
4752 TRACE_EVENT_NESTABLE_ASYNC_END0("cat", "LegacyAsync", 5678);
4753 }
4754
4755 auto trace = StopSessionAndReturnParsedTrace(tracing_session);
4756
4757 // Check that clock snapshots are monotonic and don't contain timestamps from
4758 // trace events with explicit timestamps.
4759 std::unordered_map<uint64_t, uint64_t> last_clock_ts;
4760 for (const auto& packet : trace.packet()) {
4761 if (packet.has_clock_snapshot()) {
4762 for (auto& clock : packet.clock_snapshot().clocks()) {
4763 if (!clock.is_incremental()) {
4764 uint64_t ts = clock.timestamp();
4765 uint64_t id = clock.clock_id();
4766 EXPECT_LE(last_clock_ts[id], ts);
4767 last_clock_ts[id] = ts;
4768 }
4769 }
4770
4771 // Events that don't use explicit timestamps should have exactly the same
4772 // timestamp as in the snapshot (i.e. the relative ts of 0).
4773 // Here we assume that timestamps are incremental by default.
4774 if (!packet.has_timestamp_clock_id()) {
4775 EXPECT_EQ(packet.timestamp(), 0u);
4776 }
4777 }
4778 }
4779 }
4780
TEST_P(PerfettoApiTest,LegacyTraceEventsWithCustomAnnotation)4781 TEST_P(PerfettoApiTest, LegacyTraceEventsWithCustomAnnotation) {
4782 // Create a new trace session.
4783 auto* tracing_session = NewTraceWithCategories({"cat"});
4784 tracing_session->get()->StartBlocking();
4785
4786 MyDebugAnnotation annotation;
4787 TRACE_EVENT_BEGIN1("cat", "LegacyEvent", "arg", annotation);
4788
4789 std::unique_ptr<MyDebugAnnotation> owned_annotation(new MyDebugAnnotation());
4790 TRACE_EVENT_BEGIN1("cat", "LegacyEvent", "arg", std::move(owned_annotation));
4791
4792 auto slices = StopSessionAndReadSlicesFromTrace(tracing_session);
4793 EXPECT_THAT(slices,
4794 ElementsAre("B:cat.LegacyEvent(arg=(json){\"key\": 123})",
4795 "B:cat.LegacyEvent(arg=(json){\"key\": 123})"));
4796 }
4797
TEST_P(PerfettoApiTest,LegacyTraceEventsWithConcurrentSessions)4798 TEST_P(PerfettoApiTest, LegacyTraceEventsWithConcurrentSessions) {
4799 // Make sure that a uniquely owned debug annotation can be written into
4800 // multiple concurrent tracing sessions.
4801
4802 auto* tracing_session = NewTraceWithCategories({"cat"});
4803 tracing_session->get()->StartBlocking();
4804
4805 auto* tracing_session2 = NewTraceWithCategories({"cat"});
4806 tracing_session2->get()->StartBlocking();
4807
4808 std::unique_ptr<MyDebugAnnotation> owned_annotation(new MyDebugAnnotation());
4809 TRACE_EVENT_BEGIN1("cat", "LegacyEvent", "arg", std::move(owned_annotation));
4810
4811 auto slices = StopSessionAndReadSlicesFromTrace(tracing_session);
4812 EXPECT_THAT(slices,
4813 ElementsAre("B:cat.LegacyEvent(arg=(json){\"key\": 123})"));
4814
4815 slices = StopSessionAndReadSlicesFromTrace(tracing_session2);
4816 EXPECT_THAT(slices,
4817 ElementsAre("B:cat.LegacyEvent(arg=(json){\"key\": 123})"));
4818 }
4819
TEST_P(PerfettoApiTest,LegacyTraceEventsWithId)4820 TEST_P(PerfettoApiTest, LegacyTraceEventsWithId) {
4821 auto* tracing_session = NewTraceWithCategories({"cat"});
4822 tracing_session->get()->StartBlocking();
4823
4824 TRACE_EVENT_ASYNC_BEGIN0("cat", "UnscopedId", 0x1000);
4825 TRACE_EVENT_ASYNC_BEGIN0("cat", "LocalId", TRACE_ID_LOCAL(0x2000));
4826 TRACE_EVENT_ASYNC_BEGIN0("cat", "GlobalId", TRACE_ID_GLOBAL(0x3000));
4827 TRACE_EVENT_ASYNC_BEGIN0(
4828 "cat", "WithScope",
4829 TRACE_ID_WITH_SCOPE("scope string", TRACE_ID_GLOBAL(0x4000)));
4830
4831 auto slices = StopSessionAndReadSlicesFromTrace(tracing_session);
4832 EXPECT_THAT(slices,
4833 ElementsAre("[track=0]Legacy_S(unscoped_id=4096):cat.UnscopedId",
4834 "[track=0]Legacy_S(local_id=8192):cat.LocalId",
4835 "[track=0]Legacy_S(global_id=12288):cat.GlobalId",
4836 "[track=0]Legacy_S(global_id=16384)(id_scope=\"scope "
4837 "string\"):cat.WithScope"));
4838 }
4839
TEST_P(PerfettoApiTest,NestableAsyncTraceEvent)4840 TEST_P(PerfettoApiTest, NestableAsyncTraceEvent) {
4841 auto* tracing_session = NewTraceWithCategories({"cat"});
4842 tracing_session->get()->StartBlocking();
4843 TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("cat", "foo",
4844 TRACE_ID_WITH_SCOPE("foo", 1));
4845 // Same id, different scope.
4846 TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("cat", "bar",
4847 TRACE_ID_WITH_SCOPE("bar", 1));
4848 // Same scope, different id.
4849 TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("cat", "bar",
4850 TRACE_ID_WITH_SCOPE("bar", 2));
4851
4852 TRACE_EVENT_NESTABLE_ASYNC_END0("cat", "bar", TRACE_ID_WITH_SCOPE("bar", 2));
4853 TRACE_EVENT_NESTABLE_ASYNC_END0("cat", "bar", TRACE_ID_WITH_SCOPE("bar", 1));
4854 TRACE_EVENT_NESTABLE_ASYNC_END0("cat", "foo", TRACE_ID_WITH_SCOPE("foo", 1));
4855 auto trace = StopSessionAndReturnParsedTrace(tracing_session);
4856 using LegacyEvent = perfetto::protos::gen::TrackEvent::LegacyEvent;
4857 std::vector<const LegacyEvent*> legacy_events;
4858 for (const auto& packet : trace.packet()) {
4859 if (packet.has_track_event() && packet.track_event().has_legacy_event()) {
4860 legacy_events.push_back(&packet.track_event().legacy_event());
4861 }
4862 }
4863 ASSERT_EQ(6u, legacy_events.size());
4864 EXPECT_EQ("foo", legacy_events[0]->id_scope());
4865 EXPECT_EQ("bar", legacy_events[1]->id_scope());
4866 EXPECT_EQ("bar", legacy_events[2]->id_scope());
4867 EXPECT_EQ("bar", legacy_events[3]->id_scope());
4868 EXPECT_EQ("bar", legacy_events[4]->id_scope());
4869 EXPECT_EQ("foo", legacy_events[5]->id_scope());
4870
4871 EXPECT_EQ(legacy_events[0]->unscoped_id(), legacy_events[5]->unscoped_id());
4872 EXPECT_EQ(legacy_events[1]->unscoped_id(), legacy_events[4]->unscoped_id());
4873 EXPECT_EQ(legacy_events[2]->unscoped_id(), legacy_events[3]->unscoped_id());
4874
4875 EXPECT_NE(legacy_events[0]->unscoped_id(), legacy_events[1]->unscoped_id());
4876 EXPECT_NE(legacy_events[1]->unscoped_id(), legacy_events[2]->unscoped_id());
4877 EXPECT_NE(legacy_events[2]->unscoped_id(), legacy_events[0]->unscoped_id());
4878 }
4879
TEST_P(PerfettoApiTest,LegacyTraceEventsWithFlow)4880 TEST_P(PerfettoApiTest, LegacyTraceEventsWithFlow) {
4881 auto* tracing_session = NewTraceWithCategories({"cat"});
4882 tracing_session->get()->StartBlocking();
4883
4884 const uint64_t flow_id = 1234;
4885 {
4886 TRACE_EVENT_WITH_FLOW1("cat", "LatencyInfo.Flow", TRACE_ID_GLOBAL(flow_id),
4887 TRACE_EVENT_FLAG_FLOW_OUT, "step", "Begin");
4888 }
4889
4890 {
4891 TRACE_EVENT_WITH_FLOW2("cat", "LatencyInfo.Flow", TRACE_ID_GLOBAL(flow_id),
4892 TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT,
4893 "step", "Middle", "value", false);
4894 }
4895
4896 {
4897 TRACE_EVENT_WITH_FLOW1("cat", "LatencyInfo.Flow", TRACE_ID_GLOBAL(flow_id),
4898 TRACE_EVENT_FLAG_FLOW_IN, "step", "End");
4899 }
4900
4901 auto slices = StopSessionAndReadSlicesFromTrace(tracing_session);
4902 EXPECT_THAT(slices,
4903 ElementsAre("B(bind_id=1234)(flow_direction=2):cat.LatencyInfo."
4904 "Flow(step=(string)Begin)",
4905 "E",
4906 "B(bind_id=1234)(flow_direction=3):cat.LatencyInfo."
4907 "Flow(step=(string)Middle,value=(bool)0)",
4908 "E",
4909 "B(bind_id=1234)(flow_direction=1):cat.LatencyInfo."
4910 "Flow(step=(string)End)",
4911 "E"));
4912 }
4913
TEST_P(PerfettoApiTest,LegacyCategoryGroupEnabledState)4914 TEST_P(PerfettoApiTest, LegacyCategoryGroupEnabledState) {
4915 bool foo_status;
4916 bool bar_status;
4917 bool dynamic_status;
4918 TRACE_EVENT_CATEGORY_GROUP_ENABLED("foo", &foo_status);
4919 TRACE_EVENT_CATEGORY_GROUP_ENABLED("bar", &bar_status);
4920 TRACE_EVENT_CATEGORY_GROUP_ENABLED("dynamic", &dynamic_status);
4921 EXPECT_FALSE(foo_status);
4922 EXPECT_FALSE(bar_status);
4923 EXPECT_FALSE(dynamic_status);
4924
4925 const uint8_t* foo_enabled =
4926 TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED("foo");
4927 const uint8_t* bar_enabled =
4928 TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED("bar");
4929 EXPECT_FALSE(*foo_enabled);
4930 EXPECT_FALSE(*bar_enabled);
4931
4932 // The category group enabled pointer can also be retrieved with a
4933 // runtime-computed category name.
4934 std::string computed_cat("cat");
4935 const uint8_t* computed_enabled =
4936 TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED(computed_cat.c_str());
4937 EXPECT_FALSE(*computed_enabled);
4938
4939 // The enabled pointers can be converted back to category names.
4940 EXPECT_EQ("foo", TRACE_EVENT_API_GET_CATEGORY_GROUP_NAME(foo_enabled));
4941 EXPECT_EQ("bar", TRACE_EVENT_API_GET_CATEGORY_GROUP_NAME(bar_enabled));
4942 EXPECT_EQ("cat", TRACE_EVENT_API_GET_CATEGORY_GROUP_NAME(computed_enabled));
4943
4944 auto* tracing_session = NewTraceWithCategories({"foo", "dynamic", "cat"});
4945 tracing_session->get()->StartBlocking();
4946 TRACE_EVENT_CATEGORY_GROUP_ENABLED("foo", &foo_status);
4947 TRACE_EVENT_CATEGORY_GROUP_ENABLED("bar", &bar_status);
4948 TRACE_EVENT_CATEGORY_GROUP_ENABLED("dynamic", &dynamic_status);
4949 EXPECT_TRUE(foo_status);
4950 EXPECT_FALSE(bar_status);
4951 EXPECT_TRUE(dynamic_status);
4952
4953 EXPECT_TRUE(*foo_enabled);
4954 EXPECT_FALSE(*bar_enabled);
4955 EXPECT_TRUE(*computed_enabled);
4956
4957 tracing_session->get()->StopBlocking();
4958 TRACE_EVENT_CATEGORY_GROUP_ENABLED("foo", &foo_status);
4959 TRACE_EVENT_CATEGORY_GROUP_ENABLED("bar", &bar_status);
4960 TRACE_EVENT_CATEGORY_GROUP_ENABLED("dynamic", &dynamic_status);
4961 EXPECT_FALSE(foo_status);
4962 EXPECT_FALSE(bar_status);
4963 EXPECT_FALSE(dynamic_status);
4964 EXPECT_FALSE(*foo_enabled);
4965 EXPECT_FALSE(*bar_enabled);
4966 EXPECT_FALSE(*computed_enabled);
4967 }
4968
TEST_P(PerfettoApiTest,CategoryEnabledState)4969 TEST_P(PerfettoApiTest, CategoryEnabledState) {
4970 perfetto::DynamicCategory dynamic{"dynamic"};
4971 EXPECT_FALSE(TRACE_EVENT_CATEGORY_ENABLED("foo"));
4972 EXPECT_FALSE(TRACE_EVENT_CATEGORY_ENABLED("bar"));
4973 EXPECT_FALSE(TRACE_EVENT_CATEGORY_ENABLED("red,green,blue,foo"));
4974 EXPECT_FALSE(TRACE_EVENT_CATEGORY_ENABLED("dynamic"));
4975 EXPECT_FALSE(TRACE_EVENT_CATEGORY_ENABLED("dynamic_2"));
4976 EXPECT_FALSE(TRACE_EVENT_CATEGORY_ENABLED(dynamic));
4977
4978 auto* tracing_session = NewTraceWithCategories({"foo", "dynamic"});
4979 tracing_session->get()->StartBlocking();
4980 EXPECT_TRUE(TRACE_EVENT_CATEGORY_ENABLED("foo"));
4981 EXPECT_FALSE(TRACE_EVENT_CATEGORY_ENABLED("bar"));
4982 EXPECT_TRUE(TRACE_EVENT_CATEGORY_ENABLED("red,green,blue,foo"));
4983 EXPECT_TRUE(TRACE_EVENT_CATEGORY_ENABLED("dynamic"));
4984 EXPECT_FALSE(TRACE_EVENT_CATEGORY_ENABLED("dynamic_2"));
4985 EXPECT_TRUE(TRACE_EVENT_CATEGORY_ENABLED(dynamic));
4986
4987 tracing_session->get()->StopBlocking();
4988 EXPECT_FALSE(TRACE_EVENT_CATEGORY_ENABLED("foo"));
4989 EXPECT_FALSE(TRACE_EVENT_CATEGORY_ENABLED("bar"));
4990 EXPECT_FALSE(TRACE_EVENT_CATEGORY_ENABLED("red,green,blue,foo"));
4991 EXPECT_FALSE(TRACE_EVENT_CATEGORY_ENABLED("dynamic"));
4992 EXPECT_FALSE(TRACE_EVENT_CATEGORY_ENABLED("dynamic_2"));
4993 EXPECT_FALSE(TRACE_EVENT_CATEGORY_ENABLED(dynamic));
4994 }
4995
4996 class TestInterceptor : public perfetto::Interceptor<TestInterceptor> {
4997 public:
4998 static TestInterceptor* instance;
4999
5000 struct ThreadLocalState : public perfetto::InterceptorBase::ThreadLocalState {
ThreadLocalState__anon78e5bb3c0111::TestInterceptor::ThreadLocalState5001 ThreadLocalState(ThreadLocalStateArgs& args) {
5002 // Test accessing instance state from the TLS constructor.
5003 if (auto self = args.GetInterceptorLocked()) {
5004 self->tls_initialized = true;
5005 }
5006 }
5007
5008 std::map<uint64_t, std::string> event_names;
5009 };
5010
TestInterceptor(const std::string & constructor_arg)5011 TestInterceptor(const std::string& constructor_arg) {
5012 EXPECT_EQ(constructor_arg, "Constructor argument");
5013 // Note: some tests in this suite register multiple track event data
5014 // sources. We only track data for the first in this test.
5015 if (!instance)
5016 instance = this;
5017 }
5018
~TestInterceptor()5019 ~TestInterceptor() override {
5020 if (instance != this)
5021 return;
5022 instance = nullptr;
5023 EXPECT_TRUE(setup_called);
5024 EXPECT_TRUE(start_called);
5025 EXPECT_TRUE(stop_called);
5026 EXPECT_TRUE(tls_initialized);
5027 }
5028
OnSetup(const SetupArgs &)5029 void OnSetup(const SetupArgs&) override {
5030 EXPECT_FALSE(setup_called);
5031 EXPECT_FALSE(start_called);
5032 EXPECT_FALSE(stop_called);
5033 setup_called = true;
5034 }
5035
OnStart(const StartArgs &)5036 void OnStart(const StartArgs&) override {
5037 EXPECT_TRUE(setup_called);
5038 EXPECT_FALSE(start_called);
5039 EXPECT_FALSE(stop_called);
5040 start_called = true;
5041 }
5042
OnStop(const StopArgs &)5043 void OnStop(const StopArgs&) override {
5044 EXPECT_TRUE(setup_called);
5045 EXPECT_TRUE(start_called);
5046 EXPECT_FALSE(stop_called);
5047 stop_called = true;
5048 }
5049
OnTracePacket(InterceptorContext context)5050 static void OnTracePacket(InterceptorContext context) {
5051 perfetto::protos::pbzero::TracePacket::Decoder packet(
5052 context.packet_data.data, context.packet_data.size);
5053 EXPECT_TRUE(packet.trusted_packet_sequence_id() > 0);
5054 {
5055 auto self = context.GetInterceptorLocked();
5056 ASSERT_TRUE(self);
5057 EXPECT_TRUE(self->setup_called);
5058 EXPECT_TRUE(self->start_called);
5059 EXPECT_FALSE(self->stop_called);
5060 EXPECT_TRUE(self->tls_initialized);
5061 }
5062
5063 auto& tls = context.GetThreadLocalState();
5064 if (packet.sequence_flags() &
5065 perfetto::protos::pbzero::TracePacket::SEQ_INCREMENTAL_STATE_CLEARED) {
5066 tls.event_names.clear();
5067 }
5068 if (packet.has_interned_data()) {
5069 perfetto::protos::pbzero::InternedData::Decoder interned_data(
5070 packet.interned_data());
5071 for (auto it = interned_data.event_names(); it; it++) {
5072 perfetto::protos::pbzero::EventName::Decoder entry(*it);
5073 tls.event_names[entry.iid()] = entry.name().ToStdString();
5074 }
5075 }
5076 if (packet.has_track_event()) {
5077 perfetto::protos::pbzero::TrackEvent::Decoder track_event(
5078 packet.track_event());
5079 uint64_t name_iid = track_event.name_iid();
5080 auto self = context.GetInterceptorLocked();
5081 self->events.push_back(tls.event_names[name_iid].c_str());
5082 }
5083 }
5084
5085 bool setup_called = false;
5086 bool start_called = false;
5087 bool stop_called = false;
5088 bool tls_initialized = false;
5089 std::vector<std::string> events;
5090 };
5091
5092 TestInterceptor* TestInterceptor::instance;
5093
TEST_P(PerfettoApiTest,TracePacketInterception)5094 TEST_P(PerfettoApiTest, TracePacketInterception) {
5095 perfetto::InterceptorDescriptor desc;
5096 desc.set_name("test_interceptor");
5097 TestInterceptor::Register(desc, std::string("Constructor argument"));
5098
5099 perfetto::TraceConfig cfg;
5100 cfg.set_duration_ms(500);
5101 cfg.add_buffers()->set_size_kb(1024);
5102 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
5103 ds_cfg->set_name("track_event");
5104 ds_cfg->mutable_interceptor_config()->set_name("test_interceptor");
5105
5106 auto* tracing_session = NewTrace(cfg);
5107 tracing_session->get()->StartBlocking();
5108 EXPECT_EQ(0u, TestInterceptor::instance->events.size());
5109
5110 // The interceptor should see an event immediately without any explicit
5111 // flushing.
5112 TRACE_EVENT_BEGIN("foo", "Hip");
5113 EXPECT_THAT(TestInterceptor::instance->events, ElementsAre("Hip"));
5114
5115 // Emit another event with the same title to test interning.
5116 TRACE_EVENT_BEGIN("foo", "Hip");
5117 EXPECT_THAT(TestInterceptor::instance->events, ElementsAre("Hip", "Hip"));
5118
5119 // Emit an event from another thread. It should still reach the same
5120 // interceptor instance.
5121 std::thread thread([] { TRACE_EVENT_BEGIN("foo", "Hooray"); });
5122 thread.join();
5123 EXPECT_THAT(TestInterceptor::instance->events,
5124 ElementsAre("Hip", "Hip", "Hooray"));
5125
5126 // Emit a packet that spans multiple segments and must be stitched together.
5127 TestInterceptor::instance->events.clear();
5128 static char long_title[8192];
5129 memset(long_title, 'a', sizeof(long_title) - 1);
5130 long_title[sizeof(long_title) - 1] = 0;
5131 TRACE_EVENT_BEGIN("foo", long_title);
5132 EXPECT_THAT(TestInterceptor::instance->events, ElementsAre(long_title));
5133
5134 tracing_session->get()->StopBlocking();
5135 }
5136
EmitConsoleEvents()5137 void EmitConsoleEvents() {
5138 TRACE_EVENT_INSTANT("foo", "Instant event");
5139 TRACE_EVENT("foo", "Scoped event");
5140 TRACE_EVENT_BEGIN("foo", "Nested event");
5141 TRACE_EVENT_INSTANT("foo", "Instant event");
5142 TRACE_EVENT_INSTANT("foo", "Annotated event", "foo", 1, "bar", "hello");
5143 TRACE_EVENT_END("foo");
5144 uint64_t async_id = 4004;
5145 auto track = perfetto::Track(async_id, perfetto::ThreadTrack::Current());
5146 perfetto::TrackEvent::SetTrackDescriptor(
5147 track, [](perfetto::protos::pbzero::TrackDescriptor* desc) {
5148 desc->set_name("AsyncTrack");
5149 });
5150 TRACE_EVENT_BEGIN("test", "AsyncEvent", track);
5151
5152 std::thread thread([&] {
5153 TRACE_EVENT("foo", "EventFromAnotherThread");
5154 TRACE_EVENT_INSTANT("foo", "Instant event");
5155 TRACE_EVENT_END("test", track);
5156 });
5157 thread.join();
5158
5159 TRACE_EVENT_INSTANT(
5160 "foo", "More annotations", "dict",
5161 [](perfetto::TracedValue context) {
5162 auto dict = std::move(context).WriteDictionary();
5163 dict.Add("key", 123);
5164 },
5165 "array",
5166 [](perfetto::TracedValue context) {
5167 auto array = std::move(context).WriteArray();
5168 array.Append("first");
5169 array.Append("second");
5170 });
5171 }
5172
TEST_P(PerfettoApiTest,ConsoleInterceptorPrint)5173 TEST_P(PerfettoApiTest, ConsoleInterceptorPrint) {
5174 perfetto::ConsoleInterceptor::Register();
5175
5176 perfetto::TraceConfig cfg;
5177 cfg.set_duration_ms(500);
5178 cfg.add_buffers()->set_size_kb(1024);
5179 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
5180 ds_cfg->set_name("track_event");
5181 ds_cfg->mutable_interceptor_config()->set_name("console");
5182
5183 auto* tracing_session = NewTrace(cfg);
5184 tracing_session->get()->StartBlocking();
5185 EmitConsoleEvents();
5186 tracing_session->get()->StopBlocking();
5187 }
5188
TEST_P(PerfettoApiTest,ConsoleInterceptorVerify)5189 TEST_P(PerfettoApiTest, ConsoleInterceptorVerify) {
5190 perfetto::ConsoleInterceptor::Register();
5191 auto temp_file = perfetto::test::CreateTempFile();
5192 perfetto::ConsoleInterceptor::SetOutputFdForTesting(temp_file.fd);
5193
5194 perfetto::TraceConfig cfg;
5195 cfg.set_duration_ms(500);
5196 cfg.add_buffers()->set_size_kb(1024);
5197 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
5198 ds_cfg->set_name("track_event");
5199 ds_cfg->mutable_interceptor_config()->set_name("console");
5200
5201 auto* tracing_session = NewTrace(cfg);
5202 tracing_session->get()->StartBlocking();
5203 EmitConsoleEvents();
5204 tracing_session->get()->StopBlocking();
5205 perfetto::ConsoleInterceptor::SetOutputFdForTesting(0);
5206
5207 std::vector<std::string> lines;
5208 FILE* f = fdopen(temp_file.fd, "r");
5209 fseek(f, 0u, SEEK_SET);
5210 std::array<char, 128> line{};
5211 while (fgets(line.data(), line.size(), f)) {
5212 // Ignore timestamps and process/thread ids.
5213 std::string s(line.data() + 28);
5214 // Filter out durations.
5215 s = std::regex_replace(s, std::regex(" [+][0-9]*ms"), "");
5216 lines.push_back(std::move(s));
5217 }
5218 fclose(f);
5219 EXPECT_EQ(0, remove(temp_file.path.c_str()));
5220
5221 // clang-format off
5222 std::vector<std::string> golden_lines = {
5223 "foo Instant event\n",
5224 "foo Scoped event {\n",
5225 "foo - Nested event {\n",
5226 "foo - - Instant event\n",
5227 "foo - - Annotated event(foo:1, bar:hello)\n",
5228 "foo - } Nested event\n",
5229 "test AsyncEvent {\n",
5230 "foo EventFromAnotherThread {\n",
5231 "foo - Instant event\n",
5232 "test } AsyncEvent\n",
5233 "foo } EventFromAnotherThread\n",
5234 "foo - More annotations(dict:{key:123}, array:[first, second])\n",
5235 "foo } Scoped event\n",
5236 };
5237 // clang-format on
5238 EXPECT_THAT(lines, ContainerEq(golden_lines));
5239 }
5240
TEST_P(PerfettoApiTest,TrackEventObserver)5241 TEST_P(PerfettoApiTest, TrackEventObserver) {
5242 class Observer : public perfetto::TrackEventSessionObserver {
5243 public:
5244 ~Observer() override = default;
5245
5246 void OnSetup(const perfetto::DataSourceBase::SetupArgs&) {
5247 // Since other tests here register multiple track event data sources,
5248 // ignore all but the first notifications.
5249 if (setup_called)
5250 return;
5251 setup_called = true;
5252 if (unsubscribe_at_setup)
5253 perfetto::TrackEvent::RemoveSessionObserver(this);
5254 // This event isn't recorded in the trace because tracing isn't active yet
5255 // when OnSetup is called.
5256 TRACE_EVENT_INSTANT("foo", "OnSetup");
5257 // However the active tracing categories have already been updated at this
5258 // point.
5259 EXPECT_TRUE(perfetto::TrackEvent::IsEnabled());
5260 EXPECT_TRUE(TRACE_EVENT_CATEGORY_ENABLED("foo"));
5261 }
5262
5263 void OnStart(const perfetto::DataSourceBase::StartArgs&) {
5264 if (start_called)
5265 return;
5266 start_called = true;
5267 EXPECT_TRUE(perfetto::TrackEvent::IsEnabled());
5268 EXPECT_TRUE(TRACE_EVENT_CATEGORY_ENABLED("foo"));
5269 TRACE_EVENT_INSTANT("foo", "OnStart");
5270 }
5271
5272 void OnStop(const perfetto::DataSourceBase::StopArgs&) {
5273 if (stop_called)
5274 return;
5275 stop_called = true;
5276 EXPECT_TRUE(perfetto::TrackEvent::IsEnabled());
5277 EXPECT_TRUE(TRACE_EVENT_CATEGORY_ENABLED("foo"));
5278 TRACE_EVENT_INSTANT("foo", "OnStop");
5279 perfetto::TrackEvent::Flush();
5280 }
5281
5282 bool setup_called{};
5283 bool start_called{};
5284 bool stop_called{};
5285 bool unsubscribe_at_setup{};
5286 };
5287
5288 EXPECT_FALSE(perfetto::TrackEvent::IsEnabled());
5289 {
5290 Observer observer;
5291 perfetto::TrackEvent::AddSessionObserver(&observer);
5292
5293 auto* tracing_session = NewTraceWithCategories({"foo"});
5294 tracing_session->get()->StartBlocking();
5295 EXPECT_TRUE(observer.setup_called);
5296 EXPECT_TRUE(observer.start_called);
5297 tracing_session->get()->StopBlocking();
5298 EXPECT_TRUE(observer.stop_called);
5299 perfetto::TrackEvent::RemoveSessionObserver(&observer);
5300 auto slices = ReadSlicesFromTraceSession(tracing_session->get());
5301 EXPECT_THAT(slices, ElementsAre("I:foo.OnStart", "I:foo.OnStop"));
5302 }
5303
5304 // No notifications after removing observer.
5305 {
5306 Observer observer;
5307 perfetto::TrackEvent::AddSessionObserver(&observer);
5308 perfetto::TrackEvent::RemoveSessionObserver(&observer);
5309 auto* tracing_session = NewTraceWithCategories({"foo"});
5310 tracing_session->get()->StartBlocking();
5311 EXPECT_FALSE(observer.setup_called);
5312 EXPECT_FALSE(observer.start_called);
5313 tracing_session->get()->StopBlocking();
5314 EXPECT_FALSE(observer.stop_called);
5315 }
5316
5317 // Removing observer in a callback.
5318 {
5319 Observer observer;
5320 observer.unsubscribe_at_setup = true;
5321 perfetto::TrackEvent::AddSessionObserver(&observer);
5322 auto* tracing_session = NewTraceWithCategories({"foo"});
5323 tracing_session->get()->StartBlocking();
5324 EXPECT_TRUE(observer.setup_called);
5325 EXPECT_FALSE(observer.start_called);
5326 tracing_session->get()->StopBlocking();
5327 EXPECT_FALSE(observer.stop_called);
5328 perfetto::TrackEvent::RemoveSessionObserver(&observer);
5329 }
5330
5331 // Multiple observers.
5332 {
5333 Observer observer1;
5334 Observer observer2;
5335 perfetto::TrackEvent::AddSessionObserver(&observer1);
5336 perfetto::TrackEvent::AddSessionObserver(&observer2);
5337 auto* tracing_session = NewTraceWithCategories({"foo"});
5338 tracing_session->get()->StartBlocking();
5339 tracing_session->get()->StopBlocking();
5340 perfetto::TrackEvent::RemoveSessionObserver(&observer1);
5341 perfetto::TrackEvent::RemoveSessionObserver(&observer2);
5342 auto slices = ReadSlicesFromTraceSession(tracing_session->get());
5343 EXPECT_THAT(slices, ElementsAre("I:foo.OnStart", "I:foo.OnStart",
5344 "I:foo.OnStop", "I:foo.OnStop"));
5345 }
5346
5347 // Multiple observers with one being removed midway.
5348 {
5349 Observer observer1;
5350 Observer observer2;
5351 perfetto::TrackEvent::AddSessionObserver(&observer1);
5352 perfetto::TrackEvent::AddSessionObserver(&observer2);
5353 auto* tracing_session = NewTraceWithCategories({"foo"});
5354 tracing_session->get()->StartBlocking();
5355 perfetto::TrackEvent::RemoveSessionObserver(&observer1);
5356 tracing_session->get()->StopBlocking();
5357 perfetto::TrackEvent::RemoveSessionObserver(&observer2);
5358 auto slices = ReadSlicesFromTraceSession(tracing_session->get());
5359 EXPECT_THAT(slices,
5360 ElementsAre("I:foo.OnStart", "I:foo.OnStart", "I:foo.OnStop"));
5361 }
5362 EXPECT_FALSE(perfetto::TrackEvent::IsEnabled());
5363 }
5364
TEST_P(PerfettoApiTest,TrackEventObserver_ClearIncrementalState)5365 TEST_P(PerfettoApiTest, TrackEventObserver_ClearIncrementalState) {
5366 class Observer : public perfetto::TrackEventSessionObserver {
5367 public:
5368 ~Observer() override = default;
5369
5370 void OnStart(const perfetto::DataSourceBase::StartArgs&) {
5371 EXPECT_TRUE(perfetto::TrackEvent::IsEnabled());
5372 EXPECT_TRUE(TRACE_EVENT_CATEGORY_ENABLED("foo"));
5373 TRACE_EVENT_INSTANT("foo", "OnStart");
5374 }
5375
5376 void WillClearIncrementalState(
5377 const perfetto::DataSourceBase::ClearIncrementalStateArgs&) {
5378 if (clear_incremental_state_called)
5379 return;
5380 clear_incremental_state_called = true;
5381 EXPECT_TRUE(perfetto::TrackEvent::IsEnabled());
5382 EXPECT_TRUE(TRACE_EVENT_CATEGORY_ENABLED("foo"));
5383 TRACE_EVENT_INSTANT("foo", "WillClearIncrementalState");
5384 perfetto::TrackEvent::Flush();
5385 }
5386
5387 bool clear_incremental_state_called{};
5388 };
5389
5390 EXPECT_FALSE(perfetto::TrackEvent::IsEnabled());
5391 {
5392 Observer observer;
5393 perfetto::TrackEvent::AddSessionObserver(&observer);
5394
5395 perfetto::TraceConfig cfg;
5396 cfg.mutable_incremental_state_config()->set_clear_period_ms(100);
5397 auto* tracing_session = NewTraceWithCategories({"foo"}, {}, cfg);
5398
5399 tracing_session->get()->StartBlocking();
5400 tracing_session->on_stop.Wait();
5401
5402 EXPECT_TRUE(observer.clear_incremental_state_called);
5403 perfetto::TrackEvent::RemoveSessionObserver(&observer);
5404 auto slices = ReadSlicesFromTraceSession(tracing_session->get());
5405 EXPECT_THAT(slices, ElementsAre("I:foo.OnStart",
5406 "I:foo.WillClearIncrementalState"));
5407 }
5408 EXPECT_FALSE(perfetto::TrackEvent::IsEnabled());
5409 }
5410
TEST_P(PerfettoApiTest,TrackEventObserver_TwoDataSources)5411 TEST_P(PerfettoApiTest, TrackEventObserver_TwoDataSources) {
5412 class Observer : public perfetto::TrackEventSessionObserver {
5413 public:
5414 ~Observer() override = default;
5415
5416 void OnStart(const perfetto::DataSourceBase::StartArgs&) {
5417 EXPECT_FALSE(start_called);
5418 start_called = true;
5419 }
5420
5421 bool start_called{};
5422 };
5423
5424 EXPECT_FALSE(perfetto::TrackEvent::IsEnabled());
5425 EXPECT_FALSE(tracing_module::IsEnabled());
5426
5427 {
5428 Observer observer1, observer2;
5429 perfetto::TrackEvent::AddSessionObserver(&observer1);
5430 tracing_module::AddSessionObserver(&observer2);
5431
5432 perfetto::TraceConfig cfg;
5433 auto* tracing_session = NewTraceWithCategories({"foo"}, {}, cfg);
5434
5435 tracing_session->get()->StartBlocking();
5436 tracing_session->on_stop.Wait();
5437
5438 // The tracing_module hasn't registered its data source yet, so observer2
5439 // should not be notified.
5440 EXPECT_TRUE(observer1.start_called);
5441 EXPECT_FALSE(observer2.start_called);
5442 perfetto::TrackEvent::RemoveSessionObserver(&observer1);
5443 tracing_module::RemoveSessionObserver(&observer2);
5444 }
5445
5446 tracing_module::InitializeCategories();
5447
5448 {
5449 Observer observer1, observer2;
5450 perfetto::TrackEvent::AddSessionObserver(&observer1);
5451 tracing_module::AddSessionObserver(&observer2);
5452
5453 perfetto::TraceConfig cfg;
5454 auto* tracing_session = NewTraceWithCategories({"foo"}, {}, cfg);
5455
5456 tracing_session->get()->StartBlocking();
5457 tracing_session->on_stop.Wait();
5458
5459 // Each observer should be notified exactly once.
5460 EXPECT_TRUE(observer1.start_called);
5461 EXPECT_TRUE(observer2.start_called);
5462 perfetto::TrackEvent::RemoveSessionObserver(&observer1);
5463 tracing_module::RemoveSessionObserver(&observer2);
5464 }
5465
5466 EXPECT_FALSE(perfetto::TrackEvent::IsEnabled());
5467 EXPECT_FALSE(tracing_module::IsEnabled());
5468 }
5469
TEST_P(PerfettoApiTest,TrackEventObserver_AsyncStop)5470 TEST_P(PerfettoApiTest, TrackEventObserver_AsyncStop) {
5471 class Observer : public perfetto::TrackEventSessionObserver {
5472 public:
5473 ~Observer() override = default;
5474
5475 void OnStop(const perfetto::DataSourceBase::StopArgs& args) {
5476 async_stop_closure_ = args.HandleStopAsynchronously();
5477 }
5478
5479 void EmitFinalEvents() {
5480 EXPECT_TRUE(perfetto::TrackEvent::IsEnabled());
5481 EXPECT_TRUE(TRACE_EVENT_CATEGORY_ENABLED("foo"));
5482 TRACE_EVENT_INSTANT("foo", "FinalEvent");
5483 perfetto::TrackEvent::Flush();
5484 async_stop_closure_();
5485 }
5486
5487 private:
5488 std::function<void()> async_stop_closure_;
5489 };
5490
5491 EXPECT_FALSE(perfetto::TrackEvent::IsEnabled());
5492 {
5493 Observer observer;
5494 perfetto::TrackEvent::AddSessionObserver(&observer);
5495
5496 auto* tracing_session = NewTraceWithCategories({"foo"});
5497 WaitableTestEvent consumer_stop_signal;
5498 tracing_session->get()->SetOnStopCallback(
5499 [&consumer_stop_signal] { consumer_stop_signal.Notify(); });
5500 tracing_session->get()->StartBlocking();
5501
5502 // Stop and wait for the producer to have seen the stop event.
5503 tracing_session->get()->Stop();
5504
5505 // At this point tracing should be still allowed because of the
5506 // HandleStopAsynchronously() call. This usleep is here just to prevent that
5507 // we accidentally pass the test just by virtue of hitting some race. We
5508 // should be able to trace up until 5 seconds after seeing the stop when
5509 // using the deferred stop mechanism.
5510 std::this_thread::sleep_for(std::chrono::milliseconds(250));
5511 observer.EmitFinalEvents();
5512
5513 // Wait that the stop is propagated to the consumer.
5514 consumer_stop_signal.Wait();
5515
5516 perfetto::TrackEvent::RemoveSessionObserver(&observer);
5517 auto slices = ReadSlicesFromTraceSession(tracing_session->get());
5518 EXPECT_THAT(slices, ElementsAre("I:foo.FinalEvent"));
5519 }
5520 EXPECT_FALSE(perfetto::TrackEvent::IsEnabled());
5521 }
5522
5523 #if PERFETTO_BUILDFLAG(PERFETTO_COMPILER_CLANG)
5524 struct __attribute__((capability("mutex"))) MockMutex {
Lock__anon78e5bb3c0111::MockMutex5525 void Lock() __attribute__((acquire_capability())) {}
Unlock__anon78e5bb3c0111::MockMutex5526 void Unlock() __attribute__((release_capability())) {}
5527 };
5528
5529 struct AnnotatedObject {
5530 MockMutex mutex;
5531 int value __attribute__((guarded_by(mutex))) = {};
5532 };
5533
TEST_P(PerfettoApiTest,ThreadSafetyAnnotation)5534 TEST_P(PerfettoApiTest, ThreadSafetyAnnotation) {
5535 AnnotatedObject obj;
5536
5537 // Access to the locked field is only allowed while holding the mutex.
5538 obj.mutex.Lock();
5539 obj.value = 1;
5540 obj.mutex.Unlock();
5541
5542 auto* tracing_session = NewTraceWithCategories({"cat"});
5543 tracing_session->get()->StartBlocking();
5544
5545 // It should be possible to trace the field while holding the lock.
5546 obj.mutex.Lock();
5547 TRACE_EVENT_INSTANT("cat", "Instant", "value", obj.value);
5548 TRACE_EVENT_INSTANT1("cat", "InstantLegacy", 0, "value", obj.value);
5549 { TRACE_EVENT("cat", "Scoped", "value", obj.value); }
5550 { TRACE_EVENT1("cat", "ScopedLegacy", "value", obj.value); }
5551 obj.mutex.Unlock();
5552
5553 auto slices = StopSessionAndReadSlicesFromTrace(tracing_session);
5554 EXPECT_THAT(slices, ElementsAre("I:cat.Instant(value=(int)1)",
5555 "[track=0]I:cat.InstantLegacy(value=(int)1)",
5556 "B:cat.Scoped(value=(int)1)", "E",
5557 "B:cat.ScopedLegacy(value=(int)1)", "E"));
5558 }
5559 #endif // PERFETTO_BUILDFLAG(PERFETTO_COMPILER_CLANG)
5560
TEST_P(PerfettoApiTest,CountersDeltaEncoding)5561 TEST_P(PerfettoApiTest, CountersDeltaEncoding) {
5562 auto* tracing_session = NewTraceWithCategories({"cat"});
5563 tracing_session->get()->StartBlocking();
5564
5565 // Describe a counter track.
5566 perfetto::CounterTrack track1 =
5567 perfetto::CounterTrack("Framerate1", "fps1").set_is_incremental(true);
5568 // Global tracks can be constructed at build time.
5569 constexpr perfetto::CounterTrack track2 =
5570 perfetto::CounterTrack::Global("Framerate2", "fps2")
5571 .set_is_incremental(true);
5572 perfetto::CounterTrack track3 = perfetto::CounterTrack("Framerate3", "fps3");
5573
5574 TRACE_COUNTER("cat", track1, 120);
5575 TRACE_COUNTER("cat", track2, 1000);
5576 TRACE_COUNTER("cat", track3, 10009);
5577
5578 TRACE_COUNTER("cat", track1, 10);
5579 TRACE_COUNTER("cat", track1, 1200);
5580 TRACE_COUNTER("cat", track1, 34);
5581
5582 TRACE_COUNTER("cat", track3, 975);
5583 TRACE_COUNTER("cat", track2, 449);
5584 TRACE_COUNTER("cat", track2, 2);
5585
5586 TRACE_COUNTER("cat", track3, 1091);
5587 TRACE_COUNTER("cat", track3, 110);
5588 TRACE_COUNTER("cat", track3, 1081);
5589
5590 TRACE_COUNTER("cat", track1, 98);
5591 TRACE_COUNTER("cat", track2, 1084);
5592
5593 auto trace = StopSessionAndReturnParsedTrace(tracing_session);
5594 std::unordered_map<uint64_t, std::string> counter_names;
5595 // Map(Counter name -> counter values)
5596 std::unordered_map<std::string, std::vector<int64_t>> values;
5597 for (const auto& packet : trace.packet()) {
5598 if (packet.has_track_descriptor()) {
5599 auto& desc = packet.track_descriptor();
5600 if (!desc.has_counter())
5601 continue;
5602 counter_names[desc.uuid()] = desc.name();
5603 EXPECT_EQ((desc.name() != "Framerate3"), desc.counter().is_incremental());
5604 }
5605 if (packet.has_track_event()) {
5606 auto event = packet.track_event();
5607 EXPECT_EQ(perfetto::protos::gen::TrackEvent_Type_TYPE_COUNTER,
5608 event.type());
5609 auto& counter_name = counter_names.at(event.track_uuid());
5610 values[counter_name].push_back(event.counter_value());
5611 }
5612 }
5613 ASSERT_EQ(3u, values.size());
5614 using IntVector = std::vector<int64_t>;
5615 EXPECT_EQ((IntVector{120, -110, 1190, -1166, 64}), values.at("Framerate1"));
5616 EXPECT_EQ((IntVector{1000, -551, -447, 1082}), values.at("Framerate2"));
5617 EXPECT_EQ((IntVector{10009, 975, 1091, 110, 1081}), values.at("Framerate3"));
5618 }
5619
TEST_P(PerfettoApiTest,Counters)5620 TEST_P(PerfettoApiTest, Counters) {
5621 auto* tracing_session = NewTraceWithCategories({"cat"});
5622 tracing_session->get()->StartBlocking();
5623
5624 // Describe a counter track.
5625 perfetto::CounterTrack fps_track = perfetto::CounterTrack("Framerate", "fps");
5626
5627 // Emit an integer sample.
5628 TRACE_COUNTER("cat", fps_track, 120);
5629
5630 // Global tracks can be constructed at build time.
5631 constexpr auto goats_track =
5632 perfetto::CounterTrack::Global("Goats teleported", "goats x 1000")
5633 .set_unit_multiplier(1000);
5634 static_assert(goats_track.uuid == 0x6072fc234f82df11,
5635 "Counter track uuid mismatch");
5636
5637 // Emit some floating point samples.
5638 TRACE_COUNTER("cat", goats_track, 0.25);
5639 TRACE_COUNTER("cat", goats_track, 0.5);
5640 TRACE_COUNTER("cat", goats_track, 0.75);
5641
5642 // Emit a sample using an inline track name.
5643 TRACE_COUNTER("cat", "Voltage", 220);
5644
5645 // Emit sample with a custom timestamp.
5646 TRACE_COUNTER("cat",
5647 perfetto::CounterTrack("Power", "GW").set_category("dmc"),
5648 MyTimestamp(1985u), 1.21f);
5649 auto trace = StopSessionAndReturnParsedTrace(tracing_session);
5650 std::map<uint64_t, std::string> counter_names;
5651 std::vector<std::string> counter_samples;
5652 for (const auto& packet : trace.packet()) {
5653 if (packet.has_track_event()) {
5654 auto event = packet.track_event();
5655 EXPECT_EQ(perfetto::protos::gen::TrackEvent_Type_TYPE_COUNTER,
5656 event.type());
5657 std::stringstream sample;
5658 std::string counter_name = counter_names[event.track_uuid()];
5659 sample << counter_name << " = ";
5660 if (event.has_counter_value()) {
5661 sample << event.counter_value();
5662 } else if (event.has_double_counter_value()) {
5663 sample << event.double_counter_value();
5664 }
5665 if (counter_name == "Power") {
5666 EXPECT_EQ(1985u, packet.timestamp());
5667 }
5668 counter_samples.push_back(sample.str());
5669 }
5670
5671 if (!packet.has_track_descriptor() ||
5672 !packet.track_descriptor().has_counter()) {
5673 continue;
5674 }
5675 auto desc = packet.track_descriptor();
5676 counter_names[desc.uuid()] = desc.name();
5677 if (desc.name() == "Framerate") {
5678 EXPECT_EQ("fps", desc.counter().unit_name());
5679 } else if (desc.name() == "Goats teleported") {
5680 EXPECT_EQ("goats x 1000", desc.counter().unit_name());
5681 EXPECT_EQ(1000, desc.counter().unit_multiplier());
5682 } else if (desc.name() == "Power") {
5683 EXPECT_EQ("GW", desc.counter().unit_name());
5684 EXPECT_EQ("dmc", desc.counter().categories()[0]);
5685 }
5686 }
5687 EXPECT_EQ(4u, counter_names.size());
5688 EXPECT_THAT(counter_samples,
5689 ElementsAre("Framerate = 120", "Goats teleported = 0.25",
5690 "Goats teleported = 0.5", "Goats teleported = 0.75",
5691 "Voltage = 220", "Power = 1.21"));
5692 }
5693
TEST_P(PerfettoApiTest,EmptyEvent)5694 TEST_P(PerfettoApiTest, EmptyEvent) {
5695 auto* tracing_session = NewTraceWithCategories({"test"});
5696 tracing_session->get()->StartBlocking();
5697
5698 TRACE_EVENT_BEGIN("test", "MainEvent");
5699
5700 // An empty event will allow the previous track packet to be scraped.
5701 PERFETTO_INTERNAL_ADD_EMPTY_EVENT();
5702
5703 // Stop tracing but don't flush. Rely on scraping to get the chunk contents.
5704 tracing_session->get()->StopBlocking();
5705
5706 auto slices = ReadSlicesFromTraceSession(tracing_session->get());
5707
5708 EXPECT_THAT(slices, ElementsAre("B:test.MainEvent"));
5709 }
5710
TEST_P(PerfettoApiTest,ConsecutiveEmptyEventsSkipped)5711 TEST_P(PerfettoApiTest, ConsecutiveEmptyEventsSkipped) {
5712 auto* tracing_session = NewTraceWithCategories({"test"});
5713 tracing_session->get()->StartBlocking();
5714
5715 TRACE_EVENT_BEGIN("test", "MainEvent");
5716
5717 // Emit many empty events that wouldn't fit into one chunk.
5718 constexpr int kNumEvents = 10000;
5719 for (int i = 0; i < kNumEvents; ++i) {
5720 PERFETTO_INTERNAL_ADD_EMPTY_EVENT();
5721 }
5722 auto trace = StopSessionAndReturnParsedTrace(tracing_session);
5723 auto it = std::find_if(trace.packet().begin(), trace.packet().end(),
5724 [](const perfetto::protos::gen::TracePacket& packet) {
5725 return packet.has_trace_stats();
5726 });
5727 EXPECT_NE(it, trace.packet().end());
5728 // Extra empty events should be skipped so only one chunk should be allocated.
5729 EXPECT_EQ(it->trace_stats().buffer_stats()[0].chunks_read(), 1u);
5730 }
5731
5732 // Make sure that we set correct track_uuid for legacy events
5733 // of type TrackEvent::TYPE_UNSPECIFIED.
5734 // For such events we set fields of `track_event.legacy_event` and
5735 // we set `track_event.track_uuid` to zero to dissociate it with
5736 // default track.
TEST_P(PerfettoApiTest,CorrectTrackUUIDForLegacyEvents)5737 TEST_P(PerfettoApiTest, CorrectTrackUUIDForLegacyEvents) {
5738 auto* tracing_session = NewTraceWithCategories({"cat"});
5739 tracing_session->get()->StartBlocking();
5740 TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("cat", "foo",
5741 TRACE_ID_WITH_SCOPE("foo", 1));
5742
5743 auto slices = StopSessionAndReadSlicesFromTrace(tracing_session);
5744 EXPECT_THAT(slices,
5745 ElementsAre("[track=0]Legacy_b(unscoped_id=11250026935264495724)("
5746 "id_scope=\"foo\"):cat.foo"));
5747 }
5748
TEST_P(PerfettoApiTest,ActivateTriggers)5749 TEST_P(PerfettoApiTest, ActivateTriggers) {
5750 perfetto::TraceConfig cfg;
5751 cfg.add_buffers()->set_size_kb(1024);
5752 perfetto::TraceConfig::TriggerConfig* tr_cfg = cfg.mutable_trigger_config();
5753 tr_cfg->set_trigger_mode(perfetto::TraceConfig::TriggerConfig::STOP_TRACING);
5754 tr_cfg->set_trigger_timeout_ms(5000);
5755 perfetto::TraceConfig::TriggerConfig::Trigger* trigger =
5756 tr_cfg->add_triggers();
5757 trigger->set_name("trigger1");
5758 auto* tracing_session = NewTrace(cfg);
5759 tracing_session->get()->StartBlocking();
5760
5761 perfetto::Tracing::ActivateTriggers({"trigger2", "trigger1"}, 10000);
5762
5763 tracing_session->on_stop.Wait();
5764
5765 std::vector<char> bytes = tracing_session->get()->ReadTraceBlocking();
5766 perfetto::protos::gen::Trace parsed_trace;
5767 ASSERT_TRUE(parsed_trace.ParseFromArray(bytes.data(), bytes.size()));
5768 EXPECT_THAT(
5769 parsed_trace,
5770 Property(&perfetto::protos::gen::Trace::packet,
5771 Contains(Property(
5772 &perfetto::protos::gen::TracePacket::trigger,
5773 Property(&perfetto::protos::gen::Trigger::trigger_name,
5774 "trigger1")))));
5775 }
5776
TEST_P(PerfettoApiTest,StartTracingWhileExecutingTracepoint)5777 TEST_P(PerfettoApiTest, StartTracingWhileExecutingTracepoint) {
5778 perfetto::TraceConfig cfg;
5779 auto* buffer = cfg.add_buffers();
5780 buffer->set_size_kb(64);
5781 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
5782 ds_cfg->set_name("my_data_source");
5783
5784 std::atomic<bool> quit{false};
5785 WaitableTestEvent outside_tracing;
5786 WaitableTestEvent tracing;
5787 std::thread t([&] {
5788 while (!quit) {
5789 MockDataSource::Trace([&](MockDataSource::TraceContext ctx) {
5790 {
5791 auto packet = ctx.NewTracePacket();
5792 packet->set_for_testing()->set_str("My String");
5793 }
5794 { auto packet = ctx.NewTracePacket(); }
5795 tracing.Notify();
5796 });
5797 outside_tracing.Notify();
5798 std::this_thread::yield();
5799 }
5800 });
5801 outside_tracing.Wait();
5802
5803 auto* tracing_session = NewTrace(cfg);
5804 tracing_session->get()->StartBlocking();
5805 tracing.Wait();
5806 tracing_session->get()->StopBlocking();
5807
5808 // The data source instance should be stopped.
5809 auto* data_source = &data_sources_["my_data_source"];
5810 data_source->on_stop.Wait();
5811
5812 quit = true;
5813 t.join();
5814
5815 auto trace = StopSessionAndReturnParsedTrace(tracing_session);
5816 std::vector<std::string> test_strings;
5817 for (auto& trace_packet : trace.packet()) {
5818 if (trace_packet.has_for_testing()) {
5819 test_strings.push_back(trace_packet.for_testing().str());
5820 }
5821 }
5822 EXPECT_THAT(test_strings, AllOf(Not(IsEmpty()), Each("My String")));
5823 }
5824
TEST_P(PerfettoApiTest,SystemDisconnect)5825 TEST_P(PerfettoApiTest, SystemDisconnect) {
5826 if (GetParam() != perfetto::kSystemBackend) {
5827 GTEST_SKIP();
5828 }
5829 auto* data_source = &data_sources_["my_data_source"];
5830 data_source->handle_stop_asynchronously = true;
5831
5832 perfetto::TraceConfig cfg;
5833 auto* buffer = cfg.add_buffers();
5834 buffer->set_size_kb(64);
5835 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
5836 ds_cfg->set_name("my_data_source");
5837 auto* tracing_session = NewTrace(cfg);
5838 tracing_session->get()->StartBlocking();
5839
5840 std::atomic<bool> quit1{false};
5841 WaitableTestEvent tracing1;
5842 std::atomic<bool> quit2{false};
5843 WaitableTestEvent tracing2;
5844 std::thread t([&] {
5845 while (!quit1) {
5846 MockDataSource::Trace(
5847 [&](MockDataSource::TraceContext) { tracing1.Notify(); });
5848 std::this_thread::yield();
5849 }
5850 while (!quit2) {
5851 MockDataSource::Trace([&](MockDataSource::TraceContext ctx) {
5852 {
5853 auto packet = ctx.NewTracePacket();
5854 packet->set_for_testing()->set_str("New session");
5855 }
5856 { auto packet = ctx.NewTracePacket(); }
5857 tracing2.Notify();
5858 });
5859 std::this_thread::yield();
5860 }
5861 });
5862 auto cleanup = MakeCleanup([&] {
5863 if (t.joinable()) {
5864 quit1 = true;
5865 quit2 = true;
5866 t.join();
5867 }
5868 });
5869 tracing1.Wait();
5870
5871 // Restarts the system service. This will cause the producer and consumer to
5872 // disconnect.
5873 system_service_.Restart();
5874
5875 // The data source instance should be stopped.
5876 data_source->on_stop.Wait();
5877
5878 // The stop is not finalized yet. Test that creating a new trace writer
5879 // doesn't cause any problem.
5880 MockDataSource::Trace([&](MockDataSource::TraceContext ctx) {
5881 {
5882 auto packet = ctx.NewTracePacket();
5883 packet->set_for_testing()->set_str("Content");
5884 }
5885 { auto packet = ctx.NewTracePacket(); }
5886 });
5887
5888 data_source->async_stop_closure();
5889
5890 tracing_session->on_stop.Wait();
5891
5892 std::unique_ptr<perfetto::TracingSession> new_session =
5893 perfetto::Tracing::NewTrace(/*BackendType=*/GetParam());
5894 bool reconnected = false;
5895 for (size_t i = 0; i < 100; i++) {
5896 // Blocking read.
5897 auto result = new_session->QueryServiceStateBlocking();
5898 perfetto::protos::gen::TracingServiceState state;
5899 EXPECT_TRUE(result.success);
5900 EXPECT_TRUE(state.ParseFromArray(result.service_state_data.data(),
5901 result.service_state_data.size()));
5902 // The producer has connected to the new restarted system service.
5903 if (state.producers().size() == 1) {
5904 reconnected = true;
5905 break;
5906 }
5907 std::this_thread::sleep_for(std::chrono::milliseconds(100));
5908 }
5909 ASSERT_TRUE(reconnected);
5910
5911 auto* tracing_session2 = NewTrace(cfg);
5912 tracing_session2->get()->StartBlocking();
5913
5914 quit1 = true;
5915 tracing2.Wait();
5916 quit2 = true;
5917 t.join();
5918
5919 data_source->handle_stop_asynchronously = false;
5920
5921 auto trace = StopSessionAndReturnParsedTrace(tracing_session2);
5922 std::vector<std::string> test_strings;
5923 for (auto& trace_packet : trace.packet()) {
5924 if (trace_packet.has_for_testing()) {
5925 test_strings.push_back(trace_packet.for_testing().str());
5926 }
5927 }
5928 EXPECT_THAT(test_strings, AllOf(Not(IsEmpty()), Each("New session")));
5929 }
5930
5931 class PerfettoStartupTracingApiTest : public PerfettoApiTest {
5932 public:
5933 using SetupStartupTracingOpts = perfetto::Tracing::SetupStartupTracingOpts;
SetupStartupTracing(perfetto::TraceConfig cfg={},SetupStartupTracingOpts opts={})5934 void SetupStartupTracing(perfetto::TraceConfig cfg = {},
5935 SetupStartupTracingOpts opts = {}) {
5936 // Setup startup tracing in the current process.
5937 cfg.set_duration_ms(500);
5938 cfg.add_buffers()->set_size_kb(1024);
5939 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
5940 ds_cfg->set_name("track_event");
5941
5942 perfetto::protos::gen::TrackEventConfig te_cfg;
5943 te_cfg.add_disabled_categories("*");
5944 te_cfg.add_enabled_categories("test");
5945 ds_cfg->set_track_event_config_raw(te_cfg.SerializeAsString());
5946
5947 opts.backend = GetParam();
5948 session_ =
5949 perfetto::Tracing::SetupStartupTracingBlocking(cfg, std::move(opts));
5950 EXPECT_EQ(TRACE_EVENT_CATEGORY_ENABLED("test"), true);
5951 }
5952
AbortStartupTracing()5953 void AbortStartupTracing() {
5954 session_->AbortBlocking();
5955 session_.reset();
5956 }
5957
TearDown()5958 void TearDown() override {
5959 if (session_) {
5960 AbortStartupTracing();
5961 }
5962 // We need to sync producer because when we start StartupTracing, the
5963 // producer is disconnected to reconnect again. Note that
5964 // `SetupStartupTracingBlocking` returns right after data sources are
5965 // started. `SetupStartupTracingBlocking` doesn't wait for reconnection
5966 // to succeed before returning. Hence we need to wait for reconnection here
5967 // because `TracingMuxerImpl::ResetForTesting` will destroy the
5968 // producer if it find it is not connected to service. Which is problematic
5969 // because when reconnection happens (via service transport), it will be
5970 // referencing a deleted producer, which will lead to crash.
5971 perfetto::test::SyncProducers();
5972 this->PerfettoApiTest::TearDown();
5973 }
5974
5975 protected:
5976 std::unique_ptr<perfetto::StartupTracingSession> session_;
5977 };
5978
5979 // Test `SetupStartupTracing` API (non block version).
TEST_P(PerfettoStartupTracingApiTest,NonBlockingAPI)5980 TEST_P(PerfettoStartupTracingApiTest, NonBlockingAPI) {
5981 // Setup startup tracing in the current process.
5982 perfetto::TraceConfig cfg;
5983 cfg.set_duration_ms(500);
5984 cfg.add_buffers()->set_size_kb(1024);
5985 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
5986 ds_cfg->set_name("track_event");
5987
5988 perfetto::protos::gen::TrackEventConfig te_cfg;
5989 te_cfg.add_disabled_categories("*");
5990 te_cfg.add_enabled_categories("test");
5991 ds_cfg->set_track_event_config_raw(te_cfg.SerializeAsString());
5992
5993 SetupStartupTracingOpts opts;
5994 opts.backend = GetParam();
5995 session_ = perfetto::Tracing::SetupStartupTracing(cfg, std::move(opts));
5996 // We need perfetto::test::SyncProducers() to Round-trip to ensure that the
5997 // muxer has enabled startup tracing.
5998 perfetto::test::SyncProducers();
5999 EXPECT_EQ(TRACE_EVENT_CATEGORY_ENABLED("test"), true);
6000
6001 TRACE_EVENT_BEGIN("test", "Event");
6002
6003 // Create a new trace session.
6004 auto* tracing_session = NewTraceWithCategories({"test"});
6005 tracing_session->get()->StartBlocking();
6006
6007 // Emit another event after starting.
6008 TRACE_EVENT_END("test");
6009 // Both events should be retained.
6010 auto slices = StopSessionAndReadSlicesFromTrace(tracing_session);
6011 EXPECT_THAT(slices, ElementsAre("B:test.Event", "E"));
6012 }
6013
TEST_P(PerfettoStartupTracingApiTest,WithExistingSmb)6014 TEST_P(PerfettoStartupTracingApiTest, WithExistingSmb) {
6015 {
6016 // Start and tear down a first session, just to set up the SMB.
6017 auto* tracing_session = NewTraceWithCategories({"foo"});
6018 tracing_session->get()->StartBlocking();
6019 tracing_session->get()->StopBlocking();
6020 }
6021
6022 SetupStartupTracing();
6023 TRACE_EVENT_BEGIN("test", "Event");
6024
6025 // Create a new trace session.
6026 auto* tracing_session = NewTraceWithCategories({"test"});
6027 tracing_session->get()->StartBlocking();
6028
6029 // Emit another event after starting.
6030 TRACE_EVENT_END("test");
6031
6032 // Both events should be retained.
6033 auto slices = StopSessionAndReadSlicesFromTrace(tracing_session);
6034 EXPECT_THAT(slices, ElementsAre("B:test.Event", "E"));
6035 }
6036
TEST_P(PerfettoStartupTracingApiTest,WithProducerProvidedSmb)6037 TEST_P(PerfettoStartupTracingApiTest, WithProducerProvidedSmb) {
6038 ASSERT_FALSE(perfetto::test::TracingMuxerImplInternalsForTest::
6039 DoesSystemBackendHaveSMB());
6040 // The backend has no SMB set up yet. Instead, the SDK will
6041 // reconnect to the backend with a producer-provided SMB.
6042 SetupStartupTracing();
6043 TRACE_EVENT_BEGIN("test", "Event");
6044
6045 // Create a new trace session.
6046 auto* tracing_session = NewTraceWithCategories({"test"});
6047 tracing_session->get()->StartBlocking();
6048
6049 // Emit another event after starting.
6050 TRACE_EVENT_END("test");
6051
6052 // Both events should be retained.
6053 auto slices = StopSessionAndReadSlicesFromTrace(tracing_session);
6054 EXPECT_THAT(slices, ElementsAre("B:test.Event", "E"));
6055 }
6056
TEST_P(PerfettoStartupTracingApiTest,DontTraceBeforeStartupSetup)6057 TEST_P(PerfettoStartupTracingApiTest, DontTraceBeforeStartupSetup) {
6058 // This event should not be recorded.
6059 TRACE_EVENT_BEGIN("test", "EventBeforeStartupTrace");
6060 SetupStartupTracing();
6061 TRACE_EVENT_BEGIN("test", "Event");
6062
6063 auto* tracing_session = NewTraceWithCategories({"test"});
6064 tracing_session->get()->StartBlocking();
6065
6066 TRACE_EVENT_END("test");
6067
6068 auto slices = StopSessionAndReadSlicesFromTrace(tracing_session);
6069
6070 EXPECT_THAT(slices, ElementsAre("B:test.Event", "E"));
6071 }
6072
6073 // Test the StartupTracing when there are multiple data sources registered
6074 // (2 data sources in this test) but only a few of them contribute in startup
6075 // tracing.
TEST_P(PerfettoStartupTracingApiTest,MultipleDataSourceFewContributing)6076 TEST_P(PerfettoStartupTracingApiTest, MultipleDataSourceFewContributing) {
6077 perfetto::TraceConfig cfg;
6078 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
6079 ds_cfg->set_name("CustomDataSource");
6080 SetupStartupTracing(cfg);
6081 TRACE_EVENT_BEGIN("test", "TrackEvent.Startup");
6082 auto* tracing_session = NewTraceWithCategories({"test"}, {}, cfg);
6083 tracing_session->get()->StartBlocking();
6084
6085 TRACE_EVENT_BEGIN("test", "TrackEvent.Main");
6086 perfetto::TrackEvent::Flush();
6087 CustomDataSource::Trace([](CustomDataSource::TraceContext ctx) {
6088 {
6089 auto packet = ctx.NewTracePacket();
6090 packet->set_for_testing()->set_str("CustomDataSource.Main");
6091 }
6092 ctx.Flush();
6093 });
6094
6095 auto trace = StopSessionAndReturnParsedTrace(tracing_session);
6096 auto slices = ReadSlicesFromTrace(trace);
6097 EXPECT_THAT(slices, ElementsAre("B:test.TrackEvent.Startup",
6098 "B:test.TrackEvent.Main"));
6099 std::vector<std::string> test_strings;
6100 for (auto& trace_packet : trace.packet()) {
6101 if (trace_packet.has_for_testing()) {
6102 test_strings.push_back(trace_packet.for_testing().str());
6103 }
6104 }
6105 EXPECT_THAT(test_strings, ElementsAre("CustomDataSource.Main"));
6106 }
6107
6108 // Test the StartupTracing when there are multiple data sources registered
6109 // (2 data sources in this test) and all of them are contributing in startup
6110 // tracing.
TEST_P(PerfettoStartupTracingApiTest,MultipleDataSourceAllContributing)6111 TEST_P(PerfettoStartupTracingApiTest, MultipleDataSourceAllContributing) {
6112 perfetto::TraceConfig cfg;
6113 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
6114 ds_cfg->set_name("CustomDataSource");
6115 SetupStartupTracing(cfg);
6116 TRACE_EVENT_BEGIN("test", "TrackEvent.Startup");
6117 CustomDataSource::Trace([](CustomDataSource::TraceContext ctx) {
6118 auto packet = ctx.NewTracePacket();
6119 packet->set_for_testing()->set_str("CustomDataSource.Startup");
6120 });
6121 auto* tracing_session = NewTraceWithCategories({"test"}, {}, cfg);
6122 tracing_session->get()->StartBlocking();
6123
6124 TRACE_EVENT_BEGIN("test", "TrackEvent.Main");
6125 perfetto::TrackEvent::Flush();
6126 CustomDataSource::Trace([](CustomDataSource::TraceContext ctx) {
6127 {
6128 auto packet = ctx.NewTracePacket();
6129 packet->set_for_testing()->set_str("CustomDataSource.Main");
6130 }
6131 ctx.Flush();
6132 });
6133
6134 auto trace = StopSessionAndReturnParsedTrace(tracing_session);
6135 auto slices = ReadSlicesFromTrace(trace);
6136 EXPECT_THAT(slices, ElementsAre("B:test.TrackEvent.Startup",
6137 "B:test.TrackEvent.Main"));
6138 std::vector<std::string> test_strings;
6139 for (auto& trace_packet : trace.packet()) {
6140 if (trace_packet.has_for_testing()) {
6141 test_strings.push_back(trace_packet.for_testing().str());
6142 }
6143 }
6144 EXPECT_THAT(test_strings,
6145 ElementsAre("CustomDataSource.Startup", "CustomDataSource.Main"));
6146 }
6147
6148 // Startup tracing requires BufferExhaustedPolicy::kDrop, i.e. once the SMB is
6149 // filled with startup events, any further events should be dropped.
6150 // TODO(b/261493947): fix or remove. go/aosp_ci_failure23
TEST_P(PerfettoStartupTracingApiTest,DISABLED_DropPolicy)6151 TEST_P(PerfettoStartupTracingApiTest, DISABLED_DropPolicy) {
6152 SetupStartupTracing();
6153 constexpr int kNumEvents = 100000;
6154 for (int i = 0; i < kNumEvents; i++) {
6155 TRACE_EVENT_BEGIN("test", "StartupEvent");
6156 }
6157
6158 auto* tracing_session = NewTraceWithCategories({"test"});
6159 tracing_session->get()->StartBlocking();
6160
6161 auto slices = StopSessionAndReadSlicesFromTrace(tracing_session);
6162 std::unordered_map<std::string, int> freq_map;
6163 for (auto& slice : slices) {
6164 freq_map[slice]++;
6165 }
6166 EXPECT_GT(freq_map["B:test.StartupEvent"], 0);
6167 EXPECT_LT(freq_map["B:test.StartupEvent"], kNumEvents);
6168 }
6169
6170 // TODO(b/261493947): fix or remove.
TEST_P(PerfettoStartupTracingApiTest,DISABLED_Abort)6171 TEST_P(PerfettoStartupTracingApiTest, DISABLED_Abort) {
6172 SetupStartupTracing();
6173 TRACE_EVENT_BEGIN("test", "StartupEvent");
6174 AbortStartupTracing();
6175
6176 auto* tracing_session = NewTraceWithCategories({"test"});
6177 tracing_session->get()->StartBlocking();
6178
6179 TRACE_EVENT_BEGIN("test", "MainEvent");
6180
6181 auto slices = StopSessionAndReadSlicesFromTrace(tracing_session);
6182
6183 EXPECT_THAT(slices, ElementsAre("B:test.MainEvent"));
6184 }
6185
TEST_P(PerfettoStartupTracingApiTest,AbortAndRestart)6186 TEST_P(PerfettoStartupTracingApiTest, AbortAndRestart) {
6187 SetupStartupTracing();
6188 TRACE_EVENT_BEGIN("test", "StartupEvent1");
6189 AbortStartupTracing();
6190 SetupStartupTracing();
6191 TRACE_EVENT_BEGIN("test", "StartupEvent2");
6192
6193 auto* tracing_session = NewTraceWithCategories({"test"});
6194 tracing_session->get()->StartBlocking();
6195
6196 TRACE_EVENT_BEGIN("test", "MainEvent");
6197 perfetto::TrackEvent::Flush();
6198
6199 tracing_session->get()->StopBlocking();
6200
6201 auto slices = ReadSlicesFromTraceSession(tracing_session->get());
6202
6203 EXPECT_THAT(slices, ElementsAre("B:test.StartupEvent2", "B:test.MainEvent"));
6204 }
6205
TEST_P(PerfettoStartupTracingApiTest,Timeout)6206 TEST_P(PerfettoStartupTracingApiTest, Timeout) {
6207 SetupStartupTracingOpts args;
6208 args.timeout_ms = 2000;
6209 SetupStartupTracing({}, args);
6210 for (int i = 0; i < 25; i++) {
6211 TRACE_EVENT_BEGIN("test", "StartupEvent");
6212 std::this_thread::sleep_for(std::chrono::milliseconds(100));
6213 }
6214
6215 auto* tracing_session = NewTraceWithCategories({"test"});
6216 tracing_session->get()->StartBlocking();
6217 TRACE_EVENT_BEGIN("test", "MainEvent");
6218
6219 perfetto::TrackEvent::Flush();
6220
6221 tracing_session->get()->StopBlocking();
6222
6223 auto slices = ReadSlicesFromTraceSession(tracing_session->get());
6224 EXPECT_THAT(slices, ElementsAre("B:test.MainEvent"));
6225 }
6226
6227 // TODO(b/261493947): fix or remove.
TEST_P(PerfettoStartupTracingApiTest,DISABLED_Callbacks)6228 TEST_P(PerfettoStartupTracingApiTest, DISABLED_Callbacks) {
6229 for (bool abort : {true, false}) {
6230 SetupStartupTracingOpts args;
6231 std::vector<std::string> callback_events;
6232 using CallbackArgs = perfetto::Tracing::OnStartupTracingSetupCallbackArgs;
6233 args.on_setup = [&](CallbackArgs callback_arg) {
6234 callback_events.push_back(
6235 "OnSetup(num_data_sources_started=" +
6236 std::to_string(callback_arg.num_data_sources_started) + ")");
6237 };
6238 args.on_adopted = [&]() { callback_events.push_back("OnAdopted()"); };
6239 args.on_aborted = [&]() { callback_events.push_back("OnAborted()"); };
6240 SetupStartupTracing({}, args);
6241 TRACE_EVENT_BEGIN("test", "StartupEvent");
6242 if (abort) {
6243 AbortStartupTracing();
6244 }
6245 auto* tracing_session = NewTraceWithCategories({"test"});
6246 tracing_session->get()->StartBlocking();
6247
6248 TRACE_EVENT_BEGIN("test", "MainEvent");
6249 perfetto::TrackEvent::Flush();
6250
6251 tracing_session->get()->StopBlocking();
6252
6253 auto slices = ReadSlicesFromTraceSession(tracing_session->get());
6254
6255 ASSERT_EQ(2u, callback_events.size());
6256 EXPECT_EQ("OnSetup(num_data_sources_started=1)", callback_events.at(0));
6257 if (abort) {
6258 EXPECT_THAT(slices, ElementsAre("B:test.MainEvent"));
6259 EXPECT_EQ("OnAborted()", callback_events.at(1));
6260 } else {
6261 EXPECT_THAT(slices,
6262 ElementsAre("B:test.StartupEvent", "B:test.MainEvent"));
6263 EXPECT_EQ("OnAdopted()", callback_events.at(1));
6264 }
6265 }
6266 }
6267
6268 // Test that it's ok if main tracing is never started.
6269 // TODO(b/261493947): fix or remove.
TEST_P(PerfettoStartupTracingApiTest,DISABLED_MainTracingNeverStarted)6270 TEST_P(PerfettoStartupTracingApiTest, DISABLED_MainTracingNeverStarted) {
6271 SetupStartupTracing();
6272 TRACE_EVENT_BEGIN("test", "StartupEvent");
6273 }
6274
6275 // Validates that Startup Trace works fine if we dont emit any event
6276 // during startup tracing session.
TEST_P(PerfettoStartupTracingApiTest,NoEventInStartupTracing)6277 TEST_P(PerfettoStartupTracingApiTest, NoEventInStartupTracing) {
6278 SetupStartupTracing();
6279 auto* tracing_session = NewTraceWithCategories({"test"});
6280 tracing_session->get()->StartBlocking();
6281 // Emit an event now that the session was fully started. This should go
6282 // strait to the SMB.
6283 TRACE_EVENT_BEGIN("test", "MainEvent");
6284 perfetto::TrackEvent::Flush();
6285 tracing_session->get()->StopBlocking();
6286 auto slices = ReadSlicesFromTraceSession(tracing_session->get());
6287 EXPECT_THAT(slices, ElementsAre("B:test.MainEvent"));
6288 }
6289
6290 class ConcurrentSessionTest : public ::testing::Test {
6291 public:
SetUp()6292 void SetUp() override {
6293 system_service_ = perfetto::test::SystemService::Start();
6294 if (!system_service_.valid()) {
6295 GTEST_SKIP();
6296 }
6297 ASSERT_FALSE(perfetto::Tracing::IsInitialized());
6298 }
6299
InitPerfetto(bool supports_multiple_data_source_instances=true)6300 void InitPerfetto(bool supports_multiple_data_source_instances = true) {
6301 TracingInitArgs args;
6302 args.backends = perfetto::kInProcessBackend | perfetto::kSystemBackend;
6303 args.supports_multiple_data_source_instances =
6304 supports_multiple_data_source_instances;
6305 g_test_tracing_policy->should_allow_consumer_connection = true;
6306 args.tracing_policy = g_test_tracing_policy;
6307 perfetto::Tracing::Initialize(args);
6308 perfetto::TrackEvent::Register();
6309 perfetto::test::SyncProducers();
6310 perfetto::test::DisableReconnectLimit();
6311 }
6312
TearDown()6313 void TearDown() override { perfetto::Tracing::ResetForTesting(); }
6314
StartTracing(perfetto::BackendType backend_type,bool short_stop_timeout=false)6315 static std::unique_ptr<perfetto::TracingSession> StartTracing(
6316 perfetto::BackendType backend_type,
6317 bool short_stop_timeout = false) {
6318 perfetto::TraceConfig cfg;
6319 if (short_stop_timeout) {
6320 cfg.set_data_source_stop_timeout_ms(500);
6321 }
6322 cfg.add_buffers()->set_size_kb(1024);
6323 auto* ds_cfg = cfg.add_data_sources()->mutable_config();
6324 ds_cfg->set_name("track_event");
6325 auto tracing_session = perfetto::Tracing::NewTrace(backend_type);
6326 tracing_session->Setup(cfg);
6327 tracing_session->StartBlocking();
6328 return tracing_session;
6329 }
StopTracing(std::unique_ptr<perfetto::TracingSession> tracing_session,bool expect_incremental_state_cleared=true)6330 std::vector<std::string> StopTracing(
6331 std::unique_ptr<perfetto::TracingSession> tracing_session,
6332 bool expect_incremental_state_cleared = true) {
6333 perfetto::TrackEvent::Flush();
6334 tracing_session->StopBlocking();
6335 std::vector<char> trace_data(tracing_session->ReadTraceBlocking());
6336 return ReadSlicesFromTrace(trace_data, expect_incremental_state_cleared);
6337 }
6338
6339 perfetto::test::SystemService system_service_;
6340 };
6341
6342 // Verify that concurrent sessions works well by default.
6343 // (i.e. when `disallow_concurrent_sessions` param is not set)
TEST_F(ConcurrentSessionTest,ConcurrentBackends)6344 TEST_F(ConcurrentSessionTest, ConcurrentBackends) {
6345 InitPerfetto();
6346 auto tracing_session1 = StartTracing(perfetto::kSystemBackend);
6347 TRACE_EVENT_BEGIN("test", "DrawGame1");
6348
6349 auto tracing_session2 = StartTracing(perfetto::kInProcessBackend);
6350 // Should be recorded by both sessions.
6351 TRACE_EVENT_BEGIN("test", "DrawGame2");
6352
6353 auto slices1 = StopTracing(std::move(tracing_session1));
6354 EXPECT_THAT(slices1, ElementsAre("B:test.DrawGame1", "B:test.DrawGame2"));
6355
6356 auto slices2 = StopTracing(std::move(tracing_session2));
6357 EXPECT_THAT(slices2, ElementsAre("B:test.DrawGame2"));
6358
6359 auto tracing_session3 = StartTracing(perfetto::kInProcessBackend);
6360 TRACE_EVENT_BEGIN("test", "DrawGame3");
6361
6362 auto slices3 = StopTracing(std::move(tracing_session3));
6363 EXPECT_THAT(slices3, ElementsAre("B:test.DrawGame3"));
6364 }
6365
6366 // When `supports_multiple_data_source_instances = false`, second session
6367 // should not be started.
TEST_F(ConcurrentSessionTest,DisallowMultipleSessionBasic)6368 TEST_F(ConcurrentSessionTest, DisallowMultipleSessionBasic) {
6369 InitPerfetto(/* supports_multiple_data_source_instances = */ false);
6370 auto tracing_session1 = StartTracing(perfetto::kInProcessBackend);
6371 TRACE_EVENT_BEGIN("test", "DrawGame1");
6372
6373 auto tracing_session2 =
6374 StartTracing(perfetto::kInProcessBackend, /*short_stop_timeout=*/true);
6375 TRACE_EVENT_BEGIN("test", "DrawGame2");
6376
6377 auto slices1 = StopTracing(std::move(tracing_session1));
6378 EXPECT_THAT(slices1, ElementsAre("B:test.DrawGame1", "B:test.DrawGame2"));
6379
6380 auto slices2 = StopTracing(std::move(tracing_session2),
6381 false /* expect_incremental_state_cleared */);
6382 // Because `tracing_session2` was not really started.
6383 EXPECT_THAT(slices2, ElementsAre());
6384
6385 auto tracing_session3 = StartTracing(perfetto::kInProcessBackend);
6386 TRACE_EVENT_BEGIN("test", "DrawGame3");
6387
6388 auto slices3 = StopTracing(std::move(tracing_session3));
6389 EXPECT_THAT(slices3, ElementsAre("B:test.DrawGame3"));
6390 }
6391
TEST(PerfettoApiInitTest,DisableSystemConsumer)6392 TEST(PerfettoApiInitTest, DisableSystemConsumer) {
6393 g_test_tracing_policy->should_allow_consumer_connection = true;
6394
6395 auto system_service = perfetto::test::SystemService::Start();
6396 // If the system backend isn't supported, skip
6397 if (!system_service.valid()) {
6398 GTEST_SKIP();
6399 }
6400
6401 EXPECT_FALSE(perfetto::Tracing::IsInitialized());
6402 TracingInitArgs args;
6403 args.backends = perfetto::kSystemBackend;
6404 args.tracing_policy = g_test_tracing_policy;
6405 args.enable_system_consumer = false;
6406 perfetto::Tracing::Initialize(args);
6407
6408 // If this wasn't the first test to run in this process, any producers
6409 // connected to the old system service will have been disconnected by the
6410 // service restarting above. Wait for all producers to connect again before
6411 // proceeding with the test.
6412 perfetto::test::SyncProducers();
6413
6414 perfetto::test::DisableReconnectLimit();
6415
6416 // Creating the consumer with kUnspecifiedBackend should cause a connection
6417 // error: there's no consumer backend.
6418 {
6419 std::unique_ptr<perfetto::TracingSession> ts =
6420 perfetto::Tracing::NewTrace(perfetto::kUnspecifiedBackend);
6421
6422 WaitableTestEvent got_error;
6423 ts->SetOnErrorCallback([&](perfetto::TracingError error) {
6424 EXPECT_EQ(perfetto::TracingError::kDisconnected, error.code);
6425 EXPECT_FALSE(error.message.empty());
6426 got_error.Notify();
6427 });
6428 got_error.Wait();
6429 }
6430
6431 // Creating the consumer with kSystemBackend should create a system consumer
6432 // backend on the spot.
6433 EXPECT_TRUE(perfetto::Tracing::NewTrace(perfetto::kSystemBackend)
6434 ->QueryServiceStateBlocking()
6435 .success);
6436
6437 // Now even a consumer with kUnspecifiedBackend should succeed, because the
6438 // backend has been created.
6439 EXPECT_TRUE(perfetto::Tracing::NewTrace(perfetto::kUnspecifiedBackend)
6440 ->QueryServiceStateBlocking()
6441 .success);
6442
6443 perfetto::Tracing::ResetForTesting();
6444 }
6445
TEST(PerfettoApiInitTest,SeparateInitializations)6446 TEST(PerfettoApiInitTest, SeparateInitializations) {
6447 auto system_service = perfetto::test::SystemService::Start();
6448 // If the system backend isn't supported, skip
6449 if (!system_service.valid()) {
6450 GTEST_SKIP();
6451 }
6452
6453 {
6454 EXPECT_FALSE(perfetto::Tracing::IsInitialized());
6455 TracingInitArgs args;
6456 args.backends = perfetto::kInProcessBackend;
6457 perfetto::Tracing::Initialize(args);
6458 }
6459
6460 // If this wasn't the first test to run in this process, any producers
6461 // connected to the old system service will have been disconnected by the
6462 // service restarting above. Wait for all producers to connect again before
6463 // proceeding with the test.
6464 perfetto::test::SyncProducers();
6465
6466 perfetto::test::DisableReconnectLimit();
6467
6468 {
6469 perfetto::DataSourceDescriptor dsd;
6470 dsd.set_name("CustomDataSource");
6471 CustomDataSource::Register(dsd);
6472 }
6473
6474 {
6475 std::unique_ptr<perfetto::TracingSession> tracing_session =
6476 perfetto::Tracing::NewTrace(perfetto::kInProcessBackend);
6477 auto result = tracing_session->QueryServiceStateBlocking();
6478 perfetto::protos::gen::TracingServiceState state;
6479 ASSERT_TRUE(result.success);
6480 ASSERT_TRUE(state.ParseFromArray(result.service_state_data.data(),
6481 result.service_state_data.size()));
6482 EXPECT_THAT(state.data_sources(),
6483 Contains(Property(
6484 &perfetto::protos::gen::TracingServiceState::DataSource::
6485 ds_descriptor,
6486 Property(&perfetto::protos::gen::DataSourceDescriptor::name,
6487 "CustomDataSource"))));
6488 }
6489
6490 {
6491 EXPECT_TRUE(perfetto::Tracing::IsInitialized());
6492 TracingInitArgs args;
6493 args.backends = perfetto::kSystemBackend;
6494 args.enable_system_consumer = false;
6495 perfetto::Tracing::Initialize(args);
6496 }
6497
6498 perfetto::test::SyncProducers();
6499
6500 {
6501 std::unique_ptr<perfetto::TracingSession> tracing_session =
6502 perfetto::Tracing::NewTrace(perfetto::kSystemBackend);
6503 auto result = tracing_session->QueryServiceStateBlocking();
6504 perfetto::protos::gen::TracingServiceState state;
6505 ASSERT_TRUE(result.success);
6506 ASSERT_TRUE(state.ParseFromArray(result.service_state_data.data(),
6507 result.service_state_data.size()));
6508 EXPECT_THAT(state.data_sources(),
6509 Contains(Property(
6510 &perfetto::protos::gen::TracingServiceState::DataSource::
6511 ds_descriptor,
6512 Property(&perfetto::protos::gen::DataSourceDescriptor::name,
6513 "CustomDataSource"))));
6514 }
6515 perfetto::test::TracingMuxerImplInternalsForTest::
6516 ClearDataSourceTlsStateOnReset<CustomDataSource>();
6517
6518 perfetto::Tracing::ResetForTesting();
6519 }
6520
6521 struct BackendTypeAsString {
operator ()__anon78e5bb3c0111::BackendTypeAsString6522 std::string operator()(
6523 const ::testing::TestParamInfo<perfetto::BackendType>& info) const {
6524 switch (info.param) {
6525 case perfetto::kInProcessBackend:
6526 return "InProc";
6527 case perfetto::kSystemBackend:
6528 return "System";
6529 case perfetto::kCustomBackend:
6530 return "Custom";
6531 case perfetto::kUnspecifiedBackend:
6532 return "Unspec";
6533 }
6534 return nullptr;
6535 }
6536 };
6537
6538 INSTANTIATE_TEST_SUITE_P(PerfettoApiTest,
6539 PerfettoApiTest,
6540 ::testing::Values(perfetto::kInProcessBackend,
6541 perfetto::kSystemBackend),
6542 BackendTypeAsString());
6543
6544 // In-process backend doesn't support startup tracing.
6545 INSTANTIATE_TEST_SUITE_P(PerfettoStartupTracingApiTest,
6546 PerfettoStartupTracingApiTest,
6547 ::testing::Values(perfetto::kSystemBackend),
6548 BackendTypeAsString());
6549
6550 } // namespace
6551
6552 PERFETTO_DECLARE_DATA_SOURCE_STATIC_MEMBERS(CustomDataSource);
6553 PERFETTO_DECLARE_DATA_SOURCE_STATIC_MEMBERS(MockDataSource);
6554 PERFETTO_DECLARE_DATA_SOURCE_STATIC_MEMBERS(MockDataSource2);
6555 PERFETTO_DECLARE_DATA_SOURCE_STATIC_MEMBERS(TestIncrementalDataSource,
6556 TestIncrementalDataSourceTraits);
6557
6558 PERFETTO_DEFINE_DATA_SOURCE_STATIC_MEMBERS(CustomDataSource);
6559 PERFETTO_DEFINE_DATA_SOURCE_STATIC_MEMBERS(MockDataSource);
6560 PERFETTO_DEFINE_DATA_SOURCE_STATIC_MEMBERS(MockDataSource2);
6561 PERFETTO_DEFINE_DATA_SOURCE_STATIC_MEMBERS(TestIncrementalDataSource,
6562 TestIncrementalDataSourceTraits);
6563