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