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