| // Copyright (c) 2012 The Chromium Authors. All rights reserved. |
| // Use of this source code is governed by a BSD-style license that can be |
| // found in the LICENSE file. |
| |
| #include "base/test/trace_event_analyzer.h" |
| |
| #include "base/bind.h" |
| #include "base/memory/ptr_util.h" |
| #include "base/memory/ref_counted_memory.h" |
| #include "base/synchronization/waitable_event.h" |
| #include "base/threading/platform_thread.h" |
| #include "base/trace_event/trace_buffer.h" |
| #include "base/trace_event/trace_event_argument.h" |
| #include "starboard/types.h" |
| #include "testing/gmock/include/gmock/gmock.h" |
| #include "testing/gtest/include/gtest/gtest.h" |
| |
| namespace trace_analyzer { |
| |
| namespace { |
| |
| class TraceEventAnalyzerTest : public testing::Test { |
| public: |
| void ManualSetUp(); |
| void OnTraceDataCollected( |
| base::WaitableEvent* flush_complete_event, |
| const scoped_refptr<base::RefCountedString>& json_events_str, |
| bool has_more_events); |
| void BeginTracing(); |
| void EndTracing(); |
| |
| base::trace_event::TraceResultBuffer::SimpleOutput output_; |
| base::trace_event::TraceResultBuffer buffer_; |
| }; |
| |
| void TraceEventAnalyzerTest::ManualSetUp() { |
| ASSERT_TRUE(base::trace_event::TraceLog::GetInstance()); |
| buffer_.SetOutputCallback(output_.GetCallback()); |
| output_.json_output.clear(); |
| } |
| |
| void TraceEventAnalyzerTest::OnTraceDataCollected( |
| base::WaitableEvent* flush_complete_event, |
| const scoped_refptr<base::RefCountedString>& json_events_str, |
| bool has_more_events) { |
| buffer_.AddFragment(json_events_str->data()); |
| if (!has_more_events) |
| flush_complete_event->Signal(); |
| } |
| |
| void TraceEventAnalyzerTest::BeginTracing() { |
| output_.json_output.clear(); |
| buffer_.Start(); |
| base::trace_event::TraceLog::GetInstance()->SetEnabled( |
| base::trace_event::TraceConfig("*", ""), |
| base::trace_event::TraceLog::RECORDING_MODE); |
| } |
| |
| void TraceEventAnalyzerTest::EndTracing() { |
| base::trace_event::TraceLog::GetInstance()->SetDisabled(); |
| base::WaitableEvent flush_complete_event( |
| base::WaitableEvent::ResetPolicy::AUTOMATIC, |
| base::WaitableEvent::InitialState::NOT_SIGNALED); |
| base::trace_event::TraceLog::GetInstance()->Flush( |
| base::Bind(&TraceEventAnalyzerTest::OnTraceDataCollected, |
| base::Unretained(this), |
| base::Unretained(&flush_complete_event))); |
| flush_complete_event.Wait(); |
| buffer_.Finish(); |
| } |
| |
| } // namespace |
| |
| TEST_F(TraceEventAnalyzerTest, NoEvents) { |
| ManualSetUp(); |
| |
| // Create an empty JSON event string: |
| buffer_.Start(); |
| buffer_.Finish(); |
| |
| std::unique_ptr<TraceAnalyzer> analyzer( |
| TraceAnalyzer::Create(output_.json_output)); |
| ASSERT_TRUE(analyzer.get()); |
| |
| // Search for all events and verify that nothing is returned. |
| TraceEventVector found; |
| analyzer->FindEvents(Query::Bool(true), &found); |
| EXPECT_EQ(0u, found.size()); |
| } |
| |
| TEST_F(TraceEventAnalyzerTest, TraceEvent) { |
| ManualSetUp(); |
| |
| int int_num = 2; |
| double double_num = 3.5; |
| const char str[] = "the string"; |
| |
| TraceEvent event; |
| event.arg_numbers["false"] = 0.0; |
| event.arg_numbers["true"] = 1.0; |
| event.arg_numbers["int"] = static_cast<double>(int_num); |
| event.arg_numbers["double"] = double_num; |
| event.arg_strings["string"] = str; |
| event.arg_values["dict"] = WrapUnique(new base::DictionaryValue()); |
| |
| ASSERT_TRUE(event.HasNumberArg("false")); |
| ASSERT_TRUE(event.HasNumberArg("true")); |
| ASSERT_TRUE(event.HasNumberArg("int")); |
| ASSERT_TRUE(event.HasNumberArg("double")); |
| ASSERT_TRUE(event.HasStringArg("string")); |
| ASSERT_FALSE(event.HasNumberArg("notfound")); |
| ASSERT_FALSE(event.HasStringArg("notfound")); |
| ASSERT_TRUE(event.HasArg("dict")); |
| ASSERT_FALSE(event.HasArg("notfound")); |
| |
| EXPECT_FALSE(event.GetKnownArgAsBool("false")); |
| EXPECT_TRUE(event.GetKnownArgAsBool("true")); |
| EXPECT_EQ(int_num, event.GetKnownArgAsInt("int")); |
| EXPECT_EQ(double_num, event.GetKnownArgAsDouble("double")); |
| EXPECT_STREQ(str, event.GetKnownArgAsString("string").c_str()); |
| |
| std::unique_ptr<base::Value> arg; |
| EXPECT_TRUE(event.GetArgAsValue("dict", &arg)); |
| EXPECT_EQ(base::Value::Type::DICTIONARY, arg->type()); |
| } |
| |
| TEST_F(TraceEventAnalyzerTest, QueryEventMember) { |
| ManualSetUp(); |
| |
| TraceEvent event; |
| event.thread.process_id = 3; |
| event.thread.thread_id = 4; |
| event.timestamp = 1.5; |
| event.phase = TRACE_EVENT_PHASE_BEGIN; |
| event.category = "category"; |
| event.name = "name"; |
| event.id = "1"; |
| event.arg_numbers["num"] = 7.0; |
| event.arg_strings["str"] = "the string"; |
| |
| // Other event with all different members: |
| TraceEvent other; |
| other.thread.process_id = 5; |
| other.thread.thread_id = 6; |
| other.timestamp = 2.5; |
| other.phase = TRACE_EVENT_PHASE_END; |
| other.category = "category2"; |
| other.name = "name2"; |
| other.id = "2"; |
| other.arg_numbers["num2"] = 8.0; |
| other.arg_strings["str2"] = "the string 2"; |
| |
| event.other_event = &other; |
| ASSERT_TRUE(event.has_other_event()); |
| double duration = event.GetAbsTimeToOtherEvent(); |
| |
| Query event_pid = Query::EventPidIs(event.thread.process_id); |
| Query event_tid = Query::EventTidIs(event.thread.thread_id); |
| Query event_time = Query::EventTimeIs(event.timestamp); |
| Query event_duration = Query::EventDurationIs(duration); |
| Query event_phase = Query::EventPhaseIs(event.phase); |
| Query event_category = Query::EventCategoryIs(event.category); |
| Query event_name = Query::EventNameIs(event.name); |
| Query event_id = Query::EventIdIs(event.id); |
| Query event_has_arg1 = Query::EventHasNumberArg("num"); |
| Query event_has_arg2 = Query::EventHasStringArg("str"); |
| Query event_arg1 = |
| (Query::EventArg("num") == Query::Double(event.arg_numbers["num"])); |
| Query event_arg2 = |
| (Query::EventArg("str") == Query::String(event.arg_strings["str"])); |
| Query event_has_other = Query::EventHasOther(); |
| Query other_pid = Query::OtherPidIs(other.thread.process_id); |
| Query other_tid = Query::OtherTidIs(other.thread.thread_id); |
| Query other_time = Query::OtherTimeIs(other.timestamp); |
| Query other_phase = Query::OtherPhaseIs(other.phase); |
| Query other_category = Query::OtherCategoryIs(other.category); |
| Query other_name = Query::OtherNameIs(other.name); |
| Query other_id = Query::OtherIdIs(other.id); |
| Query other_has_arg1 = Query::OtherHasNumberArg("num2"); |
| Query other_has_arg2 = Query::OtherHasStringArg("str2"); |
| Query other_arg1 = |
| (Query::OtherArg("num2") == Query::Double(other.arg_numbers["num2"])); |
| Query other_arg2 = |
| (Query::OtherArg("str2") == Query::String(other.arg_strings["str2"])); |
| |
| EXPECT_TRUE(event_pid.Evaluate(event)); |
| EXPECT_TRUE(event_tid.Evaluate(event)); |
| EXPECT_TRUE(event_time.Evaluate(event)); |
| EXPECT_TRUE(event_duration.Evaluate(event)); |
| EXPECT_TRUE(event_phase.Evaluate(event)); |
| EXPECT_TRUE(event_category.Evaluate(event)); |
| EXPECT_TRUE(event_name.Evaluate(event)); |
| EXPECT_TRUE(event_id.Evaluate(event)); |
| EXPECT_TRUE(event_has_arg1.Evaluate(event)); |
| EXPECT_TRUE(event_has_arg2.Evaluate(event)); |
| EXPECT_TRUE(event_arg1.Evaluate(event)); |
| EXPECT_TRUE(event_arg2.Evaluate(event)); |
| EXPECT_TRUE(event_has_other.Evaluate(event)); |
| EXPECT_TRUE(other_pid.Evaluate(event)); |
| EXPECT_TRUE(other_tid.Evaluate(event)); |
| EXPECT_TRUE(other_time.Evaluate(event)); |
| EXPECT_TRUE(other_phase.Evaluate(event)); |
| EXPECT_TRUE(other_category.Evaluate(event)); |
| EXPECT_TRUE(other_name.Evaluate(event)); |
| EXPECT_TRUE(other_id.Evaluate(event)); |
| EXPECT_TRUE(other_has_arg1.Evaluate(event)); |
| EXPECT_TRUE(other_has_arg2.Evaluate(event)); |
| EXPECT_TRUE(other_arg1.Evaluate(event)); |
| EXPECT_TRUE(other_arg2.Evaluate(event)); |
| |
| // Evaluate event queries against other to verify the queries fail when the |
| // event members are wrong. |
| EXPECT_FALSE(event_pid.Evaluate(other)); |
| EXPECT_FALSE(event_tid.Evaluate(other)); |
| EXPECT_FALSE(event_time.Evaluate(other)); |
| EXPECT_FALSE(event_duration.Evaluate(other)); |
| EXPECT_FALSE(event_phase.Evaluate(other)); |
| EXPECT_FALSE(event_category.Evaluate(other)); |
| EXPECT_FALSE(event_name.Evaluate(other)); |
| EXPECT_FALSE(event_id.Evaluate(other)); |
| EXPECT_FALSE(event_has_arg1.Evaluate(other)); |
| EXPECT_FALSE(event_has_arg2.Evaluate(other)); |
| EXPECT_FALSE(event_arg1.Evaluate(other)); |
| EXPECT_FALSE(event_arg2.Evaluate(other)); |
| EXPECT_FALSE(event_has_other.Evaluate(other)); |
| } |
| |
| TEST_F(TraceEventAnalyzerTest, BooleanOperators) { |
| ManualSetUp(); |
| |
| BeginTracing(); |
| { |
| TRACE_EVENT_INSTANT1("cat1", "name1", TRACE_EVENT_SCOPE_THREAD, "num", 1); |
| TRACE_EVENT_INSTANT1("cat1", "name2", TRACE_EVENT_SCOPE_THREAD, "num", 2); |
| TRACE_EVENT_INSTANT1("cat2", "name3", TRACE_EVENT_SCOPE_THREAD, "num", 3); |
| TRACE_EVENT_INSTANT1("cat2", "name4", TRACE_EVENT_SCOPE_THREAD, "num", 4); |
| } |
| EndTracing(); |
| |
| std::unique_ptr<TraceAnalyzer> analyzer( |
| TraceAnalyzer::Create(output_.json_output)); |
| ASSERT_TRUE(analyzer); |
| analyzer->SetIgnoreMetadataEvents(true); |
| |
| TraceEventVector found; |
| |
| // == |
| |
| analyzer->FindEvents(Query::EventCategory() == Query::String("cat1"), &found); |
| ASSERT_EQ(2u, found.size()); |
| EXPECT_STREQ("name1", found[0]->name.c_str()); |
| EXPECT_STREQ("name2", found[1]->name.c_str()); |
| |
| analyzer->FindEvents(Query::EventArg("num") == Query::Int(2), &found); |
| ASSERT_EQ(1u, found.size()); |
| EXPECT_STREQ("name2", found[0]->name.c_str()); |
| |
| // != |
| |
| analyzer->FindEvents(Query::EventCategory() != Query::String("cat1"), &found); |
| ASSERT_EQ(2u, found.size()); |
| EXPECT_STREQ("name3", found[0]->name.c_str()); |
| EXPECT_STREQ("name4", found[1]->name.c_str()); |
| |
| analyzer->FindEvents(Query::EventArg("num") != Query::Int(2), &found); |
| ASSERT_EQ(3u, found.size()); |
| EXPECT_STREQ("name1", found[0]->name.c_str()); |
| EXPECT_STREQ("name3", found[1]->name.c_str()); |
| EXPECT_STREQ("name4", found[2]->name.c_str()); |
| |
| // < |
| analyzer->FindEvents(Query::EventArg("num") < Query::Int(2), &found); |
| ASSERT_EQ(1u, found.size()); |
| EXPECT_STREQ("name1", found[0]->name.c_str()); |
| |
| // <= |
| analyzer->FindEvents(Query::EventArg("num") <= Query::Int(2), &found); |
| ASSERT_EQ(2u, found.size()); |
| EXPECT_STREQ("name1", found[0]->name.c_str()); |
| EXPECT_STREQ("name2", found[1]->name.c_str()); |
| |
| // > |
| analyzer->FindEvents(Query::EventArg("num") > Query::Int(3), &found); |
| ASSERT_EQ(1u, found.size()); |
| EXPECT_STREQ("name4", found[0]->name.c_str()); |
| |
| // >= |
| analyzer->FindEvents(Query::EventArg("num") >= Query::Int(4), &found); |
| ASSERT_EQ(1u, found.size()); |
| EXPECT_STREQ("name4", found[0]->name.c_str()); |
| |
| // && |
| analyzer->FindEvents(Query::EventName() != Query::String("name1") && |
| Query::EventArg("num") < Query::Int(3), &found); |
| ASSERT_EQ(1u, found.size()); |
| EXPECT_STREQ("name2", found[0]->name.c_str()); |
| |
| // || |
| analyzer->FindEvents(Query::EventName() == Query::String("name1") || |
| Query::EventArg("num") == Query::Int(3), &found); |
| ASSERT_EQ(2u, found.size()); |
| EXPECT_STREQ("name1", found[0]->name.c_str()); |
| EXPECT_STREQ("name3", found[1]->name.c_str()); |
| |
| // ! |
| analyzer->FindEvents(!(Query::EventName() == Query::String("name1") || |
| Query::EventArg("num") == Query::Int(3)), &found); |
| ASSERT_EQ(2u, found.size()); |
| EXPECT_STREQ("name2", found[0]->name.c_str()); |
| EXPECT_STREQ("name4", found[1]->name.c_str()); |
| } |
| |
| TEST_F(TraceEventAnalyzerTest, ArithmeticOperators) { |
| ManualSetUp(); |
| |
| BeginTracing(); |
| { |
| // These events are searched for: |
| TRACE_EVENT_INSTANT2("cat1", "math1", TRACE_EVENT_SCOPE_THREAD, |
| "a", 10, "b", 5); |
| TRACE_EVENT_INSTANT2("cat1", "math2", TRACE_EVENT_SCOPE_THREAD, |
| "a", 10, "b", 10); |
| // Extra events that never match, for noise: |
| TRACE_EVENT_INSTANT2("noise", "math3", TRACE_EVENT_SCOPE_THREAD, |
| "a", 1, "b", 3); |
| TRACE_EVENT_INSTANT2("noise", "math4", TRACE_EVENT_SCOPE_THREAD, |
| "c", 10, "d", 5); |
| } |
| EndTracing(); |
| |
| std::unique_ptr<TraceAnalyzer> analyzer( |
| TraceAnalyzer::Create(output_.json_output)); |
| ASSERT_TRUE(analyzer.get()); |
| |
| TraceEventVector found; |
| |
| // Verify that arithmetic operators function: |
| |
| // + |
| analyzer->FindEvents(Query::EventArg("a") + Query::EventArg("b") == |
| Query::Int(20), &found); |
| EXPECT_EQ(1u, found.size()); |
| EXPECT_STREQ("math2", found.front()->name.c_str()); |
| |
| // - |
| analyzer->FindEvents(Query::EventArg("a") - Query::EventArg("b") == |
| Query::Int(5), &found); |
| EXPECT_EQ(1u, found.size()); |
| EXPECT_STREQ("math1", found.front()->name.c_str()); |
| |
| // * |
| analyzer->FindEvents(Query::EventArg("a") * Query::EventArg("b") == |
| Query::Int(50), &found); |
| EXPECT_EQ(1u, found.size()); |
| EXPECT_STREQ("math1", found.front()->name.c_str()); |
| |
| // / |
| analyzer->FindEvents(Query::EventArg("a") / Query::EventArg("b") == |
| Query::Int(2), &found); |
| EXPECT_EQ(1u, found.size()); |
| EXPECT_STREQ("math1", found.front()->name.c_str()); |
| |
| // % |
| analyzer->FindEvents(Query::EventArg("a") % Query::EventArg("b") == |
| Query::Int(0), &found); |
| EXPECT_EQ(2u, found.size()); |
| |
| // - (negate) |
| analyzer->FindEvents(-Query::EventArg("b") == Query::Int(-10), &found); |
| EXPECT_EQ(1u, found.size()); |
| EXPECT_STREQ("math2", found.front()->name.c_str()); |
| } |
| |
| TEST_F(TraceEventAnalyzerTest, StringPattern) { |
| ManualSetUp(); |
| |
| BeginTracing(); |
| { |
| TRACE_EVENT_INSTANT0("cat1", "name1", TRACE_EVENT_SCOPE_THREAD); |
| TRACE_EVENT_INSTANT0("cat1", "name2", TRACE_EVENT_SCOPE_THREAD); |
| TRACE_EVENT_INSTANT0("cat1", "no match", TRACE_EVENT_SCOPE_THREAD); |
| TRACE_EVENT_INSTANT0("cat1", "name3x", TRACE_EVENT_SCOPE_THREAD); |
| } |
| EndTracing(); |
| |
| std::unique_ptr<TraceAnalyzer> analyzer( |
| TraceAnalyzer::Create(output_.json_output)); |
| ASSERT_TRUE(analyzer.get()); |
| analyzer->SetIgnoreMetadataEvents(true); |
| |
| TraceEventVector found; |
| |
| analyzer->FindEvents(Query::EventName() == Query::Pattern("name?"), &found); |
| ASSERT_EQ(2u, found.size()); |
| EXPECT_STREQ("name1", found[0]->name.c_str()); |
| EXPECT_STREQ("name2", found[1]->name.c_str()); |
| |
| analyzer->FindEvents(Query::EventName() == Query::Pattern("name*"), &found); |
| ASSERT_EQ(3u, found.size()); |
| EXPECT_STREQ("name1", found[0]->name.c_str()); |
| EXPECT_STREQ("name2", found[1]->name.c_str()); |
| EXPECT_STREQ("name3x", found[2]->name.c_str()); |
| |
| analyzer->FindEvents(Query::EventName() != Query::Pattern("name*"), &found); |
| ASSERT_EQ(1u, found.size()); |
| EXPECT_STREQ("no match", found[0]->name.c_str()); |
| } |
| |
| // Test that duration queries work. |
| TEST_F(TraceEventAnalyzerTest, BeginEndDuration) { |
| ManualSetUp(); |
| |
| const base::TimeDelta kSleepTime = base::TimeDelta::FromMilliseconds(200); |
| // We will search for events that have a duration of greater than 90% of the |
| // sleep time, so that there is no flakiness. |
| int64_t duration_cutoff_us = (kSleepTime.InMicroseconds() * 9) / 10; |
| |
| BeginTracing(); |
| { |
| TRACE_EVENT_BEGIN0("cat1", "name1"); // found by duration query |
| TRACE_EVENT_BEGIN0("noise", "name2"); // not searched for, just noise |
| { |
| TRACE_EVENT_BEGIN0("cat2", "name3"); // found by duration query |
| // next event not searched for, just noise |
| TRACE_EVENT_INSTANT0("noise", "name4", TRACE_EVENT_SCOPE_THREAD); |
| base::PlatformThread::Sleep(kSleepTime); |
| TRACE_EVENT_BEGIN0("cat2", "name5"); // not found (duration too short) |
| TRACE_EVENT_END0("cat2", "name5"); // not found (duration too short) |
| TRACE_EVENT_END0("cat2", "name3"); // found by duration query |
| } |
| TRACE_EVENT_END0("noise", "name2"); // not searched for, just noise |
| TRACE_EVENT_END0("cat1", "name1"); // found by duration query |
| } |
| EndTracing(); |
| |
| std::unique_ptr<TraceAnalyzer> analyzer( |
| TraceAnalyzer::Create(output_.json_output)); |
| ASSERT_TRUE(analyzer.get()); |
| analyzer->AssociateBeginEndEvents(); |
| |
| TraceEventVector found; |
| analyzer->FindEvents( |
| Query::MatchBeginWithEnd() && |
| Query::EventDuration() > |
| Query::Int(static_cast<int>(duration_cutoff_us)) && |
| (Query::EventCategory() == Query::String("cat1") || |
| Query::EventCategory() == Query::String("cat2") || |
| Query::EventCategory() == Query::String("cat3")), |
| &found); |
| ASSERT_EQ(2u, found.size()); |
| EXPECT_STREQ("name1", found[0]->name.c_str()); |
| EXPECT_STREQ("name3", found[1]->name.c_str()); |
| } |
| |
| // Test that duration queries work. |
| TEST_F(TraceEventAnalyzerTest, CompleteDuration) { |
| ManualSetUp(); |
| |
| const base::TimeDelta kSleepTime = base::TimeDelta::FromMilliseconds(200); |
| // We will search for events that have a duration of greater than 90% of the |
| // sleep time, so that there is no flakiness. |
| int64_t duration_cutoff_us = (kSleepTime.InMicroseconds() * 9) / 10; |
| |
| BeginTracing(); |
| { |
| TRACE_EVENT0("cat1", "name1"); // found by duration query |
| TRACE_EVENT0("noise", "name2"); // not searched for, just noise |
| { |
| TRACE_EVENT0("cat2", "name3"); // found by duration query |
| // next event not searched for, just noise |
| TRACE_EVENT_INSTANT0("noise", "name4", TRACE_EVENT_SCOPE_THREAD); |
| base::PlatformThread::Sleep(kSleepTime); |
| TRACE_EVENT0("cat2", "name5"); // not found (duration too short) |
| } |
| } |
| EndTracing(); |
| |
| std::unique_ptr<TraceAnalyzer> analyzer( |
| TraceAnalyzer::Create(output_.json_output)); |
| ASSERT_TRUE(analyzer.get()); |
| analyzer->AssociateBeginEndEvents(); |
| |
| TraceEventVector found; |
| analyzer->FindEvents( |
| Query::EventCompleteDuration() > |
| Query::Int(static_cast<int>(duration_cutoff_us)) && |
| (Query::EventCategory() == Query::String("cat1") || |
| Query::EventCategory() == Query::String("cat2") || |
| Query::EventCategory() == Query::String("cat3")), |
| &found); |
| ASSERT_EQ(2u, found.size()); |
| EXPECT_STREQ("name1", found[0]->name.c_str()); |
| EXPECT_STREQ("name3", found[1]->name.c_str()); |
| } |
| |
| // Test AssociateBeginEndEvents |
| TEST_F(TraceEventAnalyzerTest, BeginEndAssocations) { |
| ManualSetUp(); |
| |
| BeginTracing(); |
| { |
| TRACE_EVENT_END0("cat1", "name1"); // does not match out of order begin |
| TRACE_EVENT_BEGIN0("cat1", "name2"); |
| TRACE_EVENT_INSTANT0("cat1", "name3", TRACE_EVENT_SCOPE_THREAD); |
| TRACE_EVENT_BEGIN0("cat1", "name1"); |
| TRACE_EVENT_END0("cat1", "name2"); |
| } |
| EndTracing(); |
| |
| std::unique_ptr<TraceAnalyzer> analyzer( |
| TraceAnalyzer::Create(output_.json_output)); |
| ASSERT_TRUE(analyzer.get()); |
| analyzer->AssociateBeginEndEvents(); |
| |
| TraceEventVector found; |
| analyzer->FindEvents(Query::MatchBeginWithEnd(), &found); |
| ASSERT_EQ(1u, found.size()); |
| EXPECT_STREQ("name2", found[0]->name.c_str()); |
| } |
| |
| // Test MergeAssociatedEventArgs |
| TEST_F(TraceEventAnalyzerTest, MergeAssociatedEventArgs) { |
| ManualSetUp(); |
| |
| const char arg_string[] = "arg_string"; |
| BeginTracing(); |
| { |
| TRACE_EVENT_BEGIN0("cat1", "name1"); |
| TRACE_EVENT_END1("cat1", "name1", "arg", arg_string); |
| } |
| EndTracing(); |
| |
| std::unique_ptr<TraceAnalyzer> analyzer( |
| TraceAnalyzer::Create(output_.json_output)); |
| ASSERT_TRUE(analyzer.get()); |
| analyzer->AssociateBeginEndEvents(); |
| |
| TraceEventVector found; |
| analyzer->FindEvents(Query::MatchBeginName("name1"), &found); |
| ASSERT_EQ(1u, found.size()); |
| std::string arg_actual; |
| EXPECT_FALSE(found[0]->GetArgAsString("arg", &arg_actual)); |
| |
| analyzer->MergeAssociatedEventArgs(); |
| EXPECT_TRUE(found[0]->GetArgAsString("arg", &arg_actual)); |
| EXPECT_STREQ(arg_string, arg_actual.c_str()); |
| } |
| |
| // Test AssociateAsyncBeginEndEvents |
| TEST_F(TraceEventAnalyzerTest, AsyncBeginEndAssocations) { |
| ManualSetUp(); |
| |
| BeginTracing(); |
| { |
| TRACE_EVENT_ASYNC_END0("cat1", "name1", 0xA); // no match / out of order |
| TRACE_EVENT_ASYNC_BEGIN0("cat1", "name1", 0xB); |
| TRACE_EVENT_ASYNC_BEGIN0("cat1", "name1", 0xC); |
| TRACE_EVENT_INSTANT0("cat1", "name1", TRACE_EVENT_SCOPE_THREAD); // noise |
| TRACE_EVENT0("cat1", "name1"); // noise |
| TRACE_EVENT_ASYNC_END0("cat1", "name1", 0xB); |
| TRACE_EVENT_ASYNC_END0("cat1", "name1", 0xC); |
| TRACE_EVENT_ASYNC_BEGIN0("cat1", "name1", 0xA); // no match / out of order |
| } |
| EndTracing(); |
| |
| std::unique_ptr<TraceAnalyzer> analyzer( |
| TraceAnalyzer::Create(output_.json_output)); |
| ASSERT_TRUE(analyzer.get()); |
| analyzer->AssociateAsyncBeginEndEvents(); |
| |
| TraceEventVector found; |
| analyzer->FindEvents(Query::MatchAsyncBeginWithNext(), &found); |
| ASSERT_EQ(2u, found.size()); |
| EXPECT_STRCASEEQ("0xb", found[0]->id.c_str()); |
| EXPECT_STRCASEEQ("0xc", found[1]->id.c_str()); |
| } |
| |
| // Test AssociateAsyncBeginEndEvents |
| TEST_F(TraceEventAnalyzerTest, AsyncBeginEndAssocationsWithSteps) { |
| ManualSetUp(); |
| |
| BeginTracing(); |
| { |
| TRACE_EVENT_ASYNC_STEP_INTO0("c", "n", 0xA, "s1"); |
| TRACE_EVENT_ASYNC_END0("c", "n", 0xA); |
| TRACE_EVENT_ASYNC_BEGIN0("c", "n", 0xB); |
| TRACE_EVENT_ASYNC_BEGIN0("c", "n", 0xC); |
| TRACE_EVENT_ASYNC_STEP_PAST0("c", "n", 0xB, "s1"); |
| TRACE_EVENT_ASYNC_STEP_INTO0("c", "n", 0xC, "s1"); |
| TRACE_EVENT_ASYNC_STEP_INTO1("c", "n", 0xC, "s2", "a", 1); |
| TRACE_EVENT_ASYNC_END0("c", "n", 0xB); |
| TRACE_EVENT_ASYNC_END0("c", "n", 0xC); |
| TRACE_EVENT_ASYNC_BEGIN0("c", "n", 0xA); |
| TRACE_EVENT_ASYNC_STEP_INTO0("c", "n", 0xA, "s2"); |
| } |
| EndTracing(); |
| |
| std::unique_ptr<TraceAnalyzer> analyzer( |
| TraceAnalyzer::Create(output_.json_output)); |
| ASSERT_TRUE(analyzer.get()); |
| analyzer->AssociateAsyncBeginEndEvents(); |
| |
| TraceEventVector found; |
| analyzer->FindEvents(Query::MatchAsyncBeginWithNext(), &found); |
| ASSERT_EQ(3u, found.size()); |
| |
| EXPECT_STRCASEEQ("0xb", found[0]->id.c_str()); |
| EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP_PAST, found[0]->other_event->phase); |
| EXPECT_EQ(found[0], found[0]->other_event->prev_event); |
| EXPECT_TRUE(found[0]->other_event->other_event); |
| EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_END, |
| found[0]->other_event->other_event->phase); |
| EXPECT_EQ(found[0]->other_event, |
| found[0]->other_event->other_event->prev_event); |
| |
| EXPECT_STRCASEEQ("0xc", found[1]->id.c_str()); |
| EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP_INTO, found[1]->other_event->phase); |
| EXPECT_EQ(found[1], found[1]->other_event->prev_event); |
| EXPECT_TRUE(found[1]->other_event->other_event); |
| EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP_INTO, |
| found[1]->other_event->other_event->phase); |
| EXPECT_EQ(found[1]->other_event, |
| found[1]->other_event->other_event->prev_event); |
| double arg_actual = 0; |
| EXPECT_TRUE(found[1]->other_event->other_event->GetArgAsNumber( |
| "a", &arg_actual)); |
| EXPECT_EQ(1.0, arg_actual); |
| EXPECT_TRUE(found[1]->other_event->other_event->other_event); |
| EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_END, |
| found[1]->other_event->other_event->other_event->phase); |
| |
| EXPECT_STRCASEEQ("0xa", found[2]->id.c_str()); |
| EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP_INTO, found[2]->other_event->phase); |
| } |
| |
| // Test that the TraceAnalyzer custom associations work. |
| TEST_F(TraceEventAnalyzerTest, CustomAssociations) { |
| ManualSetUp(); |
| |
| // Add events that begin/end in pipelined ordering with unique ID parameter |
| // to match up the begin/end pairs. |
| BeginTracing(); |
| { |
| // no begin match |
| TRACE_EVENT_INSTANT1("cat1", "end", TRACE_EVENT_SCOPE_THREAD, "id", 1); |
| // end is cat4 |
| TRACE_EVENT_INSTANT1("cat2", "begin", TRACE_EVENT_SCOPE_THREAD, "id", 2); |
| // end is cat5 |
| TRACE_EVENT_INSTANT1("cat3", "begin", TRACE_EVENT_SCOPE_THREAD, "id", 3); |
| TRACE_EVENT_INSTANT1("cat4", "end", TRACE_EVENT_SCOPE_THREAD, "id", 2); |
| TRACE_EVENT_INSTANT1("cat5", "end", TRACE_EVENT_SCOPE_THREAD, "id", 3); |
| // no end match |
| TRACE_EVENT_INSTANT1("cat6", "begin", TRACE_EVENT_SCOPE_THREAD, "id", 1); |
| } |
| EndTracing(); |
| |
| std::unique_ptr<TraceAnalyzer> analyzer( |
| TraceAnalyzer::Create(output_.json_output)); |
| ASSERT_TRUE(analyzer.get()); |
| |
| // begin, end, and match queries to find proper begin/end pairs. |
| Query begin(Query::EventName() == Query::String("begin")); |
| Query end(Query::EventName() == Query::String("end")); |
| Query match(Query::EventArg("id") == Query::OtherArg("id")); |
| analyzer->AssociateEvents(begin, end, match); |
| |
| TraceEventVector found; |
| |
| // cat1 has no other_event. |
| analyzer->FindEvents(Query::EventCategory() == Query::String("cat1") && |
| Query::EventHasOther(), &found); |
| EXPECT_EQ(0u, found.size()); |
| |
| // cat1 has no other_event. |
| analyzer->FindEvents(Query::EventCategory() == Query::String("cat1") && |
| !Query::EventHasOther(), &found); |
| EXPECT_EQ(1u, found.size()); |
| |
| // cat6 has no other_event. |
| analyzer->FindEvents(Query::EventCategory() == Query::String("cat6") && |
| !Query::EventHasOther(), &found); |
| EXPECT_EQ(1u, found.size()); |
| |
| // cat2 and cat4 are associated. |
| analyzer->FindEvents(Query::EventCategory() == Query::String("cat2") && |
| Query::OtherCategory() == Query::String("cat4"), &found); |
| EXPECT_EQ(1u, found.size()); |
| |
| // cat4 and cat2 are not associated. |
| analyzer->FindEvents(Query::EventCategory() == Query::String("cat4") && |
| Query::OtherCategory() == Query::String("cat2"), &found); |
| EXPECT_EQ(0u, found.size()); |
| |
| // cat3 and cat5 are associated. |
| analyzer->FindEvents(Query::EventCategory() == Query::String("cat3") && |
| Query::OtherCategory() == Query::String("cat5"), &found); |
| EXPECT_EQ(1u, found.size()); |
| |
| // cat5 and cat3 are not associated. |
| analyzer->FindEvents(Query::EventCategory() == Query::String("cat5") && |
| Query::OtherCategory() == Query::String("cat3"), &found); |
| EXPECT_EQ(0u, found.size()); |
| } |
| |
| // Verify that Query literals and types are properly casted. |
| TEST_F(TraceEventAnalyzerTest, Literals) { |
| ManualSetUp(); |
| |
| // Since these queries don't refer to the event data, the dummy event below |
| // will never be accessed. |
| TraceEvent dummy; |
| char char_num = 5; |
| short short_num = -5; |
| EXPECT_TRUE((Query::Double(5.0) == Query::Int(char_num)).Evaluate(dummy)); |
| EXPECT_TRUE((Query::Double(-5.0) == Query::Int(short_num)).Evaluate(dummy)); |
| EXPECT_TRUE((Query::Double(1.0) == Query::Uint(1u)).Evaluate(dummy)); |
| EXPECT_TRUE((Query::Double(1.0) == Query::Int(1)).Evaluate(dummy)); |
| EXPECT_TRUE((Query::Double(-1.0) == Query::Int(-1)).Evaluate(dummy)); |
| EXPECT_TRUE((Query::Double(1.0) == Query::Double(1.0f)).Evaluate(dummy)); |
| EXPECT_TRUE((Query::Bool(true) == Query::Int(1)).Evaluate(dummy)); |
| EXPECT_TRUE((Query::Bool(false) == Query::Int(0)).Evaluate(dummy)); |
| EXPECT_TRUE((Query::Bool(true) == Query::Double(1.0f)).Evaluate(dummy)); |
| EXPECT_TRUE((Query::Bool(false) == Query::Double(0.0f)).Evaluate(dummy)); |
| } |
| |
| // Test GetRateStats. |
| TEST_F(TraceEventAnalyzerTest, RateStats) { |
| std::vector<TraceEvent> events; |
| events.reserve(100); |
| TraceEventVector event_ptrs; |
| double timestamp = 0.0; |
| double little_delta = 1.0; |
| double big_delta = 10.0; |
| double tiny_delta = 0.1; |
| RateStats stats; |
| RateStatsOptions options; |
| |
| // Insert 10 events, each apart by little_delta. |
| for (int i = 0; i < 10; ++i) { |
| timestamp += little_delta; |
| TraceEvent event; |
| event.timestamp = timestamp; |
| events.push_back(std::move(event)); |
| event_ptrs.push_back(&events.back()); |
| } |
| |
| ASSERT_TRUE(GetRateStats(event_ptrs, &stats, nullptr)); |
| EXPECT_EQ(little_delta, stats.mean_us); |
| EXPECT_EQ(little_delta, stats.min_us); |
| EXPECT_EQ(little_delta, stats.max_us); |
| EXPECT_EQ(0.0, stats.standard_deviation_us); |
| |
| // Add an event apart by big_delta. |
| { |
| timestamp += big_delta; |
| TraceEvent event; |
| event.timestamp = timestamp; |
| events.push_back(std::move(event)); |
| event_ptrs.push_back(&events.back()); |
| } |
| |
| ASSERT_TRUE(GetRateStats(event_ptrs, &stats, nullptr)); |
| EXPECT_LT(little_delta, stats.mean_us); |
| EXPECT_EQ(little_delta, stats.min_us); |
| EXPECT_EQ(big_delta, stats.max_us); |
| EXPECT_LT(0.0, stats.standard_deviation_us); |
| |
| // Trim off the biggest delta and verify stats. |
| options.trim_min = 0; |
| options.trim_max = 1; |
| ASSERT_TRUE(GetRateStats(event_ptrs, &stats, &options)); |
| EXPECT_EQ(little_delta, stats.mean_us); |
| EXPECT_EQ(little_delta, stats.min_us); |
| EXPECT_EQ(little_delta, stats.max_us); |
| EXPECT_EQ(0.0, stats.standard_deviation_us); |
| |
| // Add an event apart by tiny_delta. |
| { |
| timestamp += tiny_delta; |
| TraceEvent event; |
| event.timestamp = timestamp; |
| events.push_back(std::move(event)); |
| event_ptrs.push_back(&events.back()); |
| } |
| |
| // Trim off both the biggest and tiniest delta and verify stats. |
| options.trim_min = 1; |
| options.trim_max = 1; |
| ASSERT_TRUE(GetRateStats(event_ptrs, &stats, &options)); |
| EXPECT_EQ(little_delta, stats.mean_us); |
| EXPECT_EQ(little_delta, stats.min_us); |
| EXPECT_EQ(little_delta, stats.max_us); |
| EXPECT_EQ(0.0, stats.standard_deviation_us); |
| |
| // Verify smallest allowed number of events. |
| { |
| TraceEvent event; |
| TraceEventVector few_event_ptrs; |
| few_event_ptrs.push_back(&event); |
| few_event_ptrs.push_back(&event); |
| ASSERT_FALSE(GetRateStats(few_event_ptrs, &stats, nullptr)); |
| few_event_ptrs.push_back(&event); |
| ASSERT_TRUE(GetRateStats(few_event_ptrs, &stats, nullptr)); |
| |
| // Trim off more than allowed and verify failure. |
| options.trim_min = 0; |
| options.trim_max = 1; |
| ASSERT_FALSE(GetRateStats(few_event_ptrs, &stats, &options)); |
| } |
| } |
| |
| // Test FindFirstOf and FindLastOf. |
| TEST_F(TraceEventAnalyzerTest, FindOf) { |
| size_t num_events = 100; |
| size_t index = 0; |
| TraceEventVector event_ptrs; |
| EXPECT_FALSE(FindFirstOf(event_ptrs, Query::Bool(true), 0, &index)); |
| EXPECT_FALSE(FindFirstOf(event_ptrs, Query::Bool(true), 10, &index)); |
| EXPECT_FALSE(FindLastOf(event_ptrs, Query::Bool(true), 0, &index)); |
| EXPECT_FALSE(FindLastOf(event_ptrs, Query::Bool(true), 10, &index)); |
| |
| std::vector<TraceEvent> events; |
| events.resize(num_events); |
| for (size_t i = 0; i < events.size(); ++i) |
| event_ptrs.push_back(&events[i]); |
| size_t bam_index = num_events/2; |
| events[bam_index].name = "bam"; |
| Query query_bam = Query::EventName() == Query::String(events[bam_index].name); |
| |
| // FindFirstOf |
| EXPECT_FALSE(FindFirstOf(event_ptrs, Query::Bool(false), 0, &index)); |
| EXPECT_TRUE(FindFirstOf(event_ptrs, Query::Bool(true), 0, &index)); |
| EXPECT_EQ(0u, index); |
| EXPECT_TRUE(FindFirstOf(event_ptrs, Query::Bool(true), 5, &index)); |
| EXPECT_EQ(5u, index); |
| |
| EXPECT_FALSE(FindFirstOf(event_ptrs, query_bam, bam_index + 1, &index)); |
| EXPECT_TRUE(FindFirstOf(event_ptrs, query_bam, 0, &index)); |
| EXPECT_EQ(bam_index, index); |
| EXPECT_TRUE(FindFirstOf(event_ptrs, query_bam, bam_index, &index)); |
| EXPECT_EQ(bam_index, index); |
| |
| // FindLastOf |
| EXPECT_FALSE(FindLastOf(event_ptrs, Query::Bool(false), 1000, &index)); |
| EXPECT_TRUE(FindLastOf(event_ptrs, Query::Bool(true), 1000, &index)); |
| EXPECT_EQ(num_events - 1, index); |
| EXPECT_TRUE(FindLastOf(event_ptrs, Query::Bool(true), num_events - 5, |
| &index)); |
| EXPECT_EQ(num_events - 5, index); |
| |
| EXPECT_FALSE(FindLastOf(event_ptrs, query_bam, bam_index - 1, &index)); |
| EXPECT_TRUE(FindLastOf(event_ptrs, query_bam, num_events, &index)); |
| EXPECT_EQ(bam_index, index); |
| EXPECT_TRUE(FindLastOf(event_ptrs, query_bam, bam_index, &index)); |
| EXPECT_EQ(bam_index, index); |
| } |
| |
| // Test FindClosest. |
| TEST_F(TraceEventAnalyzerTest, FindClosest) { |
| size_t index_1 = 0; |
| size_t index_2 = 0; |
| TraceEventVector event_ptrs; |
| EXPECT_FALSE(FindClosest(event_ptrs, Query::Bool(true), 0, |
| &index_1, &index_2)); |
| |
| size_t num_events = 5; |
| std::vector<TraceEvent> events; |
| events.resize(num_events); |
| for (size_t i = 0; i < events.size(); ++i) { |
| // timestamps go up exponentially so the lower index is always closer in |
| // time than the higher index. |
| events[i].timestamp = static_cast<double>(i) * static_cast<double>(i); |
| event_ptrs.push_back(&events[i]); |
| } |
| events[0].name = "one"; |
| events[2].name = "two"; |
| events[4].name = "three"; |
| Query query_named = Query::EventName() != Query::String(std::string()); |
| Query query_one = Query::EventName() == Query::String("one"); |
| |
| // Only one event matches query_one, so two closest can't be found. |
| EXPECT_FALSE(FindClosest(event_ptrs, query_one, 0, &index_1, &index_2)); |
| |
| EXPECT_TRUE(FindClosest(event_ptrs, query_one, 3, &index_1, nullptr)); |
| EXPECT_EQ(0u, index_1); |
| |
| EXPECT_TRUE(FindClosest(event_ptrs, query_named, 1, &index_1, &index_2)); |
| EXPECT_EQ(0u, index_1); |
| EXPECT_EQ(2u, index_2); |
| |
| EXPECT_TRUE(FindClosest(event_ptrs, query_named, 4, &index_1, &index_2)); |
| EXPECT_EQ(4u, index_1); |
| EXPECT_EQ(2u, index_2); |
| |
| EXPECT_TRUE(FindClosest(event_ptrs, query_named, 3, &index_1, &index_2)); |
| EXPECT_EQ(2u, index_1); |
| EXPECT_EQ(0u, index_2); |
| } |
| |
| // Test CountMatches. |
| TEST_F(TraceEventAnalyzerTest, CountMatches) { |
| TraceEventVector event_ptrs; |
| EXPECT_EQ(0u, CountMatches(event_ptrs, Query::Bool(true), 0, 10)); |
| |
| size_t num_events = 5; |
| size_t num_named = 3; |
| std::vector<TraceEvent> events; |
| events.resize(num_events); |
| for (size_t i = 0; i < events.size(); ++i) |
| event_ptrs.push_back(&events[i]); |
| events[0].name = "one"; |
| events[2].name = "two"; |
| events[4].name = "three"; |
| Query query_named = Query::EventName() != Query::String(std::string()); |
| Query query_one = Query::EventName() == Query::String("one"); |
| |
| EXPECT_EQ(0u, CountMatches(event_ptrs, Query::Bool(false))); |
| EXPECT_EQ(num_events, CountMatches(event_ptrs, Query::Bool(true))); |
| EXPECT_EQ(num_events - 1, CountMatches(event_ptrs, Query::Bool(true), |
| 1, num_events)); |
| EXPECT_EQ(1u, CountMatches(event_ptrs, query_one)); |
| EXPECT_EQ(num_events - 1, CountMatches(event_ptrs, !query_one)); |
| EXPECT_EQ(num_named, CountMatches(event_ptrs, query_named)); |
| } |
| |
| TEST_F(TraceEventAnalyzerTest, ComplexArgument) { |
| ManualSetUp(); |
| |
| BeginTracing(); |
| { |
| std::unique_ptr<base::trace_event::TracedValue> value( |
| new base::trace_event::TracedValue); |
| value->SetString("property", "value"); |
| TRACE_EVENT1("cat", "name", "arg", std::move(value)); |
| } |
| EndTracing(); |
| |
| std::unique_ptr<TraceAnalyzer> analyzer( |
| TraceAnalyzer::Create(output_.json_output)); |
| ASSERT_TRUE(analyzer.get()); |
| |
| TraceEventVector events; |
| analyzer->FindEvents(Query::EventName() == Query::String("name"), &events); |
| |
| EXPECT_EQ(1u, events.size()); |
| EXPECT_EQ("cat", events[0]->category); |
| EXPECT_EQ("name", events[0]->name); |
| EXPECT_TRUE(events[0]->HasArg("arg")); |
| |
| std::unique_ptr<base::Value> arg; |
| events[0]->GetArgAsValue("arg", &arg); |
| base::DictionaryValue* arg_dict; |
| EXPECT_TRUE(arg->GetAsDictionary(&arg_dict)); |
| std::string property; |
| EXPECT_TRUE(arg_dict->GetString("property", &property)); |
| EXPECT_EQ("value", property); |
| } |
| |
| } // namespace trace_analyzer |