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