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

Issues Search
    My Issues | Starred     Open | Closed | All

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

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

Powered by Google App Engine
This is Rietveld 408576698