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