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