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