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