Updating trunk VERSION from 2139.0 to 2140.0
[chromium-blink-merge.git] / base / test / trace_event_analyzer_unittest.cc
bloba17c7e5d436b5593fbdf9c523573febd91f5d241
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.
5 #include "base/bind.h"
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 {
14 namespace {
16 class TraceEventAnalyzerTest : public testing::Test {
17 public:
18 void ManualSetUp();
19 void OnTraceDataCollected(
20 base::WaitableEvent* flush_complete_event,
21 const scoped_refptr<base::RefCountedString>& json_events_str,
22 bool has_more_events);
23 void BeginTracing();
24 void EndTracing();
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());
41 if (!has_more_events)
42 flush_complete_event->Signal();
45 void TraceEventAnalyzerTest::BeginTracing() {
46 output_.json_output.clear();
47 buffer_.Start();
48 base::debug::TraceLog::GetInstance()->SetEnabled(
49 base::debug::CategoryFilter("*"),
50 base::debug::TraceLog::RECORDING_MODE,
51 base::debug::TraceOptions());
54 void TraceEventAnalyzerTest::EndTracing() {
55 base::debug::TraceLog::GetInstance()->SetDisabled();
56 base::WaitableEvent flush_complete_event(false, false);
57 base::debug::TraceLog::GetInstance()->Flush(
58 base::Bind(&TraceEventAnalyzerTest::OnTraceDataCollected,
59 base::Unretained(this),
60 base::Unretained(&flush_complete_event)));
61 flush_complete_event.Wait();
62 buffer_.Finish();
65 } // namespace
67 TEST_F(TraceEventAnalyzerTest, NoEvents) {
68 ManualSetUp();
70 // Create an empty JSON event string:
71 buffer_.Start();
72 buffer_.Finish();
74 scoped_ptr<TraceAnalyzer>
75 analyzer(TraceAnalyzer::Create(output_.json_output));
76 ASSERT_TRUE(analyzer.get());
78 // Search for all events and verify that nothing is returned.
79 TraceEventVector found;
80 analyzer->FindEvents(Query::Bool(true), &found);
81 EXPECT_EQ(0u, found.size());
84 TEST_F(TraceEventAnalyzerTest, TraceEvent) {
85 ManualSetUp();
87 int int_num = 2;
88 double double_num = 3.5;
89 const char* str = "the string";
91 TraceEvent event;
92 event.arg_numbers["false"] = 0.0;
93 event.arg_numbers["true"] = 1.0;
94 event.arg_numbers["int"] = static_cast<double>(int_num);
95 event.arg_numbers["double"] = double_num;
96 event.arg_strings["string"] = str;
98 ASSERT_TRUE(event.HasNumberArg("false"));
99 ASSERT_TRUE(event.HasNumberArg("true"));
100 ASSERT_TRUE(event.HasNumberArg("int"));
101 ASSERT_TRUE(event.HasNumberArg("double"));
102 ASSERT_TRUE(event.HasStringArg("string"));
103 ASSERT_FALSE(event.HasNumberArg("notfound"));
104 ASSERT_FALSE(event.HasStringArg("notfound"));
106 EXPECT_FALSE(event.GetKnownArgAsBool("false"));
107 EXPECT_TRUE(event.GetKnownArgAsBool("true"));
108 EXPECT_EQ(int_num, event.GetKnownArgAsInt("int"));
109 EXPECT_EQ(double_num, event.GetKnownArgAsDouble("double"));
110 EXPECT_STREQ(str, event.GetKnownArgAsString("string").c_str());
113 TEST_F(TraceEventAnalyzerTest, QueryEventMember) {
114 ManualSetUp();
116 TraceEvent event;
117 event.thread.process_id = 3;
118 event.thread.thread_id = 4;
119 event.timestamp = 1.5;
120 event.phase = TRACE_EVENT_PHASE_BEGIN;
121 event.category = "category";
122 event.name = "name";
123 event.id = "1";
124 event.arg_numbers["num"] = 7.0;
125 event.arg_strings["str"] = "the string";
127 // Other event with all different members:
128 TraceEvent other;
129 other.thread.process_id = 5;
130 other.thread.thread_id = 6;
131 other.timestamp = 2.5;
132 other.phase = TRACE_EVENT_PHASE_END;
133 other.category = "category2";
134 other.name = "name2";
135 other.id = "2";
136 other.arg_numbers["num2"] = 8.0;
137 other.arg_strings["str2"] = "the string 2";
139 event.other_event = &other;
140 ASSERT_TRUE(event.has_other_event());
141 double duration = event.GetAbsTimeToOtherEvent();
143 Query event_pid = Query::EventPidIs(event.thread.process_id);
144 Query event_tid = Query::EventTidIs(event.thread.thread_id);
145 Query event_time = Query::EventTimeIs(event.timestamp);
146 Query event_duration = Query::EventDurationIs(duration);
147 Query event_phase = Query::EventPhaseIs(event.phase);
148 Query event_category = Query::EventCategoryIs(event.category);
149 Query event_name = Query::EventNameIs(event.name);
150 Query event_id = Query::EventIdIs(event.id);
151 Query event_has_arg1 = Query::EventHasNumberArg("num");
152 Query event_has_arg2 = Query::EventHasStringArg("str");
153 Query event_arg1 =
154 (Query::EventArg("num") == Query::Double(event.arg_numbers["num"]));
155 Query event_arg2 =
156 (Query::EventArg("str") == Query::String(event.arg_strings["str"]));
157 Query event_has_other = Query::EventHasOther();
158 Query other_pid = Query::OtherPidIs(other.thread.process_id);
159 Query other_tid = Query::OtherTidIs(other.thread.thread_id);
160 Query other_time = Query::OtherTimeIs(other.timestamp);
161 Query other_phase = Query::OtherPhaseIs(other.phase);
162 Query other_category = Query::OtherCategoryIs(other.category);
163 Query other_name = Query::OtherNameIs(other.name);
164 Query other_id = Query::OtherIdIs(other.id);
165 Query other_has_arg1 = Query::OtherHasNumberArg("num2");
166 Query other_has_arg2 = Query::OtherHasStringArg("str2");
167 Query other_arg1 =
168 (Query::OtherArg("num2") == Query::Double(other.arg_numbers["num2"]));
169 Query other_arg2 =
170 (Query::OtherArg("str2") == Query::String(other.arg_strings["str2"]));
172 EXPECT_TRUE(event_pid.Evaluate(event));
173 EXPECT_TRUE(event_tid.Evaluate(event));
174 EXPECT_TRUE(event_time.Evaluate(event));
175 EXPECT_TRUE(event_duration.Evaluate(event));
176 EXPECT_TRUE(event_phase.Evaluate(event));
177 EXPECT_TRUE(event_category.Evaluate(event));
178 EXPECT_TRUE(event_name.Evaluate(event));
179 EXPECT_TRUE(event_id.Evaluate(event));
180 EXPECT_TRUE(event_has_arg1.Evaluate(event));
181 EXPECT_TRUE(event_has_arg2.Evaluate(event));
182 EXPECT_TRUE(event_arg1.Evaluate(event));
183 EXPECT_TRUE(event_arg2.Evaluate(event));
184 EXPECT_TRUE(event_has_other.Evaluate(event));
185 EXPECT_TRUE(other_pid.Evaluate(event));
186 EXPECT_TRUE(other_tid.Evaluate(event));
187 EXPECT_TRUE(other_time.Evaluate(event));
188 EXPECT_TRUE(other_phase.Evaluate(event));
189 EXPECT_TRUE(other_category.Evaluate(event));
190 EXPECT_TRUE(other_name.Evaluate(event));
191 EXPECT_TRUE(other_id.Evaluate(event));
192 EXPECT_TRUE(other_has_arg1.Evaluate(event));
193 EXPECT_TRUE(other_has_arg2.Evaluate(event));
194 EXPECT_TRUE(other_arg1.Evaluate(event));
195 EXPECT_TRUE(other_arg2.Evaluate(event));
197 // Evaluate event queries against other to verify the queries fail when the
198 // event members are wrong.
199 EXPECT_FALSE(event_pid.Evaluate(other));
200 EXPECT_FALSE(event_tid.Evaluate(other));
201 EXPECT_FALSE(event_time.Evaluate(other));
202 EXPECT_FALSE(event_duration.Evaluate(other));
203 EXPECT_FALSE(event_phase.Evaluate(other));
204 EXPECT_FALSE(event_category.Evaluate(other));
205 EXPECT_FALSE(event_name.Evaluate(other));
206 EXPECT_FALSE(event_id.Evaluate(other));
207 EXPECT_FALSE(event_has_arg1.Evaluate(other));
208 EXPECT_FALSE(event_has_arg2.Evaluate(other));
209 EXPECT_FALSE(event_arg1.Evaluate(other));
210 EXPECT_FALSE(event_arg2.Evaluate(other));
211 EXPECT_FALSE(event_has_other.Evaluate(other));
214 TEST_F(TraceEventAnalyzerTest, BooleanOperators) {
215 ManualSetUp();
217 BeginTracing();
219 TRACE_EVENT_INSTANT1("cat1", "name1", TRACE_EVENT_SCOPE_THREAD, "num", 1);
220 TRACE_EVENT_INSTANT1("cat1", "name2", TRACE_EVENT_SCOPE_THREAD, "num", 2);
221 TRACE_EVENT_INSTANT1("cat2", "name3", TRACE_EVENT_SCOPE_THREAD, "num", 3);
222 TRACE_EVENT_INSTANT1("cat2", "name4", TRACE_EVENT_SCOPE_THREAD, "num", 4);
224 EndTracing();
226 scoped_ptr<TraceAnalyzer>
227 analyzer(TraceAnalyzer::Create(output_.json_output));
228 ASSERT_TRUE(!!analyzer.get());
229 analyzer->SetIgnoreMetadataEvents(true);
231 TraceEventVector found;
233 // ==
235 analyzer->FindEvents(Query::EventCategory() == Query::String("cat1"), &found);
236 ASSERT_EQ(2u, found.size());
237 EXPECT_STREQ("name1", found[0]->name.c_str());
238 EXPECT_STREQ("name2", found[1]->name.c_str());
240 analyzer->FindEvents(Query::EventArg("num") == Query::Int(2), &found);
241 ASSERT_EQ(1u, found.size());
242 EXPECT_STREQ("name2", found[0]->name.c_str());
244 // !=
246 analyzer->FindEvents(Query::EventCategory() != Query::String("cat1"), &found);
247 ASSERT_EQ(2u, found.size());
248 EXPECT_STREQ("name3", found[0]->name.c_str());
249 EXPECT_STREQ("name4", found[1]->name.c_str());
251 analyzer->FindEvents(Query::EventArg("num") != Query::Int(2), &found);
252 ASSERT_EQ(3u, found.size());
253 EXPECT_STREQ("name1", found[0]->name.c_str());
254 EXPECT_STREQ("name3", found[1]->name.c_str());
255 EXPECT_STREQ("name4", found[2]->name.c_str());
257 // <
258 analyzer->FindEvents(Query::EventArg("num") < Query::Int(2), &found);
259 ASSERT_EQ(1u, found.size());
260 EXPECT_STREQ("name1", found[0]->name.c_str());
262 // <=
263 analyzer->FindEvents(Query::EventArg("num") <= Query::Int(2), &found);
264 ASSERT_EQ(2u, found.size());
265 EXPECT_STREQ("name1", found[0]->name.c_str());
266 EXPECT_STREQ("name2", found[1]->name.c_str());
268 // >
269 analyzer->FindEvents(Query::EventArg("num") > Query::Int(3), &found);
270 ASSERT_EQ(1u, found.size());
271 EXPECT_STREQ("name4", found[0]->name.c_str());
273 // >=
274 analyzer->FindEvents(Query::EventArg("num") >= Query::Int(4), &found);
275 ASSERT_EQ(1u, found.size());
276 EXPECT_STREQ("name4", found[0]->name.c_str());
278 // &&
279 analyzer->FindEvents(Query::EventName() != Query::String("name1") &&
280 Query::EventArg("num") < Query::Int(3), &found);
281 ASSERT_EQ(1u, found.size());
282 EXPECT_STREQ("name2", found[0]->name.c_str());
284 // ||
285 analyzer->FindEvents(Query::EventName() == Query::String("name1") ||
286 Query::EventArg("num") == Query::Int(3), &found);
287 ASSERT_EQ(2u, found.size());
288 EXPECT_STREQ("name1", found[0]->name.c_str());
289 EXPECT_STREQ("name3", found[1]->name.c_str());
291 // !
292 analyzer->FindEvents(!(Query::EventName() == Query::String("name1") ||
293 Query::EventArg("num") == Query::Int(3)), &found);
294 ASSERT_EQ(2u, found.size());
295 EXPECT_STREQ("name2", found[0]->name.c_str());
296 EXPECT_STREQ("name4", found[1]->name.c_str());
299 TEST_F(TraceEventAnalyzerTest, ArithmeticOperators) {
300 ManualSetUp();
302 BeginTracing();
304 // These events are searched for:
305 TRACE_EVENT_INSTANT2("cat1", "math1", TRACE_EVENT_SCOPE_THREAD,
306 "a", 10, "b", 5);
307 TRACE_EVENT_INSTANT2("cat1", "math2", TRACE_EVENT_SCOPE_THREAD,
308 "a", 10, "b", 10);
309 // Extra events that never match, for noise:
310 TRACE_EVENT_INSTANT2("noise", "math3", TRACE_EVENT_SCOPE_THREAD,
311 "a", 1, "b", 3);
312 TRACE_EVENT_INSTANT2("noise", "math4", TRACE_EVENT_SCOPE_THREAD,
313 "c", 10, "d", 5);
315 EndTracing();
317 scoped_ptr<TraceAnalyzer>
318 analyzer(TraceAnalyzer::Create(output_.json_output));
319 ASSERT_TRUE(analyzer.get());
321 TraceEventVector found;
323 // Verify that arithmetic operators function:
325 // +
326 analyzer->FindEvents(Query::EventArg("a") + Query::EventArg("b") ==
327 Query::Int(20), &found);
328 EXPECT_EQ(1u, found.size());
329 EXPECT_STREQ("math2", found.front()->name.c_str());
331 // -
332 analyzer->FindEvents(Query::EventArg("a") - Query::EventArg("b") ==
333 Query::Int(5), &found);
334 EXPECT_EQ(1u, found.size());
335 EXPECT_STREQ("math1", found.front()->name.c_str());
337 // *
338 analyzer->FindEvents(Query::EventArg("a") * Query::EventArg("b") ==
339 Query::Int(50), &found);
340 EXPECT_EQ(1u, found.size());
341 EXPECT_STREQ("math1", found.front()->name.c_str());
343 // /
344 analyzer->FindEvents(Query::EventArg("a") / Query::EventArg("b") ==
345 Query::Int(2), &found);
346 EXPECT_EQ(1u, found.size());
347 EXPECT_STREQ("math1", found.front()->name.c_str());
349 // %
350 analyzer->FindEvents(Query::EventArg("a") % Query::EventArg("b") ==
351 Query::Int(0), &found);
352 EXPECT_EQ(2u, found.size());
354 // - (negate)
355 analyzer->FindEvents(-Query::EventArg("b") == Query::Int(-10), &found);
356 EXPECT_EQ(1u, found.size());
357 EXPECT_STREQ("math2", found.front()->name.c_str());
360 TEST_F(TraceEventAnalyzerTest, StringPattern) {
361 ManualSetUp();
363 BeginTracing();
365 TRACE_EVENT_INSTANT0("cat1", "name1", TRACE_EVENT_SCOPE_THREAD);
366 TRACE_EVENT_INSTANT0("cat1", "name2", TRACE_EVENT_SCOPE_THREAD);
367 TRACE_EVENT_INSTANT0("cat1", "no match", TRACE_EVENT_SCOPE_THREAD);
368 TRACE_EVENT_INSTANT0("cat1", "name3x", TRACE_EVENT_SCOPE_THREAD);
370 EndTracing();
372 scoped_ptr<TraceAnalyzer>
373 analyzer(TraceAnalyzer::Create(output_.json_output));
374 ASSERT_TRUE(analyzer.get());
375 analyzer->SetIgnoreMetadataEvents(true);
377 TraceEventVector found;
379 analyzer->FindEvents(Query::EventName() == Query::Pattern("name?"), &found);
380 ASSERT_EQ(2u, found.size());
381 EXPECT_STREQ("name1", found[0]->name.c_str());
382 EXPECT_STREQ("name2", found[1]->name.c_str());
384 analyzer->FindEvents(Query::EventName() == Query::Pattern("name*"), &found);
385 ASSERT_EQ(3u, found.size());
386 EXPECT_STREQ("name1", found[0]->name.c_str());
387 EXPECT_STREQ("name2", found[1]->name.c_str());
388 EXPECT_STREQ("name3x", found[2]->name.c_str());
390 analyzer->FindEvents(Query::EventName() != Query::Pattern("name*"), &found);
391 ASSERT_EQ(1u, found.size());
392 EXPECT_STREQ("no match", found[0]->name.c_str());
395 // Test that duration queries work.
396 TEST_F(TraceEventAnalyzerTest, BeginEndDuration) {
397 ManualSetUp();
399 const base::TimeDelta kSleepTime = base::TimeDelta::FromMilliseconds(200);
400 // We will search for events that have a duration of greater than 90% of the
401 // sleep time, so that there is no flakiness.
402 int duration_cutoff_us = (kSleepTime.InMicroseconds() * 9) / 10;
404 BeginTracing();
406 TRACE_EVENT_BEGIN0("cat1", "name1"); // found by duration query
407 TRACE_EVENT_BEGIN0("noise", "name2"); // not searched for, just noise
409 TRACE_EVENT_BEGIN0("cat2", "name3"); // found by duration query
410 // next event not searched for, just noise
411 TRACE_EVENT_INSTANT0("noise", "name4", TRACE_EVENT_SCOPE_THREAD);
412 base::debug::HighResSleepForTraceTest(kSleepTime);
413 TRACE_EVENT_BEGIN0("cat2", "name5"); // not found (duration too short)
414 TRACE_EVENT_END0("cat2", "name5"); // not found (duration too short)
415 TRACE_EVENT_END0("cat2", "name3"); // found by duration query
417 TRACE_EVENT_END0("noise", "name2"); // not searched for, just noise
418 TRACE_EVENT_END0("cat1", "name1"); // found by duration query
420 EndTracing();
422 scoped_ptr<TraceAnalyzer>
423 analyzer(TraceAnalyzer::Create(output_.json_output));
424 ASSERT_TRUE(analyzer.get());
425 analyzer->AssociateBeginEndEvents();
427 TraceEventVector found;
428 analyzer->FindEvents(
429 Query::MatchBeginWithEnd() &&
430 Query::EventDuration() > Query::Int(duration_cutoff_us) &&
431 (Query::EventCategory() == Query::String("cat1") ||
432 Query::EventCategory() == Query::String("cat2") ||
433 Query::EventCategory() == Query::String("cat3")),
434 &found);
435 ASSERT_EQ(2u, found.size());
436 EXPECT_STREQ("name1", found[0]->name.c_str());
437 EXPECT_STREQ("name3", found[1]->name.c_str());
440 // Test that duration queries work.
441 TEST_F(TraceEventAnalyzerTest, CompleteDuration) {
442 ManualSetUp();
444 const base::TimeDelta kSleepTime = base::TimeDelta::FromMilliseconds(200);
445 // We will search for events that have a duration of greater than 90% of the
446 // sleep time, so that there is no flakiness.
447 int duration_cutoff_us = (kSleepTime.InMicroseconds() * 9) / 10;
449 BeginTracing();
451 TRACE_EVENT0("cat1", "name1"); // found by duration query
452 TRACE_EVENT0("noise", "name2"); // not searched for, just noise
454 TRACE_EVENT0("cat2", "name3"); // found by duration query
455 // next event not searched for, just noise
456 TRACE_EVENT_INSTANT0("noise", "name4", TRACE_EVENT_SCOPE_THREAD);
457 base::debug::HighResSleepForTraceTest(kSleepTime);
458 TRACE_EVENT0("cat2", "name5"); // not found (duration too short)
461 EndTracing();
463 scoped_ptr<TraceAnalyzer>
464 analyzer(TraceAnalyzer::Create(output_.json_output));
465 ASSERT_TRUE(analyzer.get());
466 analyzer->AssociateBeginEndEvents();
468 TraceEventVector found;
469 analyzer->FindEvents(
470 Query::EventCompleteDuration() > Query::Int(duration_cutoff_us) &&
471 (Query::EventCategory() == Query::String("cat1") ||
472 Query::EventCategory() == Query::String("cat2") ||
473 Query::EventCategory() == Query::String("cat3")),
474 &found);
475 ASSERT_EQ(2u, found.size());
476 EXPECT_STREQ("name1", found[0]->name.c_str());
477 EXPECT_STREQ("name3", found[1]->name.c_str());
480 // Test AssociateBeginEndEvents
481 TEST_F(TraceEventAnalyzerTest, BeginEndAssocations) {
482 ManualSetUp();
484 BeginTracing();
486 TRACE_EVENT_END0("cat1", "name1"); // does not match out of order begin
487 TRACE_EVENT_BEGIN0("cat1", "name2");
488 TRACE_EVENT_INSTANT0("cat1", "name3", TRACE_EVENT_SCOPE_THREAD);
489 TRACE_EVENT_BEGIN0("cat1", "name1");
490 TRACE_EVENT_END0("cat1", "name2");
492 EndTracing();
494 scoped_ptr<TraceAnalyzer>
495 analyzer(TraceAnalyzer::Create(output_.json_output));
496 ASSERT_TRUE(analyzer.get());
497 analyzer->AssociateBeginEndEvents();
499 TraceEventVector found;
500 analyzer->FindEvents(Query::MatchBeginWithEnd(), &found);
501 ASSERT_EQ(1u, found.size());
502 EXPECT_STREQ("name2", found[0]->name.c_str());
505 // Test MergeAssociatedEventArgs
506 TEST_F(TraceEventAnalyzerTest, MergeAssociatedEventArgs) {
507 ManualSetUp();
509 const char* arg_string = "arg_string";
510 BeginTracing();
512 TRACE_EVENT_BEGIN0("cat1", "name1");
513 TRACE_EVENT_END1("cat1", "name1", "arg", arg_string);
515 EndTracing();
517 scoped_ptr<TraceAnalyzer>
518 analyzer(TraceAnalyzer::Create(output_.json_output));
519 ASSERT_TRUE(analyzer.get());
520 analyzer->AssociateBeginEndEvents();
522 TraceEventVector found;
523 analyzer->FindEvents(Query::MatchBeginName("name1"), &found);
524 ASSERT_EQ(1u, found.size());
525 std::string arg_actual;
526 EXPECT_FALSE(found[0]->GetArgAsString("arg", &arg_actual));
528 analyzer->MergeAssociatedEventArgs();
529 EXPECT_TRUE(found[0]->GetArgAsString("arg", &arg_actual));
530 EXPECT_STREQ(arg_string, arg_actual.c_str());
533 // Test AssociateAsyncBeginEndEvents
534 TEST_F(TraceEventAnalyzerTest, AsyncBeginEndAssocations) {
535 ManualSetUp();
537 BeginTracing();
539 TRACE_EVENT_ASYNC_END0("cat1", "name1", 0xA); // no match / out of order
540 TRACE_EVENT_ASYNC_BEGIN0("cat1", "name1", 0xB);
541 TRACE_EVENT_ASYNC_BEGIN0("cat1", "name1", 0xC);
542 TRACE_EVENT_INSTANT0("cat1", "name1", TRACE_EVENT_SCOPE_THREAD); // noise
543 TRACE_EVENT0("cat1", "name1"); // noise
544 TRACE_EVENT_ASYNC_END0("cat1", "name1", 0xB);
545 TRACE_EVENT_ASYNC_END0("cat1", "name1", 0xC);
546 TRACE_EVENT_ASYNC_BEGIN0("cat1", "name1", 0xA); // no match / out of order
548 EndTracing();
550 scoped_ptr<TraceAnalyzer>
551 analyzer(TraceAnalyzer::Create(output_.json_output));
552 ASSERT_TRUE(analyzer.get());
553 analyzer->AssociateAsyncBeginEndEvents();
555 TraceEventVector found;
556 analyzer->FindEvents(Query::MatchAsyncBeginWithNext(), &found);
557 ASSERT_EQ(2u, found.size());
558 EXPECT_STRCASEEQ("0xb", found[0]->id.c_str());
559 EXPECT_STRCASEEQ("0xc", found[1]->id.c_str());
562 // Test AssociateAsyncBeginEndEvents
563 TEST_F(TraceEventAnalyzerTest, AsyncBeginEndAssocationsWithSteps) {
564 ManualSetUp();
566 BeginTracing();
568 TRACE_EVENT_ASYNC_STEP_INTO0("c", "n", 0xA, "s1");
569 TRACE_EVENT_ASYNC_END0("c", "n", 0xA);
570 TRACE_EVENT_ASYNC_BEGIN0("c", "n", 0xB);
571 TRACE_EVENT_ASYNC_BEGIN0("c", "n", 0xC);
572 TRACE_EVENT_ASYNC_STEP_PAST0("c", "n", 0xB, "s1");
573 TRACE_EVENT_ASYNC_STEP_INTO0("c", "n", 0xC, "s1");
574 TRACE_EVENT_ASYNC_STEP_INTO1("c", "n", 0xC, "s2", "a", 1);
575 TRACE_EVENT_ASYNC_END0("c", "n", 0xB);
576 TRACE_EVENT_ASYNC_END0("c", "n", 0xC);
577 TRACE_EVENT_ASYNC_BEGIN0("c", "n", 0xA);
578 TRACE_EVENT_ASYNC_STEP_INTO0("c", "n", 0xA, "s2");
580 EndTracing();
582 scoped_ptr<TraceAnalyzer>
583 analyzer(TraceAnalyzer::Create(output_.json_output));
584 ASSERT_TRUE(analyzer.get());
585 analyzer->AssociateAsyncBeginEndEvents();
587 TraceEventVector found;
588 analyzer->FindEvents(Query::MatchAsyncBeginWithNext(), &found);
589 ASSERT_EQ(3u, found.size());
591 EXPECT_STRCASEEQ("0xb", found[0]->id.c_str());
592 EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP_PAST, found[0]->other_event->phase);
593 EXPECT_TRUE(found[0]->other_event->other_event);
594 EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_END,
595 found[0]->other_event->other_event->phase);
597 EXPECT_STRCASEEQ("0xc", found[1]->id.c_str());
598 EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP_INTO, found[1]->other_event->phase);
599 EXPECT_TRUE(found[1]->other_event->other_event);
600 EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP_INTO,
601 found[1]->other_event->other_event->phase);
602 double arg_actual = 0;
603 EXPECT_TRUE(found[1]->other_event->other_event->GetArgAsNumber(
604 "a", &arg_actual));
605 EXPECT_EQ(1.0, arg_actual);
606 EXPECT_TRUE(found[1]->other_event->other_event->other_event);
607 EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_END,
608 found[1]->other_event->other_event->other_event->phase);
610 EXPECT_STRCASEEQ("0xa", found[2]->id.c_str());
611 EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP_INTO, found[2]->other_event->phase);
614 // Test that the TraceAnalyzer custom associations work.
615 TEST_F(TraceEventAnalyzerTest, CustomAssociations) {
616 ManualSetUp();
618 // Add events that begin/end in pipelined ordering with unique ID parameter
619 // to match up the begin/end pairs.
620 BeginTracing();
622 // no begin match
623 TRACE_EVENT_INSTANT1("cat1", "end", TRACE_EVENT_SCOPE_THREAD, "id", 1);
624 // end is cat4
625 TRACE_EVENT_INSTANT1("cat2", "begin", TRACE_EVENT_SCOPE_THREAD, "id", 2);
626 // end is cat5
627 TRACE_EVENT_INSTANT1("cat3", "begin", TRACE_EVENT_SCOPE_THREAD, "id", 3);
628 TRACE_EVENT_INSTANT1("cat4", "end", TRACE_EVENT_SCOPE_THREAD, "id", 2);
629 TRACE_EVENT_INSTANT1("cat5", "end", TRACE_EVENT_SCOPE_THREAD, "id", 3);
630 // no end match
631 TRACE_EVENT_INSTANT1("cat6", "begin", TRACE_EVENT_SCOPE_THREAD, "id", 1);
633 EndTracing();
635 scoped_ptr<TraceAnalyzer>
636 analyzer(TraceAnalyzer::Create(output_.json_output));
637 ASSERT_TRUE(analyzer.get());
639 // begin, end, and match queries to find proper begin/end pairs.
640 Query begin(Query::EventName() == Query::String("begin"));
641 Query end(Query::EventName() == Query::String("end"));
642 Query match(Query::EventArg("id") == Query::OtherArg("id"));
643 analyzer->AssociateEvents(begin, end, match);
645 TraceEventVector found;
647 // cat1 has no other_event.
648 analyzer->FindEvents(Query::EventCategory() == Query::String("cat1") &&
649 Query::EventHasOther(), &found);
650 EXPECT_EQ(0u, found.size());
652 // cat1 has no other_event.
653 analyzer->FindEvents(Query::EventCategory() == Query::String("cat1") &&
654 !Query::EventHasOther(), &found);
655 EXPECT_EQ(1u, found.size());
657 // cat6 has no other_event.
658 analyzer->FindEvents(Query::EventCategory() == Query::String("cat6") &&
659 !Query::EventHasOther(), &found);
660 EXPECT_EQ(1u, found.size());
662 // cat2 and cat4 are associated.
663 analyzer->FindEvents(Query::EventCategory() == Query::String("cat2") &&
664 Query::OtherCategory() == Query::String("cat4"), &found);
665 EXPECT_EQ(1u, found.size());
667 // cat4 and cat2 are not associated.
668 analyzer->FindEvents(Query::EventCategory() == Query::String("cat4") &&
669 Query::OtherCategory() == Query::String("cat2"), &found);
670 EXPECT_EQ(0u, found.size());
672 // cat3 and cat5 are associated.
673 analyzer->FindEvents(Query::EventCategory() == Query::String("cat3") &&
674 Query::OtherCategory() == Query::String("cat5"), &found);
675 EXPECT_EQ(1u, found.size());
677 // cat5 and cat3 are not associated.
678 analyzer->FindEvents(Query::EventCategory() == Query::String("cat5") &&
679 Query::OtherCategory() == Query::String("cat3"), &found);
680 EXPECT_EQ(0u, found.size());
683 // Verify that Query literals and types are properly casted.
684 TEST_F(TraceEventAnalyzerTest, Literals) {
685 ManualSetUp();
687 // Since these queries don't refer to the event data, the dummy event below
688 // will never be accessed.
689 TraceEvent dummy;
690 char char_num = 5;
691 short short_num = -5;
692 EXPECT_TRUE((Query::Double(5.0) == Query::Int(char_num)).Evaluate(dummy));
693 EXPECT_TRUE((Query::Double(-5.0) == Query::Int(short_num)).Evaluate(dummy));
694 EXPECT_TRUE((Query::Double(1.0) == Query::Uint(1u)).Evaluate(dummy));
695 EXPECT_TRUE((Query::Double(1.0) == Query::Int(1)).Evaluate(dummy));
696 EXPECT_TRUE((Query::Double(-1.0) == Query::Int(-1)).Evaluate(dummy));
697 EXPECT_TRUE((Query::Double(1.0) == Query::Double(1.0f)).Evaluate(dummy));
698 EXPECT_TRUE((Query::Bool(true) == Query::Int(1)).Evaluate(dummy));
699 EXPECT_TRUE((Query::Bool(false) == Query::Int(0)).Evaluate(dummy));
700 EXPECT_TRUE((Query::Bool(true) == Query::Double(1.0f)).Evaluate(dummy));
701 EXPECT_TRUE((Query::Bool(false) == Query::Double(0.0f)).Evaluate(dummy));
704 // Test GetRateStats.
705 TEST_F(TraceEventAnalyzerTest, RateStats) {
706 std::vector<TraceEvent> events;
707 events.reserve(100);
708 TraceEventVector event_ptrs;
709 TraceEvent event;
710 event.timestamp = 0.0;
711 double little_delta = 1.0;
712 double big_delta = 10.0;
713 double tiny_delta = 0.1;
714 RateStats stats;
715 RateStatsOptions options;
717 // Insert 10 events, each apart by little_delta.
718 for (int i = 0; i < 10; ++i) {
719 event.timestamp += little_delta;
720 events.push_back(event);
721 event_ptrs.push_back(&events.back());
724 ASSERT_TRUE(GetRateStats(event_ptrs, &stats, NULL));
725 EXPECT_EQ(little_delta, stats.mean_us);
726 EXPECT_EQ(little_delta, stats.min_us);
727 EXPECT_EQ(little_delta, stats.max_us);
728 EXPECT_EQ(0.0, stats.standard_deviation_us);
730 // Add an event apart by big_delta.
731 event.timestamp += big_delta;
732 events.push_back(event);
733 event_ptrs.push_back(&events.back());
735 ASSERT_TRUE(GetRateStats(event_ptrs, &stats, NULL));
736 EXPECT_LT(little_delta, stats.mean_us);
737 EXPECT_EQ(little_delta, stats.min_us);
738 EXPECT_EQ(big_delta, stats.max_us);
739 EXPECT_LT(0.0, stats.standard_deviation_us);
741 // Trim off the biggest delta and verify stats.
742 options.trim_min = 0;
743 options.trim_max = 1;
744 ASSERT_TRUE(GetRateStats(event_ptrs, &stats, &options));
745 EXPECT_EQ(little_delta, stats.mean_us);
746 EXPECT_EQ(little_delta, stats.min_us);
747 EXPECT_EQ(little_delta, stats.max_us);
748 EXPECT_EQ(0.0, stats.standard_deviation_us);
750 // Add an event apart by tiny_delta.
751 event.timestamp += tiny_delta;
752 events.push_back(event);
753 event_ptrs.push_back(&events.back());
755 // Trim off both the biggest and tiniest delta and verify stats.
756 options.trim_min = 1;
757 options.trim_max = 1;
758 ASSERT_TRUE(GetRateStats(event_ptrs, &stats, &options));
759 EXPECT_EQ(little_delta, stats.mean_us);
760 EXPECT_EQ(little_delta, stats.min_us);
761 EXPECT_EQ(little_delta, stats.max_us);
762 EXPECT_EQ(0.0, stats.standard_deviation_us);
764 // Verify smallest allowed number of events.
765 TraceEventVector few_event_ptrs;
766 few_event_ptrs.push_back(&event);
767 few_event_ptrs.push_back(&event);
768 ASSERT_FALSE(GetRateStats(few_event_ptrs, &stats, NULL));
769 few_event_ptrs.push_back(&event);
770 ASSERT_TRUE(GetRateStats(few_event_ptrs, &stats, NULL));
772 // Trim off more than allowed and verify failure.
773 options.trim_min = 0;
774 options.trim_max = 1;
775 ASSERT_FALSE(GetRateStats(few_event_ptrs, &stats, &options));
778 // Test FindFirstOf and FindLastOf.
779 TEST_F(TraceEventAnalyzerTest, FindOf) {
780 size_t num_events = 100;
781 size_t index = 0;
782 TraceEventVector event_ptrs;
783 EXPECT_FALSE(FindFirstOf(event_ptrs, Query::Bool(true), 0, &index));
784 EXPECT_FALSE(FindFirstOf(event_ptrs, Query::Bool(true), 10, &index));
785 EXPECT_FALSE(FindLastOf(event_ptrs, Query::Bool(true), 0, &index));
786 EXPECT_FALSE(FindLastOf(event_ptrs, Query::Bool(true), 10, &index));
788 std::vector<TraceEvent> events;
789 events.resize(num_events);
790 for (size_t i = 0; i < events.size(); ++i)
791 event_ptrs.push_back(&events[i]);
792 size_t bam_index = num_events/2;
793 events[bam_index].name = "bam";
794 Query query_bam = Query::EventName() == Query::String(events[bam_index].name);
796 // FindFirstOf
797 EXPECT_FALSE(FindFirstOf(event_ptrs, Query::Bool(false), 0, &index));
798 EXPECT_TRUE(FindFirstOf(event_ptrs, Query::Bool(true), 0, &index));
799 EXPECT_EQ(0u, index);
800 EXPECT_TRUE(FindFirstOf(event_ptrs, Query::Bool(true), 5, &index));
801 EXPECT_EQ(5u, index);
803 EXPECT_FALSE(FindFirstOf(event_ptrs, query_bam, bam_index + 1, &index));
804 EXPECT_TRUE(FindFirstOf(event_ptrs, query_bam, 0, &index));
805 EXPECT_EQ(bam_index, index);
806 EXPECT_TRUE(FindFirstOf(event_ptrs, query_bam, bam_index, &index));
807 EXPECT_EQ(bam_index, index);
809 // FindLastOf
810 EXPECT_FALSE(FindLastOf(event_ptrs, Query::Bool(false), 1000, &index));
811 EXPECT_TRUE(FindLastOf(event_ptrs, Query::Bool(true), 1000, &index));
812 EXPECT_EQ(num_events - 1, index);
813 EXPECT_TRUE(FindLastOf(event_ptrs, Query::Bool(true), num_events - 5,
814 &index));
815 EXPECT_EQ(num_events - 5, index);
817 EXPECT_FALSE(FindLastOf(event_ptrs, query_bam, bam_index - 1, &index));
818 EXPECT_TRUE(FindLastOf(event_ptrs, query_bam, num_events, &index));
819 EXPECT_EQ(bam_index, index);
820 EXPECT_TRUE(FindLastOf(event_ptrs, query_bam, bam_index, &index));
821 EXPECT_EQ(bam_index, index);
824 // Test FindClosest.
825 TEST_F(TraceEventAnalyzerTest, FindClosest) {
826 size_t index_1 = 0;
827 size_t index_2 = 0;
828 TraceEventVector event_ptrs;
829 EXPECT_FALSE(FindClosest(event_ptrs, Query::Bool(true), 0,
830 &index_1, &index_2));
832 size_t num_events = 5;
833 std::vector<TraceEvent> events;
834 events.resize(num_events);
835 for (size_t i = 0; i < events.size(); ++i) {
836 // timestamps go up exponentially so the lower index is always closer in
837 // time than the higher index.
838 events[i].timestamp = static_cast<double>(i) * static_cast<double>(i);
839 event_ptrs.push_back(&events[i]);
841 events[0].name = "one";
842 events[2].name = "two";
843 events[4].name = "three";
844 Query query_named = Query::EventName() != Query::String(std::string());
845 Query query_one = Query::EventName() == Query::String("one");
847 // Only one event matches query_one, so two closest can't be found.
848 EXPECT_FALSE(FindClosest(event_ptrs, query_one, 0, &index_1, &index_2));
850 EXPECT_TRUE(FindClosest(event_ptrs, query_one, 3, &index_1, NULL));
851 EXPECT_EQ(0u, index_1);
853 EXPECT_TRUE(FindClosest(event_ptrs, query_named, 1, &index_1, &index_2));
854 EXPECT_EQ(0u, index_1);
855 EXPECT_EQ(2u, index_2);
857 EXPECT_TRUE(FindClosest(event_ptrs, query_named, 4, &index_1, &index_2));
858 EXPECT_EQ(4u, index_1);
859 EXPECT_EQ(2u, index_2);
861 EXPECT_TRUE(FindClosest(event_ptrs, query_named, 3, &index_1, &index_2));
862 EXPECT_EQ(2u, index_1);
863 EXPECT_EQ(0u, index_2);
866 // Test CountMatches.
867 TEST_F(TraceEventAnalyzerTest, CountMatches) {
868 TraceEventVector event_ptrs;
869 EXPECT_EQ(0u, CountMatches(event_ptrs, Query::Bool(true), 0, 10));
871 size_t num_events = 5;
872 size_t num_named = 3;
873 std::vector<TraceEvent> events;
874 events.resize(num_events);
875 for (size_t i = 0; i < events.size(); ++i)
876 event_ptrs.push_back(&events[i]);
877 events[0].name = "one";
878 events[2].name = "two";
879 events[4].name = "three";
880 Query query_named = Query::EventName() != Query::String(std::string());
881 Query query_one = Query::EventName() == Query::String("one");
883 EXPECT_EQ(0u, CountMatches(event_ptrs, Query::Bool(false)));
884 EXPECT_EQ(num_events, CountMatches(event_ptrs, Query::Bool(true)));
885 EXPECT_EQ(num_events - 1, CountMatches(event_ptrs, Query::Bool(true),
886 1, num_events));
887 EXPECT_EQ(1u, CountMatches(event_ptrs, query_one));
888 EXPECT_EQ(num_events - 1, CountMatches(event_ptrs, !query_one));
889 EXPECT_EQ(num_named, CountMatches(event_ptrs, query_named));
893 } // namespace trace_analyzer