Chromium Code Reviews
chromiumcodereview-hr@appspot.gserviceaccount.com (chromiumcodereview-hr) | Please choose your nickname with Settings | Help | Chromium Project | Gerrit Changes | Sign out
(198)

Issues Search
    My Issues | Starred     Open | Closed | All

Side by Side Diff: base/debug/trace_event_unittest.cc

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

Powered by Google App Engine
This is Rietveld 408576698