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