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