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/test/trace_event_analyzer.h" 6 7 #include <stddef.h> 8 #include <stdint.h> 9 10 #include "base/bind.h" 11 #include "base/memory/ptr_util.h" 12 #include "base/memory/ref_counted_memory.h" 13 #include "base/synchronization/waitable_event.h" 14 #include "base/threading/platform_thread.h" 15 #include "base/trace_event/trace_buffer.h" 16 #include "base/trace_event/trace_event_argument.h" 17 #include "testing/gmock/include/gmock/gmock.h" 18 #include "testing/gtest/include/gtest/gtest.h" 19 20 namespace trace_analyzer { 21 22 namespace { 23 24 class TraceEventAnalyzerTest : public testing::Test { 25 public: 26 void ManualSetUp(); 27 void OnTraceDataCollected( 28 base::WaitableEvent* flush_complete_event, 29 const scoped_refptr<base::RefCountedString>& json_events_str, 30 bool has_more_events); 31 void BeginTracing(); 32 void EndTracing(); 33 34 base::trace_event::TraceResultBuffer::SimpleOutput output_; 35 base::trace_event::TraceResultBuffer buffer_; 36 }; 37 38 void TraceEventAnalyzerTest::ManualSetUp() { 39 ASSERT_TRUE(base::trace_event::TraceLog::GetInstance()); 40 buffer_.SetOutputCallback(output_.GetCallback()); 41 output_.json_output.clear(); 42 } 43 44 void TraceEventAnalyzerTest::OnTraceDataCollected( 45 base::WaitableEvent* flush_complete_event, 46 const scoped_refptr<base::RefCountedString>& json_events_str, 47 bool has_more_events) { 48 buffer_.AddFragment(json_events_str->data()); 49 if (!has_more_events) 50 flush_complete_event->Signal(); 51 } 52 53 void TraceEventAnalyzerTest::BeginTracing() { 54 output_.json_output.clear(); 55 buffer_.Start(); 56 base::trace_event::TraceLog::GetInstance()->SetEnabled( 57 base::trace_event::TraceConfig("*", ""), 58 base::trace_event::TraceLog::RECORDING_MODE); 59 } 60 61 void TraceEventAnalyzerTest::EndTracing() { 62 base::trace_event::TraceLog::GetInstance()->SetDisabled(); 63 base::WaitableEvent flush_complete_event( 64 base::WaitableEvent::ResetPolicy::AUTOMATIC, 65 base::WaitableEvent::InitialState::NOT_SIGNALED); 66 base::trace_event::TraceLog::GetInstance()->Flush( 67 base::Bind(&TraceEventAnalyzerTest::OnTraceDataCollected, 68 base::Unretained(this), 69 base::Unretained(&flush_complete_event))); 70 flush_complete_event.Wait(); 71 buffer_.Finish(); 72 } 73 74 } // namespace 75 76 TEST_F(TraceEventAnalyzerTest, NoEvents) { 77 ManualSetUp(); 78 79 // Create an empty JSON event string: 80 buffer_.Start(); 81 buffer_.Finish(); 82 83 std::unique_ptr<TraceAnalyzer> analyzer( 84 TraceAnalyzer::Create(output_.json_output)); 85 ASSERT_TRUE(analyzer.get()); 86 87 // Search for all events and verify that nothing is returned. 88 TraceEventVector found; 89 analyzer->FindEvents(Query::Bool(true), &found); 90 EXPECT_EQ(0u, found.size()); 91 } 92 93 TEST_F(TraceEventAnalyzerTest, TraceEvent) { 94 ManualSetUp(); 95 96 int int_num = 2; 97 double double_num = 3.5; 98 const char str[] = "the string"; 99 100 TraceEvent event; 101 event.arg_numbers["false"] = 0.0; 102 event.arg_numbers["true"] = 1.0; 103 event.arg_numbers["int"] = static_cast<double>(int_num); 104 event.arg_numbers["double"] = double_num; 105 event.arg_strings["string"] = str; 106 event.arg_values["dict"] = WrapUnique(new base::DictionaryValue()); 107 108 ASSERT_TRUE(event.HasNumberArg("false")); 109 ASSERT_TRUE(event.HasNumberArg("true")); 110 ASSERT_TRUE(event.HasNumberArg("int")); 111 ASSERT_TRUE(event.HasNumberArg("double")); 112 ASSERT_TRUE(event.HasStringArg("string")); 113 ASSERT_FALSE(event.HasNumberArg("notfound")); 114 ASSERT_FALSE(event.HasStringArg("notfound")); 115 ASSERT_TRUE(event.HasArg("dict")); 116 ASSERT_FALSE(event.HasArg("notfound")); 117 118 EXPECT_FALSE(event.GetKnownArgAsBool("false")); 119 EXPECT_TRUE(event.GetKnownArgAsBool("true")); 120 EXPECT_EQ(int_num, event.GetKnownArgAsInt("int")); 121 EXPECT_EQ(double_num, event.GetKnownArgAsDouble("double")); 122 EXPECT_STREQ(str, event.GetKnownArgAsString("string").c_str()); 123 124 std::unique_ptr<base::Value> arg; 125 EXPECT_TRUE(event.GetArgAsValue("dict", &arg)); 126 EXPECT_EQ(base::Value::Type::DICTIONARY, arg->GetType()); 127 } 128 129 TEST_F(TraceEventAnalyzerTest, QueryEventMember) { 130 ManualSetUp(); 131 132 TraceEvent event; 133 event.thread.process_id = 3; 134 event.thread.thread_id = 4; 135 event.timestamp = 1.5; 136 event.phase = TRACE_EVENT_PHASE_BEGIN; 137 event.category = "category"; 138 event.name = "name"; 139 event.id = "1"; 140 event.arg_numbers["num"] = 7.0; 141 event.arg_strings["str"] = "the string"; 142 143 // Other event with all different members: 144 TraceEvent other; 145 other.thread.process_id = 5; 146 other.thread.thread_id = 6; 147 other.timestamp = 2.5; 148 other.phase = TRACE_EVENT_PHASE_END; 149 other.category = "category2"; 150 other.name = "name2"; 151 other.id = "2"; 152 other.arg_numbers["num2"] = 8.0; 153 other.arg_strings["str2"] = "the string 2"; 154 155 event.other_event = &other; 156 ASSERT_TRUE(event.has_other_event()); 157 double duration = event.GetAbsTimeToOtherEvent(); 158 159 Query event_pid = Query::EventPidIs(event.thread.process_id); 160 Query event_tid = Query::EventTidIs(event.thread.thread_id); 161 Query event_time = Query::EventTimeIs(event.timestamp); 162 Query event_duration = Query::EventDurationIs(duration); 163 Query event_phase = Query::EventPhaseIs(event.phase); 164 Query event_category = Query::EventCategoryIs(event.category); 165 Query event_name = Query::EventNameIs(event.name); 166 Query event_id = Query::EventIdIs(event.id); 167 Query event_has_arg1 = Query::EventHasNumberArg("num"); 168 Query event_has_arg2 = Query::EventHasStringArg("str"); 169 Query event_arg1 = 170 (Query::EventArg("num") == Query::Double(event.arg_numbers["num"])); 171 Query event_arg2 = 172 (Query::EventArg("str") == Query::String(event.arg_strings["str"])); 173 Query event_has_other = Query::EventHasOther(); 174 Query other_pid = Query::OtherPidIs(other.thread.process_id); 175 Query other_tid = Query::OtherTidIs(other.thread.thread_id); 176 Query other_time = Query::OtherTimeIs(other.timestamp); 177 Query other_phase = Query::OtherPhaseIs(other.phase); 178 Query other_category = Query::OtherCategoryIs(other.category); 179 Query other_name = Query::OtherNameIs(other.name); 180 Query other_id = Query::OtherIdIs(other.id); 181 Query other_has_arg1 = Query::OtherHasNumberArg("num2"); 182 Query other_has_arg2 = Query::OtherHasStringArg("str2"); 183 Query other_arg1 = 184 (Query::OtherArg("num2") == Query::Double(other.arg_numbers["num2"])); 185 Query other_arg2 = 186 (Query::OtherArg("str2") == Query::String(other.arg_strings["str2"])); 187 188 EXPECT_TRUE(event_pid.Evaluate(event)); 189 EXPECT_TRUE(event_tid.Evaluate(event)); 190 EXPECT_TRUE(event_time.Evaluate(event)); 191 EXPECT_TRUE(event_duration.Evaluate(event)); 192 EXPECT_TRUE(event_phase.Evaluate(event)); 193 EXPECT_TRUE(event_category.Evaluate(event)); 194 EXPECT_TRUE(event_name.Evaluate(event)); 195 EXPECT_TRUE(event_id.Evaluate(event)); 196 EXPECT_TRUE(event_has_arg1.Evaluate(event)); 197 EXPECT_TRUE(event_has_arg2.Evaluate(event)); 198 EXPECT_TRUE(event_arg1.Evaluate(event)); 199 EXPECT_TRUE(event_arg2.Evaluate(event)); 200 EXPECT_TRUE(event_has_other.Evaluate(event)); 201 EXPECT_TRUE(other_pid.Evaluate(event)); 202 EXPECT_TRUE(other_tid.Evaluate(event)); 203 EXPECT_TRUE(other_time.Evaluate(event)); 204 EXPECT_TRUE(other_phase.Evaluate(event)); 205 EXPECT_TRUE(other_category.Evaluate(event)); 206 EXPECT_TRUE(other_name.Evaluate(event)); 207 EXPECT_TRUE(other_id.Evaluate(event)); 208 EXPECT_TRUE(other_has_arg1.Evaluate(event)); 209 EXPECT_TRUE(other_has_arg2.Evaluate(event)); 210 EXPECT_TRUE(other_arg1.Evaluate(event)); 211 EXPECT_TRUE(other_arg2.Evaluate(event)); 212 213 // Evaluate event queries against other to verify the queries fail when the 214 // event members are wrong. 215 EXPECT_FALSE(event_pid.Evaluate(other)); 216 EXPECT_FALSE(event_tid.Evaluate(other)); 217 EXPECT_FALSE(event_time.Evaluate(other)); 218 EXPECT_FALSE(event_duration.Evaluate(other)); 219 EXPECT_FALSE(event_phase.Evaluate(other)); 220 EXPECT_FALSE(event_category.Evaluate(other)); 221 EXPECT_FALSE(event_name.Evaluate(other)); 222 EXPECT_FALSE(event_id.Evaluate(other)); 223 EXPECT_FALSE(event_has_arg1.Evaluate(other)); 224 EXPECT_FALSE(event_has_arg2.Evaluate(other)); 225 EXPECT_FALSE(event_arg1.Evaluate(other)); 226 EXPECT_FALSE(event_arg2.Evaluate(other)); 227 EXPECT_FALSE(event_has_other.Evaluate(other)); 228 } 229 230 TEST_F(TraceEventAnalyzerTest, BooleanOperators) { 231 ManualSetUp(); 232 233 BeginTracing(); 234 { 235 TRACE_EVENT_INSTANT1("cat1", "name1", TRACE_EVENT_SCOPE_THREAD, "num", 1); 236 TRACE_EVENT_INSTANT1("cat1", "name2", TRACE_EVENT_SCOPE_THREAD, "num", 2); 237 TRACE_EVENT_INSTANT1("cat2", "name3", TRACE_EVENT_SCOPE_THREAD, "num", 3); 238 TRACE_EVENT_INSTANT1("cat2", "name4", TRACE_EVENT_SCOPE_THREAD, "num", 4); 239 } 240 EndTracing(); 241 242 std::unique_ptr<TraceAnalyzer> analyzer( 243 TraceAnalyzer::Create(output_.json_output)); 244 ASSERT_TRUE(analyzer); 245 analyzer->SetIgnoreMetadataEvents(true); 246 247 TraceEventVector found; 248 249 // == 250 251 analyzer->FindEvents(Query::EventCategory() == Query::String("cat1"), &found); 252 ASSERT_EQ(2u, found.size()); 253 EXPECT_STREQ("name1", found[0]->name.c_str()); 254 EXPECT_STREQ("name2", found[1]->name.c_str()); 255 256 analyzer->FindEvents(Query::EventArg("num") == Query::Int(2), &found); 257 ASSERT_EQ(1u, found.size()); 258 EXPECT_STREQ("name2", found[0]->name.c_str()); 259 260 // != 261 262 analyzer->FindEvents(Query::EventCategory() != Query::String("cat1"), &found); 263 ASSERT_EQ(2u, found.size()); 264 EXPECT_STREQ("name3", found[0]->name.c_str()); 265 EXPECT_STREQ("name4", found[1]->name.c_str()); 266 267 analyzer->FindEvents(Query::EventArg("num") != Query::Int(2), &found); 268 ASSERT_EQ(3u, found.size()); 269 EXPECT_STREQ("name1", found[0]->name.c_str()); 270 EXPECT_STREQ("name3", found[1]->name.c_str()); 271 EXPECT_STREQ("name4", found[2]->name.c_str()); 272 273 // < 274 analyzer->FindEvents(Query::EventArg("num") < Query::Int(2), &found); 275 ASSERT_EQ(1u, found.size()); 276 EXPECT_STREQ("name1", found[0]->name.c_str()); 277 278 // <= 279 analyzer->FindEvents(Query::EventArg("num") <= Query::Int(2), &found); 280 ASSERT_EQ(2u, found.size()); 281 EXPECT_STREQ("name1", found[0]->name.c_str()); 282 EXPECT_STREQ("name2", found[1]->name.c_str()); 283 284 // > 285 analyzer->FindEvents(Query::EventArg("num") > Query::Int(3), &found); 286 ASSERT_EQ(1u, found.size()); 287 EXPECT_STREQ("name4", found[0]->name.c_str()); 288 289 // >= 290 analyzer->FindEvents(Query::EventArg("num") >= Query::Int(4), &found); 291 ASSERT_EQ(1u, found.size()); 292 EXPECT_STREQ("name4", found[0]->name.c_str()); 293 294 // && 295 analyzer->FindEvents(Query::EventName() != Query::String("name1") && 296 Query::EventArg("num") < Query::Int(3), &found); 297 ASSERT_EQ(1u, found.size()); 298 EXPECT_STREQ("name2", found[0]->name.c_str()); 299 300 // || 301 analyzer->FindEvents(Query::EventName() == Query::String("name1") || 302 Query::EventArg("num") == Query::Int(3), &found); 303 ASSERT_EQ(2u, found.size()); 304 EXPECT_STREQ("name1", found[0]->name.c_str()); 305 EXPECT_STREQ("name3", found[1]->name.c_str()); 306 307 // ! 308 analyzer->FindEvents(!(Query::EventName() == Query::String("name1") || 309 Query::EventArg("num") == Query::Int(3)), &found); 310 ASSERT_EQ(2u, found.size()); 311 EXPECT_STREQ("name2", found[0]->name.c_str()); 312 EXPECT_STREQ("name4", found[1]->name.c_str()); 313 } 314 315 TEST_F(TraceEventAnalyzerTest, ArithmeticOperators) { 316 ManualSetUp(); 317 318 BeginTracing(); 319 { 320 // These events are searched for: 321 TRACE_EVENT_INSTANT2("cat1", "math1", TRACE_EVENT_SCOPE_THREAD, 322 "a", 10, "b", 5); 323 TRACE_EVENT_INSTANT2("cat1", "math2", TRACE_EVENT_SCOPE_THREAD, 324 "a", 10, "b", 10); 325 // Extra events that never match, for noise: 326 TRACE_EVENT_INSTANT2("noise", "math3", TRACE_EVENT_SCOPE_THREAD, 327 "a", 1, "b", 3); 328 TRACE_EVENT_INSTANT2("noise", "math4", TRACE_EVENT_SCOPE_THREAD, 329 "c", 10, "d", 5); 330 } 331 EndTracing(); 332 333 std::unique_ptr<TraceAnalyzer> analyzer( 334 TraceAnalyzer::Create(output_.json_output)); 335 ASSERT_TRUE(analyzer.get()); 336 337 TraceEventVector found; 338 339 // Verify that arithmetic operators function: 340 341 // + 342 analyzer->FindEvents(Query::EventArg("a") + Query::EventArg("b") == 343 Query::Int(20), &found); 344 EXPECT_EQ(1u, found.size()); 345 EXPECT_STREQ("math2", found.front()->name.c_str()); 346 347 // - 348 analyzer->FindEvents(Query::EventArg("a") - Query::EventArg("b") == 349 Query::Int(5), &found); 350 EXPECT_EQ(1u, found.size()); 351 EXPECT_STREQ("math1", found.front()->name.c_str()); 352 353 // * 354 analyzer->FindEvents(Query::EventArg("a") * Query::EventArg("b") == 355 Query::Int(50), &found); 356 EXPECT_EQ(1u, found.size()); 357 EXPECT_STREQ("math1", found.front()->name.c_str()); 358 359 // / 360 analyzer->FindEvents(Query::EventArg("a") / Query::EventArg("b") == 361 Query::Int(2), &found); 362 EXPECT_EQ(1u, found.size()); 363 EXPECT_STREQ("math1", found.front()->name.c_str()); 364 365 // % 366 analyzer->FindEvents(Query::EventArg("a") % Query::EventArg("b") == 367 Query::Int(0), &found); 368 EXPECT_EQ(2u, found.size()); 369 370 // - (negate) 371 analyzer->FindEvents(-Query::EventArg("b") == Query::Int(-10), &found); 372 EXPECT_EQ(1u, found.size()); 373 EXPECT_STREQ("math2", found.front()->name.c_str()); 374 } 375 376 TEST_F(TraceEventAnalyzerTest, StringPattern) { 377 ManualSetUp(); 378 379 BeginTracing(); 380 { 381 TRACE_EVENT_INSTANT0("cat1", "name1", TRACE_EVENT_SCOPE_THREAD); 382 TRACE_EVENT_INSTANT0("cat1", "name2", TRACE_EVENT_SCOPE_THREAD); 383 TRACE_EVENT_INSTANT0("cat1", "no match", TRACE_EVENT_SCOPE_THREAD); 384 TRACE_EVENT_INSTANT0("cat1", "name3x", TRACE_EVENT_SCOPE_THREAD); 385 } 386 EndTracing(); 387 388 std::unique_ptr<TraceAnalyzer> analyzer( 389 TraceAnalyzer::Create(output_.json_output)); 390 ASSERT_TRUE(analyzer.get()); 391 analyzer->SetIgnoreMetadataEvents(true); 392 393 TraceEventVector found; 394 395 analyzer->FindEvents(Query::EventName() == Query::Pattern("name?"), &found); 396 ASSERT_EQ(2u, found.size()); 397 EXPECT_STREQ("name1", found[0]->name.c_str()); 398 EXPECT_STREQ("name2", found[1]->name.c_str()); 399 400 analyzer->FindEvents(Query::EventName() == Query::Pattern("name*"), &found); 401 ASSERT_EQ(3u, found.size()); 402 EXPECT_STREQ("name1", found[0]->name.c_str()); 403 EXPECT_STREQ("name2", found[1]->name.c_str()); 404 EXPECT_STREQ("name3x", found[2]->name.c_str()); 405 406 analyzer->FindEvents(Query::EventName() != Query::Pattern("name*"), &found); 407 ASSERT_EQ(1u, found.size()); 408 EXPECT_STREQ("no match", found[0]->name.c_str()); 409 } 410 411 // Test that duration queries work. 412 TEST_F(TraceEventAnalyzerTest, BeginEndDuration) { 413 ManualSetUp(); 414 415 const base::TimeDelta kSleepTime = base::TimeDelta::FromMilliseconds(200); 416 // We will search for events that have a duration of greater than 90% of the 417 // sleep time, so that there is no flakiness. 418 int64_t duration_cutoff_us = (kSleepTime.InMicroseconds() * 9) / 10; 419 420 BeginTracing(); 421 { 422 TRACE_EVENT_BEGIN0("cat1", "name1"); // found by duration query 423 TRACE_EVENT_BEGIN0("noise", "name2"); // not searched for, just noise 424 { 425 TRACE_EVENT_BEGIN0("cat2", "name3"); // found by duration query 426 // next event not searched for, just noise 427 TRACE_EVENT_INSTANT0("noise", "name4", TRACE_EVENT_SCOPE_THREAD); 428 base::PlatformThread::Sleep(kSleepTime); 429 TRACE_EVENT_BEGIN0("cat2", "name5"); // not found (duration too short) 430 TRACE_EVENT_END0("cat2", "name5"); // not found (duration too short) 431 TRACE_EVENT_END0("cat2", "name3"); // found by duration query 432 } 433 TRACE_EVENT_END0("noise", "name2"); // not searched for, just noise 434 TRACE_EVENT_END0("cat1", "name1"); // found by duration query 435 } 436 EndTracing(); 437 438 std::unique_ptr<TraceAnalyzer> analyzer( 439 TraceAnalyzer::Create(output_.json_output)); 440 ASSERT_TRUE(analyzer.get()); 441 analyzer->AssociateBeginEndEvents(); 442 443 TraceEventVector found; 444 analyzer->FindEvents( 445 Query::MatchBeginWithEnd() && 446 Query::EventDuration() > 447 Query::Int(static_cast<int>(duration_cutoff_us)) && 448 (Query::EventCategory() == Query::String("cat1") || 449 Query::EventCategory() == Query::String("cat2") || 450 Query::EventCategory() == Query::String("cat3")), 451 &found); 452 ASSERT_EQ(2u, found.size()); 453 EXPECT_STREQ("name1", found[0]->name.c_str()); 454 EXPECT_STREQ("name3", found[1]->name.c_str()); 455 } 456 457 // Test that duration queries work. 458 TEST_F(TraceEventAnalyzerTest, CompleteDuration) { 459 ManualSetUp(); 460 461 const base::TimeDelta kSleepTime = base::TimeDelta::FromMilliseconds(200); 462 // We will search for events that have a duration of greater than 90% of the 463 // sleep time, so that there is no flakiness. 464 int64_t duration_cutoff_us = (kSleepTime.InMicroseconds() * 9) / 10; 465 466 BeginTracing(); 467 { 468 TRACE_EVENT0("cat1", "name1"); // found by duration query 469 TRACE_EVENT0("noise", "name2"); // not searched for, just noise 470 { 471 TRACE_EVENT0("cat2", "name3"); // found by duration query 472 // next event not searched for, just noise 473 TRACE_EVENT_INSTANT0("noise", "name4", TRACE_EVENT_SCOPE_THREAD); 474 base::PlatformThread::Sleep(kSleepTime); 475 TRACE_EVENT0("cat2", "name5"); // not found (duration too short) 476 } 477 } 478 EndTracing(); 479 480 std::unique_ptr<TraceAnalyzer> analyzer( 481 TraceAnalyzer::Create(output_.json_output)); 482 ASSERT_TRUE(analyzer.get()); 483 analyzer->AssociateBeginEndEvents(); 484 485 TraceEventVector found; 486 analyzer->FindEvents( 487 Query::EventCompleteDuration() > 488 Query::Int(static_cast<int>(duration_cutoff_us)) && 489 (Query::EventCategory() == Query::String("cat1") || 490 Query::EventCategory() == Query::String("cat2") || 491 Query::EventCategory() == Query::String("cat3")), 492 &found); 493 ASSERT_EQ(2u, found.size()); 494 EXPECT_STREQ("name1", found[0]->name.c_str()); 495 EXPECT_STREQ("name3", found[1]->name.c_str()); 496 } 497 498 // Test AssociateBeginEndEvents 499 TEST_F(TraceEventAnalyzerTest, BeginEndAssocations) { 500 ManualSetUp(); 501 502 BeginTracing(); 503 { 504 TRACE_EVENT_END0("cat1", "name1"); // does not match out of order begin 505 TRACE_EVENT_BEGIN0("cat1", "name2"); 506 TRACE_EVENT_INSTANT0("cat1", "name3", TRACE_EVENT_SCOPE_THREAD); 507 TRACE_EVENT_BEGIN0("cat1", "name1"); 508 TRACE_EVENT_END0("cat1", "name2"); 509 } 510 EndTracing(); 511 512 std::unique_ptr<TraceAnalyzer> analyzer( 513 TraceAnalyzer::Create(output_.json_output)); 514 ASSERT_TRUE(analyzer.get()); 515 analyzer->AssociateBeginEndEvents(); 516 517 TraceEventVector found; 518 analyzer->FindEvents(Query::MatchBeginWithEnd(), &found); 519 ASSERT_EQ(1u, found.size()); 520 EXPECT_STREQ("name2", found[0]->name.c_str()); 521 } 522 523 // Test MergeAssociatedEventArgs 524 TEST_F(TraceEventAnalyzerTest, MergeAssociatedEventArgs) { 525 ManualSetUp(); 526 527 const char arg_string[] = "arg_string"; 528 BeginTracing(); 529 { 530 TRACE_EVENT_BEGIN0("cat1", "name1"); 531 TRACE_EVENT_END1("cat1", "name1", "arg", arg_string); 532 } 533 EndTracing(); 534 535 std::unique_ptr<TraceAnalyzer> analyzer( 536 TraceAnalyzer::Create(output_.json_output)); 537 ASSERT_TRUE(analyzer.get()); 538 analyzer->AssociateBeginEndEvents(); 539 540 TraceEventVector found; 541 analyzer->FindEvents(Query::MatchBeginName("name1"), &found); 542 ASSERT_EQ(1u, found.size()); 543 std::string arg_actual; 544 EXPECT_FALSE(found[0]->GetArgAsString("arg", &arg_actual)); 545 546 analyzer->MergeAssociatedEventArgs(); 547 EXPECT_TRUE(found[0]->GetArgAsString("arg", &arg_actual)); 548 EXPECT_STREQ(arg_string, arg_actual.c_str()); 549 } 550 551 // Test AssociateAsyncBeginEndEvents 552 TEST_F(TraceEventAnalyzerTest, AsyncBeginEndAssocations) { 553 ManualSetUp(); 554 555 BeginTracing(); 556 { 557 TRACE_EVENT_ASYNC_END0("cat1", "name1", 0xA); // no match / out of order 558 TRACE_EVENT_ASYNC_BEGIN0("cat1", "name1", 0xB); 559 TRACE_EVENT_ASYNC_BEGIN0("cat1", "name1", 0xC); 560 TRACE_EVENT_INSTANT0("cat1", "name1", TRACE_EVENT_SCOPE_THREAD); // noise 561 TRACE_EVENT0("cat1", "name1"); // noise 562 TRACE_EVENT_ASYNC_END0("cat1", "name1", 0xB); 563 TRACE_EVENT_ASYNC_END0("cat1", "name1", 0xC); 564 TRACE_EVENT_ASYNC_BEGIN0("cat1", "name1", 0xA); // no match / out of order 565 } 566 EndTracing(); 567 568 std::unique_ptr<TraceAnalyzer> analyzer( 569 TraceAnalyzer::Create(output_.json_output)); 570 ASSERT_TRUE(analyzer.get()); 571 analyzer->AssociateAsyncBeginEndEvents(); 572 573 TraceEventVector found; 574 analyzer->FindEvents(Query::MatchAsyncBeginWithNext(), &found); 575 ASSERT_EQ(2u, found.size()); 576 EXPECT_STRCASEEQ("0xb", found[0]->id.c_str()); 577 EXPECT_STRCASEEQ("0xc", found[1]->id.c_str()); 578 } 579 580 // Test AssociateAsyncBeginEndEvents 581 TEST_F(TraceEventAnalyzerTest, AsyncBeginEndAssocationsWithSteps) { 582 ManualSetUp(); 583 584 BeginTracing(); 585 { 586 TRACE_EVENT_ASYNC_STEP_INTO0("c", "n", 0xA, "s1"); 587 TRACE_EVENT_ASYNC_END0("c", "n", 0xA); 588 TRACE_EVENT_ASYNC_BEGIN0("c", "n", 0xB); 589 TRACE_EVENT_ASYNC_BEGIN0("c", "n", 0xC); 590 TRACE_EVENT_ASYNC_STEP_PAST0("c", "n", 0xB, "s1"); 591 TRACE_EVENT_ASYNC_STEP_INTO0("c", "n", 0xC, "s1"); 592 TRACE_EVENT_ASYNC_STEP_INTO1("c", "n", 0xC, "s2", "a", 1); 593 TRACE_EVENT_ASYNC_END0("c", "n", 0xB); 594 TRACE_EVENT_ASYNC_END0("c", "n", 0xC); 595 TRACE_EVENT_ASYNC_BEGIN0("c", "n", 0xA); 596 TRACE_EVENT_ASYNC_STEP_INTO0("c", "n", 0xA, "s2"); 597 } 598 EndTracing(); 599 600 std::unique_ptr<TraceAnalyzer> analyzer( 601 TraceAnalyzer::Create(output_.json_output)); 602 ASSERT_TRUE(analyzer.get()); 603 analyzer->AssociateAsyncBeginEndEvents(); 604 605 TraceEventVector found; 606 analyzer->FindEvents(Query::MatchAsyncBeginWithNext(), &found); 607 ASSERT_EQ(3u, found.size()); 608 609 EXPECT_STRCASEEQ("0xb", found[0]->id.c_str()); 610 EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP_PAST, found[0]->other_event->phase); 611 EXPECT_EQ(found[0], found[0]->other_event->prev_event); 612 EXPECT_TRUE(found[0]->other_event->other_event); 613 EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_END, 614 found[0]->other_event->other_event->phase); 615 EXPECT_EQ(found[0]->other_event, 616 found[0]->other_event->other_event->prev_event); 617 618 EXPECT_STRCASEEQ("0xc", found[1]->id.c_str()); 619 EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP_INTO, found[1]->other_event->phase); 620 EXPECT_EQ(found[1], found[1]->other_event->prev_event); 621 EXPECT_TRUE(found[1]->other_event->other_event); 622 EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP_INTO, 623 found[1]->other_event->other_event->phase); 624 EXPECT_EQ(found[1]->other_event, 625 found[1]->other_event->other_event->prev_event); 626 double arg_actual = 0; 627 EXPECT_TRUE(found[1]->other_event->other_event->GetArgAsNumber( 628 "a", &arg_actual)); 629 EXPECT_EQ(1.0, arg_actual); 630 EXPECT_TRUE(found[1]->other_event->other_event->other_event); 631 EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_END, 632 found[1]->other_event->other_event->other_event->phase); 633 634 EXPECT_STRCASEEQ("0xa", found[2]->id.c_str()); 635 EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP_INTO, found[2]->other_event->phase); 636 } 637 638 // Test that the TraceAnalyzer custom associations work. 639 TEST_F(TraceEventAnalyzerTest, CustomAssociations) { 640 ManualSetUp(); 641 642 // Add events that begin/end in pipelined ordering with unique ID parameter 643 // to match up the begin/end pairs. 644 BeginTracing(); 645 { 646 // no begin match 647 TRACE_EVENT_INSTANT1("cat1", "end", TRACE_EVENT_SCOPE_THREAD, "id", 1); 648 // end is cat4 649 TRACE_EVENT_INSTANT1("cat2", "begin", TRACE_EVENT_SCOPE_THREAD, "id", 2); 650 // end is cat5 651 TRACE_EVENT_INSTANT1("cat3", "begin", TRACE_EVENT_SCOPE_THREAD, "id", 3); 652 TRACE_EVENT_INSTANT1("cat4", "end", TRACE_EVENT_SCOPE_THREAD, "id", 2); 653 TRACE_EVENT_INSTANT1("cat5", "end", TRACE_EVENT_SCOPE_THREAD, "id", 3); 654 // no end match 655 TRACE_EVENT_INSTANT1("cat6", "begin", TRACE_EVENT_SCOPE_THREAD, "id", 1); 656 } 657 EndTracing(); 658 659 std::unique_ptr<TraceAnalyzer> analyzer( 660 TraceAnalyzer::Create(output_.json_output)); 661 ASSERT_TRUE(analyzer.get()); 662 663 // begin, end, and match queries to find proper begin/end pairs. 664 Query begin(Query::EventName() == Query::String("begin")); 665 Query end(Query::EventName() == Query::String("end")); 666 Query match(Query::EventArg("id") == Query::OtherArg("id")); 667 analyzer->AssociateEvents(begin, end, match); 668 669 TraceEventVector found; 670 671 // cat1 has no other_event. 672 analyzer->FindEvents(Query::EventCategory() == Query::String("cat1") && 673 Query::EventHasOther(), &found); 674 EXPECT_EQ(0u, found.size()); 675 676 // cat1 has no other_event. 677 analyzer->FindEvents(Query::EventCategory() == Query::String("cat1") && 678 !Query::EventHasOther(), &found); 679 EXPECT_EQ(1u, found.size()); 680 681 // cat6 has no other_event. 682 analyzer->FindEvents(Query::EventCategory() == Query::String("cat6") && 683 !Query::EventHasOther(), &found); 684 EXPECT_EQ(1u, found.size()); 685 686 // cat2 and cat4 are associated. 687 analyzer->FindEvents(Query::EventCategory() == Query::String("cat2") && 688 Query::OtherCategory() == Query::String("cat4"), &found); 689 EXPECT_EQ(1u, found.size()); 690 691 // cat4 and cat2 are not associated. 692 analyzer->FindEvents(Query::EventCategory() == Query::String("cat4") && 693 Query::OtherCategory() == Query::String("cat2"), &found); 694 EXPECT_EQ(0u, found.size()); 695 696 // cat3 and cat5 are associated. 697 analyzer->FindEvents(Query::EventCategory() == Query::String("cat3") && 698 Query::OtherCategory() == Query::String("cat5"), &found); 699 EXPECT_EQ(1u, found.size()); 700 701 // cat5 and cat3 are not associated. 702 analyzer->FindEvents(Query::EventCategory() == Query::String("cat5") && 703 Query::OtherCategory() == Query::String("cat3"), &found); 704 EXPECT_EQ(0u, found.size()); 705 } 706 707 // Verify that Query literals and types are properly casted. 708 TEST_F(TraceEventAnalyzerTest, Literals) { 709 ManualSetUp(); 710 711 // Since these queries don't refer to the event data, the dummy event below 712 // will never be accessed. 713 TraceEvent dummy; 714 char char_num = 5; 715 short short_num = -5; 716 EXPECT_TRUE((Query::Double(5.0) == Query::Int(char_num)).Evaluate(dummy)); 717 EXPECT_TRUE((Query::Double(-5.0) == Query::Int(short_num)).Evaluate(dummy)); 718 EXPECT_TRUE((Query::Double(1.0) == Query::Uint(1u)).Evaluate(dummy)); 719 EXPECT_TRUE((Query::Double(1.0) == Query::Int(1)).Evaluate(dummy)); 720 EXPECT_TRUE((Query::Double(-1.0) == Query::Int(-1)).Evaluate(dummy)); 721 EXPECT_TRUE((Query::Double(1.0) == Query::Double(1.0f)).Evaluate(dummy)); 722 EXPECT_TRUE((Query::Bool(true) == Query::Int(1)).Evaluate(dummy)); 723 EXPECT_TRUE((Query::Bool(false) == Query::Int(0)).Evaluate(dummy)); 724 EXPECT_TRUE((Query::Bool(true) == Query::Double(1.0f)).Evaluate(dummy)); 725 EXPECT_TRUE((Query::Bool(false) == Query::Double(0.0f)).Evaluate(dummy)); 726 } 727 728 // Test GetRateStats. 729 TEST_F(TraceEventAnalyzerTest, RateStats) { 730 std::vector<TraceEvent> events; 731 events.reserve(100); 732 TraceEventVector event_ptrs; 733 double timestamp = 0.0; 734 double little_delta = 1.0; 735 double big_delta = 10.0; 736 double tiny_delta = 0.1; 737 RateStats stats; 738 RateStatsOptions options; 739 740 // Insert 10 events, each apart by little_delta. 741 for (int i = 0; i < 10; ++i) { 742 timestamp += little_delta; 743 TraceEvent event; 744 event.timestamp = timestamp; 745 events.push_back(std::move(event)); 746 event_ptrs.push_back(&events.back()); 747 } 748 749 ASSERT_TRUE(GetRateStats(event_ptrs, &stats, NULL)); 750 EXPECT_EQ(little_delta, stats.mean_us); 751 EXPECT_EQ(little_delta, stats.min_us); 752 EXPECT_EQ(little_delta, stats.max_us); 753 EXPECT_EQ(0.0, stats.standard_deviation_us); 754 755 // Add an event apart by big_delta. 756 { 757 timestamp += big_delta; 758 TraceEvent event; 759 event.timestamp = timestamp; 760 events.push_back(std::move(event)); 761 event_ptrs.push_back(&events.back()); 762 } 763 764 ASSERT_TRUE(GetRateStats(event_ptrs, &stats, NULL)); 765 EXPECT_LT(little_delta, stats.mean_us); 766 EXPECT_EQ(little_delta, stats.min_us); 767 EXPECT_EQ(big_delta, stats.max_us); 768 EXPECT_LT(0.0, stats.standard_deviation_us); 769 770 // Trim off the biggest delta and verify stats. 771 options.trim_min = 0; 772 options.trim_max = 1; 773 ASSERT_TRUE(GetRateStats(event_ptrs, &stats, &options)); 774 EXPECT_EQ(little_delta, stats.mean_us); 775 EXPECT_EQ(little_delta, stats.min_us); 776 EXPECT_EQ(little_delta, stats.max_us); 777 EXPECT_EQ(0.0, stats.standard_deviation_us); 778 779 // Add an event apart by tiny_delta. 780 { 781 timestamp += tiny_delta; 782 TraceEvent event; 783 event.timestamp = timestamp; 784 events.push_back(std::move(event)); 785 event_ptrs.push_back(&events.back()); 786 } 787 788 // Trim off both the biggest and tiniest delta and verify stats. 789 options.trim_min = 1; 790 options.trim_max = 1; 791 ASSERT_TRUE(GetRateStats(event_ptrs, &stats, &options)); 792 EXPECT_EQ(little_delta, stats.mean_us); 793 EXPECT_EQ(little_delta, stats.min_us); 794 EXPECT_EQ(little_delta, stats.max_us); 795 EXPECT_EQ(0.0, stats.standard_deviation_us); 796 797 // Verify smallest allowed number of events. 798 { 799 TraceEvent event; 800 TraceEventVector few_event_ptrs; 801 few_event_ptrs.push_back(&event); 802 few_event_ptrs.push_back(&event); 803 ASSERT_FALSE(GetRateStats(few_event_ptrs, &stats, NULL)); 804 few_event_ptrs.push_back(&event); 805 ASSERT_TRUE(GetRateStats(few_event_ptrs, &stats, NULL)); 806 807 // Trim off more than allowed and verify failure. 808 options.trim_min = 0; 809 options.trim_max = 1; 810 ASSERT_FALSE(GetRateStats(few_event_ptrs, &stats, &options)); 811 } 812 } 813 814 // Test FindFirstOf and FindLastOf. 815 TEST_F(TraceEventAnalyzerTest, FindOf) { 816 size_t num_events = 100; 817 size_t index = 0; 818 TraceEventVector event_ptrs; 819 EXPECT_FALSE(FindFirstOf(event_ptrs, Query::Bool(true), 0, &index)); 820 EXPECT_FALSE(FindFirstOf(event_ptrs, Query::Bool(true), 10, &index)); 821 EXPECT_FALSE(FindLastOf(event_ptrs, Query::Bool(true), 0, &index)); 822 EXPECT_FALSE(FindLastOf(event_ptrs, Query::Bool(true), 10, &index)); 823 824 std::vector<TraceEvent> events; 825 events.resize(num_events); 826 for (size_t i = 0; i < events.size(); ++i) 827 event_ptrs.push_back(&events[i]); 828 size_t bam_index = num_events/2; 829 events[bam_index].name = "bam"; 830 Query query_bam = Query::EventName() == Query::String(events[bam_index].name); 831 832 // FindFirstOf 833 EXPECT_FALSE(FindFirstOf(event_ptrs, Query::Bool(false), 0, &index)); 834 EXPECT_TRUE(FindFirstOf(event_ptrs, Query::Bool(true), 0, &index)); 835 EXPECT_EQ(0u, index); 836 EXPECT_TRUE(FindFirstOf(event_ptrs, Query::Bool(true), 5, &index)); 837 EXPECT_EQ(5u, index); 838 839 EXPECT_FALSE(FindFirstOf(event_ptrs, query_bam, bam_index + 1, &index)); 840 EXPECT_TRUE(FindFirstOf(event_ptrs, query_bam, 0, &index)); 841 EXPECT_EQ(bam_index, index); 842 EXPECT_TRUE(FindFirstOf(event_ptrs, query_bam, bam_index, &index)); 843 EXPECT_EQ(bam_index, index); 844 845 // FindLastOf 846 EXPECT_FALSE(FindLastOf(event_ptrs, Query::Bool(false), 1000, &index)); 847 EXPECT_TRUE(FindLastOf(event_ptrs, Query::Bool(true), 1000, &index)); 848 EXPECT_EQ(num_events - 1, index); 849 EXPECT_TRUE(FindLastOf(event_ptrs, Query::Bool(true), num_events - 5, 850 &index)); 851 EXPECT_EQ(num_events - 5, index); 852 853 EXPECT_FALSE(FindLastOf(event_ptrs, query_bam, bam_index - 1, &index)); 854 EXPECT_TRUE(FindLastOf(event_ptrs, query_bam, num_events, &index)); 855 EXPECT_EQ(bam_index, index); 856 EXPECT_TRUE(FindLastOf(event_ptrs, query_bam, bam_index, &index)); 857 EXPECT_EQ(bam_index, index); 858 } 859 860 // Test FindClosest. 861 TEST_F(TraceEventAnalyzerTest, FindClosest) { 862 size_t index_1 = 0; 863 size_t index_2 = 0; 864 TraceEventVector event_ptrs; 865 EXPECT_FALSE(FindClosest(event_ptrs, Query::Bool(true), 0, 866 &index_1, &index_2)); 867 868 size_t num_events = 5; 869 std::vector<TraceEvent> events; 870 events.resize(num_events); 871 for (size_t i = 0; i < events.size(); ++i) { 872 // timestamps go up exponentially so the lower index is always closer in 873 // time than the higher index. 874 events[i].timestamp = static_cast<double>(i) * static_cast<double>(i); 875 event_ptrs.push_back(&events[i]); 876 } 877 events[0].name = "one"; 878 events[2].name = "two"; 879 events[4].name = "three"; 880 Query query_named = Query::EventName() != Query::String(std::string()); 881 Query query_one = Query::EventName() == Query::String("one"); 882 883 // Only one event matches query_one, so two closest can't be found. 884 EXPECT_FALSE(FindClosest(event_ptrs, query_one, 0, &index_1, &index_2)); 885 886 EXPECT_TRUE(FindClosest(event_ptrs, query_one, 3, &index_1, NULL)); 887 EXPECT_EQ(0u, index_1); 888 889 EXPECT_TRUE(FindClosest(event_ptrs, query_named, 1, &index_1, &index_2)); 890 EXPECT_EQ(0u, index_1); 891 EXPECT_EQ(2u, index_2); 892 893 EXPECT_TRUE(FindClosest(event_ptrs, query_named, 4, &index_1, &index_2)); 894 EXPECT_EQ(4u, index_1); 895 EXPECT_EQ(2u, index_2); 896 897 EXPECT_TRUE(FindClosest(event_ptrs, query_named, 3, &index_1, &index_2)); 898 EXPECT_EQ(2u, index_1); 899 EXPECT_EQ(0u, index_2); 900 } 901 902 // Test CountMatches. 903 TEST_F(TraceEventAnalyzerTest, CountMatches) { 904 TraceEventVector event_ptrs; 905 EXPECT_EQ(0u, CountMatches(event_ptrs, Query::Bool(true), 0, 10)); 906 907 size_t num_events = 5; 908 size_t num_named = 3; 909 std::vector<TraceEvent> events; 910 events.resize(num_events); 911 for (size_t i = 0; i < events.size(); ++i) 912 event_ptrs.push_back(&events[i]); 913 events[0].name = "one"; 914 events[2].name = "two"; 915 events[4].name = "three"; 916 Query query_named = Query::EventName() != Query::String(std::string()); 917 Query query_one = Query::EventName() == Query::String("one"); 918 919 EXPECT_EQ(0u, CountMatches(event_ptrs, Query::Bool(false))); 920 EXPECT_EQ(num_events, CountMatches(event_ptrs, Query::Bool(true))); 921 EXPECT_EQ(num_events - 1, CountMatches(event_ptrs, Query::Bool(true), 922 1, num_events)); 923 EXPECT_EQ(1u, CountMatches(event_ptrs, query_one)); 924 EXPECT_EQ(num_events - 1, CountMatches(event_ptrs, !query_one)); 925 EXPECT_EQ(num_named, CountMatches(event_ptrs, query_named)); 926 } 927 928 TEST_F(TraceEventAnalyzerTest, ComplexArgument) { 929 ManualSetUp(); 930 931 BeginTracing(); 932 { 933 std::unique_ptr<base::trace_event::TracedValue> value( 934 new base::trace_event::TracedValue); 935 value->SetString("property", "value"); 936 TRACE_EVENT1("cat", "name", "arg", std::move(value)); 937 } 938 EndTracing(); 939 940 std::unique_ptr<TraceAnalyzer> analyzer( 941 TraceAnalyzer::Create(output_.json_output)); 942 ASSERT_TRUE(analyzer.get()); 943 944 TraceEventVector events; 945 analyzer->FindEvents(Query::EventName() == Query::String("name"), &events); 946 947 EXPECT_EQ(1u, events.size()); 948 EXPECT_EQ("cat", events[0]->category); 949 EXPECT_EQ("name", events[0]->name); 950 EXPECT_TRUE(events[0]->HasArg("arg")); 951 952 std::unique_ptr<base::Value> arg; 953 events[0]->GetArgAsValue("arg", &arg); 954 base::DictionaryValue* arg_dict; 955 EXPECT_TRUE(arg->GetAsDictionary(&arg_dict)); 956 std::string property; 957 EXPECT_TRUE(arg_dict->GetString("property", &property)); 958 EXPECT_EQ("value", property); 959 } 960 961 } // namespace trace_analyzer 962
