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