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::trace_event::TraceResultBuffer::SimpleOutput output_;
  27   base::trace_event::TraceResultBuffer buffer_;
  28 };
  29
  30 void TraceEventAnalyzerTest::ManualSetUp() {
  31   ASSERT_TRUE(base::trace_event::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::trace_event::TraceLog::GetInstance()->SetEnabled(
  49       base::trace_event::TraceConfig("*", ""),
  50       base::trace_event::TraceLog::RECORDING_MODE);
  51 }
  52
  53 void TraceEventAnalyzerTest::EndTracing() {
  54   base::trace_event::TraceLog::GetInstance()->SetDisabled();
  55   base::WaitableEvent flush_complete_event(false, false);
  56   base::trace_event::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);
 228   analyzer->SetIgnoreMetadataEvents(true);
 229
 230   TraceEventVector found;
 231
 232   // ==
 233
 234   analyzer->FindEvents(Query::EventCategory() == Query::String("cat1"), &found);
 235   ASSERT_EQ(2u, found.size());
 236   EXPECT_STREQ("name1", found[0]->name.c_str());
 237   EXPECT_STREQ("name2", found[1]->name.c_str());
 238
 239   analyzer->FindEvents(Query::EventArg("num") == Query::Int(2), &found);
 240   ASSERT_EQ(1u, found.size());
 241   EXPECT_STREQ("name2", found[0]->name.c_str());
 242
 243   // !=
 244
 245   analyzer->FindEvents(Query::EventCategory() != Query::String("cat1"), &found);
 246   ASSERT_EQ(2u, found.size());
 247   EXPECT_STREQ("name3", found[0]->name.c_str());
 248   EXPECT_STREQ("name4", found[1]->name.c_str());
 249
 250   analyzer->FindEvents(Query::EventArg("num") != Query::Int(2), &found);
 251   ASSERT_EQ(3u, found.size());
 252   EXPECT_STREQ("name1", found[0]->name.c_str());
 253   EXPECT_STREQ("name3", found[1]->name.c_str());
 254   EXPECT_STREQ("name4", found[2]->name.c_str());
 255
 256   // <
 257   analyzer->FindEvents(Query::EventArg("num") < Query::Int(2), &found);
 258   ASSERT_EQ(1u, found.size());
 259   EXPECT_STREQ("name1", found[0]->name.c_str());
 260
 261   // <=
 262   analyzer->FindEvents(Query::EventArg("num") <= Query::Int(2), &found);
 263   ASSERT_EQ(2u, found.size());
 264   EXPECT_STREQ("name1", found[0]->name.c_str());
 265   EXPECT_STREQ("name2", found[1]->name.c_str());
 266
 267   // >
 268   analyzer->FindEvents(Query::EventArg("num") > Query::Int(3), &found);
 269   ASSERT_EQ(1u, found.size());
 270   EXPECT_STREQ("name4", found[0]->name.c_str());
 271
 272   // >=
 273   analyzer->FindEvents(Query::EventArg("num") >= Query::Int(4), &found);
 274   ASSERT_EQ(1u, found.size());
 275   EXPECT_STREQ("name4", found[0]->name.c_str());
 276
 277   // &&
 278   analyzer->FindEvents(Query::EventName() != Query::String("name1") &&
 279                        Query::EventArg("num") < Query::Int(3), &found);
 280   ASSERT_EQ(1u, found.size());
 281   EXPECT_STREQ("name2", found[0]->name.c_str());
 282
 283   // ||
 284   analyzer->FindEvents(Query::EventName() == Query::String("name1") ||
 285                        Query::EventArg("num") == Query::Int(3), &found);
 286   ASSERT_EQ(2u, found.size());
 287   EXPECT_STREQ("name1", found[0]->name.c_str());
 288   EXPECT_STREQ("name3", found[1]->name.c_str());
 289
 290   // !
 291   analyzer->FindEvents(!(Query::EventName() == Query::String("name1") ||
 292                          Query::EventArg("num") == Query::Int(3)), &found);
 293   ASSERT_EQ(2u, found.size());
 294   EXPECT_STREQ("name2", found[0]->name.c_str());
 295   EXPECT_STREQ("name4", found[1]->name.c_str());
 296 }
 297
 298 TEST_F(TraceEventAnalyzerTest, ArithmeticOperators) {
 299   ManualSetUp();
 300
 301   BeginTracing();
 302   {
 303     // These events are searched for:
 304     TRACE_EVENT_INSTANT2("cat1", "math1", TRACE_EVENT_SCOPE_THREAD,
 305                          "a", 10, "b", 5);
 306     TRACE_EVENT_INSTANT2("cat1", "math2", TRACE_EVENT_SCOPE_THREAD,
 307                          "a", 10, "b", 10);
 308     // Extra events that never match, for noise:
 309     TRACE_EVENT_INSTANT2("noise", "math3", TRACE_EVENT_SCOPE_THREAD,
 310                          "a", 1,  "b", 3);
 311     TRACE_EVENT_INSTANT2("noise", "math4", TRACE_EVENT_SCOPE_THREAD,
 312                          "c", 10, "d", 5);
 313   }
 314   EndTracing();
 315
 316   scoped_ptr<TraceAnalyzer>
 317       analyzer(TraceAnalyzer::Create(output_.json_output));
 318   ASSERT_TRUE(analyzer.get());
 319
 320   TraceEventVector found;
 321
 322   // Verify that arithmetic operators function:
 323
 324   // +
 325   analyzer->FindEvents(Query::EventArg("a") + Query::EventArg("b") ==
 326                        Query::Int(20), &found);
 327   EXPECT_EQ(1u, found.size());
 328   EXPECT_STREQ("math2", found.front()->name.c_str());
 329
 330   // -
 331   analyzer->FindEvents(Query::EventArg("a") - Query::EventArg("b") ==
 332                        Query::Int(5), &found);
 333   EXPECT_EQ(1u, found.size());
 334   EXPECT_STREQ("math1", found.front()->name.c_str());
 335
 336   // *
 337   analyzer->FindEvents(Query::EventArg("a") * Query::EventArg("b") ==
 338                        Query::Int(50), &found);
 339   EXPECT_EQ(1u, found.size());
 340   EXPECT_STREQ("math1", found.front()->name.c_str());
 341
 342   // /
 343   analyzer->FindEvents(Query::EventArg("a") / Query::EventArg("b") ==
 344                        Query::Int(2), &found);
 345   EXPECT_EQ(1u, found.size());
 346   EXPECT_STREQ("math1", found.front()->name.c_str());
 347
 348   // %
 349   analyzer->FindEvents(Query::EventArg("a") % Query::EventArg("b") ==
 350                        Query::Int(0), &found);
 351   EXPECT_EQ(2u, found.size());
 352
 353   // - (negate)
 354   analyzer->FindEvents(-Query::EventArg("b") == Query::Int(-10), &found);
 355   EXPECT_EQ(1u, found.size());
 356   EXPECT_STREQ("math2", found.front()->name.c_str());
 357 }
 358
 359 TEST_F(TraceEventAnalyzerTest, StringPattern) {
 360   ManualSetUp();
 361
 362   BeginTracing();
 363   {
 364     TRACE_EVENT_INSTANT0("cat1", "name1", TRACE_EVENT_SCOPE_THREAD);
 365     TRACE_EVENT_INSTANT0("cat1", "name2", TRACE_EVENT_SCOPE_THREAD);
 366     TRACE_EVENT_INSTANT0("cat1", "no match", TRACE_EVENT_SCOPE_THREAD);
 367     TRACE_EVENT_INSTANT0("cat1", "name3x", TRACE_EVENT_SCOPE_THREAD);
 368   }
 369   EndTracing();
 370
 371   scoped_ptr<TraceAnalyzer>
 372       analyzer(TraceAnalyzer::Create(output_.json_output));
 373   ASSERT_TRUE(analyzer.get());
 374   analyzer->SetIgnoreMetadataEvents(true);
 375
 376   TraceEventVector found;
 377
 378   analyzer->FindEvents(Query::EventName() == Query::Pattern("name?"), &found);
 379   ASSERT_EQ(2u, found.size());
 380   EXPECT_STREQ("name1", found[0]->name.c_str());
 381   EXPECT_STREQ("name2", found[1]->name.c_str());
 382
 383   analyzer->FindEvents(Query::EventName() == Query::Pattern("name*"), &found);
 384   ASSERT_EQ(3u, found.size());
 385   EXPECT_STREQ("name1", found[0]->name.c_str());
 386   EXPECT_STREQ("name2", found[1]->name.c_str());
 387   EXPECT_STREQ("name3x", found[2]->name.c_str());
 388
 389   analyzer->FindEvents(Query::EventName() != Query::Pattern("name*"), &found);
 390   ASSERT_EQ(1u, found.size());
 391   EXPECT_STREQ("no match", found[0]->name.c_str());
 392 }
 393
 394 // Test that duration queries work.
 395 TEST_F(TraceEventAnalyzerTest, BeginEndDuration) {
 396   ManualSetUp();
 397
 398   const base::TimeDelta kSleepTime = base::TimeDelta::FromMilliseconds(200);
 399   // We will search for events that have a duration of greater than 90% of the
 400   // sleep time, so that there is no flakiness.
 401   int64 duration_cutoff_us = (kSleepTime.InMicroseconds() * 9) / 10;
 402
 403   BeginTracing();
 404   {
 405     TRACE_EVENT_BEGIN0("cat1", "name1"); // found by duration query
 406     TRACE_EVENT_BEGIN0("noise", "name2"); // not searched for, just noise
 407     {
 408       TRACE_EVENT_BEGIN0("cat2", "name3"); // found by duration query
 409       // next event not searched for, just noise
 410       TRACE_EVENT_INSTANT0("noise", "name4", TRACE_EVENT_SCOPE_THREAD);
 411       base::PlatformThread::Sleep(kSleepTime);
 412       TRACE_EVENT_BEGIN0("cat2", "name5"); // not found (duration too short)
 413       TRACE_EVENT_END0("cat2", "name5"); // not found (duration too short)
 414       TRACE_EVENT_END0("cat2", "name3"); // found by duration query
 415     }
 416     TRACE_EVENT_END0("noise", "name2"); // not searched for, just noise
 417     TRACE_EVENT_END0("cat1", "name1"); // found by duration query
 418   }
 419   EndTracing();
 420
 421   scoped_ptr<TraceAnalyzer>
 422       analyzer(TraceAnalyzer::Create(output_.json_output));
 423   ASSERT_TRUE(analyzer.get());
 424   analyzer->AssociateBeginEndEvents();
 425
 426   TraceEventVector found;
 427   analyzer->FindEvents(
 428       Query::MatchBeginWithEnd() &&
 429       Query::EventDuration() >
 430           Query::Int(static_cast<int>(duration_cutoff_us)) &&
 431       (Query::EventCategory() == Query::String("cat1") ||
 432        Query::EventCategory() == Query::String("cat2") ||
 433        Query::EventCategory() == Query::String("cat3")),
 434       &found);
 435   ASSERT_EQ(2u, found.size());
 436   EXPECT_STREQ("name1", found[0]->name.c_str());
 437   EXPECT_STREQ("name3", found[1]->name.c_str());
 438 }
 439
 440 // Test that duration queries work.
 441 TEST_F(TraceEventAnalyzerTest, CompleteDuration) {
 442   ManualSetUp();
 443
 444   const base::TimeDelta kSleepTime = base::TimeDelta::FromMilliseconds(200);
 445   // We will search for events that have a duration of greater than 90% of the
 446   // sleep time, so that there is no flakiness.
 447   int64 duration_cutoff_us = (kSleepTime.InMicroseconds() * 9) / 10;
 448
 449   BeginTracing();
 450   {
 451     TRACE_EVENT0("cat1", "name1"); // found by duration query
 452     TRACE_EVENT0("noise", "name2"); // not searched for, just noise
 453     {
 454       TRACE_EVENT0("cat2", "name3"); // found by duration query
 455       // next event not searched for, just noise
 456       TRACE_EVENT_INSTANT0("noise", "name4", TRACE_EVENT_SCOPE_THREAD);
 457       base::PlatformThread::Sleep(kSleepTime);
 458       TRACE_EVENT0("cat2", "name5"); // not found (duration too short)
 459     }
 460   }
 461   EndTracing();
 462
 463   scoped_ptr<TraceAnalyzer>
 464       analyzer(TraceAnalyzer::Create(output_.json_output));
 465   ASSERT_TRUE(analyzer.get());
 466   analyzer->AssociateBeginEndEvents();
 467
 468   TraceEventVector found;
 469   analyzer->FindEvents(
 470       Query::EventCompleteDuration() >
 471           Query::Int(static_cast<int>(duration_cutoff_us)) &&
 472       (Query::EventCategory() == Query::String("cat1") ||
 473        Query::EventCategory() == Query::String("cat2") ||
 474        Query::EventCategory() == Query::String("cat3")),
 475       &found);
 476   ASSERT_EQ(2u, found.size());
 477   EXPECT_STREQ("name1", found[0]->name.c_str());
 478   EXPECT_STREQ("name3", found[1]->name.c_str());
 479 }
 480
 481 // Test AssociateBeginEndEvents
 482 TEST_F(TraceEventAnalyzerTest, BeginEndAssocations) {
 483   ManualSetUp();
 484
 485   BeginTracing();
 486   {
 487     TRACE_EVENT_END0("cat1", "name1"); // does not match out of order begin
 488     TRACE_EVENT_BEGIN0("cat1", "name2");
 489     TRACE_EVENT_INSTANT0("cat1", "name3", TRACE_EVENT_SCOPE_THREAD);
 490     TRACE_EVENT_BEGIN0("cat1", "name1");
 491     TRACE_EVENT_END0("cat1", "name2");
 492   }
 493   EndTracing();
 494
 495   scoped_ptr<TraceAnalyzer>
 496       analyzer(TraceAnalyzer::Create(output_.json_output));
 497   ASSERT_TRUE(analyzer.get());
 498   analyzer->AssociateBeginEndEvents();
 499
 500   TraceEventVector found;
 501   analyzer->FindEvents(Query::MatchBeginWithEnd(), &found);
 502   ASSERT_EQ(1u, found.size());
 503   EXPECT_STREQ("name2", found[0]->name.c_str());
 504 }
 505
 506 // Test MergeAssociatedEventArgs
 507 TEST_F(TraceEventAnalyzerTest, MergeAssociatedEventArgs) {
 508   ManualSetUp();
 509
 510   const char arg_string[] = "arg_string";
 511   BeginTracing();
 512   {
 513     TRACE_EVENT_BEGIN0("cat1", "name1");
 514     TRACE_EVENT_END1("cat1", "name1", "arg", arg_string);
 515   }
 516   EndTracing();
 517
 518   scoped_ptr<TraceAnalyzer>
 519       analyzer(TraceAnalyzer::Create(output_.json_output));
 520   ASSERT_TRUE(analyzer.get());
 521   analyzer->AssociateBeginEndEvents();
 522
 523   TraceEventVector found;
 524   analyzer->FindEvents(Query::MatchBeginName("name1"), &found);
 525   ASSERT_EQ(1u, found.size());
 526   std::string arg_actual;
 527   EXPECT_FALSE(found[0]->GetArgAsString("arg", &arg_actual));
 528
 529   analyzer->MergeAssociatedEventArgs();
 530   EXPECT_TRUE(found[0]->GetArgAsString("arg", &arg_actual));
 531   EXPECT_STREQ(arg_string, arg_actual.c_str());
 532 }
 533
 534 // Test AssociateAsyncBeginEndEvents
 535 TEST_F(TraceEventAnalyzerTest, AsyncBeginEndAssocations) {
 536   ManualSetUp();
 537
 538   BeginTracing();
 539   {
 540     TRACE_EVENT_ASYNC_END0("cat1", "name1", 0xA); // no match / out of order
 541     TRACE_EVENT_ASYNC_BEGIN0("cat1", "name1", 0xB);
 542     TRACE_EVENT_ASYNC_BEGIN0("cat1", "name1", 0xC);
 543     TRACE_EVENT_INSTANT0("cat1", "name1", TRACE_EVENT_SCOPE_THREAD); // noise
 544     TRACE_EVENT0("cat1", "name1"); // noise
 545     TRACE_EVENT_ASYNC_END0("cat1", "name1", 0xB);
 546     TRACE_EVENT_ASYNC_END0("cat1", "name1", 0xC);
 547     TRACE_EVENT_ASYNC_BEGIN0("cat1", "name1", 0xA); // no match / out of order
 548   }
 549   EndTracing();
 550
 551   scoped_ptr<TraceAnalyzer>
 552       analyzer(TraceAnalyzer::Create(output_.json_output));
 553   ASSERT_TRUE(analyzer.get());
 554   analyzer->AssociateAsyncBeginEndEvents();
 555
 556   TraceEventVector found;
 557   analyzer->FindEvents(Query::MatchAsyncBeginWithNext(), &found);
 558   ASSERT_EQ(2u, found.size());
 559   EXPECT_STRCASEEQ("0xb", found[0]->id.c_str());
 560   EXPECT_STRCASEEQ("0xc", found[1]->id.c_str());
 561 }
 562
 563 // Test AssociateAsyncBeginEndEvents
 564 TEST_F(TraceEventAnalyzerTest, AsyncBeginEndAssocationsWithSteps) {
 565   ManualSetUp();
 566
 567   BeginTracing();
 568   {
 569     TRACE_EVENT_ASYNC_STEP_INTO0("c", "n", 0xA, "s1");
 570     TRACE_EVENT_ASYNC_END0("c", "n", 0xA);
 571     TRACE_EVENT_ASYNC_BEGIN0("c", "n", 0xB);
 572     TRACE_EVENT_ASYNC_BEGIN0("c", "n", 0xC);
 573     TRACE_EVENT_ASYNC_STEP_PAST0("c", "n", 0xB, "s1");
 574     TRACE_EVENT_ASYNC_STEP_INTO0("c", "n", 0xC, "s1");
 575     TRACE_EVENT_ASYNC_STEP_INTO1("c", "n", 0xC, "s2", "a", 1);
 576     TRACE_EVENT_ASYNC_END0("c", "n", 0xB);
 577     TRACE_EVENT_ASYNC_END0("c", "n", 0xC);
 578     TRACE_EVENT_ASYNC_BEGIN0("c", "n", 0xA);
 579     TRACE_EVENT_ASYNC_STEP_INTO0("c", "n", 0xA, "s2");
 580   }
 581   EndTracing();
 582
 583   scoped_ptr<TraceAnalyzer>
 584       analyzer(TraceAnalyzer::Create(output_.json_output));
 585   ASSERT_TRUE(analyzer.get());
 586   analyzer->AssociateAsyncBeginEndEvents();
 587
 588   TraceEventVector found;
 589   analyzer->FindEvents(Query::MatchAsyncBeginWithNext(), &found);
 590   ASSERT_EQ(3u, found.size());
 591
 592   EXPECT_STRCASEEQ("0xb", found[0]->id.c_str());
 593   EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP_PAST, found[0]->other_event->phase);
 594   EXPECT_TRUE(found[0]->other_event->other_event);
 595   EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_END,
 596             found[0]->other_event->other_event->phase);
 597
 598   EXPECT_STRCASEEQ("0xc", found[1]->id.c_str());
 599   EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP_INTO, found[1]->other_event->phase);
 600   EXPECT_TRUE(found[1]->other_event->other_event);
 601   EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP_INTO,
 602             found[1]->other_event->other_event->phase);
 603   double arg_actual = 0;
 604   EXPECT_TRUE(found[1]->other_event->other_event->GetArgAsNumber(
 605                   "a", &arg_actual));
 606   EXPECT_EQ(1.0, arg_actual);
 607   EXPECT_TRUE(found[1]->other_event->other_event->other_event);
 608   EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_END,
 609             found[1]->other_event->other_event->other_event->phase);
 610
 611   EXPECT_STRCASEEQ("0xa", found[2]->id.c_str());
 612   EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP_INTO, found[2]->other_event->phase);
 613 }
 614
 615 // Test that the TraceAnalyzer custom associations work.
 616 TEST_F(TraceEventAnalyzerTest, CustomAssociations) {
 617   ManualSetUp();
 618
 619   // Add events that begin/end in pipelined ordering with unique ID parameter
 620   // to match up the begin/end pairs.
 621   BeginTracing();
 622   {
 623     // no begin match
 624     TRACE_EVENT_INSTANT1("cat1", "end", TRACE_EVENT_SCOPE_THREAD, "id", 1);
 625     // end is cat4
 626     TRACE_EVENT_INSTANT1("cat2", "begin", TRACE_EVENT_SCOPE_THREAD, "id", 2);
 627     // end is cat5
 628     TRACE_EVENT_INSTANT1("cat3", "begin", TRACE_EVENT_SCOPE_THREAD, "id", 3);
 629     TRACE_EVENT_INSTANT1("cat4", "end", TRACE_EVENT_SCOPE_THREAD, "id", 2);
 630     TRACE_EVENT_INSTANT1("cat5", "end", TRACE_EVENT_SCOPE_THREAD, "id", 3);
 631     // no end match
 632     TRACE_EVENT_INSTANT1("cat6", "begin", TRACE_EVENT_SCOPE_THREAD, "id", 1);
 633   }
 634   EndTracing();
 635
 636   scoped_ptr<TraceAnalyzer>
 637       analyzer(TraceAnalyzer::Create(output_.json_output));
 638   ASSERT_TRUE(analyzer.get());
 639
 640   // begin, end, and match queries to find proper begin/end pairs.
 641   Query begin(Query::EventName() == Query::String("begin"));
 642   Query end(Query::EventName() == Query::String("end"));
 643   Query match(Query::EventArg("id") == Query::OtherArg("id"));
 644   analyzer->AssociateEvents(begin, end, match);
 645
 646   TraceEventVector found;
 647
 648   // cat1 has no other_event.
 649   analyzer->FindEvents(Query::EventCategory() == Query::String("cat1") &&
 650                        Query::EventHasOther(), &found);
 651   EXPECT_EQ(0u, found.size());
 652
 653   // cat1 has no other_event.
 654   analyzer->FindEvents(Query::EventCategory() == Query::String("cat1") &&
 655                        !Query::EventHasOther(), &found);
 656   EXPECT_EQ(1u, found.size());
 657
 658   // cat6 has no other_event.
 659   analyzer->FindEvents(Query::EventCategory() == Query::String("cat6") &&
 660                        !Query::EventHasOther(), &found);
 661   EXPECT_EQ(1u, found.size());
 662
 663   // cat2 and cat4 are associated.
 664   analyzer->FindEvents(Query::EventCategory() == Query::String("cat2") &&
 665                        Query::OtherCategory() == Query::String("cat4"), &found);
 666   EXPECT_EQ(1u, found.size());
 667
 668   // cat4 and cat2 are not associated.
 669   analyzer->FindEvents(Query::EventCategory() == Query::String("cat4") &&
 670                        Query::OtherCategory() == Query::String("cat2"), &found);
 671   EXPECT_EQ(0u, found.size());
 672
 673   // cat3 and cat5 are associated.
 674   analyzer->FindEvents(Query::EventCategory() == Query::String("cat3") &&
 675                        Query::OtherCategory() == Query::String("cat5"), &found);
 676   EXPECT_EQ(1u, found.size());
 677
 678   // cat5 and cat3 are not associated.
 679   analyzer->FindEvents(Query::EventCategory() == Query::String("cat5") &&
 680                        Query::OtherCategory() == Query::String("cat3"), &found);
 681   EXPECT_EQ(0u, found.size());
 682 }
 683
 684 // Verify that Query literals and types are properly casted.
 685 TEST_F(TraceEventAnalyzerTest, Literals) {
 686   ManualSetUp();
 687
 688   // Since these queries don't refer to the event data, the dummy event below
 689   // will never be accessed.
 690   TraceEvent dummy;
 691   char char_num = 5;
 692   short short_num = -5;
 693   EXPECT_TRUE((Query::Double(5.0) == Query::Int(char_num)).Evaluate(dummy));
 694   EXPECT_TRUE((Query::Double(-5.0) == Query::Int(short_num)).Evaluate(dummy));
 695   EXPECT_TRUE((Query::Double(1.0) == Query::Uint(1u)).Evaluate(dummy));
 696   EXPECT_TRUE((Query::Double(1.0) == Query::Int(1)).Evaluate(dummy));
 697   EXPECT_TRUE((Query::Double(-1.0) == Query::Int(-1)).Evaluate(dummy));
 698   EXPECT_TRUE((Query::Double(1.0) == Query::Double(1.0f)).Evaluate(dummy));
 699   EXPECT_TRUE((Query::Bool(true) == Query::Int(1)).Evaluate(dummy));
 700   EXPECT_TRUE((Query::Bool(false) == Query::Int(0)).Evaluate(dummy));
 701   EXPECT_TRUE((Query::Bool(true) == Query::Double(1.0f)).Evaluate(dummy));
 702   EXPECT_TRUE((Query::Bool(false) == Query::Double(0.0f)).Evaluate(dummy));
 703 }
 704
 705 // Test GetRateStats.
 706 TEST_F(TraceEventAnalyzerTest, RateStats) {
 707   std::vector<TraceEvent> events;
 708   events.reserve(100);
 709   TraceEventVector event_ptrs;
 710   TraceEvent event;
 711   event.timestamp = 0.0;
 712   double little_delta = 1.0;
 713   double big_delta = 10.0;
 714   double tiny_delta = 0.1;
 715   RateStats stats;
 716   RateStatsOptions options;
 717
 718   // Insert 10 events, each apart by little_delta.
 719   for (int i = 0; i < 10; ++i) {
 720     event.timestamp += little_delta;
 721     events.push_back(event);
 722     event_ptrs.push_back(&events.back());
 723   }
 724
 725   ASSERT_TRUE(GetRateStats(event_ptrs, &stats, NULL));
 726   EXPECT_EQ(little_delta, stats.mean_us);
 727   EXPECT_EQ(little_delta, stats.min_us);
 728   EXPECT_EQ(little_delta, stats.max_us);
 729   EXPECT_EQ(0.0, stats.standard_deviation_us);
 730
 731   // Add an event apart by big_delta.
 732   event.timestamp += big_delta;
 733   events.push_back(event);
 734   event_ptrs.push_back(&events.back());
 735
 736   ASSERT_TRUE(GetRateStats(event_ptrs, &stats, NULL));
 737   EXPECT_LT(little_delta, stats.mean_us);
 738   EXPECT_EQ(little_delta, stats.min_us);
 739   EXPECT_EQ(big_delta, stats.max_us);
 740   EXPECT_LT(0.0, stats.standard_deviation_us);
 741
 742   // Trim off the biggest delta and verify stats.
 743   options.trim_min = 0;
 744   options.trim_max = 1;
 745   ASSERT_TRUE(GetRateStats(event_ptrs, &stats, &options));
 746   EXPECT_EQ(little_delta, stats.mean_us);
 747   EXPECT_EQ(little_delta, stats.min_us);
 748   EXPECT_EQ(little_delta, stats.max_us);
 749   EXPECT_EQ(0.0, stats.standard_deviation_us);
 750
 751   // Add an event apart by tiny_delta.
 752   event.timestamp += tiny_delta;
 753   events.push_back(event);
 754   event_ptrs.push_back(&events.back());
 755
 756   // Trim off both the biggest and tiniest delta and verify stats.
 757   options.trim_min = 1;
 758   options.trim_max = 1;
 759   ASSERT_TRUE(GetRateStats(event_ptrs, &stats, &options));
 760   EXPECT_EQ(little_delta, stats.mean_us);
 761   EXPECT_EQ(little_delta, stats.min_us);
 762   EXPECT_EQ(little_delta, stats.max_us);
 763   EXPECT_EQ(0.0, stats.standard_deviation_us);
 764
 765   // Verify smallest allowed number of events.
 766   TraceEventVector few_event_ptrs;
 767   few_event_ptrs.push_back(&event);
 768   few_event_ptrs.push_back(&event);
 769   ASSERT_FALSE(GetRateStats(few_event_ptrs, &stats, NULL));
 770   few_event_ptrs.push_back(&event);
 771   ASSERT_TRUE(GetRateStats(few_event_ptrs, &stats, NULL));
 772
 773   // Trim off more than allowed and verify failure.
 774   options.trim_min = 0;
 775   options.trim_max = 1;
 776   ASSERT_FALSE(GetRateStats(few_event_ptrs, &stats, &options));
 777 }
 778
 779 // Test FindFirstOf and FindLastOf.
 780 TEST_F(TraceEventAnalyzerTest, FindOf) {
 781   size_t num_events = 100;
 782   size_t index = 0;
 783   TraceEventVector event_ptrs;
 784   EXPECT_FALSE(FindFirstOf(event_ptrs, Query::Bool(true), 0, &index));
 785   EXPECT_FALSE(FindFirstOf(event_ptrs, Query::Bool(true), 10, &index));
 786   EXPECT_FALSE(FindLastOf(event_ptrs, Query::Bool(true), 0, &index));
 787   EXPECT_FALSE(FindLastOf(event_ptrs, Query::Bool(true), 10, &index));
 788
 789   std::vector<TraceEvent> events;
 790   events.resize(num_events);
 791   for (size_t i = 0; i < events.size(); ++i)
 792     event_ptrs.push_back(&events[i]);
 793   size_t bam_index = num_events/2;
 794   events[bam_index].name = "bam";
 795   Query query_bam = Query::EventName() == Query::String(events[bam_index].name);
 796
 797   // FindFirstOf
 798   EXPECT_FALSE(FindFirstOf(event_ptrs, Query::Bool(false), 0, &index));
 799   EXPECT_TRUE(FindFirstOf(event_ptrs, Query::Bool(true), 0, &index));
 800   EXPECT_EQ(0u, index);
 801   EXPECT_TRUE(FindFirstOf(event_ptrs, Query::Bool(true), 5, &index));
 802   EXPECT_EQ(5u, index);
 803
 804   EXPECT_FALSE(FindFirstOf(event_ptrs, query_bam, bam_index + 1, &index));
 805   EXPECT_TRUE(FindFirstOf(event_ptrs, query_bam, 0, &index));
 806   EXPECT_EQ(bam_index, index);
 807   EXPECT_TRUE(FindFirstOf(event_ptrs, query_bam, bam_index, &index));
 808   EXPECT_EQ(bam_index, index);
 809
 810   // FindLastOf
 811   EXPECT_FALSE(FindLastOf(event_ptrs, Query::Bool(false), 1000, &index));
 812   EXPECT_TRUE(FindLastOf(event_ptrs, Query::Bool(true), 1000, &index));
 813   EXPECT_EQ(num_events - 1, index);
 814   EXPECT_TRUE(FindLastOf(event_ptrs, Query::Bool(true), num_events - 5,
 815                          &index));
 816   EXPECT_EQ(num_events - 5, index);
 817
 818   EXPECT_FALSE(FindLastOf(event_ptrs, query_bam, bam_index - 1, &index));
 819   EXPECT_TRUE(FindLastOf(event_ptrs, query_bam, num_events, &index));
 820   EXPECT_EQ(bam_index, index);
 821   EXPECT_TRUE(FindLastOf(event_ptrs, query_bam, bam_index, &index));
 822   EXPECT_EQ(bam_index, index);
 823 }
 824
 825 // Test FindClosest.
 826 TEST_F(TraceEventAnalyzerTest, FindClosest) {
 827   size_t index_1 = 0;
 828   size_t index_2 = 0;
 829   TraceEventVector event_ptrs;
 830   EXPECT_FALSE(FindClosest(event_ptrs, Query::Bool(true), 0,
 831                            &index_1, &index_2));
 832
 833   size_t num_events = 5;
 834   std::vector<TraceEvent> events;
 835   events.resize(num_events);
 836   for (size_t i = 0; i < events.size(); ++i) {
 837     // timestamps go up exponentially so the lower index is always closer in
 838     // time than the higher index.
 839     events[i].timestamp = static_cast<double>(i) * static_cast<double>(i);
 840     event_ptrs.push_back(&events[i]);
 841   }
 842   events[0].name = "one";
 843   events[2].name = "two";
 844   events[4].name = "three";
 845   Query query_named = Query::EventName() != Query::String(std::string());
 846   Query query_one = Query::EventName() == Query::String("one");
 847
 848   // Only one event matches query_one, so two closest can't be found.
 849   EXPECT_FALSE(FindClosest(event_ptrs, query_one, 0, &index_1, &index_2));
 850
 851   EXPECT_TRUE(FindClosest(event_ptrs, query_one, 3, &index_1, NULL));
 852   EXPECT_EQ(0u, index_1);
 853
 854   EXPECT_TRUE(FindClosest(event_ptrs, query_named, 1, &index_1, &index_2));
 855   EXPECT_EQ(0u, index_1);
 856   EXPECT_EQ(2u, index_2);
 857
 858   EXPECT_TRUE(FindClosest(event_ptrs, query_named, 4, &index_1, &index_2));
 859   EXPECT_EQ(4u, index_1);
 860   EXPECT_EQ(2u, index_2);
 861
 862   EXPECT_TRUE(FindClosest(event_ptrs, query_named, 3, &index_1, &index_2));
 863   EXPECT_EQ(2u, index_1);
 864   EXPECT_EQ(0u, index_2);
 865 }
 866
 867 // Test CountMatches.
 868 TEST_F(TraceEventAnalyzerTest, CountMatches) {
 869   TraceEventVector event_ptrs;
 870   EXPECT_EQ(0u, CountMatches(event_ptrs, Query::Bool(true), 0, 10));
 871
 872   size_t num_events = 5;
 873   size_t num_named = 3;
 874   std::vector<TraceEvent> events;
 875   events.resize(num_events);
 876   for (size_t i = 0; i < events.size(); ++i)
 877     event_ptrs.push_back(&events[i]);
 878   events[0].name = "one";
 879   events[2].name = "two";
 880   events[4].name = "three";
 881   Query query_named = Query::EventName() != Query::String(std::string());
 882   Query query_one = Query::EventName() == Query::String("one");
 883
 884   EXPECT_EQ(0u, CountMatches(event_ptrs, Query::Bool(false)));
 885   EXPECT_EQ(num_events, CountMatches(event_ptrs, Query::Bool(true)));
 886   EXPECT_EQ(num_events - 1, CountMatches(event_ptrs, Query::Bool(true),
 887                                          1, num_events));
 888   EXPECT_EQ(1u, CountMatches(event_ptrs, query_one));
 889   EXPECT_EQ(num_events - 1, CountMatches(event_ptrs, !query_one));
 890   EXPECT_EQ(num_named, CountMatches(event_ptrs, query_named));
 891 }
 892
 893
 894 }  // namespace trace_analyzer