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