Use UintToString() for unsigned values.
[chromium-blink-merge.git] / base / test / trace_event_analyzer_unittest.cc
blob6503b1f9310871348d822932dd129e9f3c34003a
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/synchronization/waitable_event.h"
7 #include "base/test/trace_event_analyzer.h"
8 #include "base/threading/platform_thread.h"
9 #include "base/trace_event/trace_buffer.h"
10 #include "testing/gmock/include/gmock/gmock.h"
11 #include "testing/gtest/include/gtest/gtest.h"
13 namespace trace_analyzer {
15 namespace {
17 class TraceEventAnalyzerTest : public testing::Test {
18 public:
19 void ManualSetUp();
20 void OnTraceDataCollected(
21 base::WaitableEvent* flush_complete_event,
22 const scoped_refptr<base::RefCountedString>& json_events_str,
23 bool has_more_events);
24 void BeginTracing();
25 void EndTracing();
27 base::trace_event::TraceResultBuffer::SimpleOutput output_;
28 base::trace_event::TraceResultBuffer buffer_;
31 void TraceEventAnalyzerTest::ManualSetUp() {
32 ASSERT_TRUE(base::trace_event::TraceLog::GetInstance());
33 buffer_.SetOutputCallback(output_.GetCallback());
34 output_.json_output.clear();
37 void TraceEventAnalyzerTest::OnTraceDataCollected(
38 base::WaitableEvent* flush_complete_event,
39 const scoped_refptr<base::RefCountedString>& json_events_str,
40 bool has_more_events) {
41 buffer_.AddFragment(json_events_str->data());
42 if (!has_more_events)
43 flush_complete_event->Signal();
46 void TraceEventAnalyzerTest::BeginTracing() {
47 output_.json_output.clear();
48 buffer_.Start();
49 base::trace_event::TraceLog::GetInstance()->SetEnabled(
50 base::trace_event::TraceConfig("*", ""),
51 base::trace_event::TraceLog::RECORDING_MODE);
54 void TraceEventAnalyzerTest::EndTracing() {
55 base::trace_event::TraceLog::GetInstance()->SetDisabled();
56 base::WaitableEvent flush_complete_event(false, false);
57 base::trace_event::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);
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 int64 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::PlatformThread::Sleep(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() >
431 Query::Int(static_cast<int>(duration_cutoff_us)) &&
432 (Query::EventCategory() == Query::String("cat1") ||
433 Query::EventCategory() == Query::String("cat2") ||
434 Query::EventCategory() == Query::String("cat3")),
435 &found);
436 ASSERT_EQ(2u, found.size());
437 EXPECT_STREQ("name1", found[0]->name.c_str());
438 EXPECT_STREQ("name3", found[1]->name.c_str());
441 // Test that duration queries work.
442 TEST_F(TraceEventAnalyzerTest, CompleteDuration) {
443 ManualSetUp();
445 const base::TimeDelta kSleepTime = base::TimeDelta::FromMilliseconds(200);
446 // We will search for events that have a duration of greater than 90% of the
447 // sleep time, so that there is no flakiness.
448 int64 duration_cutoff_us = (kSleepTime.InMicroseconds() * 9) / 10;
450 BeginTracing();
452 TRACE_EVENT0("cat1", "name1"); // found by duration query
453 TRACE_EVENT0("noise", "name2"); // not searched for, just noise
455 TRACE_EVENT0("cat2", "name3"); // found by duration query
456 // next event not searched for, just noise
457 TRACE_EVENT_INSTANT0("noise", "name4", TRACE_EVENT_SCOPE_THREAD);
458 base::PlatformThread::Sleep(kSleepTime);
459 TRACE_EVENT0("cat2", "name5"); // not found (duration too short)
462 EndTracing();
464 scoped_ptr<TraceAnalyzer>
465 analyzer(TraceAnalyzer::Create(output_.json_output));
466 ASSERT_TRUE(analyzer.get());
467 analyzer->AssociateBeginEndEvents();
469 TraceEventVector found;
470 analyzer->FindEvents(
471 Query::EventCompleteDuration() >
472 Query::Int(static_cast<int>(duration_cutoff_us)) &&
473 (Query::EventCategory() == Query::String("cat1") ||
474 Query::EventCategory() == Query::String("cat2") ||
475 Query::EventCategory() == Query::String("cat3")),
476 &found);
477 ASSERT_EQ(2u, found.size());
478 EXPECT_STREQ("name1", found[0]->name.c_str());
479 EXPECT_STREQ("name3", found[1]->name.c_str());
482 // Test AssociateBeginEndEvents
483 TEST_F(TraceEventAnalyzerTest, BeginEndAssocations) {
484 ManualSetUp();
486 BeginTracing();
488 TRACE_EVENT_END0("cat1", "name1"); // does not match out of order begin
489 TRACE_EVENT_BEGIN0("cat1", "name2");
490 TRACE_EVENT_INSTANT0("cat1", "name3", TRACE_EVENT_SCOPE_THREAD);
491 TRACE_EVENT_BEGIN0("cat1", "name1");
492 TRACE_EVENT_END0("cat1", "name2");
494 EndTracing();
496 scoped_ptr<TraceAnalyzer>
497 analyzer(TraceAnalyzer::Create(output_.json_output));
498 ASSERT_TRUE(analyzer.get());
499 analyzer->AssociateBeginEndEvents();
501 TraceEventVector found;
502 analyzer->FindEvents(Query::MatchBeginWithEnd(), &found);
503 ASSERT_EQ(1u, found.size());
504 EXPECT_STREQ("name2", found[0]->name.c_str());
507 // Test MergeAssociatedEventArgs
508 TEST_F(TraceEventAnalyzerTest, MergeAssociatedEventArgs) {
509 ManualSetUp();
511 const char arg_string[] = "arg_string";
512 BeginTracing();
514 TRACE_EVENT_BEGIN0("cat1", "name1");
515 TRACE_EVENT_END1("cat1", "name1", "arg", arg_string);
517 EndTracing();
519 scoped_ptr<TraceAnalyzer>
520 analyzer(TraceAnalyzer::Create(output_.json_output));
521 ASSERT_TRUE(analyzer.get());
522 analyzer->AssociateBeginEndEvents();
524 TraceEventVector found;
525 analyzer->FindEvents(Query::MatchBeginName("name1"), &found);
526 ASSERT_EQ(1u, found.size());
527 std::string arg_actual;
528 EXPECT_FALSE(found[0]->GetArgAsString("arg", &arg_actual));
530 analyzer->MergeAssociatedEventArgs();
531 EXPECT_TRUE(found[0]->GetArgAsString("arg", &arg_actual));
532 EXPECT_STREQ(arg_string, arg_actual.c_str());
535 // Test AssociateAsyncBeginEndEvents
536 TEST_F(TraceEventAnalyzerTest, AsyncBeginEndAssocations) {
537 ManualSetUp();
539 BeginTracing();
541 TRACE_EVENT_ASYNC_END0("cat1", "name1", 0xA); // no match / out of order
542 TRACE_EVENT_ASYNC_BEGIN0("cat1", "name1", 0xB);
543 TRACE_EVENT_ASYNC_BEGIN0("cat1", "name1", 0xC);
544 TRACE_EVENT_INSTANT0("cat1", "name1", TRACE_EVENT_SCOPE_THREAD); // noise
545 TRACE_EVENT0("cat1", "name1"); // noise
546 TRACE_EVENT_ASYNC_END0("cat1", "name1", 0xB);
547 TRACE_EVENT_ASYNC_END0("cat1", "name1", 0xC);
548 TRACE_EVENT_ASYNC_BEGIN0("cat1", "name1", 0xA); // no match / out of order
550 EndTracing();
552 scoped_ptr<TraceAnalyzer>
553 analyzer(TraceAnalyzer::Create(output_.json_output));
554 ASSERT_TRUE(analyzer.get());
555 analyzer->AssociateAsyncBeginEndEvents();
557 TraceEventVector found;
558 analyzer->FindEvents(Query::MatchAsyncBeginWithNext(), &found);
559 ASSERT_EQ(2u, found.size());
560 EXPECT_STRCASEEQ("0xb", found[0]->id.c_str());
561 EXPECT_STRCASEEQ("0xc", found[1]->id.c_str());
564 // Test AssociateAsyncBeginEndEvents
565 TEST_F(TraceEventAnalyzerTest, AsyncBeginEndAssocationsWithSteps) {
566 ManualSetUp();
568 BeginTracing();
570 TRACE_EVENT_ASYNC_STEP_INTO0("c", "n", 0xA, "s1");
571 TRACE_EVENT_ASYNC_END0("c", "n", 0xA);
572 TRACE_EVENT_ASYNC_BEGIN0("c", "n", 0xB);
573 TRACE_EVENT_ASYNC_BEGIN0("c", "n", 0xC);
574 TRACE_EVENT_ASYNC_STEP_PAST0("c", "n", 0xB, "s1");
575 TRACE_EVENT_ASYNC_STEP_INTO0("c", "n", 0xC, "s1");
576 TRACE_EVENT_ASYNC_STEP_INTO1("c", "n", 0xC, "s2", "a", 1);
577 TRACE_EVENT_ASYNC_END0("c", "n", 0xB);
578 TRACE_EVENT_ASYNC_END0("c", "n", 0xC);
579 TRACE_EVENT_ASYNC_BEGIN0("c", "n", 0xA);
580 TRACE_EVENT_ASYNC_STEP_INTO0("c", "n", 0xA, "s2");
582 EndTracing();
584 scoped_ptr<TraceAnalyzer>
585 analyzer(TraceAnalyzer::Create(output_.json_output));
586 ASSERT_TRUE(analyzer.get());
587 analyzer->AssociateAsyncBeginEndEvents();
589 TraceEventVector found;
590 analyzer->FindEvents(Query::MatchAsyncBeginWithNext(), &found);
591 ASSERT_EQ(3u, found.size());
593 EXPECT_STRCASEEQ("0xb", found[0]->id.c_str());
594 EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP_PAST, found[0]->other_event->phase);
595 EXPECT_TRUE(found[0]->other_event->other_event);
596 EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_END,
597 found[0]->other_event->other_event->phase);
599 EXPECT_STRCASEEQ("0xc", found[1]->id.c_str());
600 EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP_INTO, found[1]->other_event->phase);
601 EXPECT_TRUE(found[1]->other_event->other_event);
602 EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP_INTO,
603 found[1]->other_event->other_event->phase);
604 double arg_actual = 0;
605 EXPECT_TRUE(found[1]->other_event->other_event->GetArgAsNumber(
606 "a", &arg_actual));
607 EXPECT_EQ(1.0, arg_actual);
608 EXPECT_TRUE(found[1]->other_event->other_event->other_event);
609 EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_END,
610 found[1]->other_event->other_event->other_event->phase);
612 EXPECT_STRCASEEQ("0xa", found[2]->id.c_str());
613 EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP_INTO, found[2]->other_event->phase);
616 // Test that the TraceAnalyzer custom associations work.
617 TEST_F(TraceEventAnalyzerTest, CustomAssociations) {
618 ManualSetUp();
620 // Add events that begin/end in pipelined ordering with unique ID parameter
621 // to match up the begin/end pairs.
622 BeginTracing();
624 // no begin match
625 TRACE_EVENT_INSTANT1("cat1", "end", TRACE_EVENT_SCOPE_THREAD, "id", 1);
626 // end is cat4
627 TRACE_EVENT_INSTANT1("cat2", "begin", TRACE_EVENT_SCOPE_THREAD, "id", 2);
628 // end is cat5
629 TRACE_EVENT_INSTANT1("cat3", "begin", TRACE_EVENT_SCOPE_THREAD, "id", 3);
630 TRACE_EVENT_INSTANT1("cat4", "end", TRACE_EVENT_SCOPE_THREAD, "id", 2);
631 TRACE_EVENT_INSTANT1("cat5", "end", TRACE_EVENT_SCOPE_THREAD, "id", 3);
632 // no end match
633 TRACE_EVENT_INSTANT1("cat6", "begin", TRACE_EVENT_SCOPE_THREAD, "id", 1);
635 EndTracing();
637 scoped_ptr<TraceAnalyzer>
638 analyzer(TraceAnalyzer::Create(output_.json_output));
639 ASSERT_TRUE(analyzer.get());
641 // begin, end, and match queries to find proper begin/end pairs.
642 Query begin(Query::EventName() == Query::String("begin"));
643 Query end(Query::EventName() == Query::String("end"));
644 Query match(Query::EventArg("id") == Query::OtherArg("id"));
645 analyzer->AssociateEvents(begin, end, match);
647 TraceEventVector found;
649 // cat1 has no other_event.
650 analyzer->FindEvents(Query::EventCategory() == Query::String("cat1") &&
651 Query::EventHasOther(), &found);
652 EXPECT_EQ(0u, found.size());
654 // cat1 has no other_event.
655 analyzer->FindEvents(Query::EventCategory() == Query::String("cat1") &&
656 !Query::EventHasOther(), &found);
657 EXPECT_EQ(1u, found.size());
659 // cat6 has no other_event.
660 analyzer->FindEvents(Query::EventCategory() == Query::String("cat6") &&
661 !Query::EventHasOther(), &found);
662 EXPECT_EQ(1u, found.size());
664 // cat2 and cat4 are associated.
665 analyzer->FindEvents(Query::EventCategory() == Query::String("cat2") &&
666 Query::OtherCategory() == Query::String("cat4"), &found);
667 EXPECT_EQ(1u, found.size());
669 // cat4 and cat2 are not associated.
670 analyzer->FindEvents(Query::EventCategory() == Query::String("cat4") &&
671 Query::OtherCategory() == Query::String("cat2"), &found);
672 EXPECT_EQ(0u, found.size());
674 // cat3 and cat5 are associated.
675 analyzer->FindEvents(Query::EventCategory() == Query::String("cat3") &&
676 Query::OtherCategory() == Query::String("cat5"), &found);
677 EXPECT_EQ(1u, found.size());
679 // cat5 and cat3 are not associated.
680 analyzer->FindEvents(Query::EventCategory() == Query::String("cat5") &&
681 Query::OtherCategory() == Query::String("cat3"), &found);
682 EXPECT_EQ(0u, found.size());
685 // Verify that Query literals and types are properly casted.
686 TEST_F(TraceEventAnalyzerTest, Literals) {
687 ManualSetUp();
689 // Since these queries don't refer to the event data, the dummy event below
690 // will never be accessed.
691 TraceEvent dummy;
692 char char_num = 5;
693 short short_num = -5;
694 EXPECT_TRUE((Query::Double(5.0) == Query::Int(char_num)).Evaluate(dummy));
695 EXPECT_TRUE((Query::Double(-5.0) == Query::Int(short_num)).Evaluate(dummy));
696 EXPECT_TRUE((Query::Double(1.0) == Query::Uint(1u)).Evaluate(dummy));
697 EXPECT_TRUE((Query::Double(1.0) == Query::Int(1)).Evaluate(dummy));
698 EXPECT_TRUE((Query::Double(-1.0) == Query::Int(-1)).Evaluate(dummy));
699 EXPECT_TRUE((Query::Double(1.0) == Query::Double(1.0f)).Evaluate(dummy));
700 EXPECT_TRUE((Query::Bool(true) == Query::Int(1)).Evaluate(dummy));
701 EXPECT_TRUE((Query::Bool(false) == Query::Int(0)).Evaluate(dummy));
702 EXPECT_TRUE((Query::Bool(true) == Query::Double(1.0f)).Evaluate(dummy));
703 EXPECT_TRUE((Query::Bool(false) == Query::Double(0.0f)).Evaluate(dummy));
706 // Test GetRateStats.
707 TEST_F(TraceEventAnalyzerTest, RateStats) {
708 std::vector<TraceEvent> events;
709 events.reserve(100);
710 TraceEventVector event_ptrs;
711 TraceEvent event;
712 event.timestamp = 0.0;
713 double little_delta = 1.0;
714 double big_delta = 10.0;
715 double tiny_delta = 0.1;
716 RateStats stats;
717 RateStatsOptions options;
719 // Insert 10 events, each apart by little_delta.
720 for (int i = 0; i < 10; ++i) {
721 event.timestamp += little_delta;
722 events.push_back(event);
723 event_ptrs.push_back(&events.back());
726 ASSERT_TRUE(GetRateStats(event_ptrs, &stats, NULL));
727 EXPECT_EQ(little_delta, stats.mean_us);
728 EXPECT_EQ(little_delta, stats.min_us);
729 EXPECT_EQ(little_delta, stats.max_us);
730 EXPECT_EQ(0.0, stats.standard_deviation_us);
732 // Add an event apart by big_delta.
733 event.timestamp += big_delta;
734 events.push_back(event);
735 event_ptrs.push_back(&events.back());
737 ASSERT_TRUE(GetRateStats(event_ptrs, &stats, NULL));
738 EXPECT_LT(little_delta, stats.mean_us);
739 EXPECT_EQ(little_delta, stats.min_us);
740 EXPECT_EQ(big_delta, stats.max_us);
741 EXPECT_LT(0.0, stats.standard_deviation_us);
743 // Trim off the biggest delta and verify stats.
744 options.trim_min = 0;
745 options.trim_max = 1;
746 ASSERT_TRUE(GetRateStats(event_ptrs, &stats, &options));
747 EXPECT_EQ(little_delta, stats.mean_us);
748 EXPECT_EQ(little_delta, stats.min_us);
749 EXPECT_EQ(little_delta, stats.max_us);
750 EXPECT_EQ(0.0, stats.standard_deviation_us);
752 // Add an event apart by tiny_delta.
753 event.timestamp += tiny_delta;
754 events.push_back(event);
755 event_ptrs.push_back(&events.back());
757 // Trim off both the biggest and tiniest delta and verify stats.
758 options.trim_min = 1;
759 options.trim_max = 1;
760 ASSERT_TRUE(GetRateStats(event_ptrs, &stats, &options));
761 EXPECT_EQ(little_delta, stats.mean_us);
762 EXPECT_EQ(little_delta, stats.min_us);
763 EXPECT_EQ(little_delta, stats.max_us);
764 EXPECT_EQ(0.0, stats.standard_deviation_us);
766 // Verify smallest allowed number of events.
767 TraceEventVector few_event_ptrs;
768 few_event_ptrs.push_back(&event);
769 few_event_ptrs.push_back(&event);
770 ASSERT_FALSE(GetRateStats(few_event_ptrs, &stats, NULL));
771 few_event_ptrs.push_back(&event);
772 ASSERT_TRUE(GetRateStats(few_event_ptrs, &stats, NULL));
774 // Trim off more than allowed and verify failure.
775 options.trim_min = 0;
776 options.trim_max = 1;
777 ASSERT_FALSE(GetRateStats(few_event_ptrs, &stats, &options));
780 // Test FindFirstOf and FindLastOf.
781 TEST_F(TraceEventAnalyzerTest, FindOf) {
782 size_t num_events = 100;
783 size_t index = 0;
784 TraceEventVector event_ptrs;
785 EXPECT_FALSE(FindFirstOf(event_ptrs, Query::Bool(true), 0, &index));
786 EXPECT_FALSE(FindFirstOf(event_ptrs, Query::Bool(true), 10, &index));
787 EXPECT_FALSE(FindLastOf(event_ptrs, Query::Bool(true), 0, &index));
788 EXPECT_FALSE(FindLastOf(event_ptrs, Query::Bool(true), 10, &index));
790 std::vector<TraceEvent> events;
791 events.resize(num_events);
792 for (size_t i = 0; i < events.size(); ++i)
793 event_ptrs.push_back(&events[i]);
794 size_t bam_index = num_events/2;
795 events[bam_index].name = "bam";
796 Query query_bam = Query::EventName() == Query::String(events[bam_index].name);
798 // FindFirstOf
799 EXPECT_FALSE(FindFirstOf(event_ptrs, Query::Bool(false), 0, &index));
800 EXPECT_TRUE(FindFirstOf(event_ptrs, Query::Bool(true), 0, &index));
801 EXPECT_EQ(0u, index);
802 EXPECT_TRUE(FindFirstOf(event_ptrs, Query::Bool(true), 5, &index));
803 EXPECT_EQ(5u, index);
805 EXPECT_FALSE(FindFirstOf(event_ptrs, query_bam, bam_index + 1, &index));
806 EXPECT_TRUE(FindFirstOf(event_ptrs, query_bam, 0, &index));
807 EXPECT_EQ(bam_index, index);
808 EXPECT_TRUE(FindFirstOf(event_ptrs, query_bam, bam_index, &index));
809 EXPECT_EQ(bam_index, index);
811 // FindLastOf
812 EXPECT_FALSE(FindLastOf(event_ptrs, Query::Bool(false), 1000, &index));
813 EXPECT_TRUE(FindLastOf(event_ptrs, Query::Bool(true), 1000, &index));
814 EXPECT_EQ(num_events - 1, index);
815 EXPECT_TRUE(FindLastOf(event_ptrs, Query::Bool(true), num_events - 5,
816 &index));
817 EXPECT_EQ(num_events - 5, index);
819 EXPECT_FALSE(FindLastOf(event_ptrs, query_bam, bam_index - 1, &index));
820 EXPECT_TRUE(FindLastOf(event_ptrs, query_bam, num_events, &index));
821 EXPECT_EQ(bam_index, index);
822 EXPECT_TRUE(FindLastOf(event_ptrs, query_bam, bam_index, &index));
823 EXPECT_EQ(bam_index, index);
826 // Test FindClosest.
827 TEST_F(TraceEventAnalyzerTest, FindClosest) {
828 size_t index_1 = 0;
829 size_t index_2 = 0;
830 TraceEventVector event_ptrs;
831 EXPECT_FALSE(FindClosest(event_ptrs, Query::Bool(true), 0,
832 &index_1, &index_2));
834 size_t num_events = 5;
835 std::vector<TraceEvent> events;
836 events.resize(num_events);
837 for (size_t i = 0; i < events.size(); ++i) {
838 // timestamps go up exponentially so the lower index is always closer in
839 // time than the higher index.
840 events[i].timestamp = static_cast<double>(i) * static_cast<double>(i);
841 event_ptrs.push_back(&events[i]);
843 events[0].name = "one";
844 events[2].name = "two";
845 events[4].name = "three";
846 Query query_named = Query::EventName() != Query::String(std::string());
847 Query query_one = Query::EventName() == Query::String("one");
849 // Only one event matches query_one, so two closest can't be found.
850 EXPECT_FALSE(FindClosest(event_ptrs, query_one, 0, &index_1, &index_2));
852 EXPECT_TRUE(FindClosest(event_ptrs, query_one, 3, &index_1, NULL));
853 EXPECT_EQ(0u, index_1);
855 EXPECT_TRUE(FindClosest(event_ptrs, query_named, 1, &index_1, &index_2));
856 EXPECT_EQ(0u, index_1);
857 EXPECT_EQ(2u, index_2);
859 EXPECT_TRUE(FindClosest(event_ptrs, query_named, 4, &index_1, &index_2));
860 EXPECT_EQ(4u, index_1);
861 EXPECT_EQ(2u, index_2);
863 EXPECT_TRUE(FindClosest(event_ptrs, query_named, 3, &index_1, &index_2));
864 EXPECT_EQ(2u, index_1);
865 EXPECT_EQ(0u, index_2);
868 // Test CountMatches.
869 TEST_F(TraceEventAnalyzerTest, CountMatches) {
870 TraceEventVector event_ptrs;
871 EXPECT_EQ(0u, CountMatches(event_ptrs, Query::Bool(true), 0, 10));
873 size_t num_events = 5;
874 size_t num_named = 3;
875 std::vector<TraceEvent> events;
876 events.resize(num_events);
877 for (size_t i = 0; i < events.size(); ++i)
878 event_ptrs.push_back(&events[i]);
879 events[0].name = "one";
880 events[2].name = "two";
881 events[4].name = "three";
882 Query query_named = Query::EventName() != Query::String(std::string());
883 Query query_one = Query::EventName() == Query::String("one");
885 EXPECT_EQ(0u, CountMatches(event_ptrs, Query::Bool(false)));
886 EXPECT_EQ(num_events, CountMatches(event_ptrs, Query::Bool(true)));
887 EXPECT_EQ(num_events - 1, CountMatches(event_ptrs, Query::Bool(true),
888 1, num_events));
889 EXPECT_EQ(1u, CountMatches(event_ptrs, query_one));
890 EXPECT_EQ(num_events - 1, CountMatches(event_ptrs, !query_one));
891 EXPECT_EQ(num_named, CountMatches(event_ptrs, query_named));
895 } // namespace trace_analyzer