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->as_string());
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.
TEST_F(TraceEventAnalyzerTest,CompleteDuration)410 TEST_F(TraceEventAnalyzerTest, CompleteDuration) {
411 ManualSetUp();
412
413 const base::TimeDelta kSleepTime = base::Milliseconds(200);
414 // We will search for events that have a duration of greater than 90% of the
415 // sleep time, so that there is no flakiness.
416 int64_t duration_cutoff_us = (kSleepTime.InMicroseconds() * 9) / 10;
417
418 BeginTracing();
419 {
420 TRACE_EVENT0("cat1", "name1"); // found by duration query
421 TRACE_EVENT0("noise", "name2"); // not searched for, just noise
422 {
423 TRACE_EVENT0("cat2", "name3"); // found by duration query
424 // next event not searched for, just noise
425 TRACE_EVENT_INSTANT0("noise", "name4", TRACE_EVENT_SCOPE_THREAD);
426 base::PlatformThread::Sleep(kSleepTime);
427 TRACE_EVENT0("cat2", "name5"); // not found (duration too short)
428 }
429 }
430 EndTracing();
431
432 std::unique_ptr<TraceAnalyzer> analyzer(
433 TraceAnalyzer::Create(output_.json_output));
434 ASSERT_TRUE(analyzer.get());
435 analyzer->AssociateBeginEndEvents();
436
437 TraceEventVector found;
438 analyzer->FindEvents(
439 Query::EventCompleteDuration() >
440 Query::Int(static_cast<int>(duration_cutoff_us)) &&
441 (Query::EventCategory() == Query::String("cat1") ||
442 Query::EventCategory() == Query::String("cat2") ||
443 Query::EventCategory() == Query::String("cat3")),
444 &found);
445 ASSERT_EQ(2u, found.size());
446 EXPECT_STREQ("name1", found[0]->name.c_str());
447 EXPECT_STREQ("name3", found[1]->name.c_str());
448 }
449
450 // Test AssociateAsyncBeginEndEvents
TEST_F(TraceEventAnalyzerTest,AsyncBeginEndAssocations)451 TEST_F(TraceEventAnalyzerTest, AsyncBeginEndAssocations) {
452 ManualSetUp();
453
454 BeginTracing();
455 {
456 TRACE_EVENT_ASYNC_END0("cat1", "name1", 0xA); // no match / out of order
457 TRACE_EVENT_ASYNC_BEGIN0("cat1", "name1", 0xB);
458 TRACE_EVENT_ASYNC_BEGIN0("cat1", "name1", 0xC);
459 TRACE_EVENT_INSTANT0("cat1", "name1", TRACE_EVENT_SCOPE_THREAD); // noise
460 TRACE_EVENT0("cat1", "name1"); // noise
461 TRACE_EVENT_ASYNC_END0("cat1", "name1", 0xB);
462 TRACE_EVENT_ASYNC_END0("cat1", "name1", 0xC);
463 TRACE_EVENT_ASYNC_BEGIN0("cat1", "name1", 0xA); // no match / out of order
464 }
465 EndTracing();
466
467 std::unique_ptr<TraceAnalyzer> analyzer(
468 TraceAnalyzer::Create(output_.json_output));
469 ASSERT_TRUE(analyzer.get());
470 analyzer->AssociateAsyncBeginEndEvents();
471
472 TraceEventVector found;
473 analyzer->FindEvents(Query::MatchAsyncBeginWithNext(), &found);
474 ASSERT_EQ(2u, found.size());
475 EXPECT_STRCASEEQ("0xb", found[0]->id.c_str());
476 EXPECT_STRCASEEQ("0xc", found[1]->id.c_str());
477 }
478
479 // Test AssociateAsyncBeginEndEvents
TEST_F(TraceEventAnalyzerTest,AsyncBeginEndAssocationsWithSteps)480 TEST_F(TraceEventAnalyzerTest, AsyncBeginEndAssocationsWithSteps) {
481 ManualSetUp();
482
483 BeginTracing();
484 {
485 TRACE_EVENT_ASYNC_STEP_INTO0("cat", "n", 0xA, "s1");
486 TRACE_EVENT_ASYNC_END0("cat", "n", 0xA);
487 TRACE_EVENT_ASYNC_BEGIN0("cat", "n", 0xB);
488 TRACE_EVENT_ASYNC_BEGIN0("cat", "n", 0xC);
489 TRACE_EVENT_ASYNC_STEP_PAST0("cat", "n", 0xB, "s1");
490 TRACE_EVENT_ASYNC_STEP_INTO0("cat", "n", 0xC, "s1");
491 TRACE_EVENT_ASYNC_STEP_INTO1("cat", "n", 0xC, "s2", "a", 1);
492 TRACE_EVENT_ASYNC_END0("cat", "n", 0xB);
493 TRACE_EVENT_ASYNC_END0("cat", "n", 0xC);
494 TRACE_EVENT_ASYNC_BEGIN0("cat", "n", 0xA);
495 TRACE_EVENT_ASYNC_STEP_INTO0("cat", "n", 0xA, "s2");
496 }
497 EndTracing();
498
499 std::unique_ptr<TraceAnalyzer> analyzer(
500 TraceAnalyzer::Create(output_.json_output));
501 ASSERT_TRUE(analyzer.get());
502 analyzer->AssociateAsyncBeginEndEvents();
503
504 TraceEventVector found;
505 analyzer->FindEvents(Query::MatchAsyncBeginWithNext(), &found);
506 ASSERT_EQ(3u, found.size());
507
508 EXPECT_STRCASEEQ("0xb", found[0]->id.c_str());
509 EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP_PAST, found[0]->other_event->phase);
510 EXPECT_EQ(found[0], found[0]->other_event->prev_event);
511 EXPECT_TRUE(found[0]->other_event->other_event);
512 EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_END,
513 found[0]->other_event->other_event->phase);
514 EXPECT_EQ(found[0]->other_event,
515 found[0]->other_event->other_event->prev_event);
516
517 EXPECT_STRCASEEQ("0xc", found[1]->id.c_str());
518 EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP_INTO, found[1]->other_event->phase);
519 EXPECT_EQ(found[1], found[1]->other_event->prev_event);
520 EXPECT_TRUE(found[1]->other_event->other_event);
521 EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP_INTO,
522 found[1]->other_event->other_event->phase);
523 EXPECT_EQ(found[1]->other_event,
524 found[1]->other_event->other_event->prev_event);
525 double arg_actual = 0;
526 EXPECT_TRUE(found[1]->other_event->other_event->GetArgAsNumber(
527 "a", &arg_actual));
528 EXPECT_EQ(1.0, arg_actual);
529 EXPECT_TRUE(found[1]->other_event->other_event->other_event);
530 EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_END,
531 found[1]->other_event->other_event->other_event->phase);
532
533 EXPECT_STRCASEEQ("0xa", found[2]->id.c_str());
534 EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP_INTO, found[2]->other_event->phase);
535 }
536
537 // Test that the TraceAnalyzer custom associations work.
TEST_F(TraceEventAnalyzerTest,CustomAssociations)538 TEST_F(TraceEventAnalyzerTest, CustomAssociations) {
539 ManualSetUp();
540
541 // Add events that begin/end in pipelined ordering with unique ID parameter
542 // to match up the begin/end pairs.
543 BeginTracing();
544 {
545 // no begin match
546 TRACE_EVENT_INSTANT1("cat1", "end", TRACE_EVENT_SCOPE_THREAD, "id", 1);
547 // end is cat4
548 TRACE_EVENT_INSTANT1("cat2", "begin", TRACE_EVENT_SCOPE_THREAD, "id", 2);
549 // end is cat5
550 TRACE_EVENT_INSTANT1("cat3", "begin", TRACE_EVENT_SCOPE_THREAD, "id", 3);
551 TRACE_EVENT_INSTANT1("cat4", "end", TRACE_EVENT_SCOPE_THREAD, "id", 2);
552 TRACE_EVENT_INSTANT1("cat5", "end", TRACE_EVENT_SCOPE_THREAD, "id", 3);
553 // no end match
554 TRACE_EVENT_INSTANT1("cat6", "begin", TRACE_EVENT_SCOPE_THREAD, "id", 1);
555 }
556 EndTracing();
557
558 std::unique_ptr<TraceAnalyzer> analyzer(
559 TraceAnalyzer::Create(output_.json_output));
560 ASSERT_TRUE(analyzer.get());
561
562 // begin, end, and match queries to find proper begin/end pairs.
563 Query begin(Query::EventName() == Query::String("begin"));
564 Query end(Query::EventName() == Query::String("end"));
565 Query match(Query::EventArg("id") == Query::OtherArg("id"));
566 analyzer->AssociateEvents(begin, end, match);
567
568 TraceEventVector found;
569
570 // cat1 has no other_event.
571 analyzer->FindEvents(Query::EventCategory() == Query::String("cat1") &&
572 Query::EventHasOther(), &found);
573 EXPECT_EQ(0u, found.size());
574
575 // cat1 has no other_event.
576 analyzer->FindEvents(Query::EventCategory() == Query::String("cat1") &&
577 !Query::EventHasOther(), &found);
578 EXPECT_EQ(1u, found.size());
579
580 // cat6 has no other_event.
581 analyzer->FindEvents(Query::EventCategory() == Query::String("cat6") &&
582 !Query::EventHasOther(), &found);
583 EXPECT_EQ(1u, found.size());
584
585 // cat2 and cat4 are associated.
586 analyzer->FindEvents(Query::EventCategory() == Query::String("cat2") &&
587 Query::OtherCategory() == Query::String("cat4"), &found);
588 EXPECT_EQ(1u, found.size());
589
590 // cat4 and cat2 are not associated.
591 analyzer->FindEvents(Query::EventCategory() == Query::String("cat4") &&
592 Query::OtherCategory() == Query::String("cat2"), &found);
593 EXPECT_EQ(0u, found.size());
594
595 // cat3 and cat5 are associated.
596 analyzer->FindEvents(Query::EventCategory() == Query::String("cat3") &&
597 Query::OtherCategory() == Query::String("cat5"), &found);
598 EXPECT_EQ(1u, found.size());
599
600 // cat5 and cat3 are not associated.
601 analyzer->FindEvents(Query::EventCategory() == Query::String("cat5") &&
602 Query::OtherCategory() == Query::String("cat3"), &found);
603 EXPECT_EQ(0u, found.size());
604 }
605
606 // Verify that Query literals and types are properly casted.
TEST_F(TraceEventAnalyzerTest,Literals)607 TEST_F(TraceEventAnalyzerTest, Literals) {
608 ManualSetUp();
609
610 // Since these queries don't refer to the event data, the dummy event below
611 // will never be accessed.
612 TraceEvent dummy;
613 char char_num = 5;
614 short short_num = -5;
615 EXPECT_TRUE((Query::Double(5.0) == Query::Int(char_num)).Evaluate(dummy));
616 EXPECT_TRUE((Query::Double(-5.0) == Query::Int(short_num)).Evaluate(dummy));
617 EXPECT_TRUE((Query::Double(1.0) == Query::Uint(1u)).Evaluate(dummy));
618 EXPECT_TRUE((Query::Double(1.0) == Query::Int(1)).Evaluate(dummy));
619 EXPECT_TRUE((Query::Double(-1.0) == Query::Int(-1)).Evaluate(dummy));
620 EXPECT_TRUE((Query::Double(1.0) == Query::Double(1.0f)).Evaluate(dummy));
621 EXPECT_TRUE((Query::Bool(true) == Query::Int(1)).Evaluate(dummy));
622 EXPECT_TRUE((Query::Bool(false) == Query::Int(0)).Evaluate(dummy));
623 EXPECT_TRUE((Query::Bool(true) == Query::Double(1.0f)).Evaluate(dummy));
624 EXPECT_TRUE((Query::Bool(false) == Query::Double(0.0f)).Evaluate(dummy));
625 }
626
627 // Test GetRateStats.
TEST_F(TraceEventAnalyzerTest,RateStats)628 TEST_F(TraceEventAnalyzerTest, RateStats) {
629 std::vector<TraceEvent> events;
630 events.reserve(100);
631 TraceEventVector event_ptrs;
632 double timestamp = 0.0;
633 double little_delta = 1.0;
634 double big_delta = 10.0;
635 double tiny_delta = 0.1;
636 RateStats stats;
637 RateStatsOptions options;
638
639 // Insert 10 events, each apart by little_delta.
640 for (int i = 0; i < 10; ++i) {
641 timestamp += little_delta;
642 TraceEvent event;
643 event.timestamp = timestamp;
644 events.push_back(std::move(event));
645 event_ptrs.push_back(&events.back());
646 }
647
648 ASSERT_TRUE(GetRateStats(event_ptrs, &stats, nullptr));
649 EXPECT_EQ(little_delta, stats.mean_us);
650 EXPECT_EQ(little_delta, stats.min_us);
651 EXPECT_EQ(little_delta, stats.max_us);
652 EXPECT_EQ(0.0, stats.standard_deviation_us);
653
654 // Add an event apart by big_delta.
655 {
656 timestamp += big_delta;
657 TraceEvent event;
658 event.timestamp = timestamp;
659 events.push_back(std::move(event));
660 event_ptrs.push_back(&events.back());
661 }
662
663 ASSERT_TRUE(GetRateStats(event_ptrs, &stats, nullptr));
664 EXPECT_LT(little_delta, stats.mean_us);
665 EXPECT_EQ(little_delta, stats.min_us);
666 EXPECT_EQ(big_delta, stats.max_us);
667 EXPECT_LT(0.0, stats.standard_deviation_us);
668
669 // Trim off the biggest delta and verify stats.
670 options.trim_min = 0;
671 options.trim_max = 1;
672 ASSERT_TRUE(GetRateStats(event_ptrs, &stats, &options));
673 EXPECT_EQ(little_delta, stats.mean_us);
674 EXPECT_EQ(little_delta, stats.min_us);
675 EXPECT_EQ(little_delta, stats.max_us);
676 EXPECT_EQ(0.0, stats.standard_deviation_us);
677
678 // Add an event apart by tiny_delta.
679 {
680 timestamp += tiny_delta;
681 TraceEvent event;
682 event.timestamp = timestamp;
683 events.push_back(std::move(event));
684 event_ptrs.push_back(&events.back());
685 }
686
687 // Trim off both the biggest and tiniest delta and verify stats.
688 options.trim_min = 1;
689 options.trim_max = 1;
690 ASSERT_TRUE(GetRateStats(event_ptrs, &stats, &options));
691 EXPECT_EQ(little_delta, stats.mean_us);
692 EXPECT_EQ(little_delta, stats.min_us);
693 EXPECT_EQ(little_delta, stats.max_us);
694 EXPECT_EQ(0.0, stats.standard_deviation_us);
695
696 // Verify smallest allowed number of events.
697 {
698 TraceEvent event;
699 TraceEventVector few_event_ptrs;
700 few_event_ptrs.push_back(&event);
701 few_event_ptrs.push_back(&event);
702 ASSERT_FALSE(GetRateStats(few_event_ptrs, &stats, nullptr));
703 few_event_ptrs.push_back(&event);
704 ASSERT_TRUE(GetRateStats(few_event_ptrs, &stats, nullptr));
705
706 // Trim off more than allowed and verify failure.
707 options.trim_min = 0;
708 options.trim_max = 1;
709 ASSERT_FALSE(GetRateStats(few_event_ptrs, &stats, &options));
710 }
711 }
712
713 // Test FindFirstOf and FindLastOf.
TEST_F(TraceEventAnalyzerTest,FindOf)714 TEST_F(TraceEventAnalyzerTest, FindOf) {
715 size_t num_events = 100;
716 size_t index = 0;
717 TraceEventVector event_ptrs;
718 EXPECT_FALSE(FindFirstOf(event_ptrs, Query::Bool(true), 0, &index));
719 EXPECT_FALSE(FindFirstOf(event_ptrs, Query::Bool(true), 10, &index));
720 EXPECT_FALSE(FindLastOf(event_ptrs, Query::Bool(true), 0, &index));
721 EXPECT_FALSE(FindLastOf(event_ptrs, Query::Bool(true), 10, &index));
722
723 std::vector<TraceEvent> events;
724 events.resize(num_events);
725 for (auto& i : events)
726 event_ptrs.push_back(&i);
727 size_t bam_index = num_events/2;
728 events[bam_index].name = "bam";
729 Query query_bam = Query::EventName() == Query::String(events[bam_index].name);
730
731 // FindFirstOf
732 EXPECT_FALSE(FindFirstOf(event_ptrs, Query::Bool(false), 0, &index));
733 EXPECT_TRUE(FindFirstOf(event_ptrs, Query::Bool(true), 0, &index));
734 EXPECT_EQ(0u, index);
735 EXPECT_TRUE(FindFirstOf(event_ptrs, Query::Bool(true), 5, &index));
736 EXPECT_EQ(5u, index);
737
738 EXPECT_FALSE(FindFirstOf(event_ptrs, query_bam, bam_index + 1, &index));
739 EXPECT_TRUE(FindFirstOf(event_ptrs, query_bam, 0, &index));
740 EXPECT_EQ(bam_index, index);
741 EXPECT_TRUE(FindFirstOf(event_ptrs, query_bam, bam_index, &index));
742 EXPECT_EQ(bam_index, index);
743
744 // FindLastOf
745 EXPECT_FALSE(FindLastOf(event_ptrs, Query::Bool(false), 1000, &index));
746 EXPECT_TRUE(FindLastOf(event_ptrs, Query::Bool(true), 1000, &index));
747 EXPECT_EQ(num_events - 1, index);
748 EXPECT_TRUE(FindLastOf(event_ptrs, Query::Bool(true), num_events - 5,
749 &index));
750 EXPECT_EQ(num_events - 5, index);
751
752 EXPECT_FALSE(FindLastOf(event_ptrs, query_bam, bam_index - 1, &index));
753 EXPECT_TRUE(FindLastOf(event_ptrs, query_bam, num_events, &index));
754 EXPECT_EQ(bam_index, index);
755 EXPECT_TRUE(FindLastOf(event_ptrs, query_bam, bam_index, &index));
756 EXPECT_EQ(bam_index, index);
757 }
758
759 // Test FindClosest.
TEST_F(TraceEventAnalyzerTest,FindClosest)760 TEST_F(TraceEventAnalyzerTest, FindClosest) {
761 size_t index_1 = 0;
762 size_t index_2 = 0;
763 TraceEventVector event_ptrs;
764 EXPECT_FALSE(FindClosest(event_ptrs, Query::Bool(true), 0,
765 &index_1, &index_2));
766
767 size_t num_events = 5;
768 std::vector<TraceEvent> events;
769 events.resize(num_events);
770 for (size_t i = 0; i < events.size(); ++i) {
771 // timestamps go up exponentially so the lower index is always closer in
772 // time than the higher index.
773 events[i].timestamp = static_cast<double>(i) * static_cast<double>(i);
774 event_ptrs.push_back(&events[i]);
775 }
776 events[0].name = "one";
777 events[2].name = "two";
778 events[4].name = "three";
779 Query query_named = Query::EventName() != Query::String(std::string());
780 Query query_one = Query::EventName() == Query::String("one");
781
782 // Only one event matches query_one, so two closest can't be found.
783 EXPECT_FALSE(FindClosest(event_ptrs, query_one, 0, &index_1, &index_2));
784
785 EXPECT_TRUE(FindClosest(event_ptrs, query_one, 3, &index_1, nullptr));
786 EXPECT_EQ(0u, index_1);
787
788 EXPECT_TRUE(FindClosest(event_ptrs, query_named, 1, &index_1, &index_2));
789 EXPECT_EQ(0u, index_1);
790 EXPECT_EQ(2u, index_2);
791
792 EXPECT_TRUE(FindClosest(event_ptrs, query_named, 4, &index_1, &index_2));
793 EXPECT_EQ(4u, index_1);
794 EXPECT_EQ(2u, index_2);
795
796 EXPECT_TRUE(FindClosest(event_ptrs, query_named, 3, &index_1, &index_2));
797 EXPECT_EQ(2u, index_1);
798 EXPECT_EQ(0u, index_2);
799 }
800
801 // Test CountMatches.
TEST_F(TraceEventAnalyzerTest,CountMatches)802 TEST_F(TraceEventAnalyzerTest, CountMatches) {
803 TraceEventVector event_ptrs;
804 EXPECT_EQ(0u, CountMatches(event_ptrs, Query::Bool(true), 0, 10));
805
806 size_t num_events = 5;
807 size_t num_named = 3;
808 std::vector<TraceEvent> events;
809 events.resize(num_events);
810 for (auto& i : events)
811 event_ptrs.push_back(&i);
812 events[0].name = "one";
813 events[2].name = "two";
814 events[4].name = "three";
815 Query query_named = Query::EventName() != Query::String(std::string());
816 Query query_one = Query::EventName() == Query::String("one");
817
818 EXPECT_EQ(0u, CountMatches(event_ptrs, Query::Bool(false)));
819 EXPECT_EQ(num_events, CountMatches(event_ptrs, Query::Bool(true)));
820 EXPECT_EQ(num_events - 1, CountMatches(event_ptrs, Query::Bool(true),
821 1, num_events));
822 EXPECT_EQ(1u, CountMatches(event_ptrs, query_one));
823 EXPECT_EQ(num_events - 1, CountMatches(event_ptrs, !query_one));
824 EXPECT_EQ(num_named, CountMatches(event_ptrs, query_named));
825 }
826
TEST_F(TraceEventAnalyzerTest,ComplexArgument)827 TEST_F(TraceEventAnalyzerTest, ComplexArgument) {
828 ManualSetUp();
829
830 BeginTracing();
831 {
832 std::unique_ptr<base::trace_event::TracedValue> value(
833 new base::trace_event::TracedValue);
834 value->SetString("property", "value");
835 TRACE_EVENT1("cat", "name", "arg", std::move(value));
836 }
837 EndTracing();
838
839 std::unique_ptr<TraceAnalyzer> analyzer(
840 TraceAnalyzer::Create(output_.json_output));
841 ASSERT_TRUE(analyzer.get());
842
843 TraceEventVector events;
844 analyzer->FindEvents(Query::EventName() == Query::String("name"), &events);
845
846 EXPECT_EQ(1u, events.size());
847 EXPECT_EQ("cat", events[0]->category);
848 EXPECT_EQ("name", events[0]->name);
849
850 ASSERT_TRUE(events[0]->HasDictArg("arg"));
851 base::Value::Dict arg = events[0]->GetKnownArgAsDict("arg");
852 EXPECT_EQ(std::optional<std::string>("value"),
853 base::OptionalFromPtr(arg.FindString("property")));
854 }
855
TEST_F(TraceEventAnalyzerTest,AssociateNestableAsyncEvents)856 TEST_F(TraceEventAnalyzerTest, AssociateNestableAsyncEvents) {
857 ManualSetUp();
858
859 BeginTracing();
860 {
861 TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0(
862 "cat", "name", 0xA, base::TimeTicks() + base::Milliseconds(100));
863 TRACE_EVENT_BEGIN0("noise", "name2"); // not searched for, just noise
864 TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP0(
865 "cat", "name", 0xA, base::TimeTicks() + base::Milliseconds(200));
866 }
867 EndTracing();
868
869 std::unique_ptr<TraceAnalyzer> analyzer(
870 TraceAnalyzer::Create(output_.json_output));
871 ASSERT_TRUE(analyzer.get());
872 analyzer->AssociateAsyncBeginEndEvents();
873
874 TraceEventVector found;
875 analyzer->FindEvents(
876 Query::EventName() == Query::String("name") &&
877 Query::EventPhaseIs(TRACE_EVENT_PHASE_NESTABLE_ASYNC_BEGIN),
878 &found);
879 ASSERT_EQ(1u, found.size());
880 EXPECT_STREQ("name", found[0]->name.c_str());
881 ASSERT_TRUE(found[0]->has_other_event());
882 EXPECT_EQ(100000, base::ClampRound(found[0]->GetAbsTimeToOtherEvent()));
883 }
884
885 } // namespace trace_analyzer
886