base/test/trace_event_analyzer_unittest.cc

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