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