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