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