1 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
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 <math.h>
8 #include <stddef.h>
9 #include <stdint.h>
10
11 #include <cstdlib>
12 #include <memory>
13 #include <utility>
14
15 #include "base/bind.h"
16 #include "base/command_line.h"
17 #include "base/json/json_reader.h"
18 #include "base/json/json_writer.h"
19 #include "base/location.h"
20 #include "base/macros.h"
21 #include "base/memory/ptr_util.h"
22 #include "base/memory/ref_counted_memory.h"
23 #include "base/memory/singleton.h"
24 #include "base/process/process_handle.h"
25 #include "base/single_thread_task_runner.h"
26 #include "base/stl_util.h"
27 #include "base/strings/pattern.h"
28 #include "base/strings/stringprintf.h"
29 #include "base/synchronization/waitable_event.h"
30 #include "base/threading/platform_thread.h"
31 #include "base/threading/thread.h"
32 #include "base/time/time.h"
33 #include "base/trace_event/event_name_filter.h"
34 #include "base/trace_event/heap_profiler_event_filter.h"
35 #include "base/trace_event/trace_buffer.h"
36 #include "base/trace_event/trace_event.h"
37 #include "base/trace_event/trace_event_filter.h"
38 #include "base/trace_event/trace_event_filter_test_utils.h"
39 #include "base/values.h"
40 #include "testing/gmock/include/gmock/gmock.h"
41 #include "testing/gtest/include/gtest/gtest.h"
42
43 namespace base {
44 namespace trace_event {
45
46 namespace {
47
48 enum CompareOp {
49 IS_EQUAL,
50 IS_NOT_EQUAL,
51 };
52
53 struct JsonKeyValue {
54 const char* key;
55 const char* value;
56 CompareOp op;
57 };
58
59 const int kThreadId = 42;
60 const int kAsyncId = 5;
61 const char kAsyncIdStr[] = "0x5";
62 const int kAsyncId2 = 6;
63 const char kAsyncId2Str[] = "0x6";
64 const int kFlowId = 7;
65 const char kFlowIdStr[] = "0x7";
66
67 const char kRecordAllCategoryFilter[] = "*";
68
69 class TraceEventTestFixture : public testing::Test {
70 public:
71 void OnTraceDataCollected(
72 WaitableEvent* flush_complete_event,
73 const scoped_refptr<base::RefCountedString>& events_str,
74 bool has_more_events);
75 DictionaryValue* FindMatchingTraceEntry(const JsonKeyValue* key_values);
76 DictionaryValue* FindNamePhase(const char* name, const char* phase);
77 DictionaryValue* FindNamePhaseKeyValue(const char* name,
78 const char* phase,
79 const char* key,
80 const char* value);
81 void DropTracedMetadataRecords();
82 bool FindMatchingValue(const char* key,
83 const char* value);
84 bool FindNonMatchingValue(const char* key,
85 const char* value);
Clear()86 void Clear() {
87 trace_parsed_.Clear();
88 json_output_.json_output.clear();
89 }
90
BeginTrace()91 void BeginTrace() {
92 BeginSpecificTrace("*");
93 }
94
BeginSpecificTrace(const std::string & filter)95 void BeginSpecificTrace(const std::string& filter) {
96 TraceLog::GetInstance()->SetEnabled(TraceConfig(filter, ""),
97 TraceLog::RECORDING_MODE);
98 }
99
CancelTrace()100 void CancelTrace() {
101 WaitableEvent flush_complete_event(
102 WaitableEvent::ResetPolicy::AUTOMATIC,
103 WaitableEvent::InitialState::NOT_SIGNALED);
104 CancelTraceAsync(&flush_complete_event);
105 flush_complete_event.Wait();
106 }
107
EndTraceAndFlush()108 void EndTraceAndFlush() {
109 num_flush_callbacks_ = 0;
110 WaitableEvent flush_complete_event(
111 WaitableEvent::ResetPolicy::AUTOMATIC,
112 WaitableEvent::InitialState::NOT_SIGNALED);
113 EndTraceAndFlushAsync(&flush_complete_event);
114 flush_complete_event.Wait();
115 }
116
117 // Used when testing thread-local buffers which requires the thread initiating
118 // flush to have a message loop.
EndTraceAndFlushInThreadWithMessageLoop()119 void EndTraceAndFlushInThreadWithMessageLoop() {
120 WaitableEvent flush_complete_event(
121 WaitableEvent::ResetPolicy::AUTOMATIC,
122 WaitableEvent::InitialState::NOT_SIGNALED);
123 Thread flush_thread("flush");
124 flush_thread.Start();
125 flush_thread.task_runner()->PostTask(
126 FROM_HERE,
127 base::BindOnce(&TraceEventTestFixture::EndTraceAndFlushAsync,
128 base::Unretained(this), &flush_complete_event));
129 flush_complete_event.Wait();
130 }
131
CancelTraceAsync(WaitableEvent * flush_complete_event)132 void CancelTraceAsync(WaitableEvent* flush_complete_event) {
133 TraceLog::GetInstance()->CancelTracing(
134 base::Bind(&TraceEventTestFixture::OnTraceDataCollected,
135 base::Unretained(static_cast<TraceEventTestFixture*>(this)),
136 base::Unretained(flush_complete_event)));
137 }
138
EndTraceAndFlushAsync(WaitableEvent * flush_complete_event)139 void EndTraceAndFlushAsync(WaitableEvent* flush_complete_event) {
140 TraceLog::GetInstance()->SetDisabled(TraceLog::RECORDING_MODE |
141 TraceLog::FILTERING_MODE);
142 TraceLog::GetInstance()->Flush(
143 base::Bind(&TraceEventTestFixture::OnTraceDataCollected,
144 base::Unretained(static_cast<TraceEventTestFixture*>(this)),
145 base::Unretained(flush_complete_event)));
146 }
147
SetUp()148 void SetUp() override {
149 const char* name = PlatformThread::GetName();
150 old_thread_name_ = name ? strdup(name) : nullptr;
151
152 TraceLog::ResetForTesting();
153 TraceLog* tracelog = TraceLog::GetInstance();
154 ASSERT_TRUE(tracelog);
155 ASSERT_FALSE(tracelog->IsEnabled());
156 trace_buffer_.SetOutputCallback(json_output_.GetCallback());
157 num_flush_callbacks_ = 0;
158 }
TearDown()159 void TearDown() override {
160 if (TraceLog::GetInstance())
161 EXPECT_FALSE(TraceLog::GetInstance()->IsEnabled());
162 PlatformThread::SetName(old_thread_name_ ? old_thread_name_ : "");
163 free(old_thread_name_);
164 old_thread_name_ = nullptr;
165 // We want our singleton torn down after each test.
166 TraceLog::ResetForTesting();
167 }
168
169 char* old_thread_name_;
170 ListValue trace_parsed_;
171 TraceResultBuffer trace_buffer_;
172 TraceResultBuffer::SimpleOutput json_output_;
173 size_t num_flush_callbacks_;
174
175 private:
176 // We want our singleton torn down after each test.
177 ShadowingAtExitManager at_exit_manager_;
178 Lock lock_;
179 };
180
OnTraceDataCollected(WaitableEvent * flush_complete_event,const scoped_refptr<base::RefCountedString> & events_str,bool has_more_events)181 void TraceEventTestFixture::OnTraceDataCollected(
182 WaitableEvent* flush_complete_event,
183 const scoped_refptr<base::RefCountedString>& events_str,
184 bool has_more_events) {
185 num_flush_callbacks_++;
186 if (num_flush_callbacks_ > 1) {
187 EXPECT_FALSE(events_str->data().empty());
188 }
189 AutoLock lock(lock_);
190 json_output_.json_output.clear();
191 trace_buffer_.Start();
192 trace_buffer_.AddFragment(events_str->data());
193 trace_buffer_.Finish();
194
195 std::unique_ptr<Value> root =
196 base::JSONReader::Read(json_output_.json_output, JSON_PARSE_RFC);
197
198 if (!root.get()) {
199 LOG(ERROR) << json_output_.json_output;
200 }
201
202 ListValue* root_list = nullptr;
203 ASSERT_TRUE(root.get());
204 ASSERT_TRUE(root->GetAsList(&root_list));
205
206 // Move items into our aggregate collection
207 while (root_list->GetSize()) {
208 std::unique_ptr<Value> item;
209 root_list->Remove(0, &item);
210 trace_parsed_.Append(std::move(item));
211 }
212
213 if (!has_more_events)
214 flush_complete_event->Signal();
215 }
216
CompareJsonValues(const std::string & lhs,const std::string & rhs,CompareOp op)217 static bool CompareJsonValues(const std::string& lhs,
218 const std::string& rhs,
219 CompareOp op) {
220 switch (op) {
221 case IS_EQUAL:
222 return lhs == rhs;
223 case IS_NOT_EQUAL:
224 return lhs != rhs;
225 default:
226 CHECK(0);
227 }
228 return false;
229 }
230
IsKeyValueInDict(const JsonKeyValue * key_value,DictionaryValue * dict)231 static bool IsKeyValueInDict(const JsonKeyValue* key_value,
232 DictionaryValue* dict) {
233 Value* value = nullptr;
234 std::string value_str;
235 if (dict->Get(key_value->key, &value) &&
236 value->GetAsString(&value_str) &&
237 CompareJsonValues(value_str, key_value->value, key_value->op))
238 return true;
239
240 // Recurse to test arguments
241 DictionaryValue* args_dict = nullptr;
242 dict->GetDictionary("args", &args_dict);
243 if (args_dict)
244 return IsKeyValueInDict(key_value, args_dict);
245
246 return false;
247 }
248
IsAllKeyValueInDict(const JsonKeyValue * key_values,DictionaryValue * dict)249 static bool IsAllKeyValueInDict(const JsonKeyValue* key_values,
250 DictionaryValue* dict) {
251 // Scan all key_values, they must all be present and equal.
252 while (key_values && key_values->key) {
253 if (!IsKeyValueInDict(key_values, dict))
254 return false;
255 ++key_values;
256 }
257 return true;
258 }
259
FindMatchingTraceEntry(const JsonKeyValue * key_values)260 DictionaryValue* TraceEventTestFixture::FindMatchingTraceEntry(
261 const JsonKeyValue* key_values) {
262 // Scan all items
263 size_t trace_parsed_count = trace_parsed_.GetSize();
264 for (size_t i = 0; i < trace_parsed_count; i++) {
265 Value* value = nullptr;
266 trace_parsed_.Get(i, &value);
267 if (!value || value->type() != Value::Type::DICTIONARY)
268 continue;
269 DictionaryValue* dict = static_cast<DictionaryValue*>(value);
270
271 if (IsAllKeyValueInDict(key_values, dict))
272 return dict;
273 }
274 return nullptr;
275 }
276
DropTracedMetadataRecords()277 void TraceEventTestFixture::DropTracedMetadataRecords() {
278 std::unique_ptr<ListValue> old_trace_parsed(trace_parsed_.CreateDeepCopy());
279 size_t old_trace_parsed_size = old_trace_parsed->GetSize();
280 trace_parsed_.Clear();
281
282 for (size_t i = 0; i < old_trace_parsed_size; i++) {
283 Value* value = nullptr;
284 old_trace_parsed->Get(i, &value);
285 if (!value || value->type() != Value::Type::DICTIONARY) {
286 trace_parsed_.Append(value->CreateDeepCopy());
287 continue;
288 }
289 DictionaryValue* dict = static_cast<DictionaryValue*>(value);
290 std::string tmp;
291 if (dict->GetString("ph", &tmp) && tmp == "M")
292 continue;
293
294 trace_parsed_.Append(value->CreateDeepCopy());
295 }
296 }
297
FindNamePhase(const char * name,const char * phase)298 DictionaryValue* TraceEventTestFixture::FindNamePhase(const char* name,
299 const char* phase) {
300 JsonKeyValue key_values[] = {{"name", name, IS_EQUAL},
301 {"ph", phase, IS_EQUAL},
302 {nullptr, nullptr, IS_EQUAL}};
303 return FindMatchingTraceEntry(key_values);
304 }
305
FindNamePhaseKeyValue(const char * name,const char * phase,const char * key,const char * value)306 DictionaryValue* TraceEventTestFixture::FindNamePhaseKeyValue(
307 const char* name,
308 const char* phase,
309 const char* key,
310 const char* value) {
311 JsonKeyValue key_values[] = {{"name", name, IS_EQUAL},
312 {"ph", phase, IS_EQUAL},
313 {key, value, IS_EQUAL},
314 {nullptr, nullptr, IS_EQUAL}};
315 return FindMatchingTraceEntry(key_values);
316 }
317
FindMatchingValue(const char * key,const char * value)318 bool TraceEventTestFixture::FindMatchingValue(const char* key,
319 const char* value) {
320 JsonKeyValue key_values[] = {{key, value, IS_EQUAL},
321 {nullptr, nullptr, IS_EQUAL}};
322 return FindMatchingTraceEntry(key_values);
323 }
324
FindNonMatchingValue(const char * key,const char * value)325 bool TraceEventTestFixture::FindNonMatchingValue(const char* key,
326 const char* value) {
327 JsonKeyValue key_values[] = {{key, value, IS_NOT_EQUAL},
328 {nullptr, nullptr, IS_EQUAL}};
329 return FindMatchingTraceEntry(key_values);
330 }
331
IsStringInDict(const char * string_to_match,const DictionaryValue * dict)332 bool IsStringInDict(const char* string_to_match, const DictionaryValue* dict) {
333 for (DictionaryValue::Iterator it(*dict); !it.IsAtEnd(); it.Advance()) {
334 if (it.key().find(string_to_match) != std::string::npos)
335 return true;
336
337 std::string value_str;
338 it.value().GetAsString(&value_str);
339 if (value_str.find(string_to_match) != std::string::npos)
340 return true;
341 }
342
343 // Recurse to test arguments
344 const DictionaryValue* args_dict = nullptr;
345 dict->GetDictionary("args", &args_dict);
346 if (args_dict)
347 return IsStringInDict(string_to_match, args_dict);
348
349 return false;
350 }
351
FindTraceEntry(const ListValue & trace_parsed,const char * string_to_match,const DictionaryValue * match_after_this_item=nullptr)352 const DictionaryValue* FindTraceEntry(
353 const ListValue& trace_parsed,
354 const char* string_to_match,
355 const DictionaryValue* match_after_this_item = nullptr) {
356 // Scan all items
357 size_t trace_parsed_count = trace_parsed.GetSize();
358 for (size_t i = 0; i < trace_parsed_count; i++) {
359 const Value* value = nullptr;
360 trace_parsed.Get(i, &value);
361 if (match_after_this_item) {
362 if (value == match_after_this_item)
363 match_after_this_item = nullptr;
364 continue;
365 }
366 if (!value || value->type() != Value::Type::DICTIONARY)
367 continue;
368 const DictionaryValue* dict = static_cast<const DictionaryValue*>(value);
369
370 if (IsStringInDict(string_to_match, dict))
371 return dict;
372 }
373 return nullptr;
374 }
375
FindTraceEntries(const ListValue & trace_parsed,const char * string_to_match)376 std::vector<const DictionaryValue*> FindTraceEntries(
377 const ListValue& trace_parsed,
378 const char* string_to_match) {
379 std::vector<const DictionaryValue*> hits;
380 size_t trace_parsed_count = trace_parsed.GetSize();
381 for (size_t i = 0; i < trace_parsed_count; i++) {
382 const Value* value = nullptr;
383 trace_parsed.Get(i, &value);
384 if (!value || value->type() != Value::Type::DICTIONARY)
385 continue;
386 const DictionaryValue* dict = static_cast<const DictionaryValue*>(value);
387
388 if (IsStringInDict(string_to_match, dict))
389 hits.push_back(dict);
390 }
391 return hits;
392 }
393
394 const char kControlCharacters[] = "\001\002\003\n\r";
395
TraceWithAllMacroVariants(WaitableEvent * task_complete_event)396 void TraceWithAllMacroVariants(WaitableEvent* task_complete_event) {
397 {
398 TRACE_EVENT0("all", "TRACE_EVENT0 call");
399 TRACE_EVENT1("all", "TRACE_EVENT1 call", "name1", "value1");
400 TRACE_EVENT2("all", "TRACE_EVENT2 call",
401 "name1", "\"value1\"",
402 "name2", "value\\2");
403
404 TRACE_EVENT_INSTANT0("all", "TRACE_EVENT_INSTANT0 call",
405 TRACE_EVENT_SCOPE_GLOBAL);
406 TRACE_EVENT_INSTANT1("all", "TRACE_EVENT_INSTANT1 call",
407 TRACE_EVENT_SCOPE_PROCESS, "name1", "value1");
408 TRACE_EVENT_INSTANT2("all", "TRACE_EVENT_INSTANT2 call",
409 TRACE_EVENT_SCOPE_THREAD,
410 "name1", "value1",
411 "name2", "value2");
412
413 TRACE_EVENT_BEGIN0("all", "TRACE_EVENT_BEGIN0 call");
414 TRACE_EVENT_BEGIN1("all", "TRACE_EVENT_BEGIN1 call", "name1", "value1");
415 TRACE_EVENT_BEGIN2("all", "TRACE_EVENT_BEGIN2 call",
416 "name1", "value1",
417 "name2", "value2");
418
419 TRACE_EVENT_END0("all", "TRACE_EVENT_END0 call");
420 TRACE_EVENT_END1("all", "TRACE_EVENT_END1 call", "name1", "value1");
421 TRACE_EVENT_END2("all", "TRACE_EVENT_END2 call",
422 "name1", "value1",
423 "name2", "value2");
424
425 TRACE_EVENT_ASYNC_BEGIN0("all", "TRACE_EVENT_ASYNC_BEGIN0 call", kAsyncId);
426 TRACE_EVENT_ASYNC_BEGIN1("all", "TRACE_EVENT_ASYNC_BEGIN1 call", kAsyncId,
427 "name1", "value1");
428 TRACE_EVENT_ASYNC_BEGIN2("all", "TRACE_EVENT_ASYNC_BEGIN2 call", kAsyncId,
429 "name1", "value1",
430 "name2", "value2");
431
432 TRACE_EVENT_ASYNC_STEP_INTO0("all", "TRACE_EVENT_ASYNC_STEP_INTO0 call",
433 kAsyncId, "step_begin1");
434 TRACE_EVENT_ASYNC_STEP_INTO1("all", "TRACE_EVENT_ASYNC_STEP_INTO1 call",
435 kAsyncId, "step_begin2", "name1", "value1");
436
437 TRACE_EVENT_ASYNC_END0("all", "TRACE_EVENT_ASYNC_END0 call", kAsyncId);
438 TRACE_EVENT_ASYNC_END1("all", "TRACE_EVENT_ASYNC_END1 call", kAsyncId,
439 "name1", "value1");
440 TRACE_EVENT_ASYNC_END2("all", "TRACE_EVENT_ASYNC_END2 call", kAsyncId,
441 "name1", "value1",
442 "name2", "value2");
443
444 TRACE_EVENT_FLOW_BEGIN0("all", "TRACE_EVENT_FLOW_BEGIN0 call", kFlowId);
445 TRACE_EVENT_FLOW_STEP0("all", "TRACE_EVENT_FLOW_STEP0 call",
446 kFlowId, "step1");
447 TRACE_EVENT_FLOW_END_BIND_TO_ENCLOSING0("all",
448 "TRACE_EVENT_FLOW_END_BIND_TO_ENCLOSING0 call", kFlowId);
449
450 TRACE_COUNTER1("all", "TRACE_COUNTER1 call", 31415);
451 TRACE_COUNTER2("all", "TRACE_COUNTER2 call",
452 "a", 30000,
453 "b", 1415);
454
455 TRACE_COUNTER_WITH_TIMESTAMP1("all", "TRACE_COUNTER_WITH_TIMESTAMP1 call",
456 TimeTicks::FromInternalValue(42), 31415);
457 TRACE_COUNTER_WITH_TIMESTAMP2("all", "TRACE_COUNTER_WITH_TIMESTAMP2 call",
458 TimeTicks::FromInternalValue(42),
459 "a", 30000, "b", 1415);
460
461 TRACE_COUNTER_ID1("all", "TRACE_COUNTER_ID1 call", 0x319009, 31415);
462 TRACE_COUNTER_ID2("all", "TRACE_COUNTER_ID2 call", 0x319009,
463 "a", 30000, "b", 1415);
464
465 TRACE_EVENT_COPY_BEGIN_WITH_ID_TID_AND_TIMESTAMP0("all",
466 "TRACE_EVENT_COPY_BEGIN_WITH_ID_TID_AND_TIMESTAMP0 call",
467 kAsyncId, kThreadId, TimeTicks::FromInternalValue(12345));
468 TRACE_EVENT_COPY_END_WITH_ID_TID_AND_TIMESTAMP0("all",
469 "TRACE_EVENT_COPY_END_WITH_ID_TID_AND_TIMESTAMP0 call",
470 kAsyncId, kThreadId, TimeTicks::FromInternalValue(23456));
471
472 TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0("all",
473 "TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0 call",
474 kAsyncId2, kThreadId, TimeTicks::FromInternalValue(34567));
475 TRACE_EVENT_ASYNC_STEP_PAST0("all", "TRACE_EVENT_ASYNC_STEP_PAST0 call",
476 kAsyncId2, "step_end1");
477 TRACE_EVENT_ASYNC_STEP_PAST1("all", "TRACE_EVENT_ASYNC_STEP_PAST1 call",
478 kAsyncId2, "step_end2", "name1", "value1");
479
480 TRACE_EVENT_END_WITH_ID_TID_AND_TIMESTAMP0("all",
481 "TRACE_EVENT_END_WITH_ID_TID_AND_TIMESTAMP0 call",
482 kAsyncId2, kThreadId, TimeTicks::FromInternalValue(45678));
483
484 TRACE_EVENT_OBJECT_CREATED_WITH_ID("all", "tracked object 1", 0x42);
485 TRACE_EVENT_OBJECT_SNAPSHOT_WITH_ID(
486 "all", "tracked object 1", 0x42, "hello");
487 TRACE_EVENT_OBJECT_DELETED_WITH_ID("all", "tracked object 1", 0x42);
488
489 TraceScopedTrackableObject<int> trackable("all", "tracked object 2",
490 0x2128506);
491 trackable.snapshot("world");
492
493 TRACE_EVENT_OBJECT_CREATED_WITH_ID(
494 "all", "tracked object 3", TRACE_ID_WITH_SCOPE("scope", 0x42));
495 TRACE_EVENT_OBJECT_SNAPSHOT_WITH_ID(
496 "all", "tracked object 3", TRACE_ID_WITH_SCOPE("scope", 0x42), "hello");
497 TRACE_EVENT_OBJECT_DELETED_WITH_ID(
498 "all", "tracked object 3", TRACE_ID_WITH_SCOPE("scope", 0x42));
499
500 TRACE_EVENT1(kControlCharacters, kControlCharacters,
501 kControlCharacters, kControlCharacters);
502
503 uint64_t context_id = 0x20151021;
504
505 TRACE_EVENT_ENTER_CONTEXT("all", "TRACE_EVENT_ENTER_CONTEXT call",
506 TRACE_ID_WITH_SCOPE("scope", context_id));
507 TRACE_EVENT_LEAVE_CONTEXT("all", "TRACE_EVENT_LEAVE_CONTEXT call",
508 TRACE_ID_WITH_SCOPE("scope", context_id));
509 TRACE_EVENT_SCOPED_CONTEXT("disabled-by-default-cat",
510 "TRACE_EVENT_SCOPED_CONTEXT disabled call",
511 context_id);
512 TRACE_EVENT_SCOPED_CONTEXT("all", "TRACE_EVENT_SCOPED_CONTEXT call",
513 context_id);
514
515 TRACE_LINK_IDS("all", "TRACE_LINK_IDS simple call", 0x1000, 0x2000);
516 TRACE_LINK_IDS("all", "TRACE_LINK_IDS scoped call",
517 TRACE_ID_WITH_SCOPE("scope 1", 0x1000),
518 TRACE_ID_WITH_SCOPE("scope 2", 0x2000));
519 TRACE_LINK_IDS("all", "TRACE_LINK_IDS to a local ID", 0x1000,
520 TRACE_ID_LOCAL(0x2000));
521 TRACE_LINK_IDS("all", "TRACE_LINK_IDS to a global ID", 0x1000,
522 TRACE_ID_GLOBAL(0x2000));
523 TRACE_LINK_IDS("all", "TRACE_LINK_IDS to a composite ID", 0x1000,
524 TRACE_ID_WITH_SCOPE("scope 1", 0x2000, 0x3000));
525
526 TRACE_EVENT_ASYNC_BEGIN0("all", "async default process scope", 0x1000);
527 TRACE_EVENT_ASYNC_BEGIN0("all", "async local id", TRACE_ID_LOCAL(0x2000));
528 TRACE_EVENT_ASYNC_BEGIN0("all", "async global id", TRACE_ID_GLOBAL(0x3000));
529 TRACE_EVENT_ASYNC_BEGIN0("all", "async global id with scope string",
530 TRACE_ID_WITH_SCOPE("scope string",
531 TRACE_ID_GLOBAL(0x4000)));
532 } // Scope close causes TRACE_EVENT0 etc to send their END events.
533
534 if (task_complete_event)
535 task_complete_event->Signal();
536 }
537
ValidateAllTraceMacrosCreatedData(const ListValue & trace_parsed)538 void ValidateAllTraceMacrosCreatedData(const ListValue& trace_parsed) {
539 const DictionaryValue* item = nullptr;
540
541 #define EXPECT_FIND_(string) \
542 item = FindTraceEntry(trace_parsed, string); \
543 EXPECT_TRUE(item);
544 #define EXPECT_NOT_FIND_(string) \
545 item = FindTraceEntry(trace_parsed, string); \
546 EXPECT_FALSE(item);
547 #define EXPECT_SUB_FIND_(string) \
548 if (item) \
549 EXPECT_TRUE(IsStringInDict(string, item));
550
551 EXPECT_FIND_("TRACE_EVENT0 call");
552 {
553 std::string ph;
554 std::string ph_end;
555 EXPECT_TRUE((item = FindTraceEntry(trace_parsed, "TRACE_EVENT0 call")));
556 EXPECT_TRUE((item && item->GetString("ph", &ph)));
557 EXPECT_EQ("X", ph);
558 item = FindTraceEntry(trace_parsed, "TRACE_EVENT0 call", item);
559 EXPECT_FALSE(item);
560 }
561 EXPECT_FIND_("TRACE_EVENT1 call");
562 EXPECT_SUB_FIND_("name1");
563 EXPECT_SUB_FIND_("value1");
564 EXPECT_FIND_("TRACE_EVENT2 call");
565 EXPECT_SUB_FIND_("name1");
566 EXPECT_SUB_FIND_("\"value1\"");
567 EXPECT_SUB_FIND_("name2");
568 EXPECT_SUB_FIND_("value\\2");
569
570 EXPECT_FIND_("TRACE_EVENT_INSTANT0 call");
571 {
572 std::string scope;
573 EXPECT_TRUE((item && item->GetString("s", &scope)));
574 EXPECT_EQ("g", scope);
575 }
576 EXPECT_FIND_("TRACE_EVENT_INSTANT1 call");
577 {
578 std::string scope;
579 EXPECT_TRUE((item && item->GetString("s", &scope)));
580 EXPECT_EQ("p", scope);
581 }
582 EXPECT_SUB_FIND_("name1");
583 EXPECT_SUB_FIND_("value1");
584 EXPECT_FIND_("TRACE_EVENT_INSTANT2 call");
585 {
586 std::string scope;
587 EXPECT_TRUE((item && item->GetString("s", &scope)));
588 EXPECT_EQ("t", scope);
589 }
590 EXPECT_SUB_FIND_("name1");
591 EXPECT_SUB_FIND_("value1");
592 EXPECT_SUB_FIND_("name2");
593 EXPECT_SUB_FIND_("value2");
594
595 EXPECT_FIND_("TRACE_EVENT_BEGIN0 call");
596 EXPECT_FIND_("TRACE_EVENT_BEGIN1 call");
597 EXPECT_SUB_FIND_("name1");
598 EXPECT_SUB_FIND_("value1");
599 EXPECT_FIND_("TRACE_EVENT_BEGIN2 call");
600 EXPECT_SUB_FIND_("name1");
601 EXPECT_SUB_FIND_("value1");
602 EXPECT_SUB_FIND_("name2");
603 EXPECT_SUB_FIND_("value2");
604
605 EXPECT_FIND_("TRACE_EVENT_END0 call");
606 EXPECT_FIND_("TRACE_EVENT_END1 call");
607 EXPECT_SUB_FIND_("name1");
608 EXPECT_SUB_FIND_("value1");
609 EXPECT_FIND_("TRACE_EVENT_END2 call");
610 EXPECT_SUB_FIND_("name1");
611 EXPECT_SUB_FIND_("value1");
612 EXPECT_SUB_FIND_("name2");
613 EXPECT_SUB_FIND_("value2");
614
615 EXPECT_FIND_("TRACE_EVENT_ASYNC_BEGIN0 call");
616 EXPECT_SUB_FIND_("id");
617 EXPECT_SUB_FIND_(kAsyncIdStr);
618 EXPECT_FIND_("TRACE_EVENT_ASYNC_BEGIN1 call");
619 EXPECT_SUB_FIND_("id");
620 EXPECT_SUB_FIND_(kAsyncIdStr);
621 EXPECT_SUB_FIND_("name1");
622 EXPECT_SUB_FIND_("value1");
623 EXPECT_FIND_("TRACE_EVENT_ASYNC_BEGIN2 call");
624 EXPECT_SUB_FIND_("id");
625 EXPECT_SUB_FIND_(kAsyncIdStr);
626 EXPECT_SUB_FIND_("name1");
627 EXPECT_SUB_FIND_("value1");
628 EXPECT_SUB_FIND_("name2");
629 EXPECT_SUB_FIND_("value2");
630
631 EXPECT_FIND_("TRACE_EVENT_ASYNC_STEP_INTO0 call");
632 EXPECT_SUB_FIND_("id");
633 EXPECT_SUB_FIND_(kAsyncIdStr);
634 EXPECT_SUB_FIND_("step_begin1");
635 EXPECT_FIND_("TRACE_EVENT_ASYNC_STEP_INTO1 call");
636 EXPECT_SUB_FIND_("id");
637 EXPECT_SUB_FIND_(kAsyncIdStr);
638 EXPECT_SUB_FIND_("step_begin2");
639 EXPECT_SUB_FIND_("name1");
640 EXPECT_SUB_FIND_("value1");
641
642 EXPECT_FIND_("TRACE_EVENT_ASYNC_END0 call");
643 EXPECT_SUB_FIND_("id");
644 EXPECT_SUB_FIND_(kAsyncIdStr);
645 EXPECT_FIND_("TRACE_EVENT_ASYNC_END1 call");
646 EXPECT_SUB_FIND_("id");
647 EXPECT_SUB_FIND_(kAsyncIdStr);
648 EXPECT_SUB_FIND_("name1");
649 EXPECT_SUB_FIND_("value1");
650 EXPECT_FIND_("TRACE_EVENT_ASYNC_END2 call");
651 EXPECT_SUB_FIND_("id");
652 EXPECT_SUB_FIND_(kAsyncIdStr);
653 EXPECT_SUB_FIND_("name1");
654 EXPECT_SUB_FIND_("value1");
655 EXPECT_SUB_FIND_("name2");
656 EXPECT_SUB_FIND_("value2");
657
658 EXPECT_FIND_("TRACE_EVENT_FLOW_BEGIN0 call");
659 EXPECT_SUB_FIND_("id");
660 EXPECT_SUB_FIND_(kFlowIdStr);
661 EXPECT_FIND_("TRACE_EVENT_FLOW_STEP0 call");
662 EXPECT_SUB_FIND_("id");
663 EXPECT_SUB_FIND_(kFlowIdStr);
664 EXPECT_SUB_FIND_("step1");
665 EXPECT_FIND_("TRACE_EVENT_FLOW_END_BIND_TO_ENCLOSING0 call");
666 EXPECT_SUB_FIND_("id");
667 EXPECT_SUB_FIND_(kFlowIdStr);
668
669 EXPECT_FIND_("TRACE_COUNTER1 call");
670 {
671 std::string ph;
672 EXPECT_TRUE((item && item->GetString("ph", &ph)));
673 EXPECT_EQ("C", ph);
674
675 int value;
676 EXPECT_TRUE((item && item->GetInteger("args.value", &value)));
677 EXPECT_EQ(31415, value);
678 }
679
680 EXPECT_FIND_("TRACE_COUNTER2 call");
681 {
682 std::string ph;
683 EXPECT_TRUE((item && item->GetString("ph", &ph)));
684 EXPECT_EQ("C", ph);
685
686 int value;
687 EXPECT_TRUE((item && item->GetInteger("args.a", &value)));
688 EXPECT_EQ(30000, value);
689
690 EXPECT_TRUE((item && item->GetInteger("args.b", &value)));
691 EXPECT_EQ(1415, value);
692 }
693
694 EXPECT_FIND_("TRACE_COUNTER_WITH_TIMESTAMP1 call");
695 {
696 std::string ph;
697 EXPECT_TRUE((item && item->GetString("ph", &ph)));
698 EXPECT_EQ("C", ph);
699
700 int value;
701 EXPECT_TRUE((item && item->GetInteger("args.value", &value)));
702 EXPECT_EQ(31415, value);
703
704 int ts;
705 EXPECT_TRUE((item && item->GetInteger("ts", &ts)));
706 EXPECT_EQ(42, ts);
707 }
708
709 EXPECT_FIND_("TRACE_COUNTER_WITH_TIMESTAMP2 call");
710 {
711 std::string ph;
712 EXPECT_TRUE((item && item->GetString("ph", &ph)));
713 EXPECT_EQ("C", ph);
714
715 int value;
716 EXPECT_TRUE((item && item->GetInteger("args.a", &value)));
717 EXPECT_EQ(30000, value);
718
719 EXPECT_TRUE((item && item->GetInteger("args.b", &value)));
720 EXPECT_EQ(1415, value);
721
722 int ts;
723 EXPECT_TRUE((item && item->GetInteger("ts", &ts)));
724 EXPECT_EQ(42, ts);
725 }
726
727 EXPECT_FIND_("TRACE_COUNTER_ID1 call");
728 {
729 std::string id;
730 EXPECT_TRUE((item && item->GetString("id", &id)));
731 EXPECT_EQ("0x319009", id);
732
733 std::string ph;
734 EXPECT_TRUE((item && item->GetString("ph", &ph)));
735 EXPECT_EQ("C", ph);
736
737 int value;
738 EXPECT_TRUE((item && item->GetInteger("args.value", &value)));
739 EXPECT_EQ(31415, value);
740 }
741
742 EXPECT_FIND_("TRACE_COUNTER_ID2 call");
743 {
744 std::string id;
745 EXPECT_TRUE((item && item->GetString("id", &id)));
746 EXPECT_EQ("0x319009", id);
747
748 std::string ph;
749 EXPECT_TRUE((item && item->GetString("ph", &ph)));
750 EXPECT_EQ("C", ph);
751
752 int value;
753 EXPECT_TRUE((item && item->GetInteger("args.a", &value)));
754 EXPECT_EQ(30000, value);
755
756 EXPECT_TRUE((item && item->GetInteger("args.b", &value)));
757 EXPECT_EQ(1415, value);
758 }
759
760 EXPECT_FIND_("TRACE_EVENT_COPY_BEGIN_WITH_ID_TID_AND_TIMESTAMP0 call");
761 {
762 int val;
763 EXPECT_TRUE((item && item->GetInteger("ts", &val)));
764 EXPECT_EQ(12345, val);
765 EXPECT_TRUE((item && item->GetInteger("tid", &val)));
766 EXPECT_EQ(kThreadId, val);
767 std::string id;
768 EXPECT_TRUE((item && item->GetString("id", &id)));
769 EXPECT_EQ(kAsyncIdStr, id);
770 }
771
772 EXPECT_FIND_("TRACE_EVENT_COPY_END_WITH_ID_TID_AND_TIMESTAMP0 call");
773 {
774 int val;
775 EXPECT_TRUE((item && item->GetInteger("ts", &val)));
776 EXPECT_EQ(23456, val);
777 EXPECT_TRUE((item && item->GetInteger("tid", &val)));
778 EXPECT_EQ(kThreadId, val);
779 std::string id;
780 EXPECT_TRUE((item && item->GetString("id", &id)));
781 EXPECT_EQ(kAsyncIdStr, id);
782 }
783
784 EXPECT_FIND_("TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0 call");
785 {
786 int val;
787 EXPECT_TRUE((item && item->GetInteger("ts", &val)));
788 EXPECT_EQ(34567, val);
789 EXPECT_TRUE((item && item->GetInteger("tid", &val)));
790 EXPECT_EQ(kThreadId, val);
791 std::string id;
792 EXPECT_TRUE((item && item->GetString("id", &id)));
793 EXPECT_EQ(kAsyncId2Str, id);
794 }
795
796 EXPECT_FIND_("TRACE_EVENT_ASYNC_STEP_PAST0 call");
797 {
798 EXPECT_SUB_FIND_("id");
799 EXPECT_SUB_FIND_(kAsyncId2Str);
800 EXPECT_SUB_FIND_("step_end1");
801 EXPECT_FIND_("TRACE_EVENT_ASYNC_STEP_PAST1 call");
802 EXPECT_SUB_FIND_("id");
803 EXPECT_SUB_FIND_(kAsyncId2Str);
804 EXPECT_SUB_FIND_("step_end2");
805 EXPECT_SUB_FIND_("name1");
806 EXPECT_SUB_FIND_("value1");
807 }
808
809 EXPECT_FIND_("TRACE_EVENT_END_WITH_ID_TID_AND_TIMESTAMP0 call");
810 {
811 int val;
812 EXPECT_TRUE((item && item->GetInteger("ts", &val)));
813 EXPECT_EQ(45678, val);
814 EXPECT_TRUE((item && item->GetInteger("tid", &val)));
815 EXPECT_EQ(kThreadId, val);
816 std::string id;
817 EXPECT_TRUE((item && item->GetString("id", &id)));
818 EXPECT_EQ(kAsyncId2Str, id);
819 }
820
821 EXPECT_FIND_("tracked object 1");
822 {
823 std::string phase;
824 std::string id;
825 std::string snapshot;
826
827 EXPECT_TRUE((item && item->GetString("ph", &phase)));
828 EXPECT_EQ("N", phase);
829 EXPECT_FALSE((item && item->HasKey("scope")));
830 EXPECT_TRUE((item && item->GetString("id", &id)));
831 EXPECT_EQ("0x42", id);
832
833 item = FindTraceEntry(trace_parsed, "tracked object 1", item);
834 EXPECT_TRUE(item);
835 EXPECT_TRUE(item && item->GetString("ph", &phase));
836 EXPECT_EQ("O", phase);
837 EXPECT_FALSE((item && item->HasKey("scope")));
838 EXPECT_TRUE(item && item->GetString("id", &id));
839 EXPECT_EQ("0x42", id);
840 EXPECT_TRUE(item && item->GetString("args.snapshot", &snapshot));
841 EXPECT_EQ("hello", snapshot);
842
843 item = FindTraceEntry(trace_parsed, "tracked object 1", item);
844 EXPECT_TRUE(item);
845 EXPECT_TRUE(item && item->GetString("ph", &phase));
846 EXPECT_EQ("D", phase);
847 EXPECT_FALSE((item && item->HasKey("scope")));
848 EXPECT_TRUE(item && item->GetString("id", &id));
849 EXPECT_EQ("0x42", id);
850 }
851
852 EXPECT_FIND_("tracked object 2");
853 {
854 std::string phase;
855 std::string id;
856 std::string snapshot;
857
858 EXPECT_TRUE(item && item->GetString("ph", &phase));
859 EXPECT_EQ("N", phase);
860 EXPECT_TRUE(item && item->GetString("id", &id));
861 EXPECT_EQ("0x2128506", id);
862
863 item = FindTraceEntry(trace_parsed, "tracked object 2", item);
864 EXPECT_TRUE(item);
865 EXPECT_TRUE(item && item->GetString("ph", &phase));
866 EXPECT_EQ("O", phase);
867 EXPECT_TRUE(item && item->GetString("id", &id));
868 EXPECT_EQ("0x2128506", id);
869 EXPECT_TRUE(item && item->GetString("args.snapshot", &snapshot));
870 EXPECT_EQ("world", snapshot);
871
872 item = FindTraceEntry(trace_parsed, "tracked object 2", item);
873 EXPECT_TRUE(item);
874 EXPECT_TRUE(item && item->GetString("ph", &phase));
875 EXPECT_EQ("D", phase);
876 EXPECT_TRUE(item && item->GetString("id", &id));
877 EXPECT_EQ("0x2128506", id);
878 }
879
880 EXPECT_FIND_("tracked object 3");
881 {
882 std::string phase;
883 std::string scope;
884 std::string id;
885 std::string snapshot;
886
887 EXPECT_TRUE((item && item->GetString("ph", &phase)));
888 EXPECT_EQ("N", phase);
889 EXPECT_TRUE((item && item->GetString("scope", &scope)));
890 EXPECT_EQ("scope", scope);
891 EXPECT_TRUE((item && item->GetString("id", &id)));
892 EXPECT_EQ("0x42", id);
893
894 item = FindTraceEntry(trace_parsed, "tracked object 3", item);
895 EXPECT_TRUE(item);
896 EXPECT_TRUE(item && item->GetString("ph", &phase));
897 EXPECT_EQ("O", phase);
898 EXPECT_TRUE((item && item->GetString("scope", &scope)));
899 EXPECT_EQ("scope", scope);
900 EXPECT_TRUE(item && item->GetString("id", &id));
901 EXPECT_EQ("0x42", id);
902 EXPECT_TRUE(item && item->GetString("args.snapshot", &snapshot));
903 EXPECT_EQ("hello", snapshot);
904
905 item = FindTraceEntry(trace_parsed, "tracked object 3", item);
906 EXPECT_TRUE(item);
907 EXPECT_TRUE(item && item->GetString("ph", &phase));
908 EXPECT_EQ("D", phase);
909 EXPECT_TRUE((item && item->GetString("scope", &scope)));
910 EXPECT_EQ("scope", scope);
911 EXPECT_TRUE(item && item->GetString("id", &id));
912 EXPECT_EQ("0x42", id);
913 }
914
915 EXPECT_FIND_(kControlCharacters);
916 EXPECT_SUB_FIND_(kControlCharacters);
917
918 EXPECT_FIND_("TRACE_EVENT_ENTER_CONTEXT call");
919 {
920 std::string ph;
921 EXPECT_TRUE((item && item->GetString("ph", &ph)));
922 EXPECT_EQ("(", ph);
923
924 std::string scope;
925 std::string id;
926 EXPECT_TRUE((item && item->GetString("scope", &scope)));
927 EXPECT_EQ("scope", scope);
928 EXPECT_TRUE((item && item->GetString("id", &id)));
929 EXPECT_EQ("0x20151021", id);
930 }
931
932 EXPECT_FIND_("TRACE_EVENT_LEAVE_CONTEXT call");
933 {
934 std::string ph;
935 EXPECT_TRUE((item && item->GetString("ph", &ph)));
936 EXPECT_EQ(")", ph);
937
938 std::string scope;
939 std::string id;
940 EXPECT_TRUE((item && item->GetString("scope", &scope)));
941 EXPECT_EQ("scope", scope);
942 EXPECT_TRUE((item && item->GetString("id", &id)));
943 EXPECT_EQ("0x20151021", id);
944 }
945
946 std::vector<const DictionaryValue*> scoped_context_calls =
947 FindTraceEntries(trace_parsed, "TRACE_EVENT_SCOPED_CONTEXT call");
948 EXPECT_EQ(2u, scoped_context_calls.size());
949 {
950 item = scoped_context_calls[0];
951 std::string ph;
952 EXPECT_TRUE((item && item->GetString("ph", &ph)));
953 EXPECT_EQ("(", ph);
954
955 std::string id;
956 EXPECT_FALSE((item && item->HasKey("scope")));
957 EXPECT_TRUE((item && item->GetString("id", &id)));
958 EXPECT_EQ("0x20151021", id);
959 }
960
961 {
962 item = scoped_context_calls[1];
963 std::string ph;
964 EXPECT_TRUE((item && item->GetString("ph", &ph)));
965 EXPECT_EQ(")", ph);
966
967 std::string id;
968 EXPECT_FALSE((item && item->HasKey("scope")));
969 EXPECT_TRUE((item && item->GetString("id", &id)));
970 EXPECT_EQ("0x20151021", id);
971 }
972
973 EXPECT_FIND_("TRACE_LINK_IDS simple call");
974 {
975 std::string ph;
976 EXPECT_TRUE((item && item->GetString("ph", &ph)));
977 EXPECT_EQ("=", ph);
978
979 EXPECT_FALSE((item && item->HasKey("scope")));
980 std::string id1;
981 EXPECT_TRUE((item && item->GetString("id", &id1)));
982 EXPECT_EQ("0x1000", id1);
983
984 EXPECT_FALSE((item && item->HasKey("args.linked_id.scope")));
985 std::string id2;
986 EXPECT_TRUE((item && item->GetString("args.linked_id.id", &id2)));
987 EXPECT_EQ("0x2000", id2);
988 }
989
990 EXPECT_FIND_("TRACE_LINK_IDS scoped call");
991 {
992 std::string ph;
993 EXPECT_TRUE((item && item->GetString("ph", &ph)));
994 EXPECT_EQ("=", ph);
995
996 std::string scope1;
997 EXPECT_TRUE((item && item->GetString("scope", &scope1)));
998 EXPECT_EQ("scope 1", scope1);
999 std::string id1;
1000 EXPECT_TRUE((item && item->GetString("id", &id1)));
1001 EXPECT_EQ("0x1000", id1);
1002
1003 std::string scope2;
1004 EXPECT_TRUE((item && item->GetString("args.linked_id.scope", &scope2)));
1005 EXPECT_EQ("scope 2", scope2);
1006 std::string id2;
1007 EXPECT_TRUE((item && item->GetString("args.linked_id.id", &id2)));
1008 EXPECT_EQ("0x2000", id2);
1009 }
1010
1011 EXPECT_FIND_("TRACE_LINK_IDS to a local ID");
1012 {
1013 std::string ph;
1014 EXPECT_TRUE((item && item->GetString("ph", &ph)));
1015 EXPECT_EQ("=", ph);
1016
1017 EXPECT_FALSE((item && item->HasKey("scope")));
1018 std::string id1;
1019 EXPECT_TRUE((item && item->GetString("id", &id1)));
1020 EXPECT_EQ("0x1000", id1);
1021
1022 EXPECT_FALSE((item && item->HasKey("args.linked_id.scope")));
1023 std::string id2;
1024 EXPECT_TRUE((item && item->GetString("args.linked_id.id2.local", &id2)));
1025 EXPECT_EQ("0x2000", id2);
1026 }
1027
1028 EXPECT_FIND_("TRACE_LINK_IDS to a global ID");
1029 {
1030 std::string ph;
1031 EXPECT_TRUE((item && item->GetString("ph", &ph)));
1032 EXPECT_EQ("=", ph);
1033
1034 EXPECT_FALSE((item && item->HasKey("scope")));
1035 std::string id1;
1036 EXPECT_TRUE((item && item->GetString("id", &id1)));
1037 EXPECT_EQ("0x1000", id1);
1038
1039 EXPECT_FALSE((item && item->HasKey("args.linked_id.scope")));
1040 std::string id2;
1041 EXPECT_TRUE((item && item->GetString("args.linked_id.id2.global", &id2)));
1042 EXPECT_EQ("0x2000", id2);
1043 }
1044
1045 EXPECT_FIND_("TRACE_LINK_IDS to a composite ID");
1046 {
1047 std::string ph;
1048 EXPECT_TRUE((item && item->GetString("ph", &ph)));
1049 EXPECT_EQ("=", ph);
1050
1051 EXPECT_FALSE(item->HasKey("scope"));
1052 std::string id1;
1053 EXPECT_TRUE(item->GetString("id", &id1));
1054 EXPECT_EQ("0x1000", id1);
1055
1056 std::string scope;
1057 EXPECT_TRUE(item->GetString("args.linked_id.scope", &scope));
1058 EXPECT_EQ("scope 1", scope);
1059 std::string id2;
1060 EXPECT_TRUE(item->GetString("args.linked_id.id", &id2));
1061 EXPECT_EQ(id2, "0x2000/0x3000");
1062 }
1063
1064 EXPECT_FIND_("async default process scope");
1065 {
1066 std::string ph;
1067 EXPECT_TRUE((item && item->GetString("ph", &ph)));
1068 EXPECT_EQ("S", ph);
1069
1070 std::string id;
1071 EXPECT_TRUE((item && item->GetString("id", &id)));
1072 EXPECT_EQ("0x1000", id);
1073 }
1074
1075 EXPECT_FIND_("async local id");
1076 {
1077 std::string ph;
1078 EXPECT_TRUE((item && item->GetString("ph", &ph)));
1079 EXPECT_EQ("S", ph);
1080
1081 std::string id;
1082 EXPECT_TRUE((item && item->GetString("id2.local", &id)));
1083 EXPECT_EQ("0x2000", id);
1084 }
1085
1086 EXPECT_FIND_("async global id");
1087 {
1088 std::string ph;
1089 EXPECT_TRUE((item && item->GetString("ph", &ph)));
1090 EXPECT_EQ("S", ph);
1091
1092 std::string id;
1093 EXPECT_TRUE((item && item->GetString("id2.global", &id)));
1094 EXPECT_EQ("0x3000", id);
1095 }
1096
1097 EXPECT_FIND_("async global id with scope string");
1098 {
1099 std::string ph;
1100 EXPECT_TRUE((item && item->GetString("ph", &ph)));
1101 EXPECT_EQ("S", ph);
1102
1103 std::string id;
1104 EXPECT_TRUE((item && item->GetString("id2.global", &id)));
1105 EXPECT_EQ("0x4000", id);
1106 std::string scope;
1107 EXPECT_TRUE((item && item->GetString("scope", &scope)));
1108 EXPECT_EQ("scope string", scope);
1109 }
1110 }
1111
TraceManyInstantEvents(int thread_id,int num_events,WaitableEvent * task_complete_event)1112 void TraceManyInstantEvents(int thread_id, int num_events,
1113 WaitableEvent* task_complete_event) {
1114 for (int i = 0; i < num_events; i++) {
1115 TRACE_EVENT_INSTANT2("all", "multi thread event",
1116 TRACE_EVENT_SCOPE_THREAD,
1117 "thread", thread_id,
1118 "event", i);
1119 }
1120
1121 if (task_complete_event)
1122 task_complete_event->Signal();
1123 }
1124
ValidateInstantEventPresentOnEveryThread(const ListValue & trace_parsed,int num_threads,int num_events)1125 void ValidateInstantEventPresentOnEveryThread(const ListValue& trace_parsed,
1126 int num_threads,
1127 int num_events) {
1128 std::map<int, std::map<int, bool> > results;
1129
1130 size_t trace_parsed_count = trace_parsed.GetSize();
1131 for (size_t i = 0; i < trace_parsed_count; i++) {
1132 const Value* value = nullptr;
1133 trace_parsed.Get(i, &value);
1134 if (!value || value->type() != Value::Type::DICTIONARY)
1135 continue;
1136 const DictionaryValue* dict = static_cast<const DictionaryValue*>(value);
1137 std::string name;
1138 dict->GetString("name", &name);
1139 if (name != "multi thread event")
1140 continue;
1141
1142 int thread = 0;
1143 int event = 0;
1144 EXPECT_TRUE(dict->GetInteger("args.thread", &thread));
1145 EXPECT_TRUE(dict->GetInteger("args.event", &event));
1146 results[thread][event] = true;
1147 }
1148
1149 EXPECT_FALSE(results[-1][-1]);
1150 for (int thread = 0; thread < num_threads; thread++) {
1151 for (int event = 0; event < num_events; event++) {
1152 EXPECT_TRUE(results[thread][event]);
1153 }
1154 }
1155 }
1156
CheckTraceDefaultCategoryFilters(const TraceLog & trace_log)1157 void CheckTraceDefaultCategoryFilters(const TraceLog& trace_log) {
1158 // Default enables all category filters except the disabled-by-default-* ones.
1159 EXPECT_TRUE(*trace_log.GetCategoryGroupEnabled("foo"));
1160 EXPECT_TRUE(*trace_log.GetCategoryGroupEnabled("bar"));
1161 EXPECT_TRUE(*trace_log.GetCategoryGroupEnabled("foo,bar"));
1162 EXPECT_TRUE(*trace_log.GetCategoryGroupEnabled(
1163 "foo,disabled-by-default-foo"));
1164 EXPECT_FALSE(*trace_log.GetCategoryGroupEnabled(
1165 "disabled-by-default-foo,disabled-by-default-bar"));
1166 }
1167
1168 } // namespace
1169
1170 // Simple Test for emitting data and validating it was received.
TEST_F(TraceEventTestFixture,DataCaptured)1171 TEST_F(TraceEventTestFixture, DataCaptured) {
1172 TraceLog::GetInstance()->SetEnabled(TraceConfig(kRecordAllCategoryFilter, ""),
1173 TraceLog::RECORDING_MODE);
1174
1175 TraceWithAllMacroVariants(nullptr);
1176
1177 EndTraceAndFlush();
1178
1179 ValidateAllTraceMacrosCreatedData(trace_parsed_);
1180 }
1181
1182 // Emit some events and validate that only empty strings are received
1183 // if we tell Flush() to discard events.
TEST_F(TraceEventTestFixture,DataDiscarded)1184 TEST_F(TraceEventTestFixture, DataDiscarded) {
1185 TraceLog::GetInstance()->SetEnabled(TraceConfig(kRecordAllCategoryFilter, ""),
1186 TraceLog::RECORDING_MODE);
1187
1188 TraceWithAllMacroVariants(nullptr);
1189
1190 CancelTrace();
1191
1192 EXPECT_TRUE(trace_parsed_.empty());
1193 }
1194
1195 class MockEnabledStateChangedObserver :
1196 public TraceLog::EnabledStateObserver {
1197 public:
1198 MOCK_METHOD0(OnTraceLogEnabled, void());
1199 MOCK_METHOD0(OnTraceLogDisabled, void());
1200 };
1201
TEST_F(TraceEventTestFixture,EnabledObserverFiresOnEnable)1202 TEST_F(TraceEventTestFixture, EnabledObserverFiresOnEnable) {
1203 MockEnabledStateChangedObserver observer;
1204 TraceLog::GetInstance()->AddEnabledStateObserver(&observer);
1205
1206 EXPECT_CALL(observer, OnTraceLogEnabled())
1207 .Times(1);
1208 TraceLog::GetInstance()->SetEnabled(TraceConfig(kRecordAllCategoryFilter, ""),
1209 TraceLog::RECORDING_MODE);
1210 testing::Mock::VerifyAndClear(&observer);
1211 EXPECT_TRUE(TraceLog::GetInstance()->IsEnabled());
1212
1213 // Cleanup.
1214 TraceLog::GetInstance()->RemoveEnabledStateObserver(&observer);
1215 TraceLog::GetInstance()->SetDisabled();
1216 }
1217
TEST_F(TraceEventTestFixture,EnabledObserverDoesntFireOnSecondEnable)1218 TEST_F(TraceEventTestFixture, EnabledObserverDoesntFireOnSecondEnable) {
1219 TraceLog::GetInstance()->SetEnabled(TraceConfig(kRecordAllCategoryFilter, ""),
1220 TraceLog::RECORDING_MODE);
1221
1222 testing::StrictMock<MockEnabledStateChangedObserver> observer;
1223 TraceLog::GetInstance()->AddEnabledStateObserver(&observer);
1224
1225 EXPECT_CALL(observer, OnTraceLogEnabled())
1226 .Times(0);
1227 EXPECT_CALL(observer, OnTraceLogDisabled())
1228 .Times(0);
1229 TraceLog::GetInstance()->SetEnabled(TraceConfig(kRecordAllCategoryFilter, ""),
1230 TraceLog::RECORDING_MODE);
1231 testing::Mock::VerifyAndClear(&observer);
1232 EXPECT_TRUE(TraceLog::GetInstance()->IsEnabled());
1233
1234 // Cleanup.
1235 TraceLog::GetInstance()->RemoveEnabledStateObserver(&observer);
1236 TraceLog::GetInstance()->SetDisabled();
1237 TraceLog::GetInstance()->SetDisabled();
1238 }
1239
TEST_F(TraceEventTestFixture,EnabledObserverFiresOnFirstDisable)1240 TEST_F(TraceEventTestFixture, EnabledObserverFiresOnFirstDisable) {
1241 TraceConfig tc_inc_all("*", "");
1242 TraceLog::GetInstance()->SetEnabled(tc_inc_all, TraceLog::RECORDING_MODE);
1243 TraceLog::GetInstance()->SetEnabled(tc_inc_all, TraceLog::RECORDING_MODE);
1244
1245 testing::StrictMock<MockEnabledStateChangedObserver> observer;
1246 TraceLog::GetInstance()->AddEnabledStateObserver(&observer);
1247
1248 EXPECT_CALL(observer, OnTraceLogEnabled())
1249 .Times(0);
1250 EXPECT_CALL(observer, OnTraceLogDisabled())
1251 .Times(1);
1252 TraceLog::GetInstance()->SetDisabled();
1253 testing::Mock::VerifyAndClear(&observer);
1254
1255 // Cleanup.
1256 TraceLog::GetInstance()->RemoveEnabledStateObserver(&observer);
1257 TraceLog::GetInstance()->SetDisabled();
1258 }
1259
TEST_F(TraceEventTestFixture,EnabledObserverFiresOnDisable)1260 TEST_F(TraceEventTestFixture, EnabledObserverFiresOnDisable) {
1261 TraceLog::GetInstance()->SetEnabled(TraceConfig(kRecordAllCategoryFilter, ""),
1262 TraceLog::RECORDING_MODE);
1263
1264 MockEnabledStateChangedObserver observer;
1265 TraceLog::GetInstance()->AddEnabledStateObserver(&observer);
1266
1267 EXPECT_CALL(observer, OnTraceLogDisabled())
1268 .Times(1);
1269 TraceLog::GetInstance()->SetDisabled();
1270 testing::Mock::VerifyAndClear(&observer);
1271
1272 // Cleanup.
1273 TraceLog::GetInstance()->RemoveEnabledStateObserver(&observer);
1274 }
1275
1276 // Tests the IsEnabled() state of TraceLog changes before callbacks.
1277 class AfterStateChangeEnabledStateObserver
1278 : public TraceLog::EnabledStateObserver {
1279 public:
1280 AfterStateChangeEnabledStateObserver() = default;
1281 ~AfterStateChangeEnabledStateObserver() override = default;
1282
1283 // TraceLog::EnabledStateObserver overrides:
OnTraceLogEnabled()1284 void OnTraceLogEnabled() override {
1285 EXPECT_TRUE(TraceLog::GetInstance()->IsEnabled());
1286 }
1287
OnTraceLogDisabled()1288 void OnTraceLogDisabled() override {
1289 EXPECT_FALSE(TraceLog::GetInstance()->IsEnabled());
1290 }
1291 };
1292
TEST_F(TraceEventTestFixture,ObserversFireAfterStateChange)1293 TEST_F(TraceEventTestFixture, ObserversFireAfterStateChange) {
1294 AfterStateChangeEnabledStateObserver observer;
1295 TraceLog::GetInstance()->AddEnabledStateObserver(&observer);
1296
1297 TraceLog::GetInstance()->SetEnabled(TraceConfig(kRecordAllCategoryFilter, ""),
1298 TraceLog::RECORDING_MODE);
1299 EXPECT_TRUE(TraceLog::GetInstance()->IsEnabled());
1300
1301 TraceLog::GetInstance()->SetDisabled();
1302 EXPECT_FALSE(TraceLog::GetInstance()->IsEnabled());
1303
1304 TraceLog::GetInstance()->RemoveEnabledStateObserver(&observer);
1305 }
1306
1307 // Tests that a state observer can remove itself during a callback.
1308 class SelfRemovingEnabledStateObserver
1309 : public TraceLog::EnabledStateObserver {
1310 public:
1311 SelfRemovingEnabledStateObserver() = default;
1312 ~SelfRemovingEnabledStateObserver() override = default;
1313
1314 // TraceLog::EnabledStateObserver overrides:
OnTraceLogEnabled()1315 void OnTraceLogEnabled() override {}
1316
OnTraceLogDisabled()1317 void OnTraceLogDisabled() override {
1318 TraceLog::GetInstance()->RemoveEnabledStateObserver(this);
1319 }
1320 };
1321
TEST_F(TraceEventTestFixture,SelfRemovingObserver)1322 TEST_F(TraceEventTestFixture, SelfRemovingObserver) {
1323 ASSERT_EQ(0u, TraceLog::GetInstance()->GetObserverCountForTest());
1324
1325 SelfRemovingEnabledStateObserver observer;
1326 TraceLog::GetInstance()->AddEnabledStateObserver(&observer);
1327 EXPECT_EQ(1u, TraceLog::GetInstance()->GetObserverCountForTest());
1328
1329 TraceLog::GetInstance()->SetEnabled(TraceConfig(kRecordAllCategoryFilter, ""),
1330 TraceLog::RECORDING_MODE);
1331 TraceLog::GetInstance()->SetDisabled();
1332 // The observer removed itself on disable.
1333 EXPECT_EQ(0u, TraceLog::GetInstance()->GetObserverCountForTest());
1334 }
1335
IsNewTrace()1336 bool IsNewTrace() {
1337 bool is_new_trace;
1338 TRACE_EVENT_IS_NEW_TRACE(&is_new_trace);
1339 return is_new_trace;
1340 }
1341
TEST_F(TraceEventTestFixture,NewTraceRecording)1342 TEST_F(TraceEventTestFixture, NewTraceRecording) {
1343 ASSERT_FALSE(IsNewTrace());
1344 TraceLog::GetInstance()->SetEnabled(TraceConfig(kRecordAllCategoryFilter, ""),
1345 TraceLog::RECORDING_MODE);
1346 // First call to IsNewTrace() should succeed. But, the second shouldn't.
1347 ASSERT_TRUE(IsNewTrace());
1348 ASSERT_FALSE(IsNewTrace());
1349 EndTraceAndFlush();
1350
1351 // IsNewTrace() should definitely be false now.
1352 ASSERT_FALSE(IsNewTrace());
1353
1354 // Start another trace. IsNewTrace() should become true again, briefly, as
1355 // before.
1356 TraceLog::GetInstance()->SetEnabled(TraceConfig(kRecordAllCategoryFilter, ""),
1357 TraceLog::RECORDING_MODE);
1358 ASSERT_TRUE(IsNewTrace());
1359 ASSERT_FALSE(IsNewTrace());
1360
1361 // Cleanup.
1362 EndTraceAndFlush();
1363 }
1364
TEST_F(TraceEventTestFixture,TestTraceFlush)1365 TEST_F(TraceEventTestFixture, TestTraceFlush) {
1366 size_t min_traces = 1;
1367 size_t max_traces = 1;
1368 do {
1369 max_traces *= 2;
1370 TraceLog::GetInstance()->SetEnabled(TraceConfig(),
1371 TraceLog::RECORDING_MODE);
1372 for (size_t i = 0; i < max_traces; i++) {
1373 TRACE_EVENT_INSTANT0("x", "y", TRACE_EVENT_SCOPE_THREAD);
1374 }
1375 EndTraceAndFlush();
1376 } while (num_flush_callbacks_ < 2);
1377
1378 while (min_traces + 50 < max_traces) {
1379 size_t traces = (min_traces + max_traces) / 2;
1380 TraceLog::GetInstance()->SetEnabled(TraceConfig(),
1381 TraceLog::RECORDING_MODE);
1382 for (size_t i = 0; i < traces; i++) {
1383 TRACE_EVENT_INSTANT0("x", "y", TRACE_EVENT_SCOPE_THREAD);
1384 }
1385 EndTraceAndFlush();
1386 if (num_flush_callbacks_ < 2) {
1387 min_traces = traces - 10;
1388 } else {
1389 max_traces = traces + 10;
1390 }
1391 }
1392
1393 for (size_t traces = min_traces; traces < max_traces; traces++) {
1394 TraceLog::GetInstance()->SetEnabled(TraceConfig(),
1395 TraceLog::RECORDING_MODE);
1396 for (size_t i = 0; i < traces; i++) {
1397 TRACE_EVENT_INSTANT0("x", "y", TRACE_EVENT_SCOPE_THREAD);
1398 }
1399 EndTraceAndFlush();
1400 }
1401 }
1402
TEST_F(TraceEventTestFixture,AddMetadataEvent)1403 TEST_F(TraceEventTestFixture, AddMetadataEvent) {
1404 int num_calls = 0;
1405
1406 class Convertable : public ConvertableToTraceFormat {
1407 public:
1408 explicit Convertable(int* num_calls) : num_calls_(num_calls) {}
1409 ~Convertable() override = default;
1410 void AppendAsTraceFormat(std::string* out) const override {
1411 (*num_calls_)++;
1412 out->append("\"metadata_value\"");
1413 }
1414
1415 private:
1416 int* num_calls_;
1417 };
1418
1419 std::unique_ptr<ConvertableToTraceFormat> conv1(new Convertable(&num_calls));
1420 std::unique_ptr<Convertable> conv2(new Convertable(&num_calls));
1421
1422 BeginTrace();
1423 TRACE_EVENT_API_ADD_METADATA_EVENT(
1424 TraceLog::GetCategoryGroupEnabled("__metadata"), "metadata_event_1",
1425 "metadata_arg_name", std::move(conv1));
1426 TRACE_EVENT_API_ADD_METADATA_EVENT(
1427 TraceLog::GetCategoryGroupEnabled("__metadata"), "metadata_event_2",
1428 "metadata_arg_name", std::move(conv2));
1429 // |AppendAsTraceFormat| should only be called on flush, not when the event
1430 // is added.
1431 ASSERT_EQ(0, num_calls);
1432 EndTraceAndFlush();
1433 ASSERT_EQ(2, num_calls);
1434 EXPECT_TRUE(FindNamePhaseKeyValue("metadata_event_1", "M",
1435 "metadata_arg_name", "metadata_value"));
1436 EXPECT_TRUE(FindNamePhaseKeyValue("metadata_event_2", "M",
1437 "metadata_arg_name", "metadata_value"));
1438
1439 // The metadata event should only be adde to the current trace. In this new
1440 // trace, the event should not appear.
1441 BeginTrace();
1442 EndTraceAndFlush();
1443 ASSERT_EQ(2, num_calls);
1444 }
1445
1446 // Test that categories work.
TEST_F(TraceEventTestFixture,Categories)1447 TEST_F(TraceEventTestFixture, Categories) {
1448 // Test that categories that are used can be retrieved whether trace was
1449 // enabled or disabled when the trace event was encountered.
1450 TRACE_EVENT_INSTANT0("c1", "name", TRACE_EVENT_SCOPE_THREAD);
1451 TRACE_EVENT_INSTANT0("c2", "name", TRACE_EVENT_SCOPE_THREAD);
1452 BeginTrace();
1453 TRACE_EVENT_INSTANT0("c3", "name", TRACE_EVENT_SCOPE_THREAD);
1454 TRACE_EVENT_INSTANT0("c4", "name", TRACE_EVENT_SCOPE_THREAD);
1455 // Category groups containing more than one category.
1456 TRACE_EVENT_INSTANT0("c5,c6", "name", TRACE_EVENT_SCOPE_THREAD);
1457 TRACE_EVENT_INSTANT0("c7,c8", "name", TRACE_EVENT_SCOPE_THREAD);
1458 TRACE_EVENT_INSTANT0(TRACE_DISABLED_BY_DEFAULT("c9"), "name",
1459 TRACE_EVENT_SCOPE_THREAD);
1460
1461 EndTraceAndFlush();
1462 std::vector<std::string> cat_groups;
1463 TraceLog::GetInstance()->GetKnownCategoryGroups(&cat_groups);
1464 EXPECT_TRUE(ContainsValue(cat_groups, "c1"));
1465 EXPECT_TRUE(ContainsValue(cat_groups, "c2"));
1466 EXPECT_TRUE(ContainsValue(cat_groups, "c3"));
1467 EXPECT_TRUE(ContainsValue(cat_groups, "c4"));
1468 EXPECT_TRUE(ContainsValue(cat_groups, "c5,c6"));
1469 EXPECT_TRUE(ContainsValue(cat_groups, "c7,c8"));
1470 EXPECT_TRUE(ContainsValue(cat_groups, "disabled-by-default-c9"));
1471 // Make sure metadata isn't returned.
1472 EXPECT_FALSE(ContainsValue(cat_groups, "__metadata"));
1473
1474 const std::vector<std::string> empty_categories;
1475 std::vector<std::string> included_categories;
1476 std::vector<std::string> excluded_categories;
1477
1478 // Test that category filtering works.
1479
1480 // Include nonexistent category -> no events
1481 Clear();
1482 included_categories.clear();
1483 TraceLog::GetInstance()->SetEnabled(TraceConfig("not_found823564786", ""),
1484 TraceLog::RECORDING_MODE);
1485 TRACE_EVENT_INSTANT0("cat1", "name", TRACE_EVENT_SCOPE_THREAD);
1486 TRACE_EVENT_INSTANT0("cat2", "name", TRACE_EVENT_SCOPE_THREAD);
1487 EndTraceAndFlush();
1488 DropTracedMetadataRecords();
1489 EXPECT_TRUE(trace_parsed_.empty());
1490
1491 // Include existent category -> only events of that category
1492 Clear();
1493 included_categories.clear();
1494 TraceLog::GetInstance()->SetEnabled(TraceConfig("inc", ""),
1495 TraceLog::RECORDING_MODE);
1496 TRACE_EVENT_INSTANT0("inc", "name", TRACE_EVENT_SCOPE_THREAD);
1497 TRACE_EVENT_INSTANT0("inc2", "name", TRACE_EVENT_SCOPE_THREAD);
1498 EndTraceAndFlush();
1499 DropTracedMetadataRecords();
1500 EXPECT_TRUE(FindMatchingValue("cat", "inc"));
1501 EXPECT_FALSE(FindNonMatchingValue("cat", "inc"));
1502
1503 // Include existent wildcard -> all categories matching wildcard
1504 Clear();
1505 included_categories.clear();
1506 TraceLog::GetInstance()->SetEnabled(
1507 TraceConfig("inc_wildcard_*,inc_wildchar_?_end", ""),
1508 TraceLog::RECORDING_MODE);
1509 TRACE_EVENT_INSTANT0("inc_wildcard_abc", "included",
1510 TRACE_EVENT_SCOPE_THREAD);
1511 TRACE_EVENT_INSTANT0("inc_wildcard_", "included", TRACE_EVENT_SCOPE_THREAD);
1512 TRACE_EVENT_INSTANT0("inc_wildchar_x_end", "included",
1513 TRACE_EVENT_SCOPE_THREAD);
1514 TRACE_EVENT_INSTANT0("inc_wildchar_bla_end", "not_inc",
1515 TRACE_EVENT_SCOPE_THREAD);
1516 TRACE_EVENT_INSTANT0("cat1", "not_inc", TRACE_EVENT_SCOPE_THREAD);
1517 TRACE_EVENT_INSTANT0("cat2", "not_inc", TRACE_EVENT_SCOPE_THREAD);
1518 TRACE_EVENT_INSTANT0("inc_wildcard_category,other_category", "included",
1519 TRACE_EVENT_SCOPE_THREAD);
1520 TRACE_EVENT_INSTANT0(
1521 "non_included_category,inc_wildcard_category", "included",
1522 TRACE_EVENT_SCOPE_THREAD);
1523 EndTraceAndFlush();
1524 EXPECT_TRUE(FindMatchingValue("cat", "inc_wildcard_abc"));
1525 EXPECT_TRUE(FindMatchingValue("cat", "inc_wildcard_"));
1526 EXPECT_TRUE(FindMatchingValue("cat", "inc_wildchar_x_end"));
1527 EXPECT_FALSE(FindMatchingValue("name", "not_inc"));
1528 EXPECT_TRUE(FindMatchingValue("cat", "inc_wildcard_category,other_category"));
1529 EXPECT_TRUE(FindMatchingValue("cat",
1530 "non_included_category,inc_wildcard_category"));
1531
1532 included_categories.clear();
1533
1534 // Exclude nonexistent category -> all events
1535 Clear();
1536 TraceLog::GetInstance()->SetEnabled(TraceConfig("-not_found823564786", ""),
1537 TraceLog::RECORDING_MODE);
1538 TRACE_EVENT_INSTANT0("cat1", "name", TRACE_EVENT_SCOPE_THREAD);
1539 TRACE_EVENT_INSTANT0("cat2", "name", TRACE_EVENT_SCOPE_THREAD);
1540 TRACE_EVENT_INSTANT0("category1,category2", "name", TRACE_EVENT_SCOPE_THREAD);
1541 EndTraceAndFlush();
1542 EXPECT_TRUE(FindMatchingValue("cat", "cat1"));
1543 EXPECT_TRUE(FindMatchingValue("cat", "cat2"));
1544 EXPECT_TRUE(FindMatchingValue("cat", "category1,category2"));
1545
1546 // Exclude existent category -> only events of other categories
1547 Clear();
1548 TraceLog::GetInstance()->SetEnabled(TraceConfig("-inc", ""),
1549 TraceLog::RECORDING_MODE);
1550 TRACE_EVENT_INSTANT0("inc", "name", TRACE_EVENT_SCOPE_THREAD);
1551 TRACE_EVENT_INSTANT0("inc2", "name", TRACE_EVENT_SCOPE_THREAD);
1552 TRACE_EVENT_INSTANT0("inc2,inc", "name", TRACE_EVENT_SCOPE_THREAD);
1553 TRACE_EVENT_INSTANT0("inc,inc2", "name", TRACE_EVENT_SCOPE_THREAD);
1554 EndTraceAndFlush();
1555 EXPECT_TRUE(FindMatchingValue("cat", "inc2"));
1556 EXPECT_FALSE(FindMatchingValue("cat", "inc"));
1557 EXPECT_TRUE(FindMatchingValue("cat", "inc2,inc"));
1558 EXPECT_TRUE(FindMatchingValue("cat", "inc,inc2"));
1559
1560 // Exclude existent wildcard -> all categories not matching wildcard
1561 Clear();
1562 TraceLog::GetInstance()->SetEnabled(
1563 TraceConfig("-inc_wildcard_*,-inc_wildchar_?_end", ""),
1564 TraceLog::RECORDING_MODE);
1565 TRACE_EVENT_INSTANT0("inc_wildcard_abc", "not_inc",
1566 TRACE_EVENT_SCOPE_THREAD);
1567 TRACE_EVENT_INSTANT0("inc_wildcard_", "not_inc",
1568 TRACE_EVENT_SCOPE_THREAD);
1569 TRACE_EVENT_INSTANT0("inc_wildchar_x_end", "not_inc",
1570 TRACE_EVENT_SCOPE_THREAD);
1571 TRACE_EVENT_INSTANT0("inc_wildchar_bla_end", "included",
1572 TRACE_EVENT_SCOPE_THREAD);
1573 TRACE_EVENT_INSTANT0("cat1", "included", TRACE_EVENT_SCOPE_THREAD);
1574 TRACE_EVENT_INSTANT0("cat2", "included", TRACE_EVENT_SCOPE_THREAD);
1575 EndTraceAndFlush();
1576 EXPECT_TRUE(FindMatchingValue("cat", "inc_wildchar_bla_end"));
1577 EXPECT_TRUE(FindMatchingValue("cat", "cat1"));
1578 EXPECT_TRUE(FindMatchingValue("cat", "cat2"));
1579 EXPECT_FALSE(FindMatchingValue("name", "not_inc"));
1580 }
1581
1582
1583 // Test ASYNC_BEGIN/END events
TEST_F(TraceEventTestFixture,AsyncBeginEndEvents)1584 TEST_F(TraceEventTestFixture, AsyncBeginEndEvents) {
1585 BeginTrace();
1586
1587 unsigned long long id = 0xfeedbeeffeedbeefull;
1588 TRACE_EVENT_ASYNC_BEGIN0("cat", "name1", id);
1589 TRACE_EVENT_ASYNC_STEP_INTO0("cat", "name1", id, "step1");
1590 TRACE_EVENT_ASYNC_END0("cat", "name1", id);
1591 TRACE_EVENT_BEGIN0("cat", "name2");
1592 TRACE_EVENT_ASYNC_BEGIN0("cat", "name3", 0);
1593 TRACE_EVENT_ASYNC_STEP_PAST0("cat", "name3", 0, "step2");
1594
1595 EndTraceAndFlush();
1596
1597 EXPECT_TRUE(FindNamePhase("name1", "S"));
1598 EXPECT_TRUE(FindNamePhase("name1", "T"));
1599 EXPECT_TRUE(FindNamePhase("name1", "F"));
1600
1601 std::string id_str;
1602 StringAppendF(&id_str, "0x%llx", id);
1603
1604 EXPECT_TRUE(FindNamePhaseKeyValue("name1", "S", "id", id_str.c_str()));
1605 EXPECT_TRUE(FindNamePhaseKeyValue("name1", "T", "id", id_str.c_str()));
1606 EXPECT_TRUE(FindNamePhaseKeyValue("name1", "F", "id", id_str.c_str()));
1607 EXPECT_TRUE(FindNamePhaseKeyValue("name3", "S", "id", "0x0"));
1608 EXPECT_TRUE(FindNamePhaseKeyValue("name3", "p", "id", "0x0"));
1609
1610 // BEGIN events should not have id
1611 EXPECT_FALSE(FindNamePhaseKeyValue("name2", "B", "id", "0"));
1612 }
1613
1614 // Test ASYNC_BEGIN/END events
TEST_F(TraceEventTestFixture,AsyncBeginEndPointerMangling)1615 TEST_F(TraceEventTestFixture, AsyncBeginEndPointerMangling) {
1616 void* ptr = this;
1617
1618 TraceLog::GetInstance()->SetProcessID(100);
1619 BeginTrace();
1620 TRACE_EVENT_ASYNC_BEGIN0("cat", "name1", ptr);
1621 TRACE_EVENT_ASYNC_BEGIN0("cat", "name2", ptr);
1622 EndTraceAndFlush();
1623
1624 TraceLog::GetInstance()->SetProcessID(200);
1625 BeginTrace();
1626 TRACE_EVENT_ASYNC_END0("cat", "name1", ptr);
1627 EndTraceAndFlush();
1628
1629 DictionaryValue* async_begin = FindNamePhase("name1", "S");
1630 DictionaryValue* async_begin2 = FindNamePhase("name2", "S");
1631 DictionaryValue* async_end = FindNamePhase("name1", "F");
1632 EXPECT_TRUE(async_begin);
1633 EXPECT_TRUE(async_begin2);
1634 EXPECT_TRUE(async_end);
1635
1636 Value* value = nullptr;
1637 std::string async_begin_id_str;
1638 std::string async_begin2_id_str;
1639 std::string async_end_id_str;
1640 ASSERT_TRUE(async_begin->Get("id", &value));
1641 ASSERT_TRUE(value->GetAsString(&async_begin_id_str));
1642 ASSERT_TRUE(async_begin2->Get("id", &value));
1643 ASSERT_TRUE(value->GetAsString(&async_begin2_id_str));
1644 ASSERT_TRUE(async_end->Get("id", &value));
1645 ASSERT_TRUE(value->GetAsString(&async_end_id_str));
1646
1647 EXPECT_STREQ(async_begin_id_str.c_str(), async_begin2_id_str.c_str());
1648 EXPECT_STRNE(async_begin_id_str.c_str(), async_end_id_str.c_str());
1649 }
1650
1651 // Test that static strings are not copied.
TEST_F(TraceEventTestFixture,StaticStringVsString)1652 TEST_F(TraceEventTestFixture, StaticStringVsString) {
1653 TraceLog* tracer = TraceLog::GetInstance();
1654 // Make sure old events are flushed:
1655 EXPECT_EQ(0u, tracer->GetStatus().event_count);
1656 const unsigned char* category_group_enabled =
1657 TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED("cat");
1658
1659 {
1660 BeginTrace();
1661 // Test that string arguments are copied.
1662 TraceEventHandle handle1 =
1663 trace_event_internal::AddTraceEvent(
1664 TRACE_EVENT_PHASE_INSTANT, category_group_enabled, "name1",
1665 trace_event_internal::kGlobalScope, trace_event_internal::kNoId,
1666 0, trace_event_internal::kNoId,
1667 "arg1", std::string("argval"), "arg2", std::string("argval"));
1668 // Test that static TRACE_STR_COPY string arguments are copied.
1669 TraceEventHandle handle2 =
1670 trace_event_internal::AddTraceEvent(
1671 TRACE_EVENT_PHASE_INSTANT, category_group_enabled, "name2",
1672 trace_event_internal::kGlobalScope, trace_event_internal::kNoId,
1673 0, trace_event_internal::kNoId,
1674 "arg1", TRACE_STR_COPY("argval"),
1675 "arg2", TRACE_STR_COPY("argval"));
1676 EXPECT_GT(tracer->GetStatus().event_count, 1u);
1677 const TraceEvent* event1 = tracer->GetEventByHandle(handle1);
1678 const TraceEvent* event2 = tracer->GetEventByHandle(handle2);
1679 ASSERT_TRUE(event1);
1680 ASSERT_TRUE(event2);
1681 EXPECT_STREQ("name1", event1->name());
1682 EXPECT_STREQ("name2", event2->name());
1683 EXPECT_TRUE(event1->parameter_copy_storage() != nullptr);
1684 EXPECT_TRUE(event2->parameter_copy_storage() != nullptr);
1685 EXPECT_GT(event1->parameter_copy_storage()->size(), 0u);
1686 EXPECT_GT(event2->parameter_copy_storage()->size(), 0u);
1687 EndTraceAndFlush();
1688 }
1689
1690 {
1691 BeginTrace();
1692 // Test that static literal string arguments are not copied.
1693 TraceEventHandle handle1 =
1694 trace_event_internal::AddTraceEvent(
1695 TRACE_EVENT_PHASE_INSTANT, category_group_enabled, "name1",
1696 trace_event_internal::kGlobalScope, trace_event_internal::kNoId,
1697 0, trace_event_internal::kNoId,
1698 "arg1", "argval", "arg2", "argval");
1699 // Test that static TRACE_STR_COPY NULL string arguments are not copied.
1700 const char* str1 = nullptr;
1701 const char* str2 = nullptr;
1702 TraceEventHandle handle2 =
1703 trace_event_internal::AddTraceEvent(
1704 TRACE_EVENT_PHASE_INSTANT, category_group_enabled, "name2",
1705 trace_event_internal::kGlobalScope, trace_event_internal::kNoId,
1706 0, trace_event_internal::kNoId,
1707 "arg1", TRACE_STR_COPY(str1),
1708 "arg2", TRACE_STR_COPY(str2));
1709 EXPECT_GT(tracer->GetStatus().event_count, 1u);
1710 const TraceEvent* event1 = tracer->GetEventByHandle(handle1);
1711 const TraceEvent* event2 = tracer->GetEventByHandle(handle2);
1712 ASSERT_TRUE(event1);
1713 ASSERT_TRUE(event2);
1714 EXPECT_STREQ("name1", event1->name());
1715 EXPECT_STREQ("name2", event2->name());
1716 EXPECT_TRUE(event1->parameter_copy_storage() == nullptr);
1717 EXPECT_TRUE(event2->parameter_copy_storage() == nullptr);
1718 EndTraceAndFlush();
1719 }
1720 }
1721
1722 // Test that data sent from other threads is gathered
TEST_F(TraceEventTestFixture,DataCapturedOnThread)1723 TEST_F(TraceEventTestFixture, DataCapturedOnThread) {
1724 BeginTrace();
1725
1726 Thread thread("1");
1727 WaitableEvent task_complete_event(WaitableEvent::ResetPolicy::AUTOMATIC,
1728 WaitableEvent::InitialState::NOT_SIGNALED);
1729 thread.Start();
1730
1731 thread.task_runner()->PostTask(
1732 FROM_HERE,
1733 base::BindOnce(&TraceWithAllMacroVariants, &task_complete_event));
1734 task_complete_event.Wait();
1735 thread.Stop();
1736
1737 EndTraceAndFlush();
1738 ValidateAllTraceMacrosCreatedData(trace_parsed_);
1739 }
1740
1741 // Test that data sent from multiple threads is gathered
TEST_F(TraceEventTestFixture,DataCapturedManyThreads)1742 TEST_F(TraceEventTestFixture, DataCapturedManyThreads) {
1743 BeginTrace();
1744
1745 const int num_threads = 4;
1746 const int num_events = 4000;
1747 Thread* threads[num_threads];
1748 WaitableEvent* task_complete_events[num_threads];
1749 for (int i = 0; i < num_threads; i++) {
1750 threads[i] = new Thread(StringPrintf("Thread %d", i));
1751 task_complete_events[i] =
1752 new WaitableEvent(WaitableEvent::ResetPolicy::AUTOMATIC,
1753 WaitableEvent::InitialState::NOT_SIGNALED);
1754 threads[i]->Start();
1755 threads[i]->task_runner()->PostTask(
1756 FROM_HERE, base::BindOnce(&TraceManyInstantEvents, i, num_events,
1757 task_complete_events[i]));
1758 }
1759
1760 for (int i = 0; i < num_threads; i++) {
1761 task_complete_events[i]->Wait();
1762 }
1763
1764 // Let half of the threads end before flush.
1765 for (int i = 0; i < num_threads / 2; i++) {
1766 threads[i]->Stop();
1767 delete threads[i];
1768 delete task_complete_events[i];
1769 }
1770
1771 EndTraceAndFlushInThreadWithMessageLoop();
1772 ValidateInstantEventPresentOnEveryThread(trace_parsed_,
1773 num_threads, num_events);
1774
1775 // Let the other half of the threads end after flush.
1776 for (int i = num_threads / 2; i < num_threads; i++) {
1777 threads[i]->Stop();
1778 delete threads[i];
1779 delete task_complete_events[i];
1780 }
1781 }
1782
1783 // Test that thread and process names show up in the trace
TEST_F(TraceEventTestFixture,ThreadNames)1784 TEST_F(TraceEventTestFixture, ThreadNames) {
1785 // Create threads before we enable tracing to make sure
1786 // that tracelog still captures them.
1787 const int kNumThreads = 4;
1788 const int kNumEvents = 10;
1789 Thread* threads[kNumThreads];
1790 PlatformThreadId thread_ids[kNumThreads];
1791 for (int i = 0; i < kNumThreads; i++)
1792 threads[i] = new Thread(StringPrintf("Thread %d", i));
1793
1794 // Enable tracing.
1795 BeginTrace();
1796
1797 // Now run some trace code on these threads.
1798 WaitableEvent* task_complete_events[kNumThreads];
1799 for (int i = 0; i < kNumThreads; i++) {
1800 task_complete_events[i] =
1801 new WaitableEvent(WaitableEvent::ResetPolicy::AUTOMATIC,
1802 WaitableEvent::InitialState::NOT_SIGNALED);
1803 threads[i]->Start();
1804 thread_ids[i] = threads[i]->GetThreadId();
1805 threads[i]->task_runner()->PostTask(
1806 FROM_HERE, base::BindOnce(&TraceManyInstantEvents, i, kNumEvents,
1807 task_complete_events[i]));
1808 }
1809 for (int i = 0; i < kNumThreads; i++) {
1810 task_complete_events[i]->Wait();
1811 }
1812
1813 // Shut things down.
1814 for (int i = 0; i < kNumThreads; i++) {
1815 threads[i]->Stop();
1816 delete threads[i];
1817 delete task_complete_events[i];
1818 }
1819
1820 EndTraceAndFlush();
1821
1822 std::string tmp;
1823 int tmp_int;
1824 const DictionaryValue* item;
1825
1826 // Make sure we get thread name metadata.
1827 // Note, the test suite may have created a ton of threads.
1828 // So, we'll have thread names for threads we didn't create.
1829 std::vector<const DictionaryValue*> items =
1830 FindTraceEntries(trace_parsed_, "thread_name");
1831 for (int i = 0; i < static_cast<int>(items.size()); i++) {
1832 item = items[i];
1833 ASSERT_TRUE(item);
1834 EXPECT_TRUE(item->GetInteger("tid", &tmp_int));
1835
1836 // See if this thread name is one of the threads we just created
1837 for (int j = 0; j < kNumThreads; j++) {
1838 if (static_cast<int>(thread_ids[j]) != tmp_int)
1839 continue;
1840
1841 std::string expected_name = StringPrintf("Thread %d", j);
1842 EXPECT_TRUE(item->GetString("ph", &tmp) && tmp == "M");
1843 EXPECT_TRUE(item->GetInteger("pid", &tmp_int) &&
1844 tmp_int == static_cast<int>(base::GetCurrentProcId()));
1845 // If the thread name changes or the tid gets reused, the name will be
1846 // a comma-separated list of thread names, so look for a substring.
1847 EXPECT_TRUE(item->GetString("args.name", &tmp) &&
1848 tmp.find(expected_name) != std::string::npos);
1849 }
1850 }
1851 }
1852
TEST_F(TraceEventTestFixture,ThreadNameChanges)1853 TEST_F(TraceEventTestFixture, ThreadNameChanges) {
1854 BeginTrace();
1855
1856 PlatformThread::SetName("");
1857 TRACE_EVENT_INSTANT0("drink", "water", TRACE_EVENT_SCOPE_THREAD);
1858
1859 PlatformThread::SetName("cafe");
1860 TRACE_EVENT_INSTANT0("drink", "coffee", TRACE_EVENT_SCOPE_THREAD);
1861
1862 PlatformThread::SetName("shop");
1863 // No event here, so won't appear in combined name.
1864
1865 PlatformThread::SetName("pub");
1866 TRACE_EVENT_INSTANT0("drink", "beer", TRACE_EVENT_SCOPE_THREAD);
1867 TRACE_EVENT_INSTANT0("drink", "wine", TRACE_EVENT_SCOPE_THREAD);
1868
1869 PlatformThread::SetName(" bar");
1870 TRACE_EVENT_INSTANT0("drink", "whisky", TRACE_EVENT_SCOPE_THREAD);
1871
1872 EndTraceAndFlush();
1873
1874 std::vector<const DictionaryValue*> items =
1875 FindTraceEntries(trace_parsed_, "thread_name");
1876 EXPECT_EQ(1u, items.size());
1877 ASSERT_GT(items.size(), 0u);
1878 const DictionaryValue* item = items[0];
1879 ASSERT_TRUE(item);
1880 int tid;
1881 EXPECT_TRUE(item->GetInteger("tid", &tid));
1882 EXPECT_EQ(PlatformThread::CurrentId(), static_cast<PlatformThreadId>(tid));
1883
1884 std::string expected_name = "cafe,pub, bar";
1885 std::string tmp;
1886 EXPECT_TRUE(item->GetString("args.name", &tmp));
1887 EXPECT_EQ(expected_name, tmp);
1888 }
1889
1890 // Test that the disabled trace categories are included/excluded from the
1891 // trace output correctly.
TEST_F(TraceEventTestFixture,DisabledCategories)1892 TEST_F(TraceEventTestFixture, DisabledCategories) {
1893 BeginTrace();
1894 TRACE_EVENT_INSTANT0(TRACE_DISABLED_BY_DEFAULT("cc"), "first",
1895 TRACE_EVENT_SCOPE_THREAD);
1896 TRACE_EVENT_INSTANT0("included", "first", TRACE_EVENT_SCOPE_THREAD);
1897 EndTraceAndFlush();
1898 {
1899 const DictionaryValue* item = nullptr;
1900 ListValue& trace_parsed = trace_parsed_;
1901 EXPECT_NOT_FIND_("disabled-by-default-cc");
1902 EXPECT_FIND_("included");
1903 }
1904 Clear();
1905
1906 BeginSpecificTrace("disabled-by-default-cc");
1907 TRACE_EVENT_INSTANT0(TRACE_DISABLED_BY_DEFAULT("cc"), "second",
1908 TRACE_EVENT_SCOPE_THREAD);
1909 TRACE_EVENT_INSTANT0("other_included", "second", TRACE_EVENT_SCOPE_THREAD);
1910 EndTraceAndFlush();
1911
1912 {
1913 const DictionaryValue* item = nullptr;
1914 ListValue& trace_parsed = trace_parsed_;
1915 EXPECT_FIND_("disabled-by-default-cc");
1916 EXPECT_FIND_("other_included");
1917 }
1918
1919 Clear();
1920
1921 BeginSpecificTrace("other_included");
1922 TRACE_EVENT_INSTANT0(TRACE_DISABLED_BY_DEFAULT("cc") ",other_included",
1923 "first", TRACE_EVENT_SCOPE_THREAD);
1924 TRACE_EVENT_INSTANT0("other_included," TRACE_DISABLED_BY_DEFAULT("cc"),
1925 "second", TRACE_EVENT_SCOPE_THREAD);
1926 EndTraceAndFlush();
1927
1928 {
1929 const DictionaryValue* item = nullptr;
1930 ListValue& trace_parsed = trace_parsed_;
1931 EXPECT_FIND_("disabled-by-default-cc,other_included");
1932 EXPECT_FIND_("other_included,disabled-by-default-cc");
1933 }
1934 }
1935
TEST_F(TraceEventTestFixture,NormallyNoDeepCopy)1936 TEST_F(TraceEventTestFixture, NormallyNoDeepCopy) {
1937 // Test that the TRACE_EVENT macros do not deep-copy their string. If they
1938 // do so it may indicate a performance regression, but more-over it would
1939 // make the DEEP_COPY overloads redundant.
1940 std::string name_string("event name");
1941
1942 BeginTrace();
1943 TRACE_EVENT_INSTANT0("category", name_string.c_str(),
1944 TRACE_EVENT_SCOPE_THREAD);
1945
1946 // Modify the string in place (a wholesale reassignment may leave the old
1947 // string intact on the heap).
1948 name_string[0] = '@';
1949
1950 EndTraceAndFlush();
1951
1952 EXPECT_FALSE(FindTraceEntry(trace_parsed_, "event name"));
1953 EXPECT_TRUE(FindTraceEntry(trace_parsed_, name_string.c_str()));
1954 }
1955
TEST_F(TraceEventTestFixture,DeepCopy)1956 TEST_F(TraceEventTestFixture, DeepCopy) {
1957 static const char kOriginalName1[] = "name1";
1958 static const char kOriginalName2[] = "name2";
1959 static const char kOriginalName3[] = "name3";
1960 std::string name1(kOriginalName1);
1961 std::string name2(kOriginalName2);
1962 std::string name3(kOriginalName3);
1963 std::string arg1("arg1");
1964 std::string arg2("arg2");
1965 std::string val1("val1");
1966 std::string val2("val2");
1967
1968 BeginTrace();
1969 TRACE_EVENT_COPY_INSTANT0("category", name1.c_str(),
1970 TRACE_EVENT_SCOPE_THREAD);
1971 TRACE_EVENT_COPY_BEGIN1("category", name2.c_str(),
1972 arg1.c_str(), 5);
1973 TRACE_EVENT_COPY_END2("category", name3.c_str(),
1974 arg1.c_str(), val1,
1975 arg2.c_str(), val2);
1976
1977 // As per NormallyNoDeepCopy, modify the strings in place.
1978 name1[0] = name2[0] = name3[0] = arg1[0] = arg2[0] = val1[0] = val2[0] = '@';
1979
1980 EndTraceAndFlush();
1981
1982 EXPECT_FALSE(FindTraceEntry(trace_parsed_, name1.c_str()));
1983 EXPECT_FALSE(FindTraceEntry(trace_parsed_, name2.c_str()));
1984 EXPECT_FALSE(FindTraceEntry(trace_parsed_, name3.c_str()));
1985
1986 const DictionaryValue* entry1 = FindTraceEntry(trace_parsed_, kOriginalName1);
1987 const DictionaryValue* entry2 = FindTraceEntry(trace_parsed_, kOriginalName2);
1988 const DictionaryValue* entry3 = FindTraceEntry(trace_parsed_, kOriginalName3);
1989 ASSERT_TRUE(entry1);
1990 ASSERT_TRUE(entry2);
1991 ASSERT_TRUE(entry3);
1992
1993 int i;
1994 EXPECT_FALSE(entry2->GetInteger("args.@rg1", &i));
1995 EXPECT_TRUE(entry2->GetInteger("args.arg1", &i));
1996 EXPECT_EQ(5, i);
1997
1998 std::string s;
1999 EXPECT_TRUE(entry3->GetString("args.arg1", &s));
2000 EXPECT_EQ("val1", s);
2001 EXPECT_TRUE(entry3->GetString("args.arg2", &s));
2002 EXPECT_EQ("val2", s);
2003 }
2004
2005 // Test that TraceResultBuffer outputs the correct result whether it is added
2006 // in chunks or added all at once.
TEST_F(TraceEventTestFixture,TraceResultBuffer)2007 TEST_F(TraceEventTestFixture, TraceResultBuffer) {
2008 Clear();
2009
2010 trace_buffer_.Start();
2011 trace_buffer_.AddFragment("bla1");
2012 trace_buffer_.AddFragment("bla2");
2013 trace_buffer_.AddFragment("bla3,bla4");
2014 trace_buffer_.Finish();
2015 EXPECT_STREQ(json_output_.json_output.c_str(), "[bla1,bla2,bla3,bla4]");
2016
2017 Clear();
2018
2019 trace_buffer_.Start();
2020 trace_buffer_.AddFragment("bla1,bla2,bla3,bla4");
2021 trace_buffer_.Finish();
2022 EXPECT_STREQ(json_output_.json_output.c_str(), "[bla1,bla2,bla3,bla4]");
2023 }
2024
2025 // Test that trace_event parameters are not evaluated if the tracing
2026 // system is disabled.
TEST_F(TraceEventTestFixture,TracingIsLazy)2027 TEST_F(TraceEventTestFixture, TracingIsLazy) {
2028 BeginTrace();
2029
2030 int a = 0;
2031 TRACE_EVENT_INSTANT1("category", "test", TRACE_EVENT_SCOPE_THREAD, "a", a++);
2032 EXPECT_EQ(1, a);
2033
2034 TraceLog::GetInstance()->SetDisabled();
2035
2036 TRACE_EVENT_INSTANT1("category", "test", TRACE_EVENT_SCOPE_THREAD, "a", a++);
2037 EXPECT_EQ(1, a);
2038
2039 EndTraceAndFlush();
2040 }
2041
TEST_F(TraceEventTestFixture,TraceEnableDisable)2042 TEST_F(TraceEventTestFixture, TraceEnableDisable) {
2043 TraceLog* trace_log = TraceLog::GetInstance();
2044 TraceConfig tc_inc_all("*", "");
2045 trace_log->SetEnabled(tc_inc_all, TraceLog::RECORDING_MODE);
2046 EXPECT_TRUE(trace_log->IsEnabled());
2047 trace_log->SetDisabled();
2048 EXPECT_FALSE(trace_log->IsEnabled());
2049
2050 trace_log->SetEnabled(tc_inc_all, TraceLog::RECORDING_MODE);
2051 EXPECT_TRUE(trace_log->IsEnabled());
2052 const std::vector<std::string> empty;
2053 trace_log->SetEnabled(TraceConfig(), TraceLog::RECORDING_MODE);
2054 EXPECT_TRUE(trace_log->IsEnabled());
2055 trace_log->SetDisabled();
2056 EXPECT_FALSE(trace_log->IsEnabled());
2057 trace_log->SetDisabled();
2058 EXPECT_FALSE(trace_log->IsEnabled());
2059 }
2060
TEST_F(TraceEventTestFixture,TraceCategoriesAfterNestedEnable)2061 TEST_F(TraceEventTestFixture, TraceCategoriesAfterNestedEnable) {
2062 TraceLog* trace_log = TraceLog::GetInstance();
2063 trace_log->SetEnabled(TraceConfig("foo,bar", ""), TraceLog::RECORDING_MODE);
2064 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("foo"));
2065 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("bar"));
2066 EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("baz"));
2067 trace_log->SetEnabled(TraceConfig("foo2", ""), TraceLog::RECORDING_MODE);
2068 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("foo2"));
2069 EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("baz"));
2070 // The "" becomes the default catergory set when applied.
2071 trace_log->SetEnabled(TraceConfig(), TraceLog::RECORDING_MODE);
2072 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("foo"));
2073 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("baz"));
2074 EXPECT_STREQ(
2075 "",
2076 trace_log->GetCurrentTraceConfig().ToCategoryFilterString().c_str());
2077 trace_log->SetDisabled();
2078 trace_log->SetDisabled();
2079 trace_log->SetDisabled();
2080 EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("foo"));
2081 EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("baz"));
2082
2083 trace_log->SetEnabled(TraceConfig("-foo,-bar", ""), TraceLog::RECORDING_MODE);
2084 EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("foo"));
2085 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("baz"));
2086 trace_log->SetEnabled(TraceConfig("moo", ""), TraceLog::RECORDING_MODE);
2087 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("baz"));
2088 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("moo"));
2089 EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("foo"));
2090 EXPECT_STREQ(
2091 "-foo,-bar",
2092 trace_log->GetCurrentTraceConfig().ToCategoryFilterString().c_str());
2093 trace_log->SetDisabled();
2094 trace_log->SetDisabled();
2095
2096 // Make sure disabled categories aren't cleared if we set in the second.
2097 trace_log->SetEnabled(TraceConfig("disabled-by-default-cc,foo", ""),
2098 TraceLog::RECORDING_MODE);
2099 EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("bar"));
2100 trace_log->SetEnabled(TraceConfig("disabled-by-default-gpu", ""),
2101 TraceLog::RECORDING_MODE);
2102 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("disabled-by-default-cc"));
2103 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("disabled-by-default-gpu"));
2104 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("bar"));
2105 EXPECT_STREQ(
2106 "disabled-by-default-cc,disabled-by-default-gpu",
2107 trace_log->GetCurrentTraceConfig().ToCategoryFilterString().c_str());
2108 trace_log->SetDisabled();
2109 trace_log->SetDisabled();
2110 }
2111
TEST_F(TraceEventTestFixture,TraceWithDefaultCategoryFilters)2112 TEST_F(TraceEventTestFixture, TraceWithDefaultCategoryFilters) {
2113 TraceLog* trace_log = TraceLog::GetInstance();
2114
2115 trace_log->SetEnabled(TraceConfig(), TraceLog::RECORDING_MODE);
2116 CheckTraceDefaultCategoryFilters(*trace_log);
2117 trace_log->SetDisabled();
2118
2119 trace_log->SetEnabled(TraceConfig("", ""), TraceLog::RECORDING_MODE);
2120 CheckTraceDefaultCategoryFilters(*trace_log);
2121 trace_log->SetDisabled();
2122
2123 trace_log->SetEnabled(TraceConfig("*", ""), TraceLog::RECORDING_MODE);
2124 CheckTraceDefaultCategoryFilters(*trace_log);
2125 trace_log->SetDisabled();
2126
2127 trace_log->SetEnabled(TraceConfig(""), TraceLog::RECORDING_MODE);
2128 CheckTraceDefaultCategoryFilters(*trace_log);
2129 trace_log->SetDisabled();
2130 }
2131
TEST_F(TraceEventTestFixture,TraceWithDisabledByDefaultCategoryFilters)2132 TEST_F(TraceEventTestFixture, TraceWithDisabledByDefaultCategoryFilters) {
2133 TraceLog* trace_log = TraceLog::GetInstance();
2134
2135 trace_log->SetEnabled(TraceConfig("foo,disabled-by-default-foo", ""),
2136 TraceLog::RECORDING_MODE);
2137 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("foo"));
2138 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("disabled-by-default-foo"));
2139 EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("bar"));
2140 EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("disabled-by-default-bar"));
2141 trace_log->SetDisabled();
2142
2143 // Enabling only the disabled-by-default-* category means the default ones
2144 // are also enabled.
2145 trace_log->SetEnabled(TraceConfig("disabled-by-default-foo", ""),
2146 TraceLog::RECORDING_MODE);
2147 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("disabled-by-default-foo"));
2148 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("foo"));
2149 EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("bar"));
2150 EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("disabled-by-default-bar"));
2151 trace_log->SetDisabled();
2152 }
2153
2154 class MyData : public ConvertableToTraceFormat {
2155 public:
2156 MyData() = default;
2157 ~MyData() override = default;
2158
AppendAsTraceFormat(std::string * out) const2159 void AppendAsTraceFormat(std::string* out) const override {
2160 out->append("{\"foo\":1}");
2161 }
2162
2163 private:
2164 DISALLOW_COPY_AND_ASSIGN(MyData);
2165 };
2166
TEST_F(TraceEventTestFixture,ConvertableTypes)2167 TEST_F(TraceEventTestFixture, ConvertableTypes) {
2168 TraceLog::GetInstance()->SetEnabled(TraceConfig(kRecordAllCategoryFilter, ""),
2169 TraceLog::RECORDING_MODE);
2170
2171 std::unique_ptr<ConvertableToTraceFormat> data(new MyData());
2172 std::unique_ptr<ConvertableToTraceFormat> data1(new MyData());
2173 std::unique_ptr<ConvertableToTraceFormat> data2(new MyData());
2174 TRACE_EVENT1("foo", "bar", "data", std::move(data));
2175 TRACE_EVENT2("foo", "baz", "data1", std::move(data1), "data2",
2176 std::move(data2));
2177
2178 // Check that std::unique_ptr<DerivedClassOfConvertable> are properly treated
2179 // as
2180 // convertable and not accidentally casted to bool.
2181 std::unique_ptr<MyData> convertData1(new MyData());
2182 std::unique_ptr<MyData> convertData2(new MyData());
2183 std::unique_ptr<MyData> convertData3(new MyData());
2184 std::unique_ptr<MyData> convertData4(new MyData());
2185 TRACE_EVENT2("foo", "string_first", "str", "string value 1", "convert",
2186 std::move(convertData1));
2187 TRACE_EVENT2("foo", "string_second", "convert", std::move(convertData2),
2188 "str", "string value 2");
2189 TRACE_EVENT2("foo", "both_conv", "convert1", std::move(convertData3),
2190 "convert2", std::move(convertData4));
2191 EndTraceAndFlush();
2192
2193 // One arg version.
2194 DictionaryValue* dict = FindNamePhase("bar", "X");
2195 ASSERT_TRUE(dict);
2196
2197 const DictionaryValue* args_dict = nullptr;
2198 dict->GetDictionary("args", &args_dict);
2199 ASSERT_TRUE(args_dict);
2200
2201 const Value* value = nullptr;
2202 const DictionaryValue* convertable_dict = nullptr;
2203 EXPECT_TRUE(args_dict->Get("data", &value));
2204 ASSERT_TRUE(value->GetAsDictionary(&convertable_dict));
2205
2206 int foo_val;
2207 EXPECT_TRUE(convertable_dict->GetInteger("foo", &foo_val));
2208 EXPECT_EQ(1, foo_val);
2209
2210 // Two arg version.
2211 dict = FindNamePhase("baz", "X");
2212 ASSERT_TRUE(dict);
2213
2214 args_dict = nullptr;
2215 dict->GetDictionary("args", &args_dict);
2216 ASSERT_TRUE(args_dict);
2217
2218 value = nullptr;
2219 convertable_dict = nullptr;
2220 EXPECT_TRUE(args_dict->Get("data1", &value));
2221 ASSERT_TRUE(value->GetAsDictionary(&convertable_dict));
2222
2223 value = nullptr;
2224 convertable_dict = nullptr;
2225 EXPECT_TRUE(args_dict->Get("data2", &value));
2226 ASSERT_TRUE(value->GetAsDictionary(&convertable_dict));
2227
2228 // Convertable with other types.
2229 dict = FindNamePhase("string_first", "X");
2230 ASSERT_TRUE(dict);
2231
2232 args_dict = nullptr;
2233 dict->GetDictionary("args", &args_dict);
2234 ASSERT_TRUE(args_dict);
2235
2236 std::string str_value;
2237 EXPECT_TRUE(args_dict->GetString("str", &str_value));
2238 EXPECT_STREQ("string value 1", str_value.c_str());
2239
2240 value = nullptr;
2241 convertable_dict = nullptr;
2242 foo_val = 0;
2243 EXPECT_TRUE(args_dict->Get("convert", &value));
2244 ASSERT_TRUE(value->GetAsDictionary(&convertable_dict));
2245 EXPECT_TRUE(convertable_dict->GetInteger("foo", &foo_val));
2246 EXPECT_EQ(1, foo_val);
2247
2248 dict = FindNamePhase("string_second", "X");
2249 ASSERT_TRUE(dict);
2250
2251 args_dict = nullptr;
2252 dict->GetDictionary("args", &args_dict);
2253 ASSERT_TRUE(args_dict);
2254
2255 EXPECT_TRUE(args_dict->GetString("str", &str_value));
2256 EXPECT_STREQ("string value 2", str_value.c_str());
2257
2258 value = nullptr;
2259 convertable_dict = nullptr;
2260 foo_val = 0;
2261 EXPECT_TRUE(args_dict->Get("convert", &value));
2262 ASSERT_TRUE(value->GetAsDictionary(&convertable_dict));
2263 EXPECT_TRUE(convertable_dict->GetInteger("foo", &foo_val));
2264 EXPECT_EQ(1, foo_val);
2265
2266 dict = FindNamePhase("both_conv", "X");
2267 ASSERT_TRUE(dict);
2268
2269 args_dict = nullptr;
2270 dict->GetDictionary("args", &args_dict);
2271 ASSERT_TRUE(args_dict);
2272
2273 value = nullptr;
2274 convertable_dict = nullptr;
2275 foo_val = 0;
2276 EXPECT_TRUE(args_dict->Get("convert1", &value));
2277 ASSERT_TRUE(value->GetAsDictionary(&convertable_dict));
2278 EXPECT_TRUE(args_dict->Get("convert2", &value));
2279 ASSERT_TRUE(value->GetAsDictionary(&convertable_dict));
2280 }
2281
TEST_F(TraceEventTestFixture,PrimitiveArgs)2282 TEST_F(TraceEventTestFixture, PrimitiveArgs) {
2283 TraceLog::GetInstance()->SetEnabled(TraceConfig(kRecordAllCategoryFilter, ""),
2284 TraceLog::RECORDING_MODE);
2285
2286 TRACE_EVENT1("foo", "event1", "int_one", 1);
2287 TRACE_EVENT1("foo", "event2", "int_neg_ten", -10);
2288 TRACE_EVENT1("foo", "event3", "float_one", 1.0f);
2289 TRACE_EVENT1("foo", "event4", "float_half", .5f);
2290 TRACE_EVENT1("foo", "event5", "float_neghalf", -.5f);
2291 TRACE_EVENT1("foo", "event6", "float_infinity",
2292 std::numeric_limits<float>::infinity());
2293 TRACE_EVENT1("foo", "event6b", "float_neg_infinity",
2294 -std::numeric_limits<float>::infinity());
2295 TRACE_EVENT1("foo", "event7", "double_nan",
2296 std::numeric_limits<double>::quiet_NaN());
2297 void* p = nullptr;
2298 TRACE_EVENT1("foo", "event8", "pointer_null", p);
2299 p = reinterpret_cast<void*>(0xbadf00d);
2300 TRACE_EVENT1("foo", "event9", "pointer_badf00d", p);
2301 TRACE_EVENT1("foo", "event10", "bool_true", true);
2302 TRACE_EVENT1("foo", "event11", "bool_false", false);
2303 TRACE_EVENT1("foo", "event12", "time_null",
2304 base::Time());
2305 TRACE_EVENT1("foo", "event13", "time_one",
2306 base::Time::FromInternalValue(1));
2307 TRACE_EVENT1("foo", "event14", "timeticks_null",
2308 base::TimeTicks());
2309 TRACE_EVENT1("foo", "event15", "timeticks_one",
2310 base::TimeTicks::FromInternalValue(1));
2311 EndTraceAndFlush();
2312
2313 const DictionaryValue* args_dict = nullptr;
2314 DictionaryValue* dict = nullptr;
2315 const Value* value = nullptr;
2316 std::string str_value;
2317 int int_value;
2318 double double_value;
2319 bool bool_value;
2320
2321 dict = FindNamePhase("event1", "X");
2322 ASSERT_TRUE(dict);
2323 dict->GetDictionary("args", &args_dict);
2324 ASSERT_TRUE(args_dict);
2325 EXPECT_TRUE(args_dict->GetInteger("int_one", &int_value));
2326 EXPECT_EQ(1, int_value);
2327
2328 dict = FindNamePhase("event2", "X");
2329 ASSERT_TRUE(dict);
2330 dict->GetDictionary("args", &args_dict);
2331 ASSERT_TRUE(args_dict);
2332 EXPECT_TRUE(args_dict->GetInteger("int_neg_ten", &int_value));
2333 EXPECT_EQ(-10, int_value);
2334
2335 // 1f must be serlized to JSON as "1.0" in order to be a double, not an int.
2336 dict = FindNamePhase("event3", "X");
2337 ASSERT_TRUE(dict);
2338 dict->GetDictionary("args", &args_dict);
2339 ASSERT_TRUE(args_dict);
2340 EXPECT_TRUE(args_dict->Get("float_one", &value));
2341 EXPECT_TRUE(value->is_double());
2342 EXPECT_TRUE(value->GetAsDouble(&double_value));
2343 EXPECT_EQ(1, double_value);
2344
2345 // .5f must be serlized to JSON as "0.5".
2346 dict = FindNamePhase("event4", "X");
2347 ASSERT_TRUE(dict);
2348 dict->GetDictionary("args", &args_dict);
2349 ASSERT_TRUE(args_dict);
2350 EXPECT_TRUE(args_dict->Get("float_half", &value));
2351 EXPECT_TRUE(value->is_double());
2352 EXPECT_TRUE(value->GetAsDouble(&double_value));
2353 EXPECT_EQ(0.5, double_value);
2354
2355 // -.5f must be serlized to JSON as "-0.5".
2356 dict = FindNamePhase("event5", "X");
2357 ASSERT_TRUE(dict);
2358 dict->GetDictionary("args", &args_dict);
2359 ASSERT_TRUE(args_dict);
2360 EXPECT_TRUE(args_dict->Get("float_neghalf", &value));
2361 EXPECT_TRUE(value->is_double());
2362 EXPECT_TRUE(value->GetAsDouble(&double_value));
2363 EXPECT_EQ(-0.5, double_value);
2364
2365 // Infinity is serialized to JSON as a string.
2366 dict = FindNamePhase("event6", "X");
2367 ASSERT_TRUE(dict);
2368 dict->GetDictionary("args", &args_dict);
2369 ASSERT_TRUE(args_dict);
2370 EXPECT_TRUE(args_dict->GetString("float_infinity", &str_value));
2371 EXPECT_STREQ("Infinity", str_value.c_str());
2372 dict = FindNamePhase("event6b", "X");
2373 ASSERT_TRUE(dict);
2374 dict->GetDictionary("args", &args_dict);
2375 ASSERT_TRUE(args_dict);
2376 EXPECT_TRUE(args_dict->GetString("float_neg_infinity", &str_value));
2377 EXPECT_STREQ("-Infinity", str_value.c_str());
2378
2379 // NaN is serialized to JSON as a string.
2380 dict = FindNamePhase("event7", "X");
2381 ASSERT_TRUE(dict);
2382 dict->GetDictionary("args", &args_dict);
2383 ASSERT_TRUE(args_dict);
2384 EXPECT_TRUE(args_dict->GetString("double_nan", &str_value));
2385 EXPECT_STREQ("NaN", str_value.c_str());
2386
2387 // NULL pointers should be serialized as "0x0".
2388 dict = FindNamePhase("event8", "X");
2389 ASSERT_TRUE(dict);
2390 dict->GetDictionary("args", &args_dict);
2391 ASSERT_TRUE(args_dict);
2392 EXPECT_TRUE(args_dict->GetString("pointer_null", &str_value));
2393 EXPECT_STREQ("0x0", str_value.c_str());
2394
2395 // Other pointers should be serlized as a hex string.
2396 dict = FindNamePhase("event9", "X");
2397 ASSERT_TRUE(dict);
2398 dict->GetDictionary("args", &args_dict);
2399 ASSERT_TRUE(args_dict);
2400 EXPECT_TRUE(args_dict->GetString("pointer_badf00d", &str_value));
2401 EXPECT_STREQ("0xbadf00d", str_value.c_str());
2402
2403 dict = FindNamePhase("event10", "X");
2404 ASSERT_TRUE(dict);
2405 dict->GetDictionary("args", &args_dict);
2406 ASSERT_TRUE(args_dict);
2407 EXPECT_TRUE(args_dict->GetBoolean("bool_true", &bool_value));
2408 EXPECT_TRUE(bool_value);
2409
2410 dict = FindNamePhase("event11", "X");
2411 ASSERT_TRUE(dict);
2412 dict->GetDictionary("args", &args_dict);
2413 ASSERT_TRUE(args_dict);
2414 EXPECT_TRUE(args_dict->GetBoolean("bool_false", &bool_value));
2415 EXPECT_FALSE(bool_value);
2416
2417 dict = FindNamePhase("event12", "X");
2418 ASSERT_TRUE(dict);
2419 dict->GetDictionary("args", &args_dict);
2420 ASSERT_TRUE(args_dict);
2421 EXPECT_TRUE(args_dict->GetInteger("time_null", &int_value));
2422 EXPECT_EQ(0, int_value);
2423
2424 dict = FindNamePhase("event13", "X");
2425 ASSERT_TRUE(dict);
2426 dict->GetDictionary("args", &args_dict);
2427 ASSERT_TRUE(args_dict);
2428 EXPECT_TRUE(args_dict->GetInteger("time_one", &int_value));
2429 EXPECT_EQ(1, int_value);
2430
2431 dict = FindNamePhase("event14", "X");
2432 ASSERT_TRUE(dict);
2433 dict->GetDictionary("args", &args_dict);
2434 ASSERT_TRUE(args_dict);
2435 EXPECT_TRUE(args_dict->GetInteger("timeticks_null", &int_value));
2436 EXPECT_EQ(0, int_value);
2437
2438 dict = FindNamePhase("event15", "X");
2439 ASSERT_TRUE(dict);
2440 dict->GetDictionary("args", &args_dict);
2441 ASSERT_TRUE(args_dict);
2442 EXPECT_TRUE(args_dict->GetInteger("timeticks_one", &int_value));
2443 EXPECT_EQ(1, int_value);
2444 }
2445
TEST_F(TraceEventTestFixture,NameIsEscaped)2446 TEST_F(TraceEventTestFixture, NameIsEscaped) {
2447 TraceLog::GetInstance()->SetEnabled(TraceConfig(kRecordAllCategoryFilter, ""),
2448 TraceLog::RECORDING_MODE);
2449 TRACE_EVENT0("category", "name\\with\\backspaces");
2450 EndTraceAndFlush();
2451
2452 EXPECT_TRUE(FindMatchingValue("cat", "category"));
2453 EXPECT_TRUE(FindMatchingValue("name", "name\\with\\backspaces"));
2454 }
2455
2456 namespace {
2457
IsArgNameWhitelisted(const char * arg_name)2458 bool IsArgNameWhitelisted(const char* arg_name) {
2459 return base::MatchPattern(arg_name, "granular_arg_whitelisted");
2460 }
2461
IsTraceEventArgsWhitelisted(const char * category_group_name,const char * event_name,ArgumentNameFilterPredicate * arg_filter)2462 bool IsTraceEventArgsWhitelisted(const char* category_group_name,
2463 const char* event_name,
2464 ArgumentNameFilterPredicate* arg_filter) {
2465 if (base::MatchPattern(category_group_name, "toplevel") &&
2466 base::MatchPattern(event_name, "*")) {
2467 return true;
2468 }
2469
2470 if (base::MatchPattern(category_group_name, "benchmark") &&
2471 base::MatchPattern(event_name, "granularly_whitelisted")) {
2472 *arg_filter = base::Bind(&IsArgNameWhitelisted);
2473 return true;
2474 }
2475
2476 return false;
2477 }
2478
2479 } // namespace
2480
TEST_F(TraceEventTestFixture,ArgsWhitelisting)2481 TEST_F(TraceEventTestFixture, ArgsWhitelisting) {
2482 TraceLog::GetInstance()->SetArgumentFilterPredicate(
2483 base::Bind(&IsTraceEventArgsWhitelisted));
2484
2485 TraceLog::GetInstance()->SetEnabled(
2486 TraceConfig(kRecordAllCategoryFilter, "enable-argument-filter"),
2487 TraceLog::RECORDING_MODE);
2488
2489 TRACE_EVENT1("toplevel", "event1", "int_one", 1);
2490 TRACE_EVENT1("whitewashed", "event2", "int_two", 1);
2491
2492 TRACE_EVENT2("benchmark", "granularly_whitelisted",
2493 "granular_arg_whitelisted", "whitelisted_value",
2494 "granular_arg_blacklisted", "blacklisted_value");
2495
2496 EndTraceAndFlush();
2497
2498 const DictionaryValue* args_dict = nullptr;
2499 DictionaryValue* dict = nullptr;
2500 int int_value;
2501
2502 dict = FindNamePhase("event1", "X");
2503 ASSERT_TRUE(dict);
2504 dict->GetDictionary("args", &args_dict);
2505 ASSERT_TRUE(args_dict);
2506 EXPECT_TRUE(args_dict->GetInteger("int_one", &int_value));
2507 EXPECT_EQ(1, int_value);
2508
2509 dict = FindNamePhase("event2", "X");
2510 ASSERT_TRUE(dict);
2511 dict->GetDictionary("args", &args_dict);
2512 ASSERT_TRUE(args_dict);
2513 EXPECT_FALSE(args_dict->GetInteger("int_two", &int_value));
2514
2515 std::string args_string;
2516 EXPECT_TRUE(dict->GetString("args", &args_string));
2517 EXPECT_EQ(args_string, "__stripped__");
2518
2519 dict = FindNamePhase("granularly_whitelisted", "X");
2520 ASSERT_TRUE(dict);
2521 dict->GetDictionary("args", &args_dict);
2522 ASSERT_TRUE(args_dict);
2523
2524 EXPECT_TRUE(args_dict->GetString("granular_arg_whitelisted", &args_string));
2525 EXPECT_EQ(args_string, "whitelisted_value");
2526
2527 EXPECT_TRUE(args_dict->GetString("granular_arg_blacklisted", &args_string));
2528 EXPECT_EQ(args_string, "__stripped__");
2529 }
2530
TEST_F(TraceEventTestFixture,TraceBufferVectorReportFull)2531 TEST_F(TraceEventTestFixture, TraceBufferVectorReportFull) {
2532 TraceLog* trace_log = TraceLog::GetInstance();
2533 trace_log->SetEnabled(
2534 TraceConfig(kRecordAllCategoryFilter, ""), TraceLog::RECORDING_MODE);
2535 trace_log->logged_events_.reset(
2536 TraceBuffer::CreateTraceBufferVectorOfSize(100));
2537 do {
2538 TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0(
2539 "all", "with_timestamp", 0, 0, TimeTicks::Now());
2540 TRACE_EVENT_END_WITH_ID_TID_AND_TIMESTAMP0(
2541 "all", "with_timestamp", 0, 0, TimeTicks::Now());
2542 } while (!trace_log->BufferIsFull());
2543
2544 EndTraceAndFlush();
2545
2546 const DictionaryValue* trace_full_metadata = nullptr;
2547
2548 trace_full_metadata = FindTraceEntry(trace_parsed_,
2549 "overflowed_at_ts");
2550 std::string phase;
2551 double buffer_limit_reached_timestamp = 0;
2552
2553 EXPECT_TRUE(trace_full_metadata);
2554 EXPECT_TRUE(trace_full_metadata->GetString("ph", &phase));
2555 EXPECT_EQ("M", phase);
2556 EXPECT_TRUE(trace_full_metadata->GetDouble(
2557 "args.overflowed_at_ts", &buffer_limit_reached_timestamp));
2558 EXPECT_DOUBLE_EQ(
2559 static_cast<double>(
2560 trace_log->buffer_limit_reached_timestamp_.ToInternalValue()),
2561 buffer_limit_reached_timestamp);
2562
2563 // Test that buffer_limit_reached_timestamp's value is between the timestamp
2564 // of the last trace event and current time.
2565 DropTracedMetadataRecords();
2566 const DictionaryValue* last_trace_event = nullptr;
2567 double last_trace_event_timestamp = 0;
2568 EXPECT_TRUE(trace_parsed_.GetDictionary(trace_parsed_.GetSize() - 1,
2569 &last_trace_event));
2570 EXPECT_TRUE(last_trace_event->GetDouble("ts", &last_trace_event_timestamp));
2571 EXPECT_LE(last_trace_event_timestamp, buffer_limit_reached_timestamp);
2572 EXPECT_LE(buffer_limit_reached_timestamp,
2573 trace_log->OffsetNow().ToInternalValue());
2574 }
2575
TEST_F(TraceEventTestFixture,TraceBufferRingBufferGetReturnChunk)2576 TEST_F(TraceEventTestFixture, TraceBufferRingBufferGetReturnChunk) {
2577 TraceLog::GetInstance()->SetEnabled(
2578 TraceConfig(kRecordAllCategoryFilter, RECORD_CONTINUOUSLY),
2579 TraceLog::RECORDING_MODE);
2580 TraceBuffer* buffer = TraceLog::GetInstance()->trace_buffer();
2581 size_t capacity = buffer->Capacity();
2582 size_t num_chunks = capacity / TraceBufferChunk::kTraceBufferChunkSize;
2583 uint32_t last_seq = 0;
2584 size_t chunk_index;
2585 EXPECT_EQ(0u, buffer->Size());
2586
2587 std::unique_ptr<TraceBufferChunk* []> chunks(
2588 new TraceBufferChunk*[num_chunks]);
2589 for (size_t i = 0; i < num_chunks; ++i) {
2590 chunks[i] = buffer->GetChunk(&chunk_index).release();
2591 EXPECT_TRUE(chunks[i]);
2592 EXPECT_EQ(i, chunk_index);
2593 EXPECT_GT(chunks[i]->seq(), last_seq);
2594 EXPECT_EQ((i + 1) * TraceBufferChunk::kTraceBufferChunkSize,
2595 buffer->Size());
2596 last_seq = chunks[i]->seq();
2597 }
2598
2599 // Ring buffer is never full.
2600 EXPECT_FALSE(buffer->IsFull());
2601
2602 // Return all chunks in original order.
2603 for (size_t i = 0; i < num_chunks; ++i)
2604 buffer->ReturnChunk(i, std::unique_ptr<TraceBufferChunk>(chunks[i]));
2605
2606 // Should recycle the chunks in the returned order.
2607 for (size_t i = 0; i < num_chunks; ++i) {
2608 chunks[i] = buffer->GetChunk(&chunk_index).release();
2609 EXPECT_TRUE(chunks[i]);
2610 EXPECT_EQ(i, chunk_index);
2611 EXPECT_GT(chunks[i]->seq(), last_seq);
2612 last_seq = chunks[i]->seq();
2613 }
2614
2615 // Return all chunks in reverse order.
2616 for (size_t i = 0; i < num_chunks; ++i) {
2617 buffer->ReturnChunk(num_chunks - i - 1, std::unique_ptr<TraceBufferChunk>(
2618 chunks[num_chunks - i - 1]));
2619 }
2620
2621 // Should recycle the chunks in the returned order.
2622 for (size_t i = 0; i < num_chunks; ++i) {
2623 chunks[i] = buffer->GetChunk(&chunk_index).release();
2624 EXPECT_TRUE(chunks[i]);
2625 EXPECT_EQ(num_chunks - i - 1, chunk_index);
2626 EXPECT_GT(chunks[i]->seq(), last_seq);
2627 last_seq = chunks[i]->seq();
2628 }
2629
2630 for (size_t i = 0; i < num_chunks; ++i)
2631 buffer->ReturnChunk(i, std::unique_ptr<TraceBufferChunk>(chunks[i]));
2632
2633 TraceLog::GetInstance()->SetDisabled();
2634 }
2635
TEST_F(TraceEventTestFixture,TraceBufferRingBufferHalfIteration)2636 TEST_F(TraceEventTestFixture, TraceBufferRingBufferHalfIteration) {
2637 TraceLog::GetInstance()->SetEnabled(
2638 TraceConfig(kRecordAllCategoryFilter, RECORD_CONTINUOUSLY),
2639 TraceLog::RECORDING_MODE);
2640 TraceBuffer* buffer = TraceLog::GetInstance()->trace_buffer();
2641 size_t capacity = buffer->Capacity();
2642 size_t num_chunks = capacity / TraceBufferChunk::kTraceBufferChunkSize;
2643 size_t chunk_index;
2644 EXPECT_EQ(0u, buffer->Size());
2645 EXPECT_FALSE(buffer->NextChunk());
2646
2647 size_t half_chunks = num_chunks / 2;
2648 std::unique_ptr<TraceBufferChunk* []> chunks(
2649 new TraceBufferChunk*[half_chunks]);
2650
2651 for (size_t i = 0; i < half_chunks; ++i) {
2652 chunks[i] = buffer->GetChunk(&chunk_index).release();
2653 EXPECT_TRUE(chunks[i]);
2654 EXPECT_EQ(i, chunk_index);
2655 }
2656 for (size_t i = 0; i < half_chunks; ++i)
2657 buffer->ReturnChunk(i, std::unique_ptr<TraceBufferChunk>(chunks[i]));
2658
2659 for (size_t i = 0; i < half_chunks; ++i)
2660 EXPECT_EQ(chunks[i], buffer->NextChunk());
2661 EXPECT_FALSE(buffer->NextChunk());
2662 TraceLog::GetInstance()->SetDisabled();
2663 }
2664
TEST_F(TraceEventTestFixture,TraceBufferRingBufferFullIteration)2665 TEST_F(TraceEventTestFixture, TraceBufferRingBufferFullIteration) {
2666 TraceLog::GetInstance()->SetEnabled(
2667 TraceConfig(kRecordAllCategoryFilter, RECORD_CONTINUOUSLY),
2668 TraceLog::RECORDING_MODE);
2669 TraceBuffer* buffer = TraceLog::GetInstance()->trace_buffer();
2670 size_t capacity = buffer->Capacity();
2671 size_t num_chunks = capacity / TraceBufferChunk::kTraceBufferChunkSize;
2672 size_t chunk_index;
2673 EXPECT_EQ(0u, buffer->Size());
2674 EXPECT_FALSE(buffer->NextChunk());
2675
2676 std::unique_ptr<TraceBufferChunk* []> chunks(
2677 new TraceBufferChunk*[num_chunks]);
2678
2679 for (size_t i = 0; i < num_chunks; ++i) {
2680 chunks[i] = buffer->GetChunk(&chunk_index).release();
2681 EXPECT_TRUE(chunks[i]);
2682 EXPECT_EQ(i, chunk_index);
2683 }
2684 for (size_t i = 0; i < num_chunks; ++i)
2685 buffer->ReturnChunk(i, std::unique_ptr<TraceBufferChunk>(chunks[i]));
2686
2687 for (size_t i = 0; i < num_chunks; ++i)
2688 EXPECT_TRUE(chunks[i] == buffer->NextChunk());
2689 EXPECT_FALSE(buffer->NextChunk());
2690 TraceLog::GetInstance()->SetDisabled();
2691 }
2692
TEST_F(TraceEventTestFixture,TraceRecordAsMuchAsPossibleMode)2693 TEST_F(TraceEventTestFixture, TraceRecordAsMuchAsPossibleMode) {
2694 TraceLog::GetInstance()->SetEnabled(
2695 TraceConfig(kRecordAllCategoryFilter, RECORD_AS_MUCH_AS_POSSIBLE),
2696 TraceLog::RECORDING_MODE);
2697 TraceBuffer* buffer = TraceLog::GetInstance()->trace_buffer();
2698 EXPECT_EQ(512000000UL, buffer->Capacity());
2699 TraceLog::GetInstance()->SetDisabled();
2700 }
2701
BlockUntilStopped(WaitableEvent * task_start_event,WaitableEvent * task_stop_event)2702 void BlockUntilStopped(WaitableEvent* task_start_event,
2703 WaitableEvent* task_stop_event) {
2704 task_start_event->Signal();
2705 task_stop_event->Wait();
2706 }
2707
TEST_F(TraceEventTestFixture,SetCurrentThreadBlocksMessageLoopBeforeTracing)2708 TEST_F(TraceEventTestFixture, SetCurrentThreadBlocksMessageLoopBeforeTracing) {
2709 BeginTrace();
2710
2711 Thread thread("1");
2712 WaitableEvent task_complete_event(WaitableEvent::ResetPolicy::AUTOMATIC,
2713 WaitableEvent::InitialState::NOT_SIGNALED);
2714 thread.Start();
2715 thread.task_runner()->PostTask(
2716 FROM_HERE, BindOnce(&TraceLog::SetCurrentThreadBlocksMessageLoop,
2717 Unretained(TraceLog::GetInstance())));
2718
2719 thread.task_runner()->PostTask(
2720 FROM_HERE, BindOnce(&TraceWithAllMacroVariants, &task_complete_event));
2721 task_complete_event.Wait();
2722
2723 WaitableEvent task_start_event(WaitableEvent::ResetPolicy::AUTOMATIC,
2724 WaitableEvent::InitialState::NOT_SIGNALED);
2725 WaitableEvent task_stop_event(WaitableEvent::ResetPolicy::AUTOMATIC,
2726 WaitableEvent::InitialState::NOT_SIGNALED);
2727 thread.task_runner()->PostTask(
2728 FROM_HERE,
2729 BindOnce(&BlockUntilStopped, &task_start_event, &task_stop_event));
2730 task_start_event.Wait();
2731
2732 EndTraceAndFlush();
2733 ValidateAllTraceMacrosCreatedData(trace_parsed_);
2734
2735 task_stop_event.Signal();
2736 thread.Stop();
2737 }
2738
TEST_F(TraceEventTestFixture,ConvertTraceConfigToInternalOptions)2739 TEST_F(TraceEventTestFixture, ConvertTraceConfigToInternalOptions) {
2740 TraceLog* trace_log = TraceLog::GetInstance();
2741 EXPECT_EQ(TraceLog::kInternalRecordUntilFull,
2742 trace_log->GetInternalOptionsFromTraceConfig(
2743 TraceConfig(kRecordAllCategoryFilter, RECORD_UNTIL_FULL)));
2744
2745 EXPECT_EQ(TraceLog::kInternalRecordContinuously,
2746 trace_log->GetInternalOptionsFromTraceConfig(
2747 TraceConfig(kRecordAllCategoryFilter, RECORD_CONTINUOUSLY)));
2748
2749 EXPECT_EQ(TraceLog::kInternalEchoToConsole,
2750 trace_log->GetInternalOptionsFromTraceConfig(
2751 TraceConfig(kRecordAllCategoryFilter, ECHO_TO_CONSOLE)));
2752
2753 EXPECT_EQ(TraceLog::kInternalEchoToConsole,
2754 trace_log->GetInternalOptionsFromTraceConfig(
2755 TraceConfig("*", "trace-to-console,enable-systrace")));
2756 }
2757
SetBlockingFlagAndBlockUntilStopped(WaitableEvent * task_start_event,WaitableEvent * task_stop_event)2758 void SetBlockingFlagAndBlockUntilStopped(WaitableEvent* task_start_event,
2759 WaitableEvent* task_stop_event) {
2760 TraceLog::GetInstance()->SetCurrentThreadBlocksMessageLoop();
2761 BlockUntilStopped(task_start_event, task_stop_event);
2762 }
2763
TEST_F(TraceEventTestFixture,SetCurrentThreadBlocksMessageLoopAfterTracing)2764 TEST_F(TraceEventTestFixture, SetCurrentThreadBlocksMessageLoopAfterTracing) {
2765 BeginTrace();
2766
2767 Thread thread("1");
2768 WaitableEvent task_complete_event(WaitableEvent::ResetPolicy::AUTOMATIC,
2769 WaitableEvent::InitialState::NOT_SIGNALED);
2770 thread.Start();
2771
2772 thread.task_runner()->PostTask(
2773 FROM_HERE, BindOnce(&TraceWithAllMacroVariants, &task_complete_event));
2774 task_complete_event.Wait();
2775
2776 WaitableEvent task_start_event(WaitableEvent::ResetPolicy::AUTOMATIC,
2777 WaitableEvent::InitialState::NOT_SIGNALED);
2778 WaitableEvent task_stop_event(WaitableEvent::ResetPolicy::AUTOMATIC,
2779 WaitableEvent::InitialState::NOT_SIGNALED);
2780 thread.task_runner()->PostTask(FROM_HERE,
2781 BindOnce(&SetBlockingFlagAndBlockUntilStopped,
2782 &task_start_event, &task_stop_event));
2783 task_start_event.Wait();
2784
2785 EndTraceAndFlush();
2786 ValidateAllTraceMacrosCreatedData(trace_parsed_);
2787
2788 task_stop_event.Signal();
2789 thread.Stop();
2790 }
2791
TEST_F(TraceEventTestFixture,ThreadOnceBlocking)2792 TEST_F(TraceEventTestFixture, ThreadOnceBlocking) {
2793 BeginTrace();
2794
2795 Thread thread("1");
2796 WaitableEvent task_complete_event(WaitableEvent::ResetPolicy::AUTOMATIC,
2797 WaitableEvent::InitialState::NOT_SIGNALED);
2798 thread.Start();
2799
2800 thread.task_runner()->PostTask(
2801 FROM_HERE, BindOnce(&TraceWithAllMacroVariants, &task_complete_event));
2802 task_complete_event.Wait();
2803
2804 WaitableEvent task_start_event(WaitableEvent::ResetPolicy::AUTOMATIC,
2805 WaitableEvent::InitialState::NOT_SIGNALED);
2806 WaitableEvent task_stop_event(WaitableEvent::ResetPolicy::AUTOMATIC,
2807 WaitableEvent::InitialState::NOT_SIGNALED);
2808 thread.task_runner()->PostTask(
2809 FROM_HERE,
2810 BindOnce(&BlockUntilStopped, &task_start_event, &task_stop_event));
2811 task_start_event.Wait();
2812
2813 // The thread will timeout in this flush.
2814 EndTraceAndFlushInThreadWithMessageLoop();
2815 Clear();
2816
2817 // Let the thread's message loop continue to spin.
2818 task_stop_event.Signal();
2819
2820 // The following sequence ensures that the FlushCurrentThread task has been
2821 // executed in the thread before continuing.
2822 thread.task_runner()->PostTask(
2823 FROM_HERE,
2824 BindOnce(&BlockUntilStopped, &task_start_event, &task_stop_event));
2825 task_start_event.Wait();
2826 task_stop_event.Signal();
2827 Clear();
2828
2829 // TraceLog should discover the generation mismatch and recover the thread
2830 // local buffer for the thread without any error.
2831 BeginTrace();
2832 thread.task_runner()->PostTask(
2833 FROM_HERE, BindOnce(&TraceWithAllMacroVariants, &task_complete_event));
2834 task_complete_event.Wait();
2835 EndTraceAndFlushInThreadWithMessageLoop();
2836 ValidateAllTraceMacrosCreatedData(trace_parsed_);
2837 }
2838
2839 std::string* g_log_buffer = nullptr;
MockLogMessageHandler(int,const char *,int,size_t,const std::string & str)2840 bool MockLogMessageHandler(int, const char*, int, size_t,
2841 const std::string& str) {
2842 if (!g_log_buffer)
2843 g_log_buffer = new std::string();
2844 g_log_buffer->append(str);
2845 return false;
2846 }
2847
TEST_F(TraceEventTestFixture,EchoToConsole)2848 TEST_F(TraceEventTestFixture, EchoToConsole) {
2849 logging::LogMessageHandlerFunction old_log_message_handler =
2850 logging::GetLogMessageHandler();
2851 logging::SetLogMessageHandler(MockLogMessageHandler);
2852
2853 TraceLog::GetInstance()->SetEnabled(
2854 TraceConfig(kRecordAllCategoryFilter, ECHO_TO_CONSOLE),
2855 TraceLog::RECORDING_MODE);
2856 TRACE_EVENT_BEGIN0("a", "begin_end");
2857 {
2858 TRACE_EVENT0("b", "duration");
2859 TRACE_EVENT0("b1", "duration1");
2860 }
2861 TRACE_EVENT_INSTANT0("c", "instant", TRACE_EVENT_SCOPE_GLOBAL);
2862 TRACE_EVENT_END0("a", "begin_end");
2863
2864 EXPECT_NE(std::string::npos, g_log_buffer->find("begin_end[a]\x1b"));
2865 EXPECT_NE(std::string::npos, g_log_buffer->find("| duration[b]\x1b"));
2866 EXPECT_NE(std::string::npos, g_log_buffer->find("| | duration1[b1]\x1b"));
2867 EXPECT_NE(std::string::npos, g_log_buffer->find("| | duration1[b1] ("));
2868 EXPECT_NE(std::string::npos, g_log_buffer->find("| duration[b] ("));
2869 EXPECT_NE(std::string::npos, g_log_buffer->find("| instant[c]\x1b"));
2870 EXPECT_NE(std::string::npos, g_log_buffer->find("begin_end[a] ("));
2871
2872 EndTraceAndFlush();
2873 delete g_log_buffer;
2874 logging::SetLogMessageHandler(old_log_message_handler);
2875 g_log_buffer = nullptr;
2876 }
2877
LogMessageHandlerWithTraceEvent(int,const char *,int,size_t,const std::string &)2878 bool LogMessageHandlerWithTraceEvent(int, const char*, int, size_t,
2879 const std::string&) {
2880 TRACE_EVENT0("log", "trace_event");
2881 return false;
2882 }
2883
TEST_F(TraceEventTestFixture,EchoToConsoleTraceEventRecursion)2884 TEST_F(TraceEventTestFixture, EchoToConsoleTraceEventRecursion) {
2885 logging::LogMessageHandlerFunction old_log_message_handler =
2886 logging::GetLogMessageHandler();
2887 logging::SetLogMessageHandler(LogMessageHandlerWithTraceEvent);
2888
2889 TraceLog::GetInstance()->SetEnabled(
2890 TraceConfig(kRecordAllCategoryFilter, ECHO_TO_CONSOLE),
2891 TraceLog::RECORDING_MODE);
2892 {
2893 // This should not cause deadlock or infinite recursion.
2894 TRACE_EVENT0("b", "duration");
2895 }
2896
2897 EndTraceAndFlush();
2898 logging::SetLogMessageHandler(old_log_message_handler);
2899 }
2900
TEST_F(TraceEventTestFixture,TimeOffset)2901 TEST_F(TraceEventTestFixture, TimeOffset) {
2902 BeginTrace();
2903 // Let TraceLog timer start from 0.
2904 TimeDelta time_offset = TimeTicks::Now() - TimeTicks();
2905 TraceLog::GetInstance()->SetTimeOffset(time_offset);
2906
2907 {
2908 TRACE_EVENT0("all", "duration1");
2909 TRACE_EVENT0("all", "duration2");
2910 }
2911 TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0(
2912 "all", "with_timestamp", 0, 0, TimeTicks::Now());
2913 TRACE_EVENT_END_WITH_ID_TID_AND_TIMESTAMP0(
2914 "all", "with_timestamp", 0, 0, TimeTicks::Now());
2915
2916 EndTraceAndFlush();
2917 DropTracedMetadataRecords();
2918
2919 double end_time = static_cast<double>(
2920 (TimeTicks::Now() - time_offset).ToInternalValue());
2921 double last_timestamp = 0;
2922 for (size_t i = 0; i < trace_parsed_.GetSize(); ++i) {
2923 const DictionaryValue* item;
2924 EXPECT_TRUE(trace_parsed_.GetDictionary(i, &item));
2925 double timestamp;
2926 EXPECT_TRUE(item->GetDouble("ts", ×tamp));
2927 EXPECT_GE(timestamp, last_timestamp);
2928 EXPECT_LE(timestamp, end_time);
2929 last_timestamp = timestamp;
2930 }
2931 }
2932
TEST_F(TraceEventTestFixture,TraceFilteringMode)2933 TEST_F(TraceEventTestFixture, TraceFilteringMode) {
2934 const char config_json[] =
2935 "{"
2936 " \"event_filters\": ["
2937 " {"
2938 " \"filter_predicate\": \"testing_predicate\", "
2939 " \"included_categories\": [\"*\"]"
2940 " }"
2941 " ]"
2942 "}";
2943
2944 // Run RECORDING_MODE within FILTERING_MODE:
2945 TestEventFilter::HitsCounter filter_hits_counter;
2946 TestEventFilter::set_filter_return_value(true);
2947 TraceLog::GetInstance()->SetFilterFactoryForTesting(TestEventFilter::Factory);
2948
2949 // Only filtering mode is enabled with test filters.
2950 TraceLog::GetInstance()->SetEnabled(TraceConfig(config_json),
2951 TraceLog::FILTERING_MODE);
2952 EXPECT_EQ(TraceLog::FILTERING_MODE, TraceLog::GetInstance()->enabled_modes());
2953 {
2954 void* ptr = this;
2955 TRACE_EVENT0("c0", "name0");
2956 TRACE_EVENT_ASYNC_BEGIN0("c1", "name1", ptr);
2957 TRACE_EVENT_INSTANT0("c0", "name0", TRACE_EVENT_SCOPE_THREAD);
2958 TRACE_EVENT_ASYNC_END0("c1", "name1", ptr);
2959 }
2960
2961 // Recording mode is enabled when filtering mode is turned on.
2962 TraceLog::GetInstance()->SetEnabled(TraceConfig("", ""),
2963 TraceLog::RECORDING_MODE);
2964 EXPECT_EQ(TraceLog::RECORDING_MODE | TraceLog::FILTERING_MODE,
2965 TraceLog::GetInstance()->enabled_modes());
2966 {
2967 TRACE_EVENT0("c2", "name2");
2968 }
2969 // Only recording mode is disabled and filtering mode will continue to run.
2970 TraceLog::GetInstance()->SetDisabled(TraceLog::RECORDING_MODE);
2971 EXPECT_EQ(TraceLog::FILTERING_MODE, TraceLog::GetInstance()->enabled_modes());
2972
2973 {
2974 TRACE_EVENT0("c0", "name0");
2975 }
2976 // Filtering mode is disabled and no tracing mode should be enabled.
2977 TraceLog::GetInstance()->SetDisabled(TraceLog::FILTERING_MODE);
2978 EXPECT_EQ(0, TraceLog::GetInstance()->enabled_modes());
2979
2980 EndTraceAndFlush();
2981 EXPECT_FALSE(FindMatchingValue("cat", "c0"));
2982 EXPECT_FALSE(FindMatchingValue("cat", "c1"));
2983 EXPECT_FALSE(FindMatchingValue("name", "name0"));
2984 EXPECT_FALSE(FindMatchingValue("name", "name1"));
2985 EXPECT_TRUE(FindMatchingValue("cat", "c2"));
2986 EXPECT_TRUE(FindMatchingValue("name", "name2"));
2987 EXPECT_EQ(6u, filter_hits_counter.filter_trace_event_hit_count);
2988 EXPECT_EQ(3u, filter_hits_counter.end_event_hit_count);
2989 Clear();
2990 filter_hits_counter.Reset();
2991
2992 // Run FILTERING_MODE within RECORDING_MODE:
2993 // Only recording mode is enabled and all events must be recorded.
2994 TraceLog::GetInstance()->SetEnabled(TraceConfig("", ""),
2995 TraceLog::RECORDING_MODE);
2996 EXPECT_EQ(TraceLog::RECORDING_MODE, TraceLog::GetInstance()->enabled_modes());
2997 {
2998 TRACE_EVENT0("c0", "name0");
2999 }
3000
3001 // Filtering mode is also enabled and all events must be filtered-out.
3002 TestEventFilter::set_filter_return_value(false);
3003 TraceLog::GetInstance()->SetEnabled(TraceConfig(config_json),
3004 TraceLog::FILTERING_MODE);
3005 EXPECT_EQ(TraceLog::RECORDING_MODE | TraceLog::FILTERING_MODE,
3006 TraceLog::GetInstance()->enabled_modes());
3007 {
3008 TRACE_EVENT0("c1", "name1");
3009 }
3010 // Only filtering mode is disabled and recording mode should continue to run
3011 // with all events being recorded.
3012 TraceLog::GetInstance()->SetDisabled(TraceLog::FILTERING_MODE);
3013 EXPECT_EQ(TraceLog::RECORDING_MODE, TraceLog::GetInstance()->enabled_modes());
3014
3015 {
3016 TRACE_EVENT0("c2", "name2");
3017 }
3018 // Recording mode is disabled and no tracing mode should be enabled.
3019 TraceLog::GetInstance()->SetDisabled(TraceLog::RECORDING_MODE);
3020 EXPECT_EQ(0, TraceLog::GetInstance()->enabled_modes());
3021
3022 EndTraceAndFlush();
3023 EXPECT_TRUE(FindMatchingValue("cat", "c0"));
3024 EXPECT_TRUE(FindMatchingValue("cat", "c2"));
3025 EXPECT_TRUE(FindMatchingValue("name", "name0"));
3026 EXPECT_TRUE(FindMatchingValue("name", "name2"));
3027 EXPECT_FALSE(FindMatchingValue("cat", "c1"));
3028 EXPECT_FALSE(FindMatchingValue("name", "name1"));
3029 EXPECT_EQ(1u, filter_hits_counter.filter_trace_event_hit_count);
3030 EXPECT_EQ(1u, filter_hits_counter.end_event_hit_count);
3031 Clear();
3032 }
3033
TEST_F(TraceEventTestFixture,EventFiltering)3034 TEST_F(TraceEventTestFixture, EventFiltering) {
3035 const char config_json[] =
3036 "{"
3037 " \"included_categories\": ["
3038 " \"filtered_cat\","
3039 " \"unfiltered_cat\","
3040 " \"" TRACE_DISABLED_BY_DEFAULT("filtered_cat") "\","
3041 " \"" TRACE_DISABLED_BY_DEFAULT("unfiltered_cat") "\"],"
3042 " \"event_filters\": ["
3043 " {"
3044 " \"filter_predicate\": \"testing_predicate\", "
3045 " \"included_categories\": ["
3046 " \"filtered_cat\","
3047 " \"" TRACE_DISABLED_BY_DEFAULT("filtered_cat") "\"]"
3048 " }"
3049 " "
3050 " ]"
3051 "}";
3052
3053 TestEventFilter::HitsCounter filter_hits_counter;
3054 TestEventFilter::set_filter_return_value(true);
3055 TraceLog::GetInstance()->SetFilterFactoryForTesting(TestEventFilter::Factory);
3056
3057 TraceConfig trace_config(config_json);
3058 TraceLog::GetInstance()->SetEnabled(
3059 trace_config, TraceLog::RECORDING_MODE | TraceLog::FILTERING_MODE);
3060 ASSERT_TRUE(TraceLog::GetInstance()->IsEnabled());
3061
3062 TRACE_EVENT0("filtered_cat", "a snake");
3063 TRACE_EVENT0("filtered_cat", "a mushroom");
3064 TRACE_EVENT0("unfiltered_cat", "a horse");
3065
3066 TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("filtered_cat"), "a dog");
3067 TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("unfiltered_cat"), "a pony");
3068
3069 // This is scoped so we can test the end event being filtered.
3070 { TRACE_EVENT0("filtered_cat", "another cat whoa"); }
3071
3072 EndTraceAndFlush();
3073
3074 EXPECT_EQ(4u, filter_hits_counter.filter_trace_event_hit_count);
3075 EXPECT_EQ(1u, filter_hits_counter.end_event_hit_count);
3076 }
3077
TEST_F(TraceEventTestFixture,EventWhitelistFiltering)3078 TEST_F(TraceEventTestFixture, EventWhitelistFiltering) {
3079 std::string config_json = StringPrintf(
3080 "{"
3081 " \"included_categories\": ["
3082 " \"filtered_cat\","
3083 " \"unfiltered_cat\","
3084 " \"" TRACE_DISABLED_BY_DEFAULT("filtered_cat") "\"],"
3085 " \"event_filters\": ["
3086 " {"
3087 " \"filter_predicate\": \"%s\", "
3088 " \"included_categories\": ["
3089 " \"filtered_cat\","
3090 " \"" TRACE_DISABLED_BY_DEFAULT("*") "\"], "
3091 " \"filter_args\": {"
3092 " \"event_name_whitelist\": [\"a snake\", \"a dog\"]"
3093 " }"
3094 " }"
3095 " "
3096 " ]"
3097 "}",
3098 EventNameFilter::kName);
3099
3100 TraceConfig trace_config(config_json);
3101 TraceLog::GetInstance()->SetEnabled(
3102 trace_config, TraceLog::RECORDING_MODE | TraceLog::FILTERING_MODE);
3103 EXPECT_TRUE(TraceLog::GetInstance()->IsEnabled());
3104
3105 TRACE_EVENT0("filtered_cat", "a snake");
3106 TRACE_EVENT0("filtered_cat", "a mushroom");
3107 TRACE_EVENT0("unfiltered_cat", "a cat");
3108 TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("filtered_cat"), "a dog");
3109 TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("filtered_cat"), "a pony");
3110
3111 EndTraceAndFlush();
3112
3113 EXPECT_TRUE(FindMatchingValue("name", "a snake"));
3114 EXPECT_FALSE(FindMatchingValue("name", "a mushroom"));
3115 EXPECT_TRUE(FindMatchingValue("name", "a cat"));
3116 EXPECT_TRUE(FindMatchingValue("name", "a dog"));
3117 EXPECT_FALSE(FindMatchingValue("name", "a pony"));
3118 }
3119
TEST_F(TraceEventTestFixture,HeapProfilerFiltering)3120 TEST_F(TraceEventTestFixture, HeapProfilerFiltering) {
3121 std::string config_json = StringPrintf(
3122 "{"
3123 " \"included_categories\": ["
3124 " \"filtered_cat\","
3125 " \"unfiltered_cat\","
3126 " \"" TRACE_DISABLED_BY_DEFAULT("filtered_cat") "\","
3127 " \"" TRACE_DISABLED_BY_DEFAULT("unfiltered_cat") "\"],"
3128 " \"excluded_categories\": [\"excluded_cat\"],"
3129 " \"event_filters\": ["
3130 " {"
3131 " \"filter_predicate\": \"%s\", "
3132 " \"included_categories\": ["
3133 " \"*\","
3134 " \"" TRACE_DISABLED_BY_DEFAULT("filtered_cat") "\"]"
3135 " }"
3136 " ]"
3137 "}",
3138 HeapProfilerEventFilter::kName);
3139
3140 TraceConfig trace_config(config_json);
3141 TraceLog::GetInstance()->SetEnabled(
3142 trace_config, TraceLog::RECORDING_MODE | TraceLog::FILTERING_MODE);
3143 EXPECT_TRUE(TraceLog::GetInstance()->IsEnabled());
3144
3145 TRACE_EVENT0("filtered_cat", "a snake");
3146 TRACE_EVENT0("excluded_cat", "a mushroom");
3147 TRACE_EVENT0("unfiltered_cat", "a cat");
3148 TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("filtered_cat"), "a dog");
3149 TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("unfiltered_cat"), "a pony");
3150
3151 EndTraceAndFlush();
3152
3153 // The predicate should not change behavior of the trace events.
3154 EXPECT_TRUE(FindMatchingValue("name", "a snake"));
3155 EXPECT_FALSE(FindMatchingValue("name", "a mushroom"));
3156 EXPECT_TRUE(FindMatchingValue("name", "a cat"));
3157 EXPECT_TRUE(FindMatchingValue("name", "a dog"));
3158 EXPECT_TRUE(FindMatchingValue("name", "a pony"));
3159 }
3160
TEST_F(TraceEventTestFixture,ClockSyncEventsAreAlwaysAddedToTrace)3161 TEST_F(TraceEventTestFixture, ClockSyncEventsAreAlwaysAddedToTrace) {
3162 BeginSpecificTrace("-*");
3163 TRACE_EVENT_CLOCK_SYNC_RECEIVER(1);
3164 EndTraceAndFlush();
3165 EXPECT_TRUE(FindNamePhase("clock_sync", "c"));
3166 }
3167
3168 } // namespace trace_event
3169 } // namespace base
3170