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->GetType());
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, NULL));
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, NULL));
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, NULL));
804 few_event_ptrs.push_back(&event);
805 ASSERT_TRUE(GetRateStats(few_event_ptrs, &stats, NULL));
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, NULL));
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