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