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