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