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