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