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