1 // Copyright 2012 The Chromium Authors
2 // Use of this source code is governed by a BSD-style license that can be
3 // found in the LICENSE file.
4
5 #include "base/trace_event/trace_event.h"
6
7 #include <inttypes.h>
8 #include <math.h>
9 #include <stddef.h>
10 #include <stdint.h>
11
12 #include <cstdlib>
13 #include <limits>
14 #include <map>
15 #include <memory>
16 #include <string>
17 #include <utility>
18 #include <vector>
19
20 #include "base/at_exit.h"
21 #include "base/command_line.h"
22 #include "base/functional/bind.h"
23 #include "base/json/json_reader.h"
24 #include "base/json/json_writer.h"
25 #include "base/location.h"
26 #include "base/logging.h"
27 #include "base/memory/ptr_util.h"
28 #include "base/memory/raw_ptr.h"
29 #include "base/memory/ref_counted_memory.h"
30 #include "base/memory/singleton.h"
31 #include "base/process/process_handle.h"
32 #include "base/stl_util.h"
33 #include "base/strings/pattern.h"
34 #include "base/strings/stringprintf.h"
35 #include "base/synchronization/waitable_event.h"
36 #include "base/task/single_thread_task_runner.h"
37 #include "base/threading/platform_thread.h"
38 #include "base/threading/thread.h"
39 #include "base/time/time.h"
40 #include "base/trace_event/trace_buffer.h"
41 #include "base/values.h"
42 #include "build/build_config.h"
43 #include "testing/gmock/include/gmock/gmock.h"
44 #include "testing/gtest/include/gtest/gtest.h"
45
46 #if BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
47 #include "third_party/perfetto/protos/perfetto/config/chrome/chrome_config.gen.h" // nogncheck
48 #endif
49
50 namespace base::trace_event {
51
52 namespace {
53
54 enum CompareOp {
55 IS_EQUAL,
56 IS_NOT_EQUAL,
57 };
58
59 struct JsonKeyValue {
60 const char* key;
61 const char* value;
62 CompareOp op;
63 };
64
65 const int kAsyncId = 5;
66 const char kAsyncIdStr[] = "0x5";
67 const int kAsyncId2 = 6;
68 const char kAsyncId2Str[] = "0x6";
69
70 constexpr const char kRecordAllCategoryFilter[] = "*";
71 constexpr const char kAllCategory[] = "test_all";
72
IsCategoryEnabled(const char * name)73 bool IsCategoryEnabled(const char* name) {
74 #if BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
75 bool result;
76 perfetto::DynamicCategory dynamic_category(name);
77 TRACE_EVENT_CATEGORY_GROUP_ENABLED(dynamic_category, &result);
78 return result;
79 #else
80 return *TraceLog::GetInstance()->GetCategoryGroupEnabled(name);
81 #endif
82 }
83
84 class TraceEventTestFixture : public testing::Test {
85 public:
86 TraceEventTestFixture() = default;
87
88 void OnTraceDataCollected(
89 WaitableEvent* flush_complete_event,
90 const scoped_refptr<base::RefCountedString>& events_str,
91 bool has_more_events);
92 const Value::Dict* FindMatchingTraceEntry(const JsonKeyValue* key_values);
93 const Value::Dict* FindNamePhase(const char* name, const char* phase);
94 const Value::Dict* FindNamePhaseKeyValue(const char* name,
95 const char* phase,
96 const char* key,
97 const char* value);
98 void DropTracedMetadataRecords();
99 bool FindMatchingValue(const char* key,
100 const char* value);
101 bool FindNonMatchingValue(const char* key,
102 const char* value);
Clear()103 void Clear() {
104 trace_parsed_ = Value::List();
105 json_output_.json_output.clear();
106 }
107
BeginTrace()108 void BeginTrace() {
109 BeginSpecificTrace("*");
110 }
111
BeginSpecificTrace(const std::string & filter)112 void BeginSpecificTrace(const std::string& filter) {
113 TraceLog::GetInstance()->SetEnabled(TraceConfig(filter, ""),
114 TraceLog::RECORDING_MODE);
115 }
116
CancelTrace()117 void CancelTrace() {
118 WaitableEvent flush_complete_event(
119 WaitableEvent::ResetPolicy::AUTOMATIC,
120 WaitableEvent::InitialState::NOT_SIGNALED);
121 CancelTraceAsync(&flush_complete_event);
122 flush_complete_event.Wait();
123 }
124
EndTraceAndFlush()125 void EndTraceAndFlush() {
126 num_flush_callbacks_ = 0;
127 WaitableEvent flush_complete_event(
128 WaitableEvent::ResetPolicy::AUTOMATIC,
129 WaitableEvent::InitialState::NOT_SIGNALED);
130 EndTraceAndFlushAsync(&flush_complete_event);
131 flush_complete_event.Wait();
132 }
133
134 // Used when testing thread-local buffers which requires the thread initiating
135 // flush to have a message loop.
EndTraceAndFlushInThreadWithMessageLoop()136 void EndTraceAndFlushInThreadWithMessageLoop() {
137 WaitableEvent flush_complete_event(
138 WaitableEvent::ResetPolicy::AUTOMATIC,
139 WaitableEvent::InitialState::NOT_SIGNALED);
140 Thread flush_thread("flush");
141 flush_thread.Start();
142 flush_thread.task_runner()->PostTask(
143 FROM_HERE,
144 base::BindOnce(&TraceEventTestFixture::EndTraceAndFlushAsync,
145 base::Unretained(this), &flush_complete_event));
146 flush_complete_event.Wait();
147 }
148
CancelTraceAsync(WaitableEvent * flush_complete_event)149 void CancelTraceAsync(WaitableEvent* flush_complete_event) {
150 TraceLog::GetInstance()->CancelTracing(base::BindRepeating(
151 &TraceEventTestFixture::OnTraceDataCollected,
152 base::Unretained(static_cast<TraceEventTestFixture*>(this)),
153 base::Unretained(flush_complete_event)));
154 }
155
EndTraceAndFlushAsync(WaitableEvent * flush_complete_event)156 void EndTraceAndFlushAsync(WaitableEvent* flush_complete_event) {
157 TraceLog::GetInstance()->SetDisabled(TraceLog::RECORDING_MODE);
158 TraceLog::GetInstance()->Flush(base::BindRepeating(
159 &TraceEventTestFixture::OnTraceDataCollected,
160 base::Unretained(static_cast<TraceEventTestFixture*>(this)),
161 base::Unretained(flush_complete_event)));
162 }
163
SetUp()164 void SetUp() override {
165 const char* name = PlatformThread::GetName();
166 old_thread_name_ = name ? name : "";
167
168 TraceLog::ResetForTesting();
169 TraceLog* tracelog = TraceLog::GetInstance();
170 ASSERT_TRUE(tracelog);
171 ASSERT_FALSE(tracelog->IsEnabled());
172 trace_buffer_.SetOutputCallback(json_output_.GetCallback());
173 num_flush_callbacks_ = 0;
174 }
TearDown()175 void TearDown() override {
176 if (TraceLog::GetInstance())
177 EXPECT_FALSE(TraceLog::GetInstance()->IsEnabled());
178 PlatformThread::SetName(old_thread_name_);
179 // We want our singleton torn down after each test.
180 TraceLog::ResetForTesting();
181 }
182
183 std::string old_thread_name_;
184 Value::List trace_parsed_;
185 TraceResultBuffer trace_buffer_;
186 TraceResultBuffer::SimpleOutput json_output_;
187 size_t num_flush_callbacks_;
188
189 private:
190 // We want our singleton torn down after each test.
191 ShadowingAtExitManager at_exit_manager_;
192 Lock lock_;
193 };
194
OnTraceDataCollected(WaitableEvent * flush_complete_event,const scoped_refptr<base::RefCountedString> & events_str,bool has_more_events)195 void TraceEventTestFixture::OnTraceDataCollected(
196 WaitableEvent* flush_complete_event,
197 const scoped_refptr<base::RefCountedString>& events_str,
198 bool has_more_events) {
199 num_flush_callbacks_++;
200 if (num_flush_callbacks_ > 1) {
201 EXPECT_FALSE(events_str->data().empty());
202 }
203 AutoLock lock(lock_);
204 json_output_.json_output.clear();
205 trace_buffer_.Start();
206 trace_buffer_.AddFragment(events_str->data());
207 trace_buffer_.Finish();
208
209 std::optional<Value> root = base::JSONReader::Read(
210 json_output_.json_output, JSON_PARSE_RFC | JSON_ALLOW_CONTROL_CHARS);
211
212 if (!root.has_value()) {
213 LOG(ERROR) << json_output_.json_output;
214 }
215
216 ASSERT_TRUE(root->is_list());
217 Value::List& root_list = root->GetList();
218
219 // Move items into our aggregate collection
220 trace_parsed_.reserve(trace_parsed_.size() + root_list.size());
221 for (auto& value : root_list)
222 trace_parsed_.Append(std::move(value));
223
224 if (!has_more_events)
225 flush_complete_event->Signal();
226 }
227
CompareJsonValues(const std::string & lhs,const std::string & rhs,CompareOp op)228 static bool CompareJsonValues(const std::string& lhs,
229 const std::string& rhs,
230 CompareOp op) {
231 switch (op) {
232 case IS_EQUAL:
233 return lhs == rhs;
234 case IS_NOT_EQUAL:
235 return lhs != rhs;
236 }
237 return false;
238 }
239
IsKeyValueInDict(const JsonKeyValue * key_value,const Value::Dict * dict)240 static bool IsKeyValueInDict(const JsonKeyValue* key_value,
241 const Value::Dict* dict) {
242 const std::string* value_str = dict->FindStringByDottedPath(key_value->key);
243 if (value_str &&
244 CompareJsonValues(*value_str, key_value->value, key_value->op))
245 return true;
246
247 // Recurse to test arguments
248 const Value::Dict* args_dict = dict->FindDictByDottedPath("args");
249 if (args_dict)
250 return IsKeyValueInDict(key_value, args_dict);
251
252 return false;
253 }
254
IsAllKeyValueInDict(const JsonKeyValue * key_values,const Value::Dict * dict)255 static bool IsAllKeyValueInDict(const JsonKeyValue* key_values,
256 const Value::Dict* dict) {
257 // Scan all key_values, they must all be present and equal.
258 while (key_values && key_values->key) {
259 if (!IsKeyValueInDict(key_values, dict)) {
260 return false;
261 }
262 ++key_values;
263 }
264 return true;
265 }
266
FindMatchingTraceEntry(const JsonKeyValue * key_values)267 const Value::Dict* TraceEventTestFixture::FindMatchingTraceEntry(
268 const JsonKeyValue* key_values) {
269 // Scan all items
270 for (const Value& value : trace_parsed_) {
271 if (!value.is_dict()) {
272 continue;
273 }
274
275 if (IsAllKeyValueInDict(key_values, &value.GetDict())) {
276 return &value.GetDict();
277 }
278 }
279 return nullptr;
280 }
281
DropTracedMetadataRecords()282 void TraceEventTestFixture::DropTracedMetadataRecords() {
283 trace_parsed_.EraseIf([](const Value& value) {
284 if (!value.is_dict()) {
285 return false;
286 }
287 const std::string* ph = value.GetDict().FindString("ph");
288 return ph && *ph == "M";
289 });
290 }
291
FindNamePhase(const char * name,const char * phase)292 const Value::Dict* TraceEventTestFixture::FindNamePhase(const char* name,
293 const char* phase) {
294 JsonKeyValue key_values[] = {{"name", name, IS_EQUAL},
295 {"ph", phase, IS_EQUAL},
296 {nullptr, nullptr, IS_EQUAL}};
297 return FindMatchingTraceEntry(key_values);
298 }
299
FindNamePhaseKeyValue(const char * name,const char * phase,const char * key,const char * value)300 const Value::Dict* TraceEventTestFixture::FindNamePhaseKeyValue(
301 const char* name,
302 const char* phase,
303 const char* key,
304 const char* value) {
305 JsonKeyValue key_values[] = {{"name", name, IS_EQUAL},
306 {"ph", phase, IS_EQUAL},
307 {key, value, IS_EQUAL},
308 {nullptr, nullptr, IS_EQUAL}};
309 return FindMatchingTraceEntry(key_values);
310 }
311
FindMatchingValue(const char * key,const char * value)312 bool TraceEventTestFixture::FindMatchingValue(const char* key,
313 const char* value) {
314 JsonKeyValue key_values[] = {{key, value, IS_EQUAL},
315 {nullptr, nullptr, IS_EQUAL}};
316 return FindMatchingTraceEntry(key_values);
317 }
318
FindNonMatchingValue(const char * key,const char * value)319 bool TraceEventTestFixture::FindNonMatchingValue(const char* key,
320 const char* value) {
321 JsonKeyValue key_values[] = {{key, value, IS_NOT_EQUAL},
322 {nullptr, nullptr, IS_EQUAL}};
323 return FindMatchingTraceEntry(key_values);
324 }
325
IsStringInDict(const char * string_to_match,const Value::Dict * dict)326 bool IsStringInDict(const char* string_to_match, const Value::Dict* dict) {
327 for (const auto pair : *dict) {
328 if (pair.first.find(string_to_match) != std::string::npos)
329 return true;
330
331 if (!pair.second.is_string())
332 continue;
333
334 if (pair.second.GetString().find(string_to_match) != std::string::npos)
335 return true;
336 }
337
338 // Recurse to test arguments
339 const Value::Dict* args_dict = dict->FindDict("args");
340 if (args_dict) {
341 return IsStringInDict(string_to_match, args_dict);
342 }
343
344 return false;
345 }
346
FindTraceEntry(const Value::List & trace_parsed,const char * string_to_match,const Value::Dict * match_after_this_item=nullptr)347 const Value::Dict* FindTraceEntry(
348 const Value::List& trace_parsed,
349 const char* string_to_match,
350 const Value::Dict* match_after_this_item = nullptr) {
351 // Scan all items.
352 for (const Value& value : trace_parsed) {
353 const Value::Dict* dict = value.GetIfDict();
354 if (!dict) {
355 continue;
356 }
357 if (match_after_this_item) {
358 if (dict == match_after_this_item) {
359 match_after_this_item = nullptr;
360 }
361 continue;
362 }
363
364 if (IsStringInDict(string_to_match, dict)) {
365 return dict;
366 }
367 }
368 return nullptr;
369 }
370
371 #if !BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
FindTraceEntries(const Value::List & trace_parsed,const char * string_to_match)372 std::vector<const Value::Dict*> FindTraceEntries(
373 const Value::List& trace_parsed,
374 const char* string_to_match) {
375 std::vector<const Value::Dict*> hits;
376 for (const Value& value : trace_parsed) {
377 if (!value.is_dict()) {
378 continue;
379 }
380
381 if (IsStringInDict(string_to_match, &value.GetDict())) {
382 hits.push_back(&value.GetDict());
383 }
384 }
385 return hits;
386 }
387 #endif // !BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
388
389 constexpr const char kControlCharacters[] = "test_\001\002\003\n\r";
390
TraceWithAllMacroVariants(WaitableEvent * task_complete_event)391 void TraceWithAllMacroVariants(WaitableEvent* task_complete_event) {
392 {
393 TRACE_EVENT0("test_all", "TRACE_EVENT0 call");
394 TRACE_EVENT1("test_all", "TRACE_EVENT1 call", "name1", "value1");
395 TRACE_EVENT2("test_all", "TRACE_EVENT2 call", "name1", "\"value1\"",
396 "name2", "value\\2");
397
398 TRACE_EVENT_INSTANT0("test_all", "TRACE_EVENT_INSTANT0 call",
399 TRACE_EVENT_SCOPE_GLOBAL);
400 TRACE_EVENT_INSTANT1("test_all", "TRACE_EVENT_INSTANT1 call",
401 TRACE_EVENT_SCOPE_PROCESS, "name1", "value1");
402 TRACE_EVENT_INSTANT2("test_all", "TRACE_EVENT_INSTANT2 call",
403 TRACE_EVENT_SCOPE_THREAD, "name1", "value1", "name2",
404 "value2");
405
406 TRACE_EVENT_BEGIN0("test_all", "TRACE_EVENT_BEGIN0 call");
407 TRACE_EVENT_BEGIN1("test_all", "TRACE_EVENT_BEGIN1 call", "name1",
408 "value1");
409 TRACE_EVENT_BEGIN2("test_all", "TRACE_EVENT_BEGIN2 call", "name1", "value1",
410 "name2", "value2");
411
412 TRACE_EVENT_END0("test_all", "TRACE_EVENT_BEGIN2 call");
413 TRACE_EVENT_END1("test_all", "TRACE_EVENT_BEGIN1 call", "name1", "value1");
414 TRACE_EVENT_END2("test_all", "TRACE_EVENT_BEGIN0 call", "name1", "value1",
415 "name2", "value2");
416
417 TRACE_EVENT_ASYNC_BEGIN0("test_all", "TRACE_EVENT_ASYNC_BEGIN0 call",
418 kAsyncId);
419 TRACE_EVENT_ASYNC_BEGIN1("test_all", "TRACE_EVENT_ASYNC_BEGIN1 call",
420 kAsyncId, "name1", "value1");
421 TRACE_EVENT_ASYNC_BEGIN2("test_all", "TRACE_EVENT_ASYNC_BEGIN2 call",
422 kAsyncId, "name1", "value1", "name2", "value2");
423
424 TRACE_EVENT_ASYNC_STEP_INTO0("test_all",
425 "TRACE_EVENT_ASYNC_STEP_INTO0 call", kAsyncId,
426 "step_begin1");
427 TRACE_EVENT_ASYNC_STEP_INTO1("test_all",
428 "TRACE_EVENT_ASYNC_STEP_INTO1 call", kAsyncId,
429 "step_begin2", "name1", "value1");
430
431 TRACE_EVENT_ASYNC_END0("test_all", "TRACE_EVENT_ASYNC_END0 call", kAsyncId);
432 TRACE_EVENT_ASYNC_END1("test_all", "TRACE_EVENT_ASYNC_END1 call", kAsyncId,
433 "name1", "value1");
434 TRACE_EVENT_ASYNC_END2("test_all", "TRACE_EVENT_ASYNC_END2 call", kAsyncId,
435 "name1", "value1", "name2", "value2");
436
437 TRACE_COUNTER1("test_all", "TRACE_COUNTER1 call", 31415);
438 TRACE_COUNTER2("test_all", "TRACE_COUNTER2 call", "a", 30000, "b", 1415);
439
440 TRACE_COUNTER_WITH_TIMESTAMP1("test_all",
441 "TRACE_COUNTER_WITH_TIMESTAMP1 call",
442 TimeTicks::FromInternalValue(42), 31415);
443 TRACE_COUNTER_WITH_TIMESTAMP2(
444 "test_all", "TRACE_COUNTER_WITH_TIMESTAMP2 call",
445 TimeTicks::FromInternalValue(42), "a", 30000, "b", 1415);
446
447 TRACE_COUNTER_ID1("test_all", "TRACE_COUNTER_ID1 call", 0x319009, 31415);
448 TRACE_COUNTER_ID2("test_all", "TRACE_COUNTER_ID2 call", 0x319009, "a",
449 30000, "b", 1415);
450
451 TRACE_EVENT_ASYNC_STEP_PAST0("test_all",
452 "TRACE_EVENT_ASYNC_STEP_PAST0 call", kAsyncId2,
453 "step_end1");
454 TRACE_EVENT_ASYNC_STEP_PAST1("test_all",
455 "TRACE_EVENT_ASYNC_STEP_PAST1 call", kAsyncId2,
456 "step_end2", "name1", "value1");
457
458 TRACE_EVENT_OBJECT_CREATED_WITH_ID("test_all", "tracked object 1", 0x42);
459 TRACE_EVENT_OBJECT_SNAPSHOT_WITH_ID("test_all", "tracked object 1", 0x42,
460 "hello");
461 TRACE_EVENT_OBJECT_DELETED_WITH_ID("test_all", "tracked object 1", 0x42);
462
463 TraceScopedTrackableObject<int, kAllCategory> trackable("tracked object 2",
464 0x2128506);
465 trackable.snapshot("world");
466
467 TRACE_EVENT_OBJECT_CREATED_WITH_ID("test_all", "tracked object 3",
468 TRACE_ID_WITH_SCOPE("scope", 0x42));
469 TRACE_EVENT_OBJECT_SNAPSHOT_WITH_ID("test_all", "tracked object 3",
470 TRACE_ID_WITH_SCOPE("scope", 0x42),
471 "hello");
472 TRACE_EVENT_OBJECT_DELETED_WITH_ID("test_all", "tracked object 3",
473 TRACE_ID_WITH_SCOPE("scope", 0x42));
474
475 TRACE_EVENT1(kControlCharacters, kControlCharacters,
476 kControlCharacters, kControlCharacters);
477
478 TRACE_EVENT_ASYNC_BEGIN0("test_all", "async default process scope", 0x1000);
479 TRACE_EVENT_ASYNC_BEGIN0("test_all", "async local id",
480 TRACE_ID_LOCAL(0x2000));
481 TRACE_EVENT_ASYNC_BEGIN0("test_all", "async global id",
482 TRACE_ID_GLOBAL(0x3000));
483 TRACE_EVENT_ASYNC_BEGIN0(
484 "test_all", "async global id with scope string",
485 TRACE_ID_WITH_SCOPE("scope string", TRACE_ID_GLOBAL(0x4000)));
486 } // Scope close causes TRACE_EVENT0 etc to send their END events.
487
488 if (task_complete_event)
489 task_complete_event->Signal();
490 }
491
ValidateAllTraceMacrosCreatedData(const Value::List & trace_parsed)492 void ValidateAllTraceMacrosCreatedData(const Value::List& trace_parsed) {
493 const Value::Dict* item = nullptr;
494
495 #define EXPECT_FIND_(string) \
496 item = FindTraceEntry(trace_parsed, string); \
497 EXPECT_TRUE(item);
498 #define EXPECT_NOT_FIND_(string) \
499 item = FindTraceEntry(trace_parsed, string); \
500 EXPECT_FALSE(item);
501 #define EXPECT_SUB_FIND_(string) \
502 if (item) \
503 EXPECT_TRUE(IsStringInDict(string, item));
504
505 EXPECT_FIND_("TRACE_EVENT0 call");
506 {
507 EXPECT_TRUE((item = FindTraceEntry(trace_parsed, "TRACE_EVENT0 call")));
508 EXPECT_EQ(*item->FindString("ph"), "X");
509 item = FindTraceEntry(trace_parsed, "TRACE_EVENT0 call", item);
510 EXPECT_FALSE(item);
511 }
512 EXPECT_FIND_("TRACE_EVENT1 call");
513 EXPECT_SUB_FIND_("name1");
514 EXPECT_SUB_FIND_("value1");
515 EXPECT_FIND_("TRACE_EVENT2 call");
516 EXPECT_SUB_FIND_("name1");
517 EXPECT_SUB_FIND_("\"value1\"");
518 EXPECT_SUB_FIND_("name2");
519 EXPECT_SUB_FIND_("value\\2");
520
521 EXPECT_FIND_("TRACE_EVENT_INSTANT0 call");
522 { EXPECT_EQ(*item->FindString("s"), "g"); }
523 EXPECT_FIND_("TRACE_EVENT_INSTANT1 call");
524 { EXPECT_EQ(*item->FindString("s"), "p"); }
525 EXPECT_SUB_FIND_("name1");
526 EXPECT_SUB_FIND_("value1");
527 EXPECT_FIND_("TRACE_EVENT_INSTANT2 call");
528 { EXPECT_EQ(*item->FindString("s"), "t"); }
529 EXPECT_SUB_FIND_("name1");
530 EXPECT_SUB_FIND_("value1");
531 EXPECT_SUB_FIND_("name2");
532 EXPECT_SUB_FIND_("value2");
533
534 EXPECT_FIND_("TRACE_EVENT_BEGIN0 call");
535 EXPECT_FIND_("TRACE_EVENT_BEGIN1 call");
536 EXPECT_SUB_FIND_("name1");
537 EXPECT_SUB_FIND_("value1");
538 EXPECT_FIND_("TRACE_EVENT_BEGIN2 call");
539 EXPECT_SUB_FIND_("name1");
540 EXPECT_SUB_FIND_("value1");
541 EXPECT_SUB_FIND_("name2");
542 EXPECT_SUB_FIND_("value2");
543
544 EXPECT_FIND_("TRACE_EVENT_ASYNC_BEGIN0 call");
545 EXPECT_SUB_FIND_("id");
546 EXPECT_SUB_FIND_(kAsyncIdStr);
547 EXPECT_FIND_("TRACE_EVENT_ASYNC_BEGIN1 call");
548 EXPECT_SUB_FIND_("id");
549 EXPECT_SUB_FIND_(kAsyncIdStr);
550 EXPECT_SUB_FIND_("name1");
551 EXPECT_SUB_FIND_("value1");
552 EXPECT_FIND_("TRACE_EVENT_ASYNC_BEGIN2 call");
553 EXPECT_SUB_FIND_("id");
554 EXPECT_SUB_FIND_(kAsyncIdStr);
555 EXPECT_SUB_FIND_("name1");
556 EXPECT_SUB_FIND_("value1");
557 EXPECT_SUB_FIND_("name2");
558 EXPECT_SUB_FIND_("value2");
559
560 EXPECT_FIND_("TRACE_EVENT_ASYNC_STEP_INTO0 call");
561 EXPECT_SUB_FIND_("id");
562 EXPECT_SUB_FIND_(kAsyncIdStr);
563 EXPECT_SUB_FIND_("step_begin1");
564 EXPECT_FIND_("TRACE_EVENT_ASYNC_STEP_INTO1 call");
565 EXPECT_SUB_FIND_("id");
566 EXPECT_SUB_FIND_(kAsyncIdStr);
567 EXPECT_SUB_FIND_("step_begin2");
568 EXPECT_SUB_FIND_("name1");
569 EXPECT_SUB_FIND_("value1");
570
571 // Perfetto doesn't have separate begin and end events.
572 #if !BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
573 EXPECT_FIND_("TRACE_EVENT_ASYNC_END0 call");
574 EXPECT_SUB_FIND_("id");
575 EXPECT_SUB_FIND_(kAsyncIdStr);
576 EXPECT_FIND_("TRACE_EVENT_ASYNC_END1 call");
577 EXPECT_SUB_FIND_("id");
578 EXPECT_SUB_FIND_(kAsyncIdStr);
579 EXPECT_SUB_FIND_("name1");
580 EXPECT_SUB_FIND_("value1");
581 EXPECT_FIND_("TRACE_EVENT_ASYNC_END2 call");
582 EXPECT_SUB_FIND_("id");
583 EXPECT_SUB_FIND_(kAsyncIdStr);
584 EXPECT_SUB_FIND_("name1");
585 EXPECT_SUB_FIND_("value1");
586 EXPECT_SUB_FIND_("name2");
587 EXPECT_SUB_FIND_("value2");
588 #endif // !BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
589
590 EXPECT_FIND_("TRACE_COUNTER1 call");
591 {
592 EXPECT_EQ(*item->FindString("ph"), "C");
593
594 EXPECT_EQ(*item->FindIntByDottedPath("args.value"), 31415);
595 }
596
597 EXPECT_FIND_("TRACE_COUNTER2 call");
598 {
599 EXPECT_EQ(*item->FindString("ph"), "C");
600
601 EXPECT_EQ(*item->FindIntByDottedPath("args.a"), 30000);
602
603 EXPECT_EQ(*item->FindIntByDottedPath("args.b"), 1415);
604 }
605
606 EXPECT_FIND_("TRACE_COUNTER_WITH_TIMESTAMP1 call");
607 {
608 EXPECT_EQ(*item->FindString("ph"), "C");
609
610 EXPECT_EQ(*item->FindIntByDottedPath("args.value"), 31415);
611
612 EXPECT_EQ(*item->FindInt("ts"), 42);
613 }
614
615 EXPECT_FIND_("TRACE_COUNTER_WITH_TIMESTAMP2 call");
616 {
617 EXPECT_EQ(*item->FindString("ph"), "C");
618
619 EXPECT_EQ(*item->FindIntByDottedPath("args.a"), 30000);
620
621 EXPECT_EQ(*item->FindIntByDottedPath("args.b"), 1415);
622
623 EXPECT_EQ(*item->FindInt("ts"), 42);
624 }
625
626 EXPECT_FIND_("TRACE_COUNTER_ID1 call");
627 {
628 EXPECT_EQ(*item->FindString("id"), "0x319009");
629
630 EXPECT_EQ(*item->FindString("ph"), "C");
631
632 EXPECT_EQ(*item->FindIntByDottedPath("args.value"), 31415);
633 }
634
635 EXPECT_FIND_("TRACE_COUNTER_ID2 call");
636 {
637 EXPECT_EQ(*item->FindString("id"), "0x319009");
638
639 EXPECT_EQ(*item->FindString("ph"), "C");
640
641 EXPECT_EQ(*item->FindIntByDottedPath("args.a"), 30000);
642
643 EXPECT_EQ(*item->FindIntByDottedPath("args.b"), 1415);
644 }
645
646 EXPECT_FIND_("TRACE_EVENT_ASYNC_STEP_PAST0 call");
647 {
648 EXPECT_SUB_FIND_("id");
649 EXPECT_SUB_FIND_(kAsyncId2Str);
650 EXPECT_SUB_FIND_("step_end1");
651 EXPECT_FIND_("TRACE_EVENT_ASYNC_STEP_PAST1 call");
652 EXPECT_SUB_FIND_("id");
653 EXPECT_SUB_FIND_(kAsyncId2Str);
654 EXPECT_SUB_FIND_("step_end2");
655 EXPECT_SUB_FIND_("name1");
656 EXPECT_SUB_FIND_("value1");
657 }
658
659 EXPECT_FIND_("tracked object 1");
660 {
661 EXPECT_EQ(*item->FindString("ph"), "N");
662 EXPECT_FALSE(item->contains("scope"));
663 EXPECT_EQ(*item->FindString("id"), "0x42");
664
665 item = FindTraceEntry(trace_parsed, "tracked object 1", item);
666 EXPECT_TRUE(item);
667 EXPECT_EQ(*item->FindString("ph"), "O");
668 EXPECT_FALSE(item->contains("scope"));
669 EXPECT_EQ(*item->FindString("id"), "0x42");
670 EXPECT_EQ(*item->FindStringByDottedPath("args.snapshot"), "hello");
671
672 item = FindTraceEntry(trace_parsed, "tracked object 1", item);
673 EXPECT_TRUE(item);
674 EXPECT_EQ(*item->FindString("ph"), "D");
675 EXPECT_FALSE(item->contains("scope"));
676 EXPECT_EQ(*item->FindString("id"), "0x42");
677 }
678
679 EXPECT_FIND_("tracked object 2");
680 {
681 EXPECT_EQ(*item->FindString("ph"), "N");
682 EXPECT_EQ(*item->FindString("id"), "0x2128506");
683
684 item = FindTraceEntry(trace_parsed, "tracked object 2", item);
685 EXPECT_TRUE(item);
686 EXPECT_EQ(*item->FindString("ph"), "O");
687 EXPECT_EQ(*item->FindString("id"), "0x2128506");
688 EXPECT_EQ(*item->FindStringByDottedPath("args.snapshot"), "world");
689
690 item = FindTraceEntry(trace_parsed, "tracked object 2", item);
691 EXPECT_TRUE(item);
692 EXPECT_EQ(*item->FindString("ph"), "D");
693 EXPECT_EQ(*item->FindString("id"), "0x2128506");
694 }
695
696 EXPECT_FIND_("tracked object 3");
697 {
698 #if BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
699 auto* id_hash = "0x6a31ee0fa7951e05";
700 #else
701 auto* id_hash = "0x42";
702 #endif
703 EXPECT_EQ(*item->FindString("ph"), "N");
704 EXPECT_EQ(*item->FindString("scope"), "scope");
705 EXPECT_EQ(*item->FindString("id"), id_hash);
706
707 item = FindTraceEntry(trace_parsed, "tracked object 3", item);
708 EXPECT_TRUE(item);
709 EXPECT_EQ(*item->FindString("ph"), "O");
710 EXPECT_EQ(*item->FindString("scope"), "scope");
711 EXPECT_EQ(*item->FindString("id"), id_hash);
712 EXPECT_EQ(*item->FindStringByDottedPath("args.snapshot"), "hello");
713
714 item = FindTraceEntry(trace_parsed, "tracked object 3", item);
715 EXPECT_TRUE(item);
716 EXPECT_EQ(*item->FindString("ph"), "D");
717 EXPECT_EQ(*item->FindString("scope"), "scope");
718 EXPECT_EQ(*item->FindString("id"), id_hash);
719 }
720
721 EXPECT_FIND_(kControlCharacters);
722 EXPECT_SUB_FIND_(kControlCharacters);
723
724 EXPECT_FIND_("async default process scope");
725 {
726 EXPECT_EQ(*item->FindString("ph"), "S");
727
728 EXPECT_EQ(*item->FindString("id"), "0x1000");
729 }
730
731 EXPECT_FIND_("async local id");
732 {
733 EXPECT_EQ(*item->FindString("ph"), "S");
734
735 EXPECT_EQ(*item->FindStringByDottedPath("id2.local"), "0x2000");
736 }
737
738 EXPECT_FIND_("async global id");
739 {
740 EXPECT_EQ(*item->FindString("ph"), "S");
741
742 #if BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
743 const char kIdPath[] = "id";
744 #else
745 const char kIdPath[] = "id2.global";
746 #endif
747 EXPECT_EQ(*item->FindStringByDottedPath(kIdPath), "0x3000");
748 }
749
750 EXPECT_FIND_("async global id with scope string");
751 {
752 EXPECT_EQ(*item->FindString("ph"), "S");
753
754 #if BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
755 const char kIdPath[] = "id";
756 #else
757 const char kIdPath[] = "id2.global";
758 #endif
759 EXPECT_EQ(*item->FindStringByDottedPath(kIdPath), "0x4000");
760
761 #if BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
762 const char kExpectedScope[] = "test_all:scope string";
763 #else
764 const char kExpectedScope[] = "scope string";
765 #endif
766
767 EXPECT_EQ(*item->FindStringByDottedPath("scope"), kExpectedScope);
768 }
769 }
770
TraceManyInstantEvents(int thread_id,int num_events,WaitableEvent * task_complete_event)771 void TraceManyInstantEvents(int thread_id, int num_events,
772 WaitableEvent* task_complete_event) {
773 for (int i = 0; i < num_events; i++) {
774 TRACE_EVENT_INSTANT2("test_all", "multi thread event",
775 TRACE_EVENT_SCOPE_THREAD, "thread", thread_id, "event",
776 i);
777 }
778
779 if (task_complete_event)
780 task_complete_event->Signal();
781 }
782
ValidateInstantEventPresentOnEveryThread(const Value::List & trace_parsed,int num_threads,int num_events)783 void ValidateInstantEventPresentOnEveryThread(const Value::List& trace_parsed,
784 int num_threads,
785 int num_events) {
786 std::map<int, std::map<int, bool>> results;
787
788 for (const Value& value : trace_parsed) {
789 const Value::Dict* dict = value.GetIfDict();
790 if (!dict) {
791 continue;
792 }
793
794 const std::string* name = dict->FindString("name");
795 if (!name || *name != "multi thread event")
796 continue;
797
798 std::optional<int> maybe_thread = dict->FindIntByDottedPath("args.thread");
799 std::optional<int> maybe_event = dict->FindIntByDottedPath("args.event");
800
801 EXPECT_TRUE(maybe_thread.has_value());
802 EXPECT_TRUE(maybe_event.has_value());
803 results[maybe_thread.value_or(0)][maybe_event.value_or(0)] = true;
804 }
805
806 EXPECT_FALSE(results[-1][-1]);
807 for (int thread = 0; thread < num_threads; thread++) {
808 for (int event = 0; event < num_events; event++) {
809 EXPECT_TRUE(results[thread][event]);
810 }
811 }
812 }
813
CheckTraceDefaultCategoryFilters(const TraceLog & trace_log)814 void CheckTraceDefaultCategoryFilters(const TraceLog& trace_log) {
815 // Default enables all category filters except the disabled-by-default-* ones.
816 EXPECT_TRUE(IsCategoryEnabled("foo"));
817 EXPECT_TRUE(IsCategoryEnabled("bar"));
818 EXPECT_TRUE(IsCategoryEnabled("foo,bar"));
819 EXPECT_TRUE(IsCategoryEnabled("foo,disabled-by-default-foo"));
820 EXPECT_FALSE(
821 IsCategoryEnabled("disabled-by-default-foo,disabled-by-default-bar"));
822 }
823
824 } // namespace
825
826 // Simple Test for emitting data and validating it was received.
TEST_F(TraceEventTestFixture,DataCaptured)827 TEST_F(TraceEventTestFixture, DataCaptured) {
828 TraceLog::GetInstance()->SetEnabled(TraceConfig(kRecordAllCategoryFilter, ""),
829 TraceLog::RECORDING_MODE);
830
831 TraceWithAllMacroVariants(nullptr);
832
833 EndTraceAndFlush();
834
835 ValidateAllTraceMacrosCreatedData(trace_parsed_);
836 }
837
838 // Emit some events and validate that only empty strings are received
839 // if we tell Flush() to discard events.
TEST_F(TraceEventTestFixture,DataDiscarded)840 TEST_F(TraceEventTestFixture, DataDiscarded) {
841 TraceLog::GetInstance()->SetEnabled(TraceConfig(kRecordAllCategoryFilter, ""),
842 TraceLog::RECORDING_MODE);
843
844 TraceWithAllMacroVariants(nullptr);
845
846 CancelTrace();
847
848 EXPECT_TRUE(trace_parsed_.empty());
849 }
850
851 class MockEnabledStateChangedObserver :
852 public TraceLog::EnabledStateObserver {
853 public:
854 MOCK_METHOD0(OnTraceLogEnabled, void());
855 MOCK_METHOD0(OnTraceLogDisabled, void());
856 };
857
TEST_F(TraceEventTestFixture,EnabledObserverFiresOnEnable)858 TEST_F(TraceEventTestFixture, EnabledObserverFiresOnEnable) {
859 MockEnabledStateChangedObserver observer;
860 TraceLog::GetInstance()->AddEnabledStateObserver(&observer);
861
862 EXPECT_CALL(observer, OnTraceLogEnabled())
863 .Times(1);
864 TraceLog::GetInstance()->SetEnabled(TraceConfig(kRecordAllCategoryFilter, ""),
865 TraceLog::RECORDING_MODE);
866 testing::Mock::VerifyAndClear(&observer);
867 EXPECT_TRUE(TraceLog::GetInstance()->IsEnabled());
868
869 // Cleanup.
870 TraceLog::GetInstance()->RemoveEnabledStateObserver(&observer);
871 TraceLog::GetInstance()->SetDisabled();
872 }
873
874 // Nested TraceLog enabling isn't supported by Perfetto.
875 #if !BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
TEST_F(TraceEventTestFixture,EnabledObserverDoesntFireOnSecondEnable)876 TEST_F(TraceEventTestFixture, EnabledObserverDoesntFireOnSecondEnable) {
877 TraceLog::GetInstance()->SetEnabled(TraceConfig(kRecordAllCategoryFilter, ""),
878 TraceLog::RECORDING_MODE);
879
880 testing::StrictMock<MockEnabledStateChangedObserver> observer;
881 TraceLog::GetInstance()->AddEnabledStateObserver(&observer);
882
883 EXPECT_CALL(observer, OnTraceLogEnabled())
884 .Times(0);
885 EXPECT_CALL(observer, OnTraceLogDisabled())
886 .Times(0);
887 TraceLog::GetInstance()->SetEnabled(TraceConfig(kRecordAllCategoryFilter, ""),
888 TraceLog::RECORDING_MODE);
889 testing::Mock::VerifyAndClear(&observer);
890 EXPECT_TRUE(TraceLog::GetInstance()->IsEnabled());
891
892 // Cleanup.
893 TraceLog::GetInstance()->RemoveEnabledStateObserver(&observer);
894 TraceLog::GetInstance()->SetDisabled();
895 TraceLog::GetInstance()->SetDisabled();
896 }
897
TEST_F(TraceEventTestFixture,EnabledObserverFiresOnFirstDisable)898 TEST_F(TraceEventTestFixture, EnabledObserverFiresOnFirstDisable) {
899 TraceConfig tc_inc_all("*", "");
900 TraceLog::GetInstance()->SetEnabled(tc_inc_all, TraceLog::RECORDING_MODE);
901 TraceLog::GetInstance()->SetEnabled(tc_inc_all, TraceLog::RECORDING_MODE);
902
903 testing::StrictMock<MockEnabledStateChangedObserver> observer;
904 TraceLog::GetInstance()->AddEnabledStateObserver(&observer);
905
906 EXPECT_CALL(observer, OnTraceLogEnabled())
907 .Times(0);
908 EXPECT_CALL(observer, OnTraceLogDisabled())
909 .Times(1);
910 TraceLog::GetInstance()->SetDisabled();
911 testing::Mock::VerifyAndClear(&observer);
912
913 // Cleanup.
914 TraceLog::GetInstance()->RemoveEnabledStateObserver(&observer);
915 TraceLog::GetInstance()->SetDisabled();
916 }
917 #endif // !BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
918
TEST_F(TraceEventTestFixture,EnabledObserverFiresOnDisable)919 TEST_F(TraceEventTestFixture, EnabledObserverFiresOnDisable) {
920 TraceLog::GetInstance()->SetEnabled(TraceConfig(kRecordAllCategoryFilter, ""),
921 TraceLog::RECORDING_MODE);
922
923 MockEnabledStateChangedObserver observer;
924 TraceLog::GetInstance()->AddEnabledStateObserver(&observer);
925
926 EXPECT_CALL(observer, OnTraceLogDisabled())
927 .Times(1);
928 TraceLog::GetInstance()->SetDisabled();
929 testing::Mock::VerifyAndClear(&observer);
930
931 // Cleanup.
932 TraceLog::GetInstance()->RemoveEnabledStateObserver(&observer);
933 }
934
TEST_F(TraceEventTestFixture,EnabledObserverOwnedByTraceLog)935 TEST_F(TraceEventTestFixture, EnabledObserverOwnedByTraceLog) {
936 auto observer = std::make_unique<MockEnabledStateChangedObserver>();
937 EXPECT_CALL(*observer, OnTraceLogEnabled()).Times(1);
938 EXPECT_CALL(*observer, OnTraceLogDisabled()).Times(1);
939 TraceLog::GetInstance()->AddOwnedEnabledStateObserver(std::move(observer));
940 TraceLog::GetInstance()->SetEnabled(TraceConfig(kRecordAllCategoryFilter, ""),
941 TraceLog::RECORDING_MODE);
942 TraceLog::GetInstance()->SetDisabled();
943 TraceLog::ResetForTesting();
944 // These notifications won't be sent.
945 TraceLog::GetInstance()->SetEnabled(TraceConfig(kRecordAllCategoryFilter, ""),
946 TraceLog::RECORDING_MODE);
947 TraceLog::GetInstance()->SetDisabled();
948 }
949
950 // Tests the IsEnabled() state of TraceLog changes before callbacks.
951 class AfterStateChangeEnabledStateObserver
952 : public TraceLog::EnabledStateObserver {
953 public:
954 AfterStateChangeEnabledStateObserver() = default;
955 ~AfterStateChangeEnabledStateObserver() override = default;
956
957 // TraceLog::EnabledStateObserver overrides:
OnTraceLogEnabled()958 void OnTraceLogEnabled() override {
959 EXPECT_TRUE(TraceLog::GetInstance()->IsEnabled());
960 }
961
OnTraceLogDisabled()962 void OnTraceLogDisabled() override {
963 EXPECT_FALSE(TraceLog::GetInstance()->IsEnabled());
964 }
965 };
966
TEST_F(TraceEventTestFixture,ObserversFireAfterStateChange)967 TEST_F(TraceEventTestFixture, ObserversFireAfterStateChange) {
968 AfterStateChangeEnabledStateObserver observer;
969 TraceLog::GetInstance()->AddEnabledStateObserver(&observer);
970
971 TraceLog::GetInstance()->SetEnabled(TraceConfig(kRecordAllCategoryFilter, ""),
972 TraceLog::RECORDING_MODE);
973 EXPECT_TRUE(TraceLog::GetInstance()->IsEnabled());
974
975 TraceLog::GetInstance()->SetDisabled();
976 EXPECT_FALSE(TraceLog::GetInstance()->IsEnabled());
977
978 TraceLog::GetInstance()->RemoveEnabledStateObserver(&observer);
979 }
980
981 // Tests that a state observer can remove itself during a callback.
982 class SelfRemovingEnabledStateObserver
983 : public TraceLog::EnabledStateObserver {
984 public:
985 SelfRemovingEnabledStateObserver() = default;
986 ~SelfRemovingEnabledStateObserver() override = default;
987
988 // TraceLog::EnabledStateObserver overrides:
OnTraceLogEnabled()989 void OnTraceLogEnabled() override {}
990
OnTraceLogDisabled()991 void OnTraceLogDisabled() override {
992 TraceLog::GetInstance()->RemoveEnabledStateObserver(this);
993 }
994 };
995
996 // Self removing observers are not supported at the moment.
997 // TODO(alph): We could add support once we have recursive locks.
TEST_F(TraceEventTestFixture,DISABLED_SelfRemovingObserver)998 TEST_F(TraceEventTestFixture, DISABLED_SelfRemovingObserver) {
999 ASSERT_EQ(0u, TraceLog::GetInstance()->GetObserverCountForTest());
1000
1001 SelfRemovingEnabledStateObserver observer;
1002 TraceLog::GetInstance()->AddEnabledStateObserver(&observer);
1003 EXPECT_EQ(1u, TraceLog::GetInstance()->GetObserverCountForTest());
1004
1005 TraceLog::GetInstance()->SetEnabled(TraceConfig(kRecordAllCategoryFilter, ""),
1006 TraceLog::RECORDING_MODE);
1007 TraceLog::GetInstance()->SetDisabled();
1008 // The observer removed itself on disable.
1009 EXPECT_EQ(0u, TraceLog::GetInstance()->GetObserverCountForTest());
1010 }
1011
IsNewTrace()1012 bool IsNewTrace() {
1013 bool is_new_trace;
1014 TRACE_EVENT_IS_NEW_TRACE(&is_new_trace);
1015 return is_new_trace;
1016 }
1017
TEST_F(TraceEventTestFixture,NewTraceRecording)1018 TEST_F(TraceEventTestFixture, NewTraceRecording) {
1019 ASSERT_FALSE(IsNewTrace());
1020 TraceLog::GetInstance()->SetEnabled(TraceConfig(kRecordAllCategoryFilter, ""),
1021 TraceLog::RECORDING_MODE);
1022 // First call to IsNewTrace() should succeed. But, the second shouldn't.
1023 ASSERT_TRUE(IsNewTrace());
1024 ASSERT_FALSE(IsNewTrace());
1025 EndTraceAndFlush();
1026
1027 // IsNewTrace() should definitely be false now.
1028 ASSERT_FALSE(IsNewTrace());
1029
1030 // Start another trace. IsNewTrace() should become true again, briefly, as
1031 // before.
1032 TraceLog::GetInstance()->SetEnabled(TraceConfig(kRecordAllCategoryFilter, ""),
1033 TraceLog::RECORDING_MODE);
1034 ASSERT_TRUE(IsNewTrace());
1035 ASSERT_FALSE(IsNewTrace());
1036
1037 // Cleanup.
1038 EndTraceAndFlush();
1039 }
1040
1041 // This test is not meaningful with Perfetto's deferred flushing behavior.
1042 #if !BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
TEST_F(TraceEventTestFixture,TestTraceFlush)1043 TEST_F(TraceEventTestFixture, TestTraceFlush) {
1044 size_t min_traces = 1;
1045 size_t max_traces = 1;
1046 do {
1047 max_traces *= 2;
1048 TraceLog::GetInstance()->SetEnabled(TraceConfig(),
1049 TraceLog::RECORDING_MODE);
1050 for (size_t i = 0; i < max_traces; i++) {
1051 TRACE_EVENT_INSTANT0("test_x", "y", TRACE_EVENT_SCOPE_THREAD);
1052 }
1053 EndTraceAndFlush();
1054 } while (num_flush_callbacks_ < 2);
1055
1056 while (min_traces + 50 < max_traces) {
1057 size_t traces = (min_traces + max_traces) / 2;
1058 TraceLog::GetInstance()->SetEnabled(TraceConfig(),
1059 TraceLog::RECORDING_MODE);
1060 for (size_t i = 0; i < traces; i++) {
1061 TRACE_EVENT_INSTANT0("test_x", "y", TRACE_EVENT_SCOPE_THREAD);
1062 }
1063 EndTraceAndFlush();
1064 if (num_flush_callbacks_ < 2) {
1065 min_traces = traces - 10;
1066 } else {
1067 max_traces = traces + 10;
1068 }
1069 }
1070
1071 for (size_t traces = min_traces; traces < max_traces; traces++) {
1072 TraceLog::GetInstance()->SetEnabled(TraceConfig(),
1073 TraceLog::RECORDING_MODE);
1074 for (size_t i = 0; i < traces; i++) {
1075 TRACE_EVENT_INSTANT0("test_x", "y", TRACE_EVENT_SCOPE_THREAD);
1076 }
1077 EndTraceAndFlush();
1078 }
1079 }
1080 #endif // !BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
1081
TEST_F(TraceEventTestFixture,AddMetadataEvent)1082 TEST_F(TraceEventTestFixture, AddMetadataEvent) {
1083 int num_calls = 0;
1084
1085 class Convertable : public ConvertableToTraceFormat {
1086 public:
1087 explicit Convertable(int* num_calls) : num_calls_(num_calls) {}
1088 ~Convertable() override = default;
1089 void AppendAsTraceFormat(std::string* out) const override {
1090 (*num_calls_)++;
1091 out->append("\"metadata_value\"");
1092 }
1093
1094 private:
1095 raw_ptr<int> num_calls_;
1096 };
1097
1098 std::unique_ptr<ConvertableToTraceFormat> conv1(new Convertable(&num_calls));
1099 std::unique_ptr<Convertable> conv2(new Convertable(&num_calls));
1100
1101 BeginTrace();
1102 TRACE_EVENT_API_ADD_METADATA_EVENT(
1103 TraceLog::GetCategoryGroupEnabled("__metadata"), "metadata_event_1",
1104 "metadata_arg_name", std::move(conv1));
1105 TRACE_EVENT_API_ADD_METADATA_EVENT(
1106 TraceLog::GetCategoryGroupEnabled("__metadata"), "metadata_event_2",
1107 "metadata_arg_name", std::move(conv2));
1108 // |AppendAsTraceFormat| should only be called on flush, not when the event
1109 // is added.
1110 ASSERT_EQ(0, num_calls);
1111 EndTraceAndFlush();
1112 ASSERT_EQ(2, num_calls);
1113 EXPECT_TRUE(FindNamePhaseKeyValue("metadata_event_1", "M",
1114 "metadata_arg_name", "metadata_value"));
1115 EXPECT_TRUE(FindNamePhaseKeyValue("metadata_event_2", "M",
1116 "metadata_arg_name", "metadata_value"));
1117
1118 // The metadata event should only be adde to the current trace. In this new
1119 // trace, the event should not appear.
1120 BeginTrace();
1121 EndTraceAndFlush();
1122 ASSERT_EQ(2, num_calls);
1123 }
1124
1125 // Test that categories work.
TEST_F(TraceEventTestFixture,Categories)1126 TEST_F(TraceEventTestFixture, Categories) {
1127 const std::vector<std::string> empty_categories;
1128 std::vector<std::string> included_categories;
1129 std::vector<std::string> excluded_categories;
1130
1131 // Test that category filtering works.
1132
1133 // Include nonexistent category -> no events
1134 Clear();
1135 included_categories.clear();
1136 TraceLog::GetInstance()->SetEnabled(TraceConfig("not_found823564786", ""),
1137 TraceLog::RECORDING_MODE);
1138 TRACE_EVENT_INSTANT0("cat1", "name", TRACE_EVENT_SCOPE_THREAD);
1139 TRACE_EVENT_INSTANT0("cat2", "name", TRACE_EVENT_SCOPE_THREAD);
1140 EndTraceAndFlush();
1141 DropTracedMetadataRecords();
1142 EXPECT_TRUE(trace_parsed_.empty());
1143
1144 // Include existent category -> only events of that category
1145 Clear();
1146 included_categories.clear();
1147 TraceLog::GetInstance()->SetEnabled(TraceConfig("test_inc", ""),
1148 TraceLog::RECORDING_MODE);
1149 TRACE_EVENT_INSTANT0("test_inc", "name", TRACE_EVENT_SCOPE_THREAD);
1150 TRACE_EVENT_INSTANT0("test_inc2", "name", TRACE_EVENT_SCOPE_THREAD);
1151 EndTraceAndFlush();
1152 DropTracedMetadataRecords();
1153 EXPECT_TRUE(FindMatchingValue("cat", "test_inc"));
1154 EXPECT_FALSE(FindNonMatchingValue("cat", "test_inc"));
1155
1156 // Include existent wildcard -> all categories matching wildcard
1157 Clear();
1158 included_categories.clear();
1159 TraceLog::GetInstance()->SetEnabled(TraceConfig("test_inc_wildcard_*", ""),
1160 TraceLog::RECORDING_MODE);
1161 TRACE_EVENT_INSTANT0("test_inc_wildcard_abc", "included",
1162 TRACE_EVENT_SCOPE_THREAD);
1163 TRACE_EVENT_INSTANT0("test_inc_wildcard_", "included",
1164 TRACE_EVENT_SCOPE_THREAD);
1165 TRACE_EVENT_INSTANT0("cat1", "not_inc", TRACE_EVENT_SCOPE_THREAD);
1166 TRACE_EVENT_INSTANT0("cat2", "not_inc", TRACE_EVENT_SCOPE_THREAD);
1167 TRACE_EVENT_INSTANT0("test_inc_wildcard_category,test_other_category",
1168 "included", TRACE_EVENT_SCOPE_THREAD);
1169 TRACE_EVENT_INSTANT0("test_non_included_category,test_inc_wildcard_category",
1170 "included", TRACE_EVENT_SCOPE_THREAD);
1171 EndTraceAndFlush();
1172 EXPECT_TRUE(FindMatchingValue("cat", "test_inc_wildcard_abc"));
1173 EXPECT_TRUE(FindMatchingValue("cat", "test_inc_wildcard_"));
1174 EXPECT_FALSE(FindMatchingValue("name", "not_inc"));
1175 EXPECT_TRUE(FindMatchingValue(
1176 "cat", "test_inc_wildcard_category,test_other_category"));
1177 EXPECT_TRUE(FindMatchingValue(
1178 "cat", "test_non_included_category,test_inc_wildcard_category"));
1179
1180 included_categories.clear();
1181
1182 // Exclude nonexistent category -> all events
1183 Clear();
1184 TraceLog::GetInstance()->SetEnabled(TraceConfig("-not_found823564786", ""),
1185 TraceLog::RECORDING_MODE);
1186 TRACE_EVENT_INSTANT0("cat1", "name", TRACE_EVENT_SCOPE_THREAD);
1187 TRACE_EVENT_INSTANT0("cat2", "name", TRACE_EVENT_SCOPE_THREAD);
1188 TRACE_EVENT_INSTANT0("category1,category2", "name", TRACE_EVENT_SCOPE_THREAD);
1189 EndTraceAndFlush();
1190 EXPECT_TRUE(FindMatchingValue("cat", "cat1"));
1191 EXPECT_TRUE(FindMatchingValue("cat", "cat2"));
1192 EXPECT_TRUE(FindMatchingValue("cat", "category1,category2"));
1193
1194 // Exclude existent category -> only events of other categories
1195 Clear();
1196 TraceLog::GetInstance()->SetEnabled(TraceConfig("-test_inc", ""),
1197 TraceLog::RECORDING_MODE);
1198 TRACE_EVENT_INSTANT0("test_inc", "name", TRACE_EVENT_SCOPE_THREAD);
1199 TRACE_EVENT_INSTANT0("test_inc2", "name", TRACE_EVENT_SCOPE_THREAD);
1200 TRACE_EVENT_INSTANT0("test_inc2,test_inc", "name", TRACE_EVENT_SCOPE_THREAD);
1201 TRACE_EVENT_INSTANT0("test_inc,test_inc2", "name", TRACE_EVENT_SCOPE_THREAD);
1202 EndTraceAndFlush();
1203 EXPECT_TRUE(FindMatchingValue("cat", "test_inc2"));
1204 EXPECT_FALSE(FindMatchingValue("cat", "test_inc"));
1205 EXPECT_TRUE(FindMatchingValue("cat", "test_inc2,test_inc"));
1206 EXPECT_TRUE(FindMatchingValue("cat", "test_inc,test_inc2"));
1207 }
1208
1209
1210 // Test ASYNC_BEGIN/END events
TEST_F(TraceEventTestFixture,AsyncBeginEndEvents)1211 TEST_F(TraceEventTestFixture, AsyncBeginEndEvents) {
1212 BeginTrace();
1213
1214 uint64_t id = 0xfeedbeeffeedbeefull;
1215 TRACE_EVENT_ASYNC_BEGIN0("cat", "name1", id);
1216 TRACE_EVENT_ASYNC_STEP_INTO0("cat", "name1", id, "step1");
1217 TRACE_EVENT_ASYNC_END0("cat", "name1", id);
1218 TRACE_EVENT_BEGIN0("cat", "name2");
1219 TRACE_EVENT_ASYNC_BEGIN0("cat", "name3", 0);
1220 TRACE_EVENT_ASYNC_STEP_PAST0("cat", "name3", 0, "step2");
1221
1222 EndTraceAndFlush();
1223
1224 EXPECT_TRUE(FindNamePhase("name1", "S"));
1225 EXPECT_TRUE(FindNamePhase("name1", "T"));
1226 EXPECT_TRUE(FindNamePhase("name1", "F"));
1227
1228 std::string id_str;
1229 StringAppendF(&id_str, "0x%" PRIx64, id);
1230
1231 EXPECT_TRUE(FindNamePhaseKeyValue("name1", "S", "id", id_str.c_str()));
1232 EXPECT_TRUE(FindNamePhaseKeyValue("name1", "T", "id", id_str.c_str()));
1233 EXPECT_TRUE(FindNamePhaseKeyValue("name1", "F", "id", id_str.c_str()));
1234 EXPECT_TRUE(FindNamePhaseKeyValue("name3", "S", "id", "0x0"));
1235 EXPECT_TRUE(FindNamePhaseKeyValue("name3", "p", "id", "0x0"));
1236
1237 // BEGIN events should not have id
1238 EXPECT_FALSE(FindNamePhaseKeyValue("name2", "B", "id", "0"));
1239 }
1240
1241 // Test ASYNC_BEGIN/END events
TEST_F(TraceEventTestFixture,AsyncBeginEndPointerNotMangled)1242 TEST_F(TraceEventTestFixture, AsyncBeginEndPointerNotMangled) {
1243 void* ptr = this;
1244
1245 TraceLog::GetInstance()->SetProcessID(100);
1246 BeginTrace();
1247 TRACE_EVENT_ASYNC_BEGIN0("cat", "name1", ptr);
1248 TRACE_EVENT_ASYNC_BEGIN0("cat", "name2", ptr);
1249 EndTraceAndFlush();
1250
1251 TraceLog::GetInstance()->SetProcessID(200);
1252 BeginTrace();
1253 TRACE_EVENT_ASYNC_BEGIN0("cat", "name1", ptr);
1254 TRACE_EVENT_ASYNC_END0("cat", "name1", ptr);
1255 EndTraceAndFlush();
1256
1257 const Value::Dict* async_begin = FindNamePhase("name1", "S");
1258 const Value::Dict* async_begin2 = FindNamePhase("name2", "S");
1259 const Value::Dict* async_end = FindNamePhase("name1", "F");
1260 EXPECT_TRUE(async_begin);
1261 EXPECT_TRUE(async_begin2);
1262 EXPECT_TRUE(async_end);
1263
1264 std::string async_begin_id_str =
1265 *async_begin->FindStringByDottedPath("id2.local");
1266 std::string async_begin2_id_str =
1267 *async_begin2->FindStringByDottedPath("id2.local");
1268 std::string async_end_id_str =
1269 *async_end->FindStringByDottedPath("id2.local");
1270
1271 // Since all ids are process-local and not mangled, they should be equal.
1272 EXPECT_STREQ(async_begin_id_str.c_str(), async_begin2_id_str.c_str());
1273 EXPECT_STREQ(async_begin_id_str.c_str(), async_end_id_str.c_str());
1274 }
1275
1276 // Test that static strings are not copied.
TEST_F(TraceEventTestFixture,StaticStringVsString)1277 TEST_F(TraceEventTestFixture, StaticStringVsString) {
1278 TraceLog* tracer = TraceLog::GetInstance();
1279 // Make sure old events are flushed:
1280 EXPECT_EQ(0u, tracer->GetStatus().event_count);
1281 const unsigned char* category_group_enabled =
1282 TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED("base");
1283
1284 {
1285 BeginTrace();
1286 // Test that string arguments are copied.
1287 [[maybe_unused]] TraceEventHandle handle1 =
1288 trace_event_internal::AddTraceEvent(
1289 TRACE_EVENT_PHASE_INSTANT, category_group_enabled, "name1",
1290 trace_event_internal::kGlobalScope, trace_event_internal::kNoId, 0,
1291 trace_event_internal::kNoId, "arg1", std::string("argval"), "arg2",
1292 std::string("argval"));
1293 // Test that static TRACE_STR_COPY string arguments are copied.
1294 [[maybe_unused]] TraceEventHandle handle2 =
1295 trace_event_internal::AddTraceEvent(
1296 TRACE_EVENT_PHASE_INSTANT, category_group_enabled, "name2",
1297 trace_event_internal::kGlobalScope, trace_event_internal::kNoId, 0,
1298 trace_event_internal::kNoId, "arg1", TRACE_STR_COPY("argval"),
1299 "arg2", TRACE_STR_COPY("argval"));
1300 #if !BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
1301 EXPECT_GT(tracer->GetStatus().event_count, 1u);
1302 const TraceEvent* event1 = tracer->GetEventByHandle(handle1);
1303 const TraceEvent* event2 = tracer->GetEventByHandle(handle2);
1304 ASSERT_TRUE(event1);
1305 ASSERT_TRUE(event2);
1306 EXPECT_STREQ("name1", event1->name());
1307 EXPECT_STREQ("name2", event2->name());
1308 EXPECT_FALSE(event1->parameter_copy_storage().empty());
1309 EXPECT_FALSE(event2->parameter_copy_storage().empty());
1310 EXPECT_GT(event1->parameter_copy_storage().size(), 0u);
1311 EXPECT_GT(event2->parameter_copy_storage().size(), 0u);
1312 #endif // !BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
1313 EndTraceAndFlush();
1314 }
1315
1316 {
1317 BeginTrace();
1318 // Test that static literal string arguments are not copied.
1319 [[maybe_unused]] TraceEventHandle handle1 =
1320 trace_event_internal::AddTraceEvent(
1321 TRACE_EVENT_PHASE_INSTANT, category_group_enabled, "name1",
1322 trace_event_internal::kGlobalScope, trace_event_internal::kNoId, 0,
1323 trace_event_internal::kNoId, "arg1", "argval", "arg2", "argval");
1324 #if !BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
1325 EXPECT_GT(tracer->GetStatus().event_count, 1u);
1326 const TraceEvent* event1 = tracer->GetEventByHandle(handle1);
1327 ASSERT_TRUE(event1);
1328 EXPECT_STREQ("name1", event1->name());
1329 EXPECT_TRUE(event1->parameter_copy_storage().empty());
1330 #endif
1331 EndTraceAndFlush();
1332 }
1333 }
1334
1335 // Test that data sent from other threads is gathered
TEST_F(TraceEventTestFixture,DataCapturedOnThread)1336 TEST_F(TraceEventTestFixture, DataCapturedOnThread) {
1337 BeginTrace();
1338
1339 Thread thread("1");
1340 WaitableEvent task_complete_event(WaitableEvent::ResetPolicy::AUTOMATIC,
1341 WaitableEvent::InitialState::NOT_SIGNALED);
1342 thread.Start();
1343
1344 thread.task_runner()->PostTask(
1345 FROM_HERE,
1346 base::BindOnce(&TraceWithAllMacroVariants, &task_complete_event));
1347 task_complete_event.Wait();
1348 thread.Stop();
1349
1350 EndTraceAndFlush();
1351 ValidateAllTraceMacrosCreatedData(trace_parsed_);
1352 }
1353
1354 // Test that data sent from multiple threads is gathered
TEST_F(TraceEventTestFixture,DataCapturedManyThreads)1355 TEST_F(TraceEventTestFixture, DataCapturedManyThreads) {
1356 BeginTrace();
1357
1358 const int num_threads = 4;
1359 const int num_events = 4000;
1360 Thread* threads[num_threads];
1361 WaitableEvent* task_complete_events[num_threads];
1362 for (int i = 0; i < num_threads; i++) {
1363 threads[i] = new Thread(StringPrintf("Thread %d", i));
1364 task_complete_events[i] =
1365 new WaitableEvent(WaitableEvent::ResetPolicy::AUTOMATIC,
1366 WaitableEvent::InitialState::NOT_SIGNALED);
1367 threads[i]->Start();
1368 threads[i]->task_runner()->PostTask(
1369 FROM_HERE, base::BindOnce(&TraceManyInstantEvents, i, num_events,
1370 task_complete_events[i]));
1371 }
1372
1373 for (auto* event : task_complete_events) {
1374 event->Wait();
1375 }
1376
1377 // Let half of the threads end before flush.
1378 for (int i = 0; i < num_threads / 2; i++) {
1379 threads[i]->Stop();
1380 delete threads[i];
1381 delete task_complete_events[i];
1382 }
1383
1384 EndTraceAndFlushInThreadWithMessageLoop();
1385 ValidateInstantEventPresentOnEveryThread(trace_parsed_,
1386 num_threads, num_events);
1387
1388 // Let the other half of the threads end after flush.
1389 for (int i = num_threads / 2; i < num_threads; i++) {
1390 threads[i]->Stop();
1391 delete threads[i];
1392 delete task_complete_events[i];
1393 }
1394 }
1395
1396 // Test that thread and process names show up in the trace.
1397 // In SDK build, thread names are not tracked inside //base. Instead, there's
1398 // a special TrackNameRecorder component in //services that is tested in
1399 // services_unittests.
1400 // TODO(khokhlov): Verify if we need thread name support for unit-test tracing.
1401 #if !BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
TEST_F(TraceEventTestFixture,ThreadNames)1402 TEST_F(TraceEventTestFixture, ThreadNames) {
1403 // Create threads before we enable tracing to make sure
1404 // that tracelog still captures them.
1405 const int kNumThreads = 4;
1406 const int kNumEvents = 10;
1407 Thread* threads[kNumThreads];
1408 PlatformThreadId thread_ids[kNumThreads];
1409 for (int i = 0; i < kNumThreads; i++)
1410 threads[i] = new Thread(StringPrintf("Thread %d", i));
1411
1412 // Enable tracing.
1413 BeginTrace();
1414
1415 // Now run some trace code on these threads.
1416 WaitableEvent* task_complete_events[kNumThreads];
1417 for (int i = 0; i < kNumThreads; i++) {
1418 task_complete_events[i] =
1419 new WaitableEvent(WaitableEvent::ResetPolicy::AUTOMATIC,
1420 WaitableEvent::InitialState::NOT_SIGNALED);
1421 threads[i]->Start();
1422 thread_ids[i] = threads[i]->GetThreadId();
1423 threads[i]->task_runner()->PostTask(
1424 FROM_HERE, base::BindOnce(&TraceManyInstantEvents, i, kNumEvents,
1425 task_complete_events[i]));
1426 }
1427 for (auto* event : task_complete_events) {
1428 event->Wait();
1429 }
1430
1431 // Shut things down.
1432 for (int i = 0; i < kNumThreads; i++) {
1433 threads[i]->Stop();
1434 delete threads[i];
1435 delete task_complete_events[i];
1436 }
1437
1438 EndTraceAndFlush();
1439
1440 // Make sure we get thread name metadata.
1441 // Note, the test suite may have created a ton of threads.
1442 // So, we'll have thread names for threads we didn't create.
1443 std::vector<const Value::Dict*> items =
1444 FindTraceEntries(trace_parsed_, "thread_name");
1445 for (const Value::Dict* item : items) {
1446 ASSERT_TRUE(item);
1447
1448 std::optional<int> maybe_tid = item->FindInt("tid");
1449 EXPECT_TRUE(maybe_tid.has_value());
1450
1451 // See if this thread name is one of the threads we just created
1452 for (int j = 0; j < kNumThreads; j++) {
1453 if (static_cast<int>(thread_ids[j]) != maybe_tid.value())
1454 continue;
1455
1456 EXPECT_EQ(*item->FindString("ph"), "M");
1457 EXPECT_EQ(*item->FindInt("pid"),
1458 static_cast<int>(base::GetCurrentProcId()));
1459
1460 // If the thread name changes or the tid gets reused, the name will be
1461 // a comma-separated list of thread names, so look for a substring.
1462 std::string expected_name = StringPrintf("Thread %d", j);
1463 const std::string* name = item->FindStringByDottedPath("args.name");
1464 EXPECT_TRUE(name && name->find(expected_name) != std::string::npos);
1465 }
1466 }
1467 }
1468 #endif // !BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
1469
1470 // Test that the disabled trace categories are included/excluded from the
1471 // trace output correctly.
TEST_F(TraceEventTestFixture,DisabledCategories)1472 TEST_F(TraceEventTestFixture, DisabledCategories) {
1473 BeginTrace();
1474 TRACE_EVENT_INSTANT0(TRACE_DISABLED_BY_DEFAULT("cc"), "first",
1475 TRACE_EVENT_SCOPE_THREAD);
1476 TRACE_EVENT_INSTANT0("test_included", "first", TRACE_EVENT_SCOPE_THREAD);
1477 EndTraceAndFlush();
1478 {
1479 const Value::Dict* item = nullptr;
1480 Value::List& trace_parsed = trace_parsed_;
1481 EXPECT_NOT_FIND_("disabled-by-default-cc");
1482 EXPECT_FIND_("test_included");
1483 }
1484 Clear();
1485
1486 BeginSpecificTrace("disabled-by-default-cc");
1487 TRACE_EVENT_INSTANT0(TRACE_DISABLED_BY_DEFAULT("cc"), "second",
1488 TRACE_EVENT_SCOPE_THREAD);
1489 TRACE_EVENT_INSTANT0("test_other_included", "second",
1490 TRACE_EVENT_SCOPE_THREAD);
1491 EndTraceAndFlush();
1492
1493 {
1494 const Value::Dict* item = nullptr;
1495 Value::List& trace_parsed = trace_parsed_;
1496 EXPECT_FIND_("disabled-by-default-cc");
1497 EXPECT_FIND_("test_other_included");
1498 }
1499
1500 Clear();
1501
1502 BeginSpecificTrace("test_other_included");
1503 TRACE_EVENT_INSTANT0("test_other_included," TRACE_DISABLED_BY_DEFAULT("cc"),
1504 "test_first", TRACE_EVENT_SCOPE_THREAD);
1505 TRACE_EVENT_INSTANT0(
1506 "test," TRACE_DISABLED_BY_DEFAULT("cc") ",test_other_included", "second",
1507 TRACE_EVENT_SCOPE_THREAD);
1508 EndTraceAndFlush();
1509
1510 {
1511 const Value::Dict* item = nullptr;
1512 Value::List& trace_parsed = trace_parsed_;
1513 EXPECT_FIND_("test,disabled-by-default-cc,test_other_included");
1514 EXPECT_FIND_("test_other_included,disabled-by-default-cc");
1515 }
1516 }
1517
1518 // Perfetto always traces all macro arguments immediately.
1519 #if !BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
TEST_F(TraceEventTestFixture,NormallyNoDeepCopy)1520 TEST_F(TraceEventTestFixture, NormallyNoDeepCopy) {
1521 // Test that the TRACE_EVENT macros do not deep-copy their string. If they
1522 // do so it may indicate a performance regression, but more-over it would
1523 // make the DEEP_COPY overloads redundant.
1524 std::string name_string("event name");
1525
1526 BeginTrace();
1527 TRACE_EVENT_INSTANT0("category", name_string.c_str(),
1528 TRACE_EVENT_SCOPE_THREAD);
1529
1530 // Modify the string in place (a wholesale reassignment may leave the old
1531 // string intact on the heap).
1532 name_string[0] = '@';
1533
1534 EndTraceAndFlush();
1535
1536 EXPECT_FALSE(FindTraceEntry(trace_parsed_, "event name"));
1537 EXPECT_TRUE(FindTraceEntry(trace_parsed_, name_string.c_str()));
1538 }
1539 #endif // !BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
1540
TEST_F(TraceEventTestFixture,DeepCopy)1541 TEST_F(TraceEventTestFixture, DeepCopy) {
1542 static const char kOriginalName[] = "name1";
1543 std::string name(kOriginalName);
1544 std::string arg1("arg1");
1545 std::string arg2("arg2");
1546 std::string val("val");
1547
1548 BeginTrace();
1549 TRACE_EVENT_COPY_BEGIN2("category", name.c_str(), arg1.c_str(), 5,
1550 arg2.c_str(), val);
1551 TRACE_EVENT_COPY_BEGIN2("category", name.c_str(), arg1.c_str(), 5,
1552 arg2.c_str(), val);
1553
1554 // As per NormallyNoDeepCopy, modify the strings in place.
1555 name[0] = arg1[0] = arg2[0] = val[0] = '@';
1556
1557 EndTraceAndFlush();
1558
1559 EXPECT_FALSE(FindTraceEntry(trace_parsed_, name.c_str()));
1560
1561 const Value::Dict* entry = FindTraceEntry(trace_parsed_, kOriginalName);
1562 ASSERT_TRUE(entry);
1563
1564 EXPECT_FALSE(entry->FindIntByDottedPath("args.@rg1"));
1565
1566 ASSERT_TRUE(entry->FindIntByDottedPath("args.arg1"));
1567 EXPECT_EQ(*entry->FindIntByDottedPath("args.arg1"), 5);
1568
1569 ASSERT_TRUE(entry->FindStringByDottedPath("args.arg2"));
1570 EXPECT_EQ(*entry->FindStringByDottedPath("args.arg2"), "val");
1571 }
1572
1573 // Test that TraceResultBuffer outputs the correct result whether it is added
1574 // in chunks or added all at once.
TEST_F(TraceEventTestFixture,TraceResultBuffer)1575 TEST_F(TraceEventTestFixture, TraceResultBuffer) {
1576 Clear();
1577
1578 trace_buffer_.Start();
1579 trace_buffer_.AddFragment("bla1");
1580 trace_buffer_.AddFragment("bla2");
1581 trace_buffer_.AddFragment("bla3,bla4");
1582 trace_buffer_.Finish();
1583 EXPECT_STREQ(json_output_.json_output.c_str(), "[bla1,bla2,bla3,bla4]");
1584
1585 Clear();
1586
1587 trace_buffer_.Start();
1588 trace_buffer_.AddFragment("bla1,bla2,bla3,bla4");
1589 trace_buffer_.Finish();
1590 EXPECT_STREQ(json_output_.json_output.c_str(), "[bla1,bla2,bla3,bla4]");
1591 }
1592
1593 // Test that trace_event parameters are not evaluated if the tracing
1594 // system is disabled.
TEST_F(TraceEventTestFixture,TracingIsLazy)1595 TEST_F(TraceEventTestFixture, TracingIsLazy) {
1596 BeginTrace();
1597
1598 int a = 0;
1599 TRACE_EVENT_INSTANT1("category", "test", TRACE_EVENT_SCOPE_THREAD, "a", a++);
1600 EXPECT_EQ(1, a);
1601
1602 TraceLog::GetInstance()->SetDisabled();
1603
1604 TRACE_EVENT_INSTANT1("category", "test", TRACE_EVENT_SCOPE_THREAD, "a", a++);
1605 EXPECT_EQ(1, a);
1606
1607 EndTraceAndFlush();
1608 }
1609
TEST_F(TraceEventTestFixture,TraceEnableDisable)1610 TEST_F(TraceEventTestFixture, TraceEnableDisable) {
1611 TraceLog* trace_log = TraceLog::GetInstance();
1612 TraceConfig tc_inc_all("*", "");
1613 trace_log->SetEnabled(tc_inc_all, TraceLog::RECORDING_MODE);
1614 EXPECT_TRUE(trace_log->IsEnabled());
1615 trace_log->SetDisabled();
1616 EXPECT_FALSE(trace_log->IsEnabled());
1617
1618 trace_log->SetEnabled(tc_inc_all, TraceLog::RECORDING_MODE);
1619 EXPECT_TRUE(trace_log->IsEnabled());
1620 // Nested enable isn't supported by Perfetto.
1621 #if !BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
1622 trace_log->SetEnabled(TraceConfig(), TraceLog::RECORDING_MODE);
1623 EXPECT_TRUE(trace_log->IsEnabled());
1624 trace_log->SetDisabled();
1625 EXPECT_FALSE(trace_log->IsEnabled());
1626 #endif // !BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
1627 trace_log->SetDisabled();
1628 EXPECT_FALSE(trace_log->IsEnabled());
1629 }
1630
1631 // Nested enable isn't supported by Perfetto.
1632 #if !BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
TEST_F(TraceEventTestFixture,TraceCategoriesAfterNestedEnable)1633 TEST_F(TraceEventTestFixture, TraceCategoriesAfterNestedEnable) {
1634 TraceLog* trace_log = TraceLog::GetInstance();
1635 trace_log->SetEnabled(TraceConfig("foo,bar", ""), TraceLog::RECORDING_MODE);
1636 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("foo"));
1637 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("bar"));
1638 EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("baz"));
1639 trace_log->SetEnabled(TraceConfig("foo2", ""), TraceLog::RECORDING_MODE);
1640 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("foo2"));
1641 EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("baz"));
1642 // The "" becomes the default category set when applied.
1643 trace_log->SetEnabled(TraceConfig(), TraceLog::RECORDING_MODE);
1644 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("foo"));
1645 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("baz"));
1646 EXPECT_STREQ(
1647 "",
1648 trace_log->GetCurrentTraceConfig().ToCategoryFilterString().c_str());
1649 trace_log->SetDisabled();
1650 trace_log->SetDisabled();
1651 trace_log->SetDisabled();
1652 EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("foo"));
1653 EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("baz"));
1654
1655 trace_log->SetEnabled(TraceConfig("-foo,-bar", ""), TraceLog::RECORDING_MODE);
1656 EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("foo"));
1657 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("baz"));
1658 trace_log->SetEnabled(TraceConfig("moo", ""), TraceLog::RECORDING_MODE);
1659 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("baz"));
1660 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("moo"));
1661 EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("foo"));
1662 EXPECT_STREQ(
1663 "-foo,-bar",
1664 trace_log->GetCurrentTraceConfig().ToCategoryFilterString().c_str());
1665 trace_log->SetDisabled();
1666 trace_log->SetDisabled();
1667
1668 // Make sure disabled categories aren't cleared if we set in the second.
1669 trace_log->SetEnabled(TraceConfig("disabled-by-default-cc,foo", ""),
1670 TraceLog::RECORDING_MODE);
1671 EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("bar"));
1672 trace_log->SetEnabled(TraceConfig("disabled-by-default-gpu", ""),
1673 TraceLog::RECORDING_MODE);
1674 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("disabled-by-default-cc"));
1675 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("disabled-by-default-gpu"));
1676 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("bar"));
1677 EXPECT_STREQ(
1678 "disabled-by-default-cc,disabled-by-default-gpu",
1679 trace_log->GetCurrentTraceConfig().ToCategoryFilterString().c_str());
1680 trace_log->SetDisabled();
1681 trace_log->SetDisabled();
1682 }
1683 #endif // !BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
1684
TEST_F(TraceEventTestFixture,TraceWithDefaultCategoryFilters)1685 TEST_F(TraceEventTestFixture, TraceWithDefaultCategoryFilters) {
1686 TraceLog* trace_log = TraceLog::GetInstance();
1687
1688 trace_log->SetEnabled(TraceConfig(), TraceLog::RECORDING_MODE);
1689 CheckTraceDefaultCategoryFilters(*trace_log);
1690 trace_log->SetDisabled();
1691
1692 trace_log->SetEnabled(TraceConfig("", ""), TraceLog::RECORDING_MODE);
1693 CheckTraceDefaultCategoryFilters(*trace_log);
1694 trace_log->SetDisabled();
1695
1696 trace_log->SetEnabled(TraceConfig("*", ""), TraceLog::RECORDING_MODE);
1697 CheckTraceDefaultCategoryFilters(*trace_log);
1698 trace_log->SetDisabled();
1699
1700 trace_log->SetEnabled(TraceConfig(""), TraceLog::RECORDING_MODE);
1701 CheckTraceDefaultCategoryFilters(*trace_log);
1702 trace_log->SetDisabled();
1703 }
1704
TEST_F(TraceEventTestFixture,TraceWithDisabledByDefaultCategoryFilters)1705 TEST_F(TraceEventTestFixture, TraceWithDisabledByDefaultCategoryFilters) {
1706 TraceLog* trace_log = TraceLog::GetInstance();
1707
1708 trace_log->SetEnabled(TraceConfig("foo,disabled-by-default-foo", ""),
1709 TraceLog::RECORDING_MODE);
1710 EXPECT_TRUE(IsCategoryEnabled("foo"));
1711 EXPECT_TRUE(IsCategoryEnabled("disabled-by-default-foo"));
1712 EXPECT_FALSE(IsCategoryEnabled("bar"));
1713 EXPECT_FALSE(IsCategoryEnabled("disabled-by-default-bar"));
1714 trace_log->SetDisabled();
1715
1716 // Enabling only the disabled-by-default-* category means the default ones
1717 // are also enabled.
1718 trace_log->SetEnabled(TraceConfig("disabled-by-default-foo", ""),
1719 TraceLog::RECORDING_MODE);
1720 EXPECT_TRUE(IsCategoryEnabled("disabled-by-default-foo"));
1721 EXPECT_TRUE(IsCategoryEnabled("foo"));
1722 EXPECT_TRUE(IsCategoryEnabled("bar"));
1723 EXPECT_FALSE(IsCategoryEnabled("disabled-by-default-bar"));
1724 trace_log->SetDisabled();
1725 }
1726
1727 class MyData : public ConvertableToTraceFormat {
1728 public:
1729 MyData() = default;
1730 MyData(const MyData&) = delete;
1731 MyData& operator=(const MyData&) = delete;
1732 ~MyData() override = default;
1733
AppendAsTraceFormat(std::string * out) const1734 void AppendAsTraceFormat(std::string* out) const override {
1735 out->append("{\"foo\":1}");
1736 }
1737 };
1738
TEST_F(TraceEventTestFixture,ConvertableTypes)1739 TEST_F(TraceEventTestFixture, ConvertableTypes) {
1740 TraceLog::GetInstance()->SetEnabled(TraceConfig(kRecordAllCategoryFilter, ""),
1741 TraceLog::RECORDING_MODE);
1742
1743 {
1744 std::unique_ptr<ConvertableToTraceFormat> data(new MyData());
1745 std::unique_ptr<ConvertableToTraceFormat> data1(new MyData());
1746 std::unique_ptr<ConvertableToTraceFormat> data2(new MyData());
1747 TRACE_EVENT1("foo", "bar", "data", std::move(data));
1748 TRACE_EVENT2("foo", "baz", "data1", std::move(data1), "data2",
1749 std::move(data2));
1750 }
1751
1752 // Check that std::unique_ptr<DerivedClassOfConvertable> are properly treated
1753 // as convertable and not accidentally casted to bool.
1754 {
1755 std::unique_ptr<MyData> convertData1(new MyData());
1756 std::unique_ptr<MyData> convertData2(new MyData());
1757 std::unique_ptr<MyData> convertData3(new MyData());
1758 std::unique_ptr<MyData> convertData4(new MyData());
1759 TRACE_EVENT2("foo", "string_first", "str", "string value 1", "convert",
1760 std::move(convertData1));
1761 TRACE_EVENT2("foo", "string_second", "convert", std::move(convertData2),
1762 "str", "string value 2");
1763 TRACE_EVENT2("foo", "both_conv", "convert1", std::move(convertData3),
1764 "convert2", std::move(convertData4));
1765 }
1766 EndTraceAndFlush();
1767
1768 // One arg version.
1769 const Value::Dict* dict = FindNamePhase("bar", "X");
1770 ASSERT_TRUE(dict);
1771
1772 const Value::Dict* args_dict = dict->FindDict("args");
1773 ASSERT_TRUE(args_dict);
1774
1775 const Value::Dict* convertable_dict = args_dict->FindDict("data");
1776 ASSERT_TRUE(convertable_dict);
1777
1778 EXPECT_EQ(*convertable_dict->FindInt("foo"), 1);
1779
1780 // Two arg version.
1781 dict = FindNamePhase("baz", "X");
1782 ASSERT_TRUE(dict);
1783
1784 args_dict = dict->FindDict("args");
1785 ASSERT_TRUE(args_dict);
1786
1787 convertable_dict = args_dict->FindDict("data1");
1788 ASSERT_TRUE(convertable_dict);
1789
1790 convertable_dict = args_dict->FindDict("data2");
1791 ASSERT_TRUE(convertable_dict);
1792
1793 // Convertable with other types.
1794 dict = FindNamePhase("string_first", "X");
1795 ASSERT_TRUE(dict);
1796
1797 args_dict = dict->FindDict("args");
1798 ASSERT_TRUE(args_dict);
1799
1800 EXPECT_EQ(*args_dict->FindString("str"), "string value 1");
1801
1802 convertable_dict = args_dict->FindDict("convert");
1803 ASSERT_TRUE(convertable_dict);
1804
1805 EXPECT_EQ(*convertable_dict->FindInt("foo"), 1);
1806
1807 dict = FindNamePhase("string_second", "X");
1808 ASSERT_TRUE(dict);
1809
1810 args_dict = dict->FindDict("args");
1811 ASSERT_TRUE(args_dict);
1812
1813 EXPECT_EQ(*args_dict->FindString("str"), "string value 2");
1814
1815 convertable_dict = args_dict->FindDict("convert");
1816 ASSERT_TRUE(convertable_dict);
1817
1818 EXPECT_EQ(*convertable_dict->FindInt("foo"), 1);
1819
1820 dict = FindNamePhase("both_conv", "X");
1821 ASSERT_TRUE(dict);
1822
1823 args_dict = dict->FindDict("args");
1824 ASSERT_TRUE(args_dict);
1825
1826 convertable_dict = args_dict->FindDict("convert1");
1827 ASSERT_TRUE(convertable_dict);
1828 convertable_dict = args_dict->FindDict("convert2");
1829 ASSERT_TRUE(convertable_dict);
1830 }
1831
TEST_F(TraceEventTestFixture,PrimitiveArgs)1832 TEST_F(TraceEventTestFixture, PrimitiveArgs) {
1833 TraceLog::GetInstance()->SetEnabled(TraceConfig(kRecordAllCategoryFilter, ""),
1834 TraceLog::RECORDING_MODE);
1835
1836 {
1837 TRACE_EVENT1("foo", "event1", "int_one", 1);
1838 TRACE_EVENT1("foo", "event2", "int_neg_ten", -10);
1839 TRACE_EVENT1("foo", "event3", "float_one", 1.0f);
1840 TRACE_EVENT1("foo", "event4", "float_half", .5f);
1841 TRACE_EVENT1("foo", "event5", "float_neghalf", -.5f);
1842 TRACE_EVENT1("foo", "event6", "float_infinity",
1843 std::numeric_limits<float>::infinity());
1844 TRACE_EVENT1("foo", "event6b", "float_neg_infinity",
1845 -std::numeric_limits<float>::infinity());
1846 TRACE_EVENT1("foo", "event7", "double_nan",
1847 std::numeric_limits<double>::quiet_NaN());
1848 void* p = nullptr;
1849 TRACE_EVENT1("foo", "event8", "pointer_null", p);
1850 p = reinterpret_cast<void*>(0xbadf00d);
1851 TRACE_EVENT1("foo", "event9", "pointer_badf00d", p);
1852 TRACE_EVENT1("foo", "event10", "bool_true", true);
1853 TRACE_EVENT1("foo", "event11", "bool_false", false);
1854 TRACE_EVENT1("foo", "event12", "time_null", base::Time());
1855 TRACE_EVENT1("foo", "event13", "time_one",
1856 base::Time::FromInternalValue(1));
1857 TRACE_EVENT1("foo", "event14", "timeticks_null", base::TimeTicks());
1858 TRACE_EVENT1("foo", "event15", "timeticks_one",
1859 base::TimeTicks::FromInternalValue(1));
1860 }
1861 EndTraceAndFlush();
1862
1863 const Value::Dict* args_dict = nullptr;
1864 const Value::Dict* dict = nullptr;
1865 std::string str_value;
1866
1867 dict = FindNamePhase("event1", "X");
1868 ASSERT_TRUE(dict);
1869 args_dict = dict->FindDict("args");
1870 ASSERT_TRUE(args_dict);
1871 EXPECT_EQ(*args_dict->FindInt("int_one"), 1);
1872
1873 dict = FindNamePhase("event2", "X");
1874 ASSERT_TRUE(dict);
1875 args_dict = dict->FindDict("args");
1876 ASSERT_TRUE(args_dict);
1877 EXPECT_EQ(*args_dict->FindInt("int_neg_ten"), -10);
1878
1879 // 1f must be serialized to JSON as "1.0" in order to be a double, not an int.
1880 dict = FindNamePhase("event3", "X");
1881 ASSERT_TRUE(dict);
1882 args_dict = dict->FindDict("args");
1883 ASSERT_TRUE(args_dict);
1884 EXPECT_EQ(*args_dict->FindDouble("float_one"), 1.0);
1885
1886 // .5f must be serialized to JSON as "0.5".
1887 dict = FindNamePhase("event4", "X");
1888 ASSERT_TRUE(dict);
1889 args_dict = dict->FindDict("args");
1890 ASSERT_TRUE(args_dict);
1891 EXPECT_EQ(*args_dict->FindDouble("float_half"), 0.5);
1892
1893 // -.5f must be serialized to JSON as "-0.5".
1894 dict = FindNamePhase("event5", "X");
1895 ASSERT_TRUE(dict);
1896 args_dict = dict->FindDict("args");
1897 ASSERT_TRUE(args_dict);
1898 EXPECT_EQ(*args_dict->FindDouble("float_neghalf"), -0.5);
1899
1900 // Infinity is serialized to JSON as a string.
1901 dict = FindNamePhase("event6", "X");
1902 ASSERT_TRUE(dict);
1903 args_dict = dict->FindDict("args");
1904 ASSERT_TRUE(args_dict);
1905 EXPECT_EQ(*args_dict->FindString("float_infinity"), "Infinity");
1906 dict = FindNamePhase("event6b", "X");
1907 ASSERT_TRUE(dict);
1908 args_dict = dict->FindDict("args");
1909 ASSERT_TRUE(args_dict);
1910 EXPECT_EQ(*args_dict->FindString("float_neg_infinity"), "-Infinity");
1911
1912 // NaN is serialized to JSON as a string.
1913 dict = FindNamePhase("event7", "X");
1914 ASSERT_TRUE(dict);
1915 args_dict = dict->FindDict("args");
1916 ASSERT_TRUE(args_dict);
1917 EXPECT_EQ(*args_dict->FindString("double_nan"), "NaN");
1918
1919 // NULL pointers should be serialized as "0x0".
1920 dict = FindNamePhase("event8", "X");
1921 ASSERT_TRUE(dict);
1922 args_dict = dict->FindDict("args");
1923 ASSERT_TRUE(args_dict);
1924 EXPECT_EQ(*args_dict->FindString("pointer_null"), "0x0");
1925
1926 // Other pointers should be serlized as a hex string.
1927 dict = FindNamePhase("event9", "X");
1928 ASSERT_TRUE(dict);
1929 args_dict = dict->FindDict("args");
1930 ASSERT_TRUE(args_dict);
1931 EXPECT_EQ(*args_dict->FindString("pointer_badf00d"), "0xbadf00d");
1932
1933 dict = FindNamePhase("event10", "X");
1934 ASSERT_TRUE(dict);
1935 args_dict = dict->FindDict("args");
1936 ASSERT_TRUE(args_dict);
1937 EXPECT_EQ(*args_dict->FindBool("bool_true"), true);
1938
1939 dict = FindNamePhase("event11", "X");
1940 ASSERT_TRUE(dict);
1941 args_dict = dict->FindDict("args");
1942 ASSERT_TRUE(args_dict);
1943 EXPECT_EQ(*args_dict->FindBool("bool_false"), false);
1944
1945 dict = FindNamePhase("event12", "X");
1946 ASSERT_TRUE(dict);
1947 args_dict = dict->FindDict("args");
1948 ASSERT_TRUE(args_dict);
1949 EXPECT_EQ(*args_dict->FindInt("time_null"), 0);
1950
1951 dict = FindNamePhase("event13", "X");
1952 ASSERT_TRUE(dict);
1953 args_dict = dict->FindDict("args");
1954 ASSERT_TRUE(args_dict);
1955 EXPECT_EQ(*args_dict->FindInt("time_one"), 1);
1956
1957 dict = FindNamePhase("event14", "X");
1958 ASSERT_TRUE(dict);
1959 args_dict = dict->FindDict("args");
1960 ASSERT_TRUE(args_dict);
1961 EXPECT_EQ(*args_dict->FindInt("timeticks_null"), 0);
1962
1963 dict = FindNamePhase("event15", "X");
1964 ASSERT_TRUE(dict);
1965 args_dict = dict->FindDict("args");
1966 ASSERT_TRUE(args_dict);
1967 EXPECT_EQ(*args_dict->FindInt("timeticks_one"), 1);
1968 }
1969
TEST_F(TraceEventTestFixture,NameIsEscaped)1970 TEST_F(TraceEventTestFixture, NameIsEscaped) {
1971 TraceLog::GetInstance()->SetEnabled(TraceConfig(kRecordAllCategoryFilter, ""),
1972 TraceLog::RECORDING_MODE);
1973 TRACE_EVENT0("category", "name\\with\\backspaces");
1974 EndTraceAndFlush();
1975
1976 EXPECT_TRUE(FindMatchingValue("cat", "category"));
1977 EXPECT_TRUE(FindMatchingValue("name", "name\\with\\backspaces"));
1978 }
1979
1980 // Runtime args filtering is not supported by Perfetto.
1981 #if !BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
1982 namespace {
1983
IsArgNameAllowed(const char * arg_name)1984 bool IsArgNameAllowed(const char* arg_name) {
1985 return base::MatchPattern(arg_name, "granular_arg_allowed");
1986 }
1987
IsTraceEventArgsAllowlisted(const char * category_group_name,const char * event_name,ArgumentNameFilterPredicate * arg_filter)1988 bool IsTraceEventArgsAllowlisted(const char* category_group_name,
1989 const char* event_name,
1990 ArgumentNameFilterPredicate* arg_filter) {
1991 if (base::MatchPattern(category_group_name, "toplevel") &&
1992 base::MatchPattern(event_name, "*")) {
1993 return true;
1994 }
1995
1996 if (base::MatchPattern(category_group_name, "benchmark") &&
1997 base::MatchPattern(event_name, "granularly_allowed")) {
1998 *arg_filter = base::BindRepeating(&IsArgNameAllowed);
1999 return true;
2000 }
2001
2002 return false;
2003 }
2004
2005 } // namespace
2006
TEST_F(TraceEventTestFixture,ArgsAllowlisting)2007 TEST_F(TraceEventTestFixture, ArgsAllowlisting) {
2008 TraceLog::GetInstance()->SetArgumentFilterPredicate(
2009 base::BindRepeating(&IsTraceEventArgsAllowlisted));
2010
2011 TraceLog::GetInstance()->SetEnabled(
2012 TraceConfig(kRecordAllCategoryFilter, "enable-argument-filter"),
2013 TraceLog::RECORDING_MODE);
2014
2015 TRACE_EVENT1("toplevel", "event1", "int_one", 1);
2016 TRACE_EVENT1("Testing", "event2", "int_two", 1);
2017
2018 TRACE_EVENT2("benchmark", "granularly_allowed", "granular_arg_allowed",
2019 "allowed_value", "granular_arg_disallowed", "disallowed_value");
2020
2021 EndTraceAndFlush();
2022
2023 const Value::Dict* args_dict = nullptr;
2024 const Value::Dict* dict = nullptr;
2025
2026 dict = FindNamePhase("event1", "X");
2027 ASSERT_TRUE(dict);
2028 args_dict = dict->FindDict("args");
2029 ASSERT_TRUE(args_dict);
2030 EXPECT_EQ(*args_dict->FindInt("int_one"), 1);
2031 EXPECT_FALSE(args_dict->FindInt("int_two"));
2032
2033 dict = FindNamePhase("event2", "X");
2034 ASSERT_TRUE(dict);
2035 EXPECT_EQ(*dict->FindString("args"), "__stripped__");
2036
2037 dict = FindNamePhase("granularly_allowed", "X");
2038 ASSERT_TRUE(dict);
2039 args_dict = dict->FindDict("args");
2040 ASSERT_TRUE(args_dict);
2041
2042 EXPECT_EQ(*args_dict->FindString("granular_arg_allowed"), "allowed_value");
2043
2044 EXPECT_EQ(*args_dict->FindString("granular_arg_disallowed"), "__stripped__");
2045 }
2046 #endif // !BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
2047
2048 // TraceBuffer isn't used with Perfetto.
2049 #if !BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
TEST_F(TraceEventTestFixture,TraceBufferVectorReportFull)2050 TEST_F(TraceEventTestFixture, TraceBufferVectorReportFull) {
2051 TraceLog* trace_log = TraceLog::GetInstance();
2052 trace_log->SetEnabled(
2053 TraceConfig(kRecordAllCategoryFilter, ""), TraceLog::RECORDING_MODE);
2054 trace_log->logged_events_.reset(
2055 TraceBuffer::CreateTraceBufferVectorOfSize(100));
2056 do {
2057 TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0("test_all", "with_timestamp",
2058 0, 0, TimeTicks::Now());
2059 TRACE_EVENT_END_WITH_ID_TID_AND_TIMESTAMP0("test_all", "with_timestamp", 0,
2060 0, TimeTicks::Now());
2061 } while (!trace_log->BufferIsFull());
2062
2063 EndTraceAndFlush();
2064
2065 const Value::Dict* trace_full_metadata = nullptr;
2066
2067 trace_full_metadata = FindTraceEntry(trace_parsed_,
2068 "overflowed_at_ts");
2069
2070 EXPECT_TRUE(trace_full_metadata);
2071 EXPECT_EQ(*trace_full_metadata->FindString("ph"), "M");
2072 std::optional<double> maybe_buffer_limit_reached_timestamp =
2073 trace_full_metadata->FindDoubleByDottedPath("args.overflowed_at_ts");
2074
2075 EXPECT_EQ(*maybe_buffer_limit_reached_timestamp,
2076 static_cast<double>(
2077 trace_log->buffer_limit_reached_timestamp_.ToInternalValue()));
2078
2079 // Test that buffer_limit_reached_timestamp's value is between the timestamp
2080 // of the last trace event and current time.
2081 DropTracedMetadataRecords();
2082 ASSERT_TRUE(!trace_parsed_.empty());
2083 const Value& last_trace_event = trace_parsed_.back();
2084 EXPECT_TRUE(last_trace_event.is_dict());
2085 std::optional<double> maybe_last_trace_event_timestamp =
2086 last_trace_event.GetDict().FindDouble("ts");
2087 EXPECT_TRUE(maybe_last_trace_event_timestamp.has_value());
2088 EXPECT_LE(maybe_last_trace_event_timestamp.value(),
2089 maybe_buffer_limit_reached_timestamp.value());
2090 EXPECT_LE(maybe_buffer_limit_reached_timestamp.value(),
2091 trace_log->OffsetNow().ToInternalValue());
2092 }
2093
TEST_F(TraceEventTestFixture,TraceBufferRingBufferGetReturnChunk)2094 TEST_F(TraceEventTestFixture, TraceBufferRingBufferGetReturnChunk) {
2095 TraceLog::GetInstance()->SetEnabled(
2096 TraceConfig(kRecordAllCategoryFilter, RECORD_CONTINUOUSLY),
2097 TraceLog::RECORDING_MODE);
2098 TraceBuffer* buffer = TraceLog::GetInstance()->trace_buffer();
2099 size_t capacity = buffer->Capacity();
2100 size_t num_chunks = capacity / TraceBufferChunk::kTraceBufferChunkSize;
2101 uint32_t last_seq = 0;
2102 size_t chunk_index;
2103 EXPECT_EQ(0u, buffer->Size());
2104
2105 std::unique_ptr<TraceBufferChunk* []> chunks(
2106 new TraceBufferChunk*[num_chunks]);
2107 for (size_t i = 0; i < num_chunks; ++i) {
2108 chunks[i] = buffer->GetChunk(&chunk_index).release();
2109 EXPECT_TRUE(chunks[i]);
2110 EXPECT_EQ(i, chunk_index);
2111 EXPECT_GT(chunks[i]->seq(), last_seq);
2112 EXPECT_EQ((i + 1) * TraceBufferChunk::kTraceBufferChunkSize,
2113 buffer->Size());
2114 last_seq = chunks[i]->seq();
2115 }
2116
2117 // Ring buffer is never full.
2118 EXPECT_FALSE(buffer->IsFull());
2119
2120 // Return all chunks in original order.
2121 for (size_t i = 0; i < num_chunks; ++i)
2122 buffer->ReturnChunk(i, std::unique_ptr<TraceBufferChunk>(chunks[i]));
2123
2124 // Should recycle the chunks in the returned order.
2125 for (size_t i = 0; i < num_chunks; ++i) {
2126 chunks[i] = buffer->GetChunk(&chunk_index).release();
2127 EXPECT_TRUE(chunks[i]);
2128 EXPECT_EQ(i, chunk_index);
2129 EXPECT_GT(chunks[i]->seq(), last_seq);
2130 last_seq = chunks[i]->seq();
2131 }
2132
2133 // Return all chunks in reverse order.
2134 for (size_t i = 0; i < num_chunks; ++i) {
2135 buffer->ReturnChunk(num_chunks - i - 1, std::unique_ptr<TraceBufferChunk>(
2136 chunks[num_chunks - i - 1]));
2137 }
2138
2139 // Should recycle the chunks in the returned order.
2140 for (size_t i = 0; i < num_chunks; ++i) {
2141 chunks[i] = buffer->GetChunk(&chunk_index).release();
2142 EXPECT_TRUE(chunks[i]);
2143 EXPECT_EQ(num_chunks - i - 1, chunk_index);
2144 EXPECT_GT(chunks[i]->seq(), last_seq);
2145 last_seq = chunks[i]->seq();
2146 }
2147
2148 for (size_t i = 0; i < num_chunks; ++i)
2149 buffer->ReturnChunk(i, std::unique_ptr<TraceBufferChunk>(chunks[i]));
2150
2151 TraceLog::GetInstance()->SetDisabled();
2152 }
2153
TEST_F(TraceEventTestFixture,TraceBufferRingBufferHalfIteration)2154 TEST_F(TraceEventTestFixture, TraceBufferRingBufferHalfIteration) {
2155 TraceLog::GetInstance()->SetEnabled(
2156 TraceConfig(kRecordAllCategoryFilter, RECORD_CONTINUOUSLY),
2157 TraceLog::RECORDING_MODE);
2158 TraceBuffer* buffer = TraceLog::GetInstance()->trace_buffer();
2159 size_t capacity = buffer->Capacity();
2160 size_t num_chunks = capacity / TraceBufferChunk::kTraceBufferChunkSize;
2161 size_t chunk_index;
2162 EXPECT_EQ(0u, buffer->Size());
2163 EXPECT_FALSE(buffer->NextChunk());
2164
2165 size_t half_chunks = num_chunks / 2;
2166 std::unique_ptr<TraceBufferChunk* []> chunks(
2167 new TraceBufferChunk*[half_chunks]);
2168
2169 for (size_t i = 0; i < half_chunks; ++i) {
2170 chunks[i] = buffer->GetChunk(&chunk_index).release();
2171 EXPECT_TRUE(chunks[i]);
2172 EXPECT_EQ(i, chunk_index);
2173 }
2174 for (size_t i = 0; i < half_chunks; ++i)
2175 buffer->ReturnChunk(i, std::unique_ptr<TraceBufferChunk>(chunks[i]));
2176
2177 for (size_t i = 0; i < half_chunks; ++i)
2178 EXPECT_EQ(chunks[i], buffer->NextChunk());
2179 EXPECT_FALSE(buffer->NextChunk());
2180 TraceLog::GetInstance()->SetDisabled();
2181 }
2182
TEST_F(TraceEventTestFixture,TraceBufferRingBufferFullIteration)2183 TEST_F(TraceEventTestFixture, TraceBufferRingBufferFullIteration) {
2184 TraceLog::GetInstance()->SetEnabled(
2185 TraceConfig(kRecordAllCategoryFilter, RECORD_CONTINUOUSLY),
2186 TraceLog::RECORDING_MODE);
2187 TraceBuffer* buffer = TraceLog::GetInstance()->trace_buffer();
2188 size_t capacity = buffer->Capacity();
2189 size_t num_chunks = capacity / TraceBufferChunk::kTraceBufferChunkSize;
2190 size_t chunk_index;
2191 EXPECT_EQ(0u, buffer->Size());
2192 EXPECT_FALSE(buffer->NextChunk());
2193
2194 std::unique_ptr<TraceBufferChunk* []> chunks(
2195 new TraceBufferChunk*[num_chunks]);
2196
2197 for (size_t i = 0; i < num_chunks; ++i) {
2198 chunks[i] = buffer->GetChunk(&chunk_index).release();
2199 EXPECT_TRUE(chunks[i]);
2200 EXPECT_EQ(i, chunk_index);
2201 }
2202 for (size_t i = 0; i < num_chunks; ++i)
2203 buffer->ReturnChunk(i, std::unique_ptr<TraceBufferChunk>(chunks[i]));
2204
2205 for (size_t i = 0; i < num_chunks; ++i)
2206 EXPECT_TRUE(chunks[i] == buffer->NextChunk());
2207 EXPECT_FALSE(buffer->NextChunk());
2208 TraceLog::GetInstance()->SetDisabled();
2209 }
2210
TEST_F(TraceEventTestFixture,TraceRecordAsMuchAsPossibleMode)2211 TEST_F(TraceEventTestFixture, TraceRecordAsMuchAsPossibleMode) {
2212 TraceLog::GetInstance()->SetEnabled(
2213 TraceConfig(kRecordAllCategoryFilter, RECORD_AS_MUCH_AS_POSSIBLE),
2214 TraceLog::RECORDING_MODE);
2215 TraceBuffer* buffer = TraceLog::GetInstance()->trace_buffer();
2216 EXPECT_EQ(512000000UL, buffer->Capacity());
2217 TraceLog::GetInstance()->SetDisabled();
2218 }
2219
TEST_F(TraceEventTestFixture,ConfigTraceBufferLimit)2220 TEST_F(TraceEventTestFixture, ConfigTraceBufferLimit) {
2221 const size_t kLimit = 2048;
2222 TraceConfig config(kRecordAllCategoryFilter, RECORD_UNTIL_FULL);
2223 config.SetTraceBufferSizeInEvents(kLimit);
2224 TraceLog::GetInstance()->SetEnabled(config, TraceLog::RECORDING_MODE);
2225 TraceBuffer* buffer = TraceLog::GetInstance()->trace_buffer();
2226 EXPECT_EQ(kLimit, buffer->Capacity());
2227 TraceLog::GetInstance()->SetDisabled();
2228 }
2229 #endif // BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
2230
BlockUntilStopped(WaitableEvent * task_start_event,WaitableEvent * task_stop_event)2231 void BlockUntilStopped(WaitableEvent* task_start_event,
2232 WaitableEvent* task_stop_event) {
2233 task_start_event->Signal();
2234 task_stop_event->Wait();
2235 }
2236
TEST_F(TraceEventTestFixture,SetCurrentThreadBlocksMessageLoopBeforeTracing)2237 TEST_F(TraceEventTestFixture, SetCurrentThreadBlocksMessageLoopBeforeTracing) {
2238 BeginTrace();
2239
2240 Thread thread("1");
2241 WaitableEvent task_complete_event(WaitableEvent::ResetPolicy::AUTOMATIC,
2242 WaitableEvent::InitialState::NOT_SIGNALED);
2243 thread.Start();
2244 thread.task_runner()->PostTask(
2245 FROM_HERE, BindOnce(&TraceLog::SetCurrentThreadBlocksMessageLoop,
2246 Unretained(TraceLog::GetInstance())));
2247
2248 thread.task_runner()->PostTask(
2249 FROM_HERE, BindOnce(&TraceWithAllMacroVariants, &task_complete_event));
2250 task_complete_event.Wait();
2251
2252 WaitableEvent task_start_event(WaitableEvent::ResetPolicy::AUTOMATIC,
2253 WaitableEvent::InitialState::NOT_SIGNALED);
2254 WaitableEvent task_stop_event(WaitableEvent::ResetPolicy::AUTOMATIC,
2255 WaitableEvent::InitialState::NOT_SIGNALED);
2256 thread.task_runner()->PostTask(
2257 FROM_HERE,
2258 BindOnce(&BlockUntilStopped, &task_start_event, &task_stop_event));
2259 task_start_event.Wait();
2260
2261 EndTraceAndFlush();
2262 ValidateAllTraceMacrosCreatedData(trace_parsed_);
2263
2264 task_stop_event.Signal();
2265 thread.Stop();
2266 }
2267
TEST_F(TraceEventTestFixture,ConvertTraceConfigToInternalOptions)2268 TEST_F(TraceEventTestFixture, ConvertTraceConfigToInternalOptions) {
2269 TraceLog* trace_log = TraceLog::GetInstance();
2270 EXPECT_EQ(TraceLog::kInternalRecordUntilFull,
2271 trace_log->GetInternalOptionsFromTraceConfig(
2272 TraceConfig(kRecordAllCategoryFilter, RECORD_UNTIL_FULL)));
2273
2274 EXPECT_EQ(TraceLog::kInternalRecordContinuously,
2275 trace_log->GetInternalOptionsFromTraceConfig(
2276 TraceConfig(kRecordAllCategoryFilter, RECORD_CONTINUOUSLY)));
2277
2278 EXPECT_EQ(TraceLog::kInternalEchoToConsole,
2279 trace_log->GetInternalOptionsFromTraceConfig(
2280 TraceConfig(kRecordAllCategoryFilter, ECHO_TO_CONSOLE)));
2281
2282 EXPECT_EQ(TraceLog::kInternalEchoToConsole,
2283 trace_log->GetInternalOptionsFromTraceConfig(
2284 TraceConfig("*", "trace-to-console,enable-systrace")));
2285 }
2286
SetBlockingFlagAndBlockUntilStopped(WaitableEvent * task_start_event,WaitableEvent * task_stop_event)2287 void SetBlockingFlagAndBlockUntilStopped(WaitableEvent* task_start_event,
2288 WaitableEvent* task_stop_event) {
2289 TraceLog::GetInstance()->SetCurrentThreadBlocksMessageLoop();
2290 BlockUntilStopped(task_start_event, task_stop_event);
2291 }
2292
TEST_F(TraceEventTestFixture,SetCurrentThreadBlocksMessageLoopAfterTracing)2293 TEST_F(TraceEventTestFixture, SetCurrentThreadBlocksMessageLoopAfterTracing) {
2294 BeginTrace();
2295
2296 Thread thread("1");
2297 WaitableEvent task_complete_event(WaitableEvent::ResetPolicy::AUTOMATIC,
2298 WaitableEvent::InitialState::NOT_SIGNALED);
2299 thread.Start();
2300
2301 thread.task_runner()->PostTask(
2302 FROM_HERE, BindOnce(&TraceWithAllMacroVariants, &task_complete_event));
2303 task_complete_event.Wait();
2304
2305 WaitableEvent task_start_event(WaitableEvent::ResetPolicy::AUTOMATIC,
2306 WaitableEvent::InitialState::NOT_SIGNALED);
2307 WaitableEvent task_stop_event(WaitableEvent::ResetPolicy::AUTOMATIC,
2308 WaitableEvent::InitialState::NOT_SIGNALED);
2309 thread.task_runner()->PostTask(FROM_HERE,
2310 BindOnce(&SetBlockingFlagAndBlockUntilStopped,
2311 &task_start_event, &task_stop_event));
2312 task_start_event.Wait();
2313
2314 EndTraceAndFlush();
2315 ValidateAllTraceMacrosCreatedData(trace_parsed_);
2316
2317 task_stop_event.Signal();
2318 thread.Stop();
2319 }
2320
TEST_F(TraceEventTestFixture,ThreadOnceBlocking)2321 TEST_F(TraceEventTestFixture, ThreadOnceBlocking) {
2322 BeginTrace();
2323
2324 Thread thread("1");
2325 WaitableEvent task_complete_event(WaitableEvent::ResetPolicy::AUTOMATIC,
2326 WaitableEvent::InitialState::NOT_SIGNALED);
2327 thread.Start();
2328
2329 thread.task_runner()->PostTask(
2330 FROM_HERE, BindOnce(&TraceWithAllMacroVariants, &task_complete_event));
2331 task_complete_event.Wait();
2332
2333 WaitableEvent task_start_event(WaitableEvent::ResetPolicy::AUTOMATIC,
2334 WaitableEvent::InitialState::NOT_SIGNALED);
2335 WaitableEvent task_stop_event(WaitableEvent::ResetPolicy::AUTOMATIC,
2336 WaitableEvent::InitialState::NOT_SIGNALED);
2337 thread.task_runner()->PostTask(
2338 FROM_HERE,
2339 BindOnce(&BlockUntilStopped, &task_start_event, &task_stop_event));
2340 task_start_event.Wait();
2341
2342 // The thread will timeout in this flush.
2343 EndTraceAndFlushInThreadWithMessageLoop();
2344 Clear();
2345
2346 // Let the thread's message loop continue to spin.
2347 task_stop_event.Signal();
2348
2349 // The following sequence ensures that the FlushCurrentThread task has been
2350 // executed in the thread before continuing.
2351 thread.task_runner()->PostTask(
2352 FROM_HERE,
2353 BindOnce(&BlockUntilStopped, &task_start_event, &task_stop_event));
2354 task_start_event.Wait();
2355 task_stop_event.Signal();
2356 Clear();
2357
2358 // TraceLog should discover the generation mismatch and recover the thread
2359 // local buffer for the thread without any error.
2360 BeginTrace();
2361 thread.task_runner()->PostTask(
2362 FROM_HERE, BindOnce(&TraceWithAllMacroVariants, &task_complete_event));
2363 task_complete_event.Wait();
2364 EndTraceAndFlushInThreadWithMessageLoop();
2365 ValidateAllTraceMacrosCreatedData(trace_parsed_);
2366 }
2367
2368 std::string* g_log_buffer = nullptr;
MockLogMessageHandler(int,const char *,int,size_t,const std::string & str)2369 bool MockLogMessageHandler(int, const char*, int, size_t,
2370 const std::string& str) {
2371 if (!g_log_buffer)
2372 g_log_buffer = new std::string();
2373 g_log_buffer->append(str);
2374 return false;
2375 }
2376
TEST_F(TraceEventTestFixture,EchoToConsole)2377 TEST_F(TraceEventTestFixture, EchoToConsole) {
2378 logging::LogMessageHandlerFunction old_log_message_handler =
2379 logging::GetLogMessageHandler();
2380 logging::SetLogMessageHandler(MockLogMessageHandler);
2381
2382 TraceLog::GetInstance()->SetEnabled(
2383 TraceConfig(kRecordAllCategoryFilter, ECHO_TO_CONSOLE),
2384 TraceLog::RECORDING_MODE);
2385 TRACE_EVENT_BEGIN0("test_a", "begin_end");
2386 {
2387 TRACE_EVENT0("test_b", "duration");
2388 TRACE_EVENT0("test_b1", "duration1");
2389 }
2390 TRACE_EVENT_INSTANT0("test_c", "instant", TRACE_EVENT_SCOPE_GLOBAL);
2391 TRACE_EVENT_END0("test_a", "begin_end");
2392
2393 // Perfetto's console interceptor outputs directly to the console and has test
2394 // coverage upstream.
2395 #if !BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
2396 EXPECT_NE(std::string::npos, g_log_buffer->find("begin_end[test_a]\x1b"));
2397 EXPECT_NE(std::string::npos, g_log_buffer->find("| duration[test_b]\x1b"));
2398 EXPECT_NE(std::string::npos,
2399 g_log_buffer->find("| | duration1[test_b1]\x1b"));
2400 EXPECT_NE(std::string::npos, g_log_buffer->find("| | duration1[test_b1] ("));
2401 EXPECT_NE(std::string::npos, g_log_buffer->find("| duration[test_b] ("));
2402 EXPECT_NE(std::string::npos, g_log_buffer->find("| instant[test_c]\x1b"));
2403 EXPECT_NE(std::string::npos, g_log_buffer->find("begin_end[test_a] ("));
2404 #endif // !BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
2405
2406 EndTraceAndFlush();
2407 delete g_log_buffer;
2408 logging::SetLogMessageHandler(old_log_message_handler);
2409 g_log_buffer = nullptr;
2410 }
2411
LogMessageHandlerWithTraceEvent(int,const char *,int,size_t,const std::string &)2412 bool LogMessageHandlerWithTraceEvent(int, const char*, int, size_t,
2413 const std::string&) {
2414 TRACE_EVENT0("log", "trace_event");
2415 return false;
2416 }
2417
TEST_F(TraceEventTestFixture,EchoToConsoleTraceEventRecursion)2418 TEST_F(TraceEventTestFixture, EchoToConsoleTraceEventRecursion) {
2419 logging::LogMessageHandlerFunction old_log_message_handler =
2420 logging::GetLogMessageHandler();
2421 logging::SetLogMessageHandler(LogMessageHandlerWithTraceEvent);
2422
2423 TraceLog::GetInstance()->SetEnabled(
2424 TraceConfig(kRecordAllCategoryFilter, ECHO_TO_CONSOLE),
2425 TraceLog::RECORDING_MODE);
2426 {
2427 // This should not cause deadlock or infinite recursion.
2428 TRACE_EVENT0("test_b", "duration");
2429 }
2430
2431 EndTraceAndFlush();
2432 logging::SetLogMessageHandler(old_log_message_handler);
2433 }
2434
2435 // Perfetto doesn't support overriding the time offset.
2436 #if !BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
TEST_F(TraceEventTestFixture,TimeOffset)2437 TEST_F(TraceEventTestFixture, TimeOffset) {
2438 BeginTrace();
2439 // Let TraceLog timer start from 0.
2440 TimeDelta time_offset = TimeTicks::Now() - TimeTicks();
2441 TraceLog::GetInstance()->SetTimeOffset(time_offset);
2442
2443 {
2444 TRACE_EVENT0("test_all", "duration1");
2445 TRACE_EVENT0("test_all", "duration2");
2446 }
2447 TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0("test_all", "with_timestamp", 0,
2448 0, TimeTicks::Now());
2449 TRACE_EVENT_END_WITH_ID_TID_AND_TIMESTAMP0("test_all", "with_timestamp", 0, 0,
2450 TimeTicks::Now());
2451
2452 EndTraceAndFlush();
2453 DropTracedMetadataRecords();
2454
2455 double end_time = static_cast<double>(
2456 (TimeTicks::Now() - time_offset).ToInternalValue());
2457 double last_timestamp = 0;
2458 for (const Value& item : trace_parsed_) {
2459 EXPECT_TRUE(item.is_dict());
2460 std::optional<double> timestamp = item.GetDict().FindDouble("ts");
2461 EXPECT_TRUE(timestamp.has_value());
2462 EXPECT_GE(timestamp.value(), last_timestamp);
2463 EXPECT_LE(timestamp.value(), end_time);
2464 last_timestamp = timestamp.value();
2465 }
2466 }
2467 #endif // !BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
2468
TEST_F(TraceEventTestFixture,ClockSyncEventsAreAlwaysAddedToTrace)2469 TEST_F(TraceEventTestFixture, ClockSyncEventsAreAlwaysAddedToTrace) {
2470 BeginSpecificTrace("-*");
2471 TRACE_EVENT_CLOCK_SYNC_RECEIVER(1);
2472 EndTraceAndFlush();
2473 EXPECT_TRUE(FindNamePhase("clock_sync", "c"));
2474 }
2475
TEST_F(TraceEventTestFixture,ContextLambda)2476 TEST_F(TraceEventTestFixture, ContextLambda) {
2477 TraceLog::GetInstance()->SetEnabled(TraceConfig(kRecordAllCategoryFilter, ""),
2478 TraceLog::RECORDING_MODE);
2479
2480 {
2481 TRACE_EVENT1("cat", "Name", "arg", [&](perfetto::TracedValue ctx) {
2482 std::move(ctx).WriteString("foobar");
2483 });
2484 }
2485 EndTraceAndFlush();
2486
2487 const Value::Dict* dict = FindNamePhase("Name", "X");
2488 ASSERT_TRUE(dict);
2489
2490 const Value::Dict* args_dict = dict->FindDict("args");
2491 ASSERT_TRUE(args_dict);
2492
2493 #if BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
2494 EXPECT_EQ(*args_dict->FindString("arg"), "foobar");
2495 #else
2496 // Pre-client-lib, these types of TracedValues can't be serialized to JSON.
2497 EXPECT_EQ(*args_dict->FindString("arg"), "Unsupported (crbug.com/1225176)");
2498 #endif
2499 }
2500
2501 #if BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
2502 class ConfigObserver : public TraceLog::EnabledStateObserver {
2503 public:
2504 ConfigObserver() = default;
2505 ~ConfigObserver() override = default;
2506
OnTraceLogEnabled()2507 void OnTraceLogEnabled() override {
2508 observed_config = TraceLog::GetInstance()->GetCurrentTraceConfig();
2509 tracing_enabled.Signal();
2510 }
2511
OnTraceLogDisabled()2512 void OnTraceLogDisabled() override { tracing_disabled.Signal(); }
2513
2514 TraceConfig observed_config;
2515 WaitableEvent tracing_enabled{WaitableEvent::ResetPolicy::AUTOMATIC,
2516 WaitableEvent::InitialState::NOT_SIGNALED};
2517 WaitableEvent tracing_disabled{WaitableEvent::ResetPolicy::AUTOMATIC,
2518 WaitableEvent::InitialState::NOT_SIGNALED};
2519 };
2520
2521 // Test that GetCurrentTraceConfig() returns the correct config when tracing
2522 // was started through Perfetto SDK.
TEST_F(TraceEventTestFixture,GetCurrentTraceConfig)2523 TEST_F(TraceEventTestFixture, GetCurrentTraceConfig) {
2524 ConfigObserver observer;
2525 TraceLog::GetInstance()->AddEnabledStateObserver(&observer);
2526
2527 const TraceConfig actual_config{"foo,bar", ""};
2528 perfetto::TraceConfig perfetto_config;
2529 perfetto_config.add_buffers()->set_size_kb(1000);
2530 auto* source_config = perfetto_config.add_data_sources()->mutable_config();
2531 source_config->set_name("track_event");
2532 source_config->set_target_buffer(0);
2533 source_config->mutable_chrome_config()->set_trace_config(
2534 actual_config.ToString());
2535
2536 auto tracing_session = perfetto::Tracing::NewTrace();
2537 tracing_session->Setup(perfetto_config);
2538 tracing_session->Start();
2539
2540 observer.tracing_enabled.Wait();
2541 tracing_session->Stop();
2542 observer.tracing_disabled.Wait();
2543
2544 EXPECT_EQ(actual_config.ToString(), observer.observed_config.ToString());
2545 }
2546 #endif // BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
2547
2548 } // namespace base::trace_event
2549