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