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.
6 #include "base/debug/trace_event_unittest.h"
7 #include "base/synchronization/waitable_event.h"
8 #include "base/test/trace_event_analyzer.h"
9 #include "testing/gmock/include/gmock/gmock.h"
10 #include "testing/gtest/include/gtest/gtest.h"
12 namespace trace_analyzer {
16 class TraceEventAnalyzerTest : public testing::Test {
19 void OnTraceDataCollected(
20 base::WaitableEvent* flush_complete_event,
21 const scoped_refptr<base::RefCountedString>& json_events_str,
22 bool has_more_events);
26 base::debug::TraceResultBuffer::SimpleOutput output_;
27 base::debug::TraceResultBuffer buffer_;
30 void TraceEventAnalyzerTest::ManualSetUp() {
31 ASSERT_TRUE(base::debug::TraceLog::GetInstance());
32 buffer_.SetOutputCallback(output_.GetCallback());
33 output_.json_output.clear();
36 void TraceEventAnalyzerTest::OnTraceDataCollected(
37 base::WaitableEvent* flush_complete_event,
38 const scoped_refptr<base::RefCountedString>& json_events_str,
39 bool has_more_events) {
40 buffer_.AddFragment(json_events_str->data());
42 flush_complete_event->Signal();
45 void TraceEventAnalyzerTest::BeginTracing() {
46 output_.json_output.clear();
48 base::debug::TraceLog::GetInstance()->SetEnabled(
49 base::debug::CategoryFilter("*"),
50 base::debug::TraceLog::RECORD_UNTIL_FULL);
53 void TraceEventAnalyzerTest::EndTracing() {
54 base::debug::TraceLog::GetInstance()->SetDisabled();
55 base::WaitableEvent flush_complete_event(false, false);
56 base::debug::TraceLog::GetInstance()->Flush(
57 base::Bind(&TraceEventAnalyzerTest::OnTraceDataCollected,
58 base::Unretained(this),
59 base::Unretained(&flush_complete_event)));
60 flush_complete_event.Wait();
66 TEST_F(TraceEventAnalyzerTest, NoEvents) {
69 // Create an empty JSON event string:
73 scoped_ptr<TraceAnalyzer>
74 analyzer(TraceAnalyzer::Create(output_.json_output));
75 ASSERT_TRUE(analyzer.get());
77 // Search for all events and verify that nothing is returned.
78 TraceEventVector found;
79 analyzer->FindEvents(Query::Bool(true), &found);
80 EXPECT_EQ(0u, found.size());
83 TEST_F(TraceEventAnalyzerTest, TraceEvent) {
87 double double_num = 3.5;
88 const char* str = "the string";
91 event.arg_numbers["false"] = 0.0;
92 event.arg_numbers["true"] = 1.0;
93 event.arg_numbers["int"] = static_cast<double>(int_num);
94 event.arg_numbers["double"] = double_num;
95 event.arg_strings["string"] = str;
97 ASSERT_TRUE(event.HasNumberArg("false"));
98 ASSERT_TRUE(event.HasNumberArg("true"));
99 ASSERT_TRUE(event.HasNumberArg("int"));
100 ASSERT_TRUE(event.HasNumberArg("double"));
101 ASSERT_TRUE(event.HasStringArg("string"));
102 ASSERT_FALSE(event.HasNumberArg("notfound"));
103 ASSERT_FALSE(event.HasStringArg("notfound"));
105 EXPECT_FALSE(event.GetKnownArgAsBool("false"));
106 EXPECT_TRUE(event.GetKnownArgAsBool("true"));
107 EXPECT_EQ(int_num, event.GetKnownArgAsInt("int"));
108 EXPECT_EQ(double_num, event.GetKnownArgAsDouble("double"));
109 EXPECT_STREQ(str, event.GetKnownArgAsString("string").c_str());
112 TEST_F(TraceEventAnalyzerTest, QueryEventMember) {
116 event.thread.process_id = 3;
117 event.thread.thread_id = 4;
118 event.timestamp = 1.5;
119 event.phase = TRACE_EVENT_PHASE_BEGIN;
120 event.category = "category";
123 event.arg_numbers["num"] = 7.0;
124 event.arg_strings["str"] = "the string";
126 // Other event with all different members:
128 other.thread.process_id = 5;
129 other.thread.thread_id = 6;
130 other.timestamp = 2.5;
131 other.phase = TRACE_EVENT_PHASE_END;
132 other.category = "category2";
133 other.name = "name2";
135 other.arg_numbers["num2"] = 8.0;
136 other.arg_strings["str2"] = "the string 2";
138 event.other_event = &other;
139 ASSERT_TRUE(event.has_other_event());
140 double duration = event.GetAbsTimeToOtherEvent();
142 Query event_pid = Query::EventPidIs(event.thread.process_id);
143 Query event_tid = Query::EventTidIs(event.thread.thread_id);
144 Query event_time = Query::EventTimeIs(event.timestamp);
145 Query event_duration = Query::EventDurationIs(duration);
146 Query event_phase = Query::EventPhaseIs(event.phase);
147 Query event_category = Query::EventCategoryIs(event.category);
148 Query event_name = Query::EventNameIs(event.name);
149 Query event_id = Query::EventIdIs(event.id);
150 Query event_has_arg1 = Query::EventHasNumberArg("num");
151 Query event_has_arg2 = Query::EventHasStringArg("str");
153 (Query::EventArg("num") == Query::Double(event.arg_numbers["num"]));
155 (Query::EventArg("str") == Query::String(event.arg_strings["str"]));
156 Query event_has_other = Query::EventHasOther();
157 Query other_pid = Query::OtherPidIs(other.thread.process_id);
158 Query other_tid = Query::OtherTidIs(other.thread.thread_id);
159 Query other_time = Query::OtherTimeIs(other.timestamp);
160 Query other_phase = Query::OtherPhaseIs(other.phase);
161 Query other_category = Query::OtherCategoryIs(other.category);
162 Query other_name = Query::OtherNameIs(other.name);
163 Query other_id = Query::OtherIdIs(other.id);
164 Query other_has_arg1 = Query::OtherHasNumberArg("num2");
165 Query other_has_arg2 = Query::OtherHasStringArg("str2");
167 (Query::OtherArg("num2") == Query::Double(other.arg_numbers["num2"]));
169 (Query::OtherArg("str2") == Query::String(other.arg_strings["str2"]));
171 EXPECT_TRUE(event_pid.Evaluate(event));
172 EXPECT_TRUE(event_tid.Evaluate(event));
173 EXPECT_TRUE(event_time.Evaluate(event));
174 EXPECT_TRUE(event_duration.Evaluate(event));
175 EXPECT_TRUE(event_phase.Evaluate(event));
176 EXPECT_TRUE(event_category.Evaluate(event));
177 EXPECT_TRUE(event_name.Evaluate(event));
178 EXPECT_TRUE(event_id.Evaluate(event));
179 EXPECT_TRUE(event_has_arg1.Evaluate(event));
180 EXPECT_TRUE(event_has_arg2.Evaluate(event));
181 EXPECT_TRUE(event_arg1.Evaluate(event));
182 EXPECT_TRUE(event_arg2.Evaluate(event));
183 EXPECT_TRUE(event_has_other.Evaluate(event));
184 EXPECT_TRUE(other_pid.Evaluate(event));
185 EXPECT_TRUE(other_tid.Evaluate(event));
186 EXPECT_TRUE(other_time.Evaluate(event));
187 EXPECT_TRUE(other_phase.Evaluate(event));
188 EXPECT_TRUE(other_category.Evaluate(event));
189 EXPECT_TRUE(other_name.Evaluate(event));
190 EXPECT_TRUE(other_id.Evaluate(event));
191 EXPECT_TRUE(other_has_arg1.Evaluate(event));
192 EXPECT_TRUE(other_has_arg2.Evaluate(event));
193 EXPECT_TRUE(other_arg1.Evaluate(event));
194 EXPECT_TRUE(other_arg2.Evaluate(event));
196 // Evaluate event queries against other to verify the queries fail when the
197 // event members are wrong.
198 EXPECT_FALSE(event_pid.Evaluate(other));
199 EXPECT_FALSE(event_tid.Evaluate(other));
200 EXPECT_FALSE(event_time.Evaluate(other));
201 EXPECT_FALSE(event_duration.Evaluate(other));
202 EXPECT_FALSE(event_phase.Evaluate(other));
203 EXPECT_FALSE(event_category.Evaluate(other));
204 EXPECT_FALSE(event_name.Evaluate(other));
205 EXPECT_FALSE(event_id.Evaluate(other));
206 EXPECT_FALSE(event_has_arg1.Evaluate(other));
207 EXPECT_FALSE(event_has_arg2.Evaluate(other));
208 EXPECT_FALSE(event_arg1.Evaluate(other));
209 EXPECT_FALSE(event_arg2.Evaluate(other));
210 EXPECT_FALSE(event_has_other.Evaluate(other));
213 TEST_F(TraceEventAnalyzerTest, BooleanOperators) {
218 TRACE_EVENT_INSTANT1("cat1", "name1", TRACE_EVENT_SCOPE_THREAD, "num", 1);
219 TRACE_EVENT_INSTANT1("cat1", "name2", TRACE_EVENT_SCOPE_THREAD, "num", 2);
220 TRACE_EVENT_INSTANT1("cat2", "name3", TRACE_EVENT_SCOPE_THREAD, "num", 3);
221 TRACE_EVENT_INSTANT1("cat2", "name4", TRACE_EVENT_SCOPE_THREAD, "num", 4);
225 scoped_ptr<TraceAnalyzer>
226 analyzer(TraceAnalyzer::Create(output_.json_output));
227 ASSERT_TRUE(!!analyzer.get());
229 TraceEventVector found;
233 analyzer->FindEvents(Query::EventCategory() == Query::String("cat1"), &found);
234 ASSERT_EQ(2u, found.size());
235 EXPECT_STREQ("name1", found[0]->name.c_str());
236 EXPECT_STREQ("name2", found[1]->name.c_str());
238 analyzer->FindEvents(Query::EventArg("num") == Query::Int(2), &found);
239 ASSERT_EQ(1u, found.size());
240 EXPECT_STREQ("name2", found[0]->name.c_str());
244 analyzer->FindEvents(Query::EventCategory() != Query::String("cat1"), &found);
245 ASSERT_EQ(2u, found.size());
246 EXPECT_STREQ("name3", found[0]->name.c_str());
247 EXPECT_STREQ("name4", found[1]->name.c_str());
249 analyzer->FindEvents(Query::EventArg("num") != Query::Int(2), &found);
250 ASSERT_EQ(3u, found.size());
251 EXPECT_STREQ("name1", found[0]->name.c_str());
252 EXPECT_STREQ("name3", found[1]->name.c_str());
253 EXPECT_STREQ("name4", found[2]->name.c_str());
256 analyzer->FindEvents(Query::EventArg("num") < Query::Int(2), &found);
257 ASSERT_EQ(1u, found.size());
258 EXPECT_STREQ("name1", found[0]->name.c_str());
261 analyzer->FindEvents(Query::EventArg("num") <= Query::Int(2), &found);
262 ASSERT_EQ(2u, found.size());
263 EXPECT_STREQ("name1", found[0]->name.c_str());
264 EXPECT_STREQ("name2", found[1]->name.c_str());
267 analyzer->FindEvents(Query::EventArg("num") > Query::Int(3), &found);
268 ASSERT_EQ(1u, found.size());
269 EXPECT_STREQ("name4", found[0]->name.c_str());
272 analyzer->FindEvents(Query::EventArg("num") >= Query::Int(4), &found);
273 ASSERT_EQ(1u, found.size());
274 EXPECT_STREQ("name4", found[0]->name.c_str());
277 analyzer->FindEvents(Query::EventName() != Query::String("name1") &&
278 Query::EventArg("num") < Query::Int(3), &found);
279 ASSERT_EQ(1u, found.size());
280 EXPECT_STREQ("name2", found[0]->name.c_str());
283 analyzer->FindEvents(Query::EventName() == Query::String("name1") ||
284 Query::EventArg("num") == Query::Int(3), &found);
285 ASSERT_EQ(2u, found.size());
286 EXPECT_STREQ("name1", found[0]->name.c_str());
287 EXPECT_STREQ("name3", found[1]->name.c_str());
290 analyzer->FindEvents(!(Query::EventName() == Query::String("name1") ||
291 Query::EventArg("num") == Query::Int(3)), &found);
292 ASSERT_EQ(2u, found.size());
293 EXPECT_STREQ("name2", found[0]->name.c_str());
294 EXPECT_STREQ("name4", found[1]->name.c_str());
297 TEST_F(TraceEventAnalyzerTest, ArithmeticOperators) {
302 // These events are searched for:
303 TRACE_EVENT_INSTANT2("cat1", "math1", TRACE_EVENT_SCOPE_THREAD,
305 TRACE_EVENT_INSTANT2("cat1", "math2", TRACE_EVENT_SCOPE_THREAD,
307 // Extra events that never match, for noise:
308 TRACE_EVENT_INSTANT2("noise", "math3", TRACE_EVENT_SCOPE_THREAD,
310 TRACE_EVENT_INSTANT2("noise", "math4", TRACE_EVENT_SCOPE_THREAD,
315 scoped_ptr<TraceAnalyzer>
316 analyzer(TraceAnalyzer::Create(output_.json_output));
317 ASSERT_TRUE(analyzer.get());
319 TraceEventVector found;
321 // Verify that arithmetic operators function:
324 analyzer->FindEvents(Query::EventArg("a") + Query::EventArg("b") ==
325 Query::Int(20), &found);
326 EXPECT_EQ(1u, found.size());
327 EXPECT_STREQ("math2", found.front()->name.c_str());
330 analyzer->FindEvents(Query::EventArg("a") - Query::EventArg("b") ==
331 Query::Int(5), &found);
332 EXPECT_EQ(1u, found.size());
333 EXPECT_STREQ("math1", found.front()->name.c_str());
336 analyzer->FindEvents(Query::EventArg("a") * Query::EventArg("b") ==
337 Query::Int(50), &found);
338 EXPECT_EQ(1u, found.size());
339 EXPECT_STREQ("math1", found.front()->name.c_str());
342 analyzer->FindEvents(Query::EventArg("a") / Query::EventArg("b") ==
343 Query::Int(2), &found);
344 EXPECT_EQ(1u, found.size());
345 EXPECT_STREQ("math1", found.front()->name.c_str());
348 analyzer->FindEvents(Query::EventArg("a") % Query::EventArg("b") ==
349 Query::Int(0), &found);
350 EXPECT_EQ(2u, found.size());
353 analyzer->FindEvents(-Query::EventArg("b") == Query::Int(-10), &found);
354 EXPECT_EQ(1u, found.size());
355 EXPECT_STREQ("math2", found.front()->name.c_str());
358 TEST_F(TraceEventAnalyzerTest, StringPattern) {
363 TRACE_EVENT_INSTANT0("cat1", "name1", TRACE_EVENT_SCOPE_THREAD);
364 TRACE_EVENT_INSTANT0("cat1", "name2", TRACE_EVENT_SCOPE_THREAD);
365 TRACE_EVENT_INSTANT0("cat1", "no match", TRACE_EVENT_SCOPE_THREAD);
366 TRACE_EVENT_INSTANT0("cat1", "name3x", TRACE_EVENT_SCOPE_THREAD);
370 scoped_ptr<TraceAnalyzer>
371 analyzer(TraceAnalyzer::Create(output_.json_output));
372 ASSERT_TRUE(analyzer.get());
374 TraceEventVector found;
376 analyzer->FindEvents(Query::EventName() == Query::Pattern("name?"), &found);
377 ASSERT_EQ(2u, found.size());
378 EXPECT_STREQ("name1", found[0]->name.c_str());
379 EXPECT_STREQ("name2", found[1]->name.c_str());
381 analyzer->FindEvents(Query::EventName() == Query::Pattern("name*"), &found);
382 ASSERT_EQ(3u, found.size());
383 EXPECT_STREQ("name1", found[0]->name.c_str());
384 EXPECT_STREQ("name2", found[1]->name.c_str());
385 EXPECT_STREQ("name3x", found[2]->name.c_str());
387 analyzer->FindEvents(Query::EventName() != Query::Pattern("name*"), &found);
388 ASSERT_EQ(1u, found.size());
389 EXPECT_STREQ("no match", found[0]->name.c_str());
392 // Test that duration queries work.
393 TEST_F(TraceEventAnalyzerTest, BeginEndDuration) {
396 const base::TimeDelta kSleepTime = base::TimeDelta::FromMilliseconds(200);
397 // We will search for events that have a duration of greater than 90% of the
398 // sleep time, so that there is no flakiness.
399 int duration_cutoff_us = (kSleepTime.InMicroseconds() * 9) / 10;
403 TRACE_EVENT_BEGIN0("cat1", "name1"); // found by duration query
404 TRACE_EVENT_BEGIN0("noise", "name2"); // not searched for, just noise
406 TRACE_EVENT_BEGIN0("cat2", "name3"); // found by duration query
407 // next event not searched for, just noise
408 TRACE_EVENT_INSTANT0("noise", "name4", TRACE_EVENT_SCOPE_THREAD);
409 base::debug::HighResSleepForTraceTest(kSleepTime);
410 TRACE_EVENT_BEGIN0("cat2", "name5"); // not found (duration too short)
411 TRACE_EVENT_END0("cat2", "name5"); // not found (duration too short)
412 TRACE_EVENT_END0("cat2", "name3"); // found by duration query
414 TRACE_EVENT_END0("noise", "name2"); // not searched for, just noise
415 TRACE_EVENT_END0("cat1", "name1"); // found by duration query
419 scoped_ptr<TraceAnalyzer>
420 analyzer(TraceAnalyzer::Create(output_.json_output));
421 ASSERT_TRUE(analyzer.get());
422 analyzer->AssociateBeginEndEvents();
424 TraceEventVector found;
425 analyzer->FindEvents(
426 Query::MatchBeginWithEnd() &&
427 Query::EventDuration() > Query::Int(duration_cutoff_us) &&
428 (Query::EventCategory() == Query::String("cat1") ||
429 Query::EventCategory() == Query::String("cat2") ||
430 Query::EventCategory() == Query::String("cat3")),
432 ASSERT_EQ(2u, found.size());
433 EXPECT_STREQ("name1", found[0]->name.c_str());
434 EXPECT_STREQ("name3", found[1]->name.c_str());
437 // Test that duration queries work.
438 TEST_F(TraceEventAnalyzerTest, CompleteDuration) {
441 const base::TimeDelta kSleepTime = base::TimeDelta::FromMilliseconds(200);
442 // We will search for events that have a duration of greater than 90% of the
443 // sleep time, so that there is no flakiness.
444 int duration_cutoff_us = (kSleepTime.InMicroseconds() * 9) / 10;
448 TRACE_EVENT0("cat1", "name1"); // found by duration query
449 TRACE_EVENT0("noise", "name2"); // not searched for, just noise
451 TRACE_EVENT0("cat2", "name3"); // found by duration query
452 // next event not searched for, just noise
453 TRACE_EVENT_INSTANT0("noise", "name4", TRACE_EVENT_SCOPE_THREAD);
454 base::debug::HighResSleepForTraceTest(kSleepTime);
455 TRACE_EVENT0("cat2", "name5"); // not found (duration too short)
460 scoped_ptr<TraceAnalyzer>
461 analyzer(TraceAnalyzer::Create(output_.json_output));
462 ASSERT_TRUE(analyzer.get());
463 analyzer->AssociateBeginEndEvents();
465 TraceEventVector found;
466 analyzer->FindEvents(
467 Query::EventCompleteDuration() > Query::Int(duration_cutoff_us) &&
468 (Query::EventCategory() == Query::String("cat1") ||
469 Query::EventCategory() == Query::String("cat2") ||
470 Query::EventCategory() == Query::String("cat3")),
472 ASSERT_EQ(2u, found.size());
473 EXPECT_STREQ("name1", found[0]->name.c_str());
474 EXPECT_STREQ("name3", found[1]->name.c_str());
477 // Test AssociateBeginEndEvents
478 TEST_F(TraceEventAnalyzerTest, BeginEndAssocations) {
483 TRACE_EVENT_END0("cat1", "name1"); // does not match out of order begin
484 TRACE_EVENT_BEGIN0("cat1", "name2");
485 TRACE_EVENT_INSTANT0("cat1", "name3", TRACE_EVENT_SCOPE_THREAD);
486 TRACE_EVENT_BEGIN0("cat1", "name1");
487 TRACE_EVENT_END0("cat1", "name2");
491 scoped_ptr<TraceAnalyzer>
492 analyzer(TraceAnalyzer::Create(output_.json_output));
493 ASSERT_TRUE(analyzer.get());
494 analyzer->AssociateBeginEndEvents();
496 TraceEventVector found;
497 analyzer->FindEvents(Query::MatchBeginWithEnd(), &found);
498 ASSERT_EQ(1u, found.size());
499 EXPECT_STREQ("name2", found[0]->name.c_str());
502 // Test MergeAssociatedEventArgs
503 TEST_F(TraceEventAnalyzerTest, MergeAssociatedEventArgs) {
506 const char* arg_string = "arg_string";
509 TRACE_EVENT_BEGIN0("cat1", "name1");
510 TRACE_EVENT_END1("cat1", "name1", "arg", arg_string);
514 scoped_ptr<TraceAnalyzer>
515 analyzer(TraceAnalyzer::Create(output_.json_output));
516 ASSERT_TRUE(analyzer.get());
517 analyzer->AssociateBeginEndEvents();
519 TraceEventVector found;
520 analyzer->FindEvents(Query::MatchBeginName("name1"), &found);
521 ASSERT_EQ(1u, found.size());
522 std::string arg_actual;
523 EXPECT_FALSE(found[0]->GetArgAsString("arg", &arg_actual));
525 analyzer->MergeAssociatedEventArgs();
526 EXPECT_TRUE(found[0]->GetArgAsString("arg", &arg_actual));
527 EXPECT_STREQ(arg_string, arg_actual.c_str());
530 // Test AssociateAsyncBeginEndEvents
531 TEST_F(TraceEventAnalyzerTest, AsyncBeginEndAssocations) {
536 TRACE_EVENT_ASYNC_END0("cat1", "name1", 0xA); // no match / out of order
537 TRACE_EVENT_ASYNC_BEGIN0("cat1", "name1", 0xB);
538 TRACE_EVENT_ASYNC_BEGIN0("cat1", "name1", 0xC);
539 TRACE_EVENT_INSTANT0("cat1", "name1", TRACE_EVENT_SCOPE_THREAD); // noise
540 TRACE_EVENT0("cat1", "name1"); // noise
541 TRACE_EVENT_ASYNC_END0("cat1", "name1", 0xB);
542 TRACE_EVENT_ASYNC_END0("cat1", "name1", 0xC);
543 TRACE_EVENT_ASYNC_BEGIN0("cat1", "name1", 0xA); // no match / out of order
547 scoped_ptr<TraceAnalyzer>
548 analyzer(TraceAnalyzer::Create(output_.json_output));
549 ASSERT_TRUE(analyzer.get());
550 analyzer->AssociateAsyncBeginEndEvents();
552 TraceEventVector found;
553 analyzer->FindEvents(Query::MatchAsyncBeginWithNext(), &found);
554 ASSERT_EQ(2u, found.size());
555 EXPECT_STRCASEEQ("0xb", found[0]->id.c_str());
556 EXPECT_STRCASEEQ("0xc", found[1]->id.c_str());
559 // Test AssociateAsyncBeginEndEvents
560 TEST_F(TraceEventAnalyzerTest, AsyncBeginEndAssocationsWithSteps) {
565 TRACE_EVENT_ASYNC_STEP_INTO0("c", "n", 0xA, "s1");
566 TRACE_EVENT_ASYNC_END0("c", "n", 0xA);
567 TRACE_EVENT_ASYNC_BEGIN0("c", "n", 0xB);
568 TRACE_EVENT_ASYNC_BEGIN0("c", "n", 0xC);
569 TRACE_EVENT_ASYNC_STEP_PAST0("c", "n", 0xB, "s1");
570 TRACE_EVENT_ASYNC_STEP_INTO0("c", "n", 0xC, "s1");
571 TRACE_EVENT_ASYNC_STEP_INTO1("c", "n", 0xC, "s2", "a", 1);
572 TRACE_EVENT_ASYNC_END0("c", "n", 0xB);
573 TRACE_EVENT_ASYNC_END0("c", "n", 0xC);
574 TRACE_EVENT_ASYNC_BEGIN0("c", "n", 0xA);
575 TRACE_EVENT_ASYNC_STEP_INTO0("c", "n", 0xA, "s2");
579 scoped_ptr<TraceAnalyzer>
580 analyzer(TraceAnalyzer::Create(output_.json_output));
581 ASSERT_TRUE(analyzer.get());
582 analyzer->AssociateAsyncBeginEndEvents();
584 TraceEventVector found;
585 analyzer->FindEvents(Query::MatchAsyncBeginWithNext(), &found);
586 ASSERT_EQ(3u, found.size());
588 EXPECT_STRCASEEQ("0xb", found[0]->id.c_str());
589 EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP_PAST, found[0]->other_event->phase);
590 EXPECT_TRUE(found[0]->other_event->other_event);
591 EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_END,
592 found[0]->other_event->other_event->phase);
594 EXPECT_STRCASEEQ("0xc", found[1]->id.c_str());
595 EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP_INTO, found[1]->other_event->phase);
596 EXPECT_TRUE(found[1]->other_event->other_event);
597 EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP_INTO,
598 found[1]->other_event->other_event->phase);
599 double arg_actual = 0;
600 EXPECT_TRUE(found[1]->other_event->other_event->GetArgAsNumber(
602 EXPECT_EQ(1.0, arg_actual);
603 EXPECT_TRUE(found[1]->other_event->other_event->other_event);
604 EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_END,
605 found[1]->other_event->other_event->other_event->phase);
607 EXPECT_STRCASEEQ("0xa", found[2]->id.c_str());
608 EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP_INTO, found[2]->other_event->phase);
611 // Test that the TraceAnalyzer custom associations work.
612 TEST_F(TraceEventAnalyzerTest, CustomAssociations) {
615 // Add events that begin/end in pipelined ordering with unique ID parameter
616 // to match up the begin/end pairs.
620 TRACE_EVENT_INSTANT1("cat1", "end", TRACE_EVENT_SCOPE_THREAD, "id", 1);
622 TRACE_EVENT_INSTANT1("cat2", "begin", TRACE_EVENT_SCOPE_THREAD, "id", 2);
624 TRACE_EVENT_INSTANT1("cat3", "begin", TRACE_EVENT_SCOPE_THREAD, "id", 3);
625 TRACE_EVENT_INSTANT1("cat4", "end", TRACE_EVENT_SCOPE_THREAD, "id", 2);
626 TRACE_EVENT_INSTANT1("cat5", "end", TRACE_EVENT_SCOPE_THREAD, "id", 3);
628 TRACE_EVENT_INSTANT1("cat6", "begin", TRACE_EVENT_SCOPE_THREAD, "id", 1);
632 scoped_ptr<TraceAnalyzer>
633 analyzer(TraceAnalyzer::Create(output_.json_output));
634 ASSERT_TRUE(analyzer.get());
636 // begin, end, and match queries to find proper begin/end pairs.
637 Query begin(Query::EventName() == Query::String("begin"));
638 Query end(Query::EventName() == Query::String("end"));
639 Query match(Query::EventArg("id") == Query::OtherArg("id"));
640 analyzer->AssociateEvents(begin, end, match);
642 TraceEventVector found;
644 // cat1 has no other_event.
645 analyzer->FindEvents(Query::EventCategory() == Query::String("cat1") &&
646 Query::EventHasOther(), &found);
647 EXPECT_EQ(0u, found.size());
649 // cat1 has no other_event.
650 analyzer->FindEvents(Query::EventCategory() == Query::String("cat1") &&
651 !Query::EventHasOther(), &found);
652 EXPECT_EQ(1u, found.size());
654 // cat6 has no other_event.
655 analyzer->FindEvents(Query::EventCategory() == Query::String("cat6") &&
656 !Query::EventHasOther(), &found);
657 EXPECT_EQ(1u, found.size());
659 // cat2 and cat4 are associated.
660 analyzer->FindEvents(Query::EventCategory() == Query::String("cat2") &&
661 Query::OtherCategory() == Query::String("cat4"), &found);
662 EXPECT_EQ(1u, found.size());
664 // cat4 and cat2 are not associated.
665 analyzer->FindEvents(Query::EventCategory() == Query::String("cat4") &&
666 Query::OtherCategory() == Query::String("cat2"), &found);
667 EXPECT_EQ(0u, found.size());
669 // cat3 and cat5 are associated.
670 analyzer->FindEvents(Query::EventCategory() == Query::String("cat3") &&
671 Query::OtherCategory() == Query::String("cat5"), &found);
672 EXPECT_EQ(1u, found.size());
674 // cat5 and cat3 are not associated.
675 analyzer->FindEvents(Query::EventCategory() == Query::String("cat5") &&
676 Query::OtherCategory() == Query::String("cat3"), &found);
677 EXPECT_EQ(0u, found.size());
680 // Verify that Query literals and types are properly casted.
681 TEST_F(TraceEventAnalyzerTest, Literals) {
684 // Since these queries don't refer to the event data, the dummy event below
685 // will never be accessed.
688 short short_num = -5;
689 EXPECT_TRUE((Query::Double(5.0) == Query::Int(char_num)).Evaluate(dummy));
690 EXPECT_TRUE((Query::Double(-5.0) == Query::Int(short_num)).Evaluate(dummy));
691 EXPECT_TRUE((Query::Double(1.0) == Query::Uint(1u)).Evaluate(dummy));
692 EXPECT_TRUE((Query::Double(1.0) == Query::Int(1)).Evaluate(dummy));
693 EXPECT_TRUE((Query::Double(-1.0) == Query::Int(-1)).Evaluate(dummy));
694 EXPECT_TRUE((Query::Double(1.0) == Query::Double(1.0f)).Evaluate(dummy));
695 EXPECT_TRUE((Query::Bool(true) == Query::Int(1)).Evaluate(dummy));
696 EXPECT_TRUE((Query::Bool(false) == Query::Int(0)).Evaluate(dummy));
697 EXPECT_TRUE((Query::Bool(true) == Query::Double(1.0f)).Evaluate(dummy));
698 EXPECT_TRUE((Query::Bool(false) == Query::Double(0.0f)).Evaluate(dummy));
701 // Test GetRateStats.
702 TEST_F(TraceEventAnalyzerTest, RateStats) {
703 std::vector<TraceEvent> events;
705 TraceEventVector event_ptrs;
707 event.timestamp = 0.0;
708 double little_delta = 1.0;
709 double big_delta = 10.0;
710 double tiny_delta = 0.1;
712 RateStatsOptions options;
714 // Insert 10 events, each apart by little_delta.
715 for (int i = 0; i < 10; ++i) {
716 event.timestamp += little_delta;
717 events.push_back(event);
718 event_ptrs.push_back(&events.back());
721 ASSERT_TRUE(GetRateStats(event_ptrs, &stats, NULL));
722 EXPECT_EQ(little_delta, stats.mean_us);
723 EXPECT_EQ(little_delta, stats.min_us);
724 EXPECT_EQ(little_delta, stats.max_us);
725 EXPECT_EQ(0.0, stats.standard_deviation_us);
727 // Add an event apart by big_delta.
728 event.timestamp += big_delta;
729 events.push_back(event);
730 event_ptrs.push_back(&events.back());
732 ASSERT_TRUE(GetRateStats(event_ptrs, &stats, NULL));
733 EXPECT_LT(little_delta, stats.mean_us);
734 EXPECT_EQ(little_delta, stats.min_us);
735 EXPECT_EQ(big_delta, stats.max_us);
736 EXPECT_LT(0.0, stats.standard_deviation_us);
738 // Trim off the biggest delta and verify stats.
739 options.trim_min = 0;
740 options.trim_max = 1;
741 ASSERT_TRUE(GetRateStats(event_ptrs, &stats, &options));
742 EXPECT_EQ(little_delta, stats.mean_us);
743 EXPECT_EQ(little_delta, stats.min_us);
744 EXPECT_EQ(little_delta, stats.max_us);
745 EXPECT_EQ(0.0, stats.standard_deviation_us);
747 // Add an event apart by tiny_delta.
748 event.timestamp += tiny_delta;
749 events.push_back(event);
750 event_ptrs.push_back(&events.back());
752 // Trim off both the biggest and tiniest delta and verify stats.
753 options.trim_min = 1;
754 options.trim_max = 1;
755 ASSERT_TRUE(GetRateStats(event_ptrs, &stats, &options));
756 EXPECT_EQ(little_delta, stats.mean_us);
757 EXPECT_EQ(little_delta, stats.min_us);
758 EXPECT_EQ(little_delta, stats.max_us);
759 EXPECT_EQ(0.0, stats.standard_deviation_us);
761 // Verify smallest allowed number of events.
762 TraceEventVector few_event_ptrs;
763 few_event_ptrs.push_back(&event);
764 few_event_ptrs.push_back(&event);
765 ASSERT_FALSE(GetRateStats(few_event_ptrs, &stats, NULL));
766 few_event_ptrs.push_back(&event);
767 ASSERT_TRUE(GetRateStats(few_event_ptrs, &stats, NULL));
769 // Trim off more than allowed and verify failure.
770 options.trim_min = 0;
771 options.trim_max = 1;
772 ASSERT_FALSE(GetRateStats(few_event_ptrs, &stats, &options));
775 // Test FindFirstOf and FindLastOf.
776 TEST_F(TraceEventAnalyzerTest, FindOf) {
777 size_t num_events = 100;
779 TraceEventVector event_ptrs;
780 EXPECT_FALSE(FindFirstOf(event_ptrs, Query::Bool(true), 0, &index));
781 EXPECT_FALSE(FindFirstOf(event_ptrs, Query::Bool(true), 10, &index));
782 EXPECT_FALSE(FindLastOf(event_ptrs, Query::Bool(true), 0, &index));
783 EXPECT_FALSE(FindLastOf(event_ptrs, Query::Bool(true), 10, &index));
785 std::vector<TraceEvent> events;
786 events.resize(num_events);
787 for (size_t i = 0; i < events.size(); ++i)
788 event_ptrs.push_back(&events[i]);
789 size_t bam_index = num_events/2;
790 events[bam_index].name = "bam";
791 Query query_bam = Query::EventName() == Query::String(events[bam_index].name);
794 EXPECT_FALSE(FindFirstOf(event_ptrs, Query::Bool(false), 0, &index));
795 EXPECT_TRUE(FindFirstOf(event_ptrs, Query::Bool(true), 0, &index));
796 EXPECT_EQ(0u, index);
797 EXPECT_TRUE(FindFirstOf(event_ptrs, Query::Bool(true), 5, &index));
798 EXPECT_EQ(5u, index);
800 EXPECT_FALSE(FindFirstOf(event_ptrs, query_bam, bam_index + 1, &index));
801 EXPECT_TRUE(FindFirstOf(event_ptrs, query_bam, 0, &index));
802 EXPECT_EQ(bam_index, index);
803 EXPECT_TRUE(FindFirstOf(event_ptrs, query_bam, bam_index, &index));
804 EXPECT_EQ(bam_index, index);
807 EXPECT_FALSE(FindLastOf(event_ptrs, Query::Bool(false), 1000, &index));
808 EXPECT_TRUE(FindLastOf(event_ptrs, Query::Bool(true), 1000, &index));
809 EXPECT_EQ(num_events - 1, index);
810 EXPECT_TRUE(FindLastOf(event_ptrs, Query::Bool(true), num_events - 5,
812 EXPECT_EQ(num_events - 5, index);
814 EXPECT_FALSE(FindLastOf(event_ptrs, query_bam, bam_index - 1, &index));
815 EXPECT_TRUE(FindLastOf(event_ptrs, query_bam, num_events, &index));
816 EXPECT_EQ(bam_index, index);
817 EXPECT_TRUE(FindLastOf(event_ptrs, query_bam, bam_index, &index));
818 EXPECT_EQ(bam_index, index);
822 TEST_F(TraceEventAnalyzerTest, FindClosest) {
825 TraceEventVector event_ptrs;
826 EXPECT_FALSE(FindClosest(event_ptrs, Query::Bool(true), 0,
827 &index_1, &index_2));
829 size_t num_events = 5;
830 std::vector<TraceEvent> events;
831 events.resize(num_events);
832 for (size_t i = 0; i < events.size(); ++i) {
833 // timestamps go up exponentially so the lower index is always closer in
834 // time than the higher index.
835 events[i].timestamp = static_cast<double>(i) * static_cast<double>(i);
836 event_ptrs.push_back(&events[i]);
838 events[0].name = "one";
839 events[2].name = "two";
840 events[4].name = "three";
841 Query query_named = Query::EventName() != Query::String(std::string());
842 Query query_one = Query::EventName() == Query::String("one");
844 // Only one event matches query_one, so two closest can't be found.
845 EXPECT_FALSE(FindClosest(event_ptrs, query_one, 0, &index_1, &index_2));
847 EXPECT_TRUE(FindClosest(event_ptrs, query_one, 3, &index_1, NULL));
848 EXPECT_EQ(0u, index_1);
850 EXPECT_TRUE(FindClosest(event_ptrs, query_named, 1, &index_1, &index_2));
851 EXPECT_EQ(0u, index_1);
852 EXPECT_EQ(2u, index_2);
854 EXPECT_TRUE(FindClosest(event_ptrs, query_named, 4, &index_1, &index_2));
855 EXPECT_EQ(4u, index_1);
856 EXPECT_EQ(2u, index_2);
858 EXPECT_TRUE(FindClosest(event_ptrs, query_named, 3, &index_1, &index_2));
859 EXPECT_EQ(2u, index_1);
860 EXPECT_EQ(0u, index_2);
863 // Test CountMatches.
864 TEST_F(TraceEventAnalyzerTest, CountMatches) {
865 TraceEventVector event_ptrs;
866 EXPECT_EQ(0u, CountMatches(event_ptrs, Query::Bool(true), 0, 10));
868 size_t num_events = 5;
869 size_t num_named = 3;
870 std::vector<TraceEvent> events;
871 events.resize(num_events);
872 for (size_t i = 0; i < events.size(); ++i)
873 event_ptrs.push_back(&events[i]);
874 events[0].name = "one";
875 events[2].name = "two";
876 events[4].name = "three";
877 Query query_named = Query::EventName() != Query::String(std::string());
878 Query query_one = Query::EventName() == Query::String("one");
880 EXPECT_EQ(0u, CountMatches(event_ptrs, Query::Bool(false)));
881 EXPECT_EQ(num_events, CountMatches(event_ptrs, Query::Bool(true)));
882 EXPECT_EQ(num_events - 1, CountMatches(event_ptrs, Query::Bool(true),
884 EXPECT_EQ(1u, CountMatches(event_ptrs, query_one));
885 EXPECT_EQ(num_events - 1, CountMatches(event_ptrs, !query_one));
886 EXPECT_EQ(num_named, CountMatches(event_ptrs, query_named));
890 } // namespace trace_analyzer