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