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