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