xref: /aosp_15_r20/external/cronet/base/trace_event/trace_event_unittest.cc (revision 6777b5387eb2ff775bb5750e3f5d96f37fb7352b)
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