| // Copyright 2019 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 "services/tracing/perfetto/track_event_json_exporter.h" |
| |
| #include <memory> |
| #include <utility> |
| |
| #include "base/bind.h" |
| #include "base/callback.h" |
| #include "base/json/json_reader.h" |
| #include "base/json/json_writer.h" |
| #include "base/optional.h" |
| #include "base/strings/stringprintf.h" |
| #include "base/test/gtest_util.h" |
| #include "base/test/trace_event_analyzer.h" |
| #include "base/values.h" |
| #include "testing/gmock/include/gmock/gmock.h" |
| #include "testing/gtest/include/gtest/gtest.h" |
| #include "third_party/perfetto/include/perfetto/tracing/core/trace_config.h" |
| #include "third_party/perfetto/include/perfetto/tracing/core/trace_packet.h" |
| #include "third_party/perfetto/protos/perfetto/trace/chrome/chrome_trace_event.pbzero.h" |
| #include "third_party/perfetto/protos/perfetto/trace/trace_packet.pb.h" |
| |
| namespace tracing { |
| namespace { |
| |
| using ::perfetto::protos::ProcessDescriptor; |
| using ::perfetto::protos::ThreadDescriptor; |
| using ::perfetto::protos::TrackEvent; |
| using ::trace_analyzer::Query; |
| |
| constexpr int64_t kPid = 4; |
| constexpr int64_t kTid = 5; |
| constexpr int64_t kReferenceTimeUs = 1; |
| constexpr int64_t kReferenceThreadTimeUs = 2; |
| constexpr char kThreadName[] = "kThreadName"; |
| |
| // Defaults for LegacyEvents. |
| constexpr int32_t kLegacyPhase = TRACE_EVENT_PHASE_MEMORY_DUMP; |
| constexpr uint32_t kLegacyFlags = TRACE_EVENT_FLAG_HAS_ID; |
| constexpr int64_t kLegacyDuration = 100; |
| constexpr int64_t kLegacyThreadDuration = 101; |
| constexpr uint64_t kLegacyId = 102; |
| constexpr char kLegacyIdStr[] = "0x66"; |
| constexpr char kLegacyScope[] = "legacy_scope"; |
| constexpr uint64_t kLegacyBindId = 103; |
| constexpr char kLegacyBindIdStr[] = "0x67"; |
| |
| class TrackEventJsonExporterTest : public testing::Test { |
| public: |
| void SetUp() override {} |
| |
| void TearDown() override { json_trace_exporter_.reset(); } |
| |
| void OnTraceEventJson(std::string* json, |
| base::DictionaryValue* metadata, |
| bool has_more) { |
| CHECK(!has_more); |
| |
| unparsed_trace_data_.swap(*json); |
| parsed_trace_data_ = base::DictionaryValue::From( |
| base::JSONReader::ReadDeprecated(unparsed_trace_data_)); |
| ASSERT_TRUE(parsed_trace_data_) << "Couldn't parse json: \n" |
| << unparsed_trace_data_; |
| |
| // The TraceAnalyzer expects the raw trace output, without the |
| // wrapping root-node. |
| std::string raw_events; |
| auto* events_value = parsed_trace_data_->FindKey("traceEvents"); |
| ASSERT_TRUE(events_value); |
| base::JSONWriter::Write(*events_value, &raw_events); |
| |
| trace_analyzer_.reset(trace_analyzer::TraceAnalyzer::Create(raw_events)); |
| EXPECT_TRUE(trace_analyzer_); |
| } |
| |
| void FinalizePackets( |
| const std::vector<perfetto::protos::TracePacket>& trace_packet_protos) { |
| json_trace_exporter_.reset(new TrackEventJSONExporter( |
| JSONTraceExporter::ArgumentFilterPredicate(), |
| JSONTraceExporter::MetadataFilterPredicate(), |
| base::BindRepeating(&TrackEventJsonExporterTest::OnTraceEventJson, |
| base::Unretained(this)))); |
| |
| std::vector<std::string> serialized_packets; |
| // We need stable addressing of the string pointers so ensure we won't |
| // reallocate the backing vector. |
| serialized_packets.reserve(trace_packet_protos.size()); |
| std::vector<perfetto::TracePacket> packets; |
| for (const auto& proto_packet : trace_packet_protos) { |
| // Since we use AddSlice which does not copy the data the string has to |
| // live as long as we want to use it. So it needs to survive until the |
| // call to OnTraceData finishes below. |
| serialized_packets.push_back(proto_packet.SerializeAsString()); |
| const std::string& ser_buf = serialized_packets.back(); |
| // Now we construct the inmemory TracePacket and store it. |
| perfetto::TracePacket trace_packet; |
| trace_packet.AddSlice(&ser_buf[0], ser_buf.size()); |
| packets.emplace_back(std::move(trace_packet)); |
| } |
| |
| json_trace_exporter_->OnTraceData(std::move(packets), false); |
| } |
| |
| protected: |
| // This class makes it easier to construct TrackEvents because NestedValues in |
| // DebugAnnotations can be quite complex to set up. |
| class NestedValue { |
| public: |
| NestedValue(const NestedValue& copy) : result_(copy.result_) {} |
| |
| explicit NestedValue(int64_t val) { result_.set_int_value(val); } |
| explicit NestedValue(double val) { result_.set_double_value(val); } |
| explicit NestedValue(bool val) { result_.set_bool_value(val); } |
| explicit NestedValue(const std::string& val) { |
| result_.set_string_value(val); |
| } |
| NestedValue(const std::vector<std::pair<std::string, NestedValue>>& vals) { |
| result_.set_nested_type( |
| perfetto::protos::DebugAnnotation::NestedValue::DICT); |
| for (const auto& val : vals) { |
| *result_.add_dict_keys() = val.first; |
| *result_.add_dict_values() = val.second; |
| } |
| } |
| |
| explicit NestedValue(const std::vector<NestedValue>& vals) { |
| result_.set_nested_type( |
| perfetto::protos::DebugAnnotation::NestedValue::ARRAY); |
| for (const auto& val : vals) { |
| *result_.add_array_values() = val; |
| } |
| } |
| |
| // Intentionally implicit to allow assigning directly to the proto field. |
| operator perfetto::protos::DebugAnnotation::NestedValue() const { |
| return result_; |
| } |
| |
| private: |
| perfetto::protos::DebugAnnotation::NestedValue result_; |
| }; |
| |
| trace_analyzer::TraceAnalyzer* trace_analyzer() { |
| return trace_analyzer_.get(); |
| } |
| |
| const base::DictionaryValue* parsed_trace_data() const { |
| return parsed_trace_data_.get(); |
| } |
| |
| void AddProcessDescriptorPacket( |
| std::vector<std::string> cmds, |
| base::Optional<int32_t> sort_index, |
| ProcessDescriptor::ChromeProcessType type, |
| std::vector<perfetto::protos::TracePacket>* output, |
| int32_t pid = kPid) { |
| output->emplace_back(); |
| auto* result = output->back().mutable_process_descriptor(); |
| result->set_pid(pid); |
| for (const auto& cmd : cmds) { |
| *result->add_cmdline() = cmd; |
| } |
| if (sort_index) { |
| result->set_legacy_sort_index(*sort_index); |
| } |
| result->set_chrome_process_type(type); |
| // ProcessDescriptors don't require previous state. |
| output->back().set_incremental_state_cleared(true); |
| } |
| |
| void AddThreadDescriptorPacket( |
| const base::Optional<int32_t>& sort_index, |
| ThreadDescriptor::ChromeThreadType type, |
| const base::Optional<std::string>& thread_name, |
| int64_t reference_time_us, |
| int64_t reference_thread_time_us, |
| std::vector<perfetto::protos::TracePacket>* output, |
| int32_t pid = kPid, |
| int32_t tid = kTid) { |
| output->emplace_back(); |
| auto* result = output->back().mutable_thread_descriptor(); |
| result->set_pid(pid); |
| result->set_tid(tid); |
| if (sort_index) { |
| result->set_legacy_sort_index(*sort_index); |
| } |
| result->set_chrome_thread_type(type); |
| if (thread_name) { |
| result->set_thread_name(*thread_name); |
| } |
| result->set_reference_timestamp_us(reference_time_us); |
| result->set_reference_thread_time_us(reference_thread_time_us); |
| // ThreadDescriptors don't require previous state. |
| output->back().set_incremental_state_cleared(true); |
| } |
| |
| template <typename T> |
| T CreateInternedName(uint32_t iid, const std::string& value) { |
| T result; |
| result.set_iid(iid); |
| result.set_name(value); |
| return result; |
| } |
| |
| void AddInternedEventCategory( |
| uint32_t iid, |
| const std::string& value, |
| std::vector<perfetto::protos::TracePacket>* output) { |
| output->emplace_back(); |
| *output->back().mutable_interned_data()->add_event_categories() = |
| CreateInternedName<perfetto::protos::EventCategory>(iid, value); |
| } |
| |
| void AddInternedLegacyEventName( |
| uint32_t iid, |
| const std::string& value, |
| std::vector<perfetto::protos::TracePacket>* output) { |
| output->emplace_back(); |
| *output->back().mutable_interned_data()->add_legacy_event_names() = |
| CreateInternedName<perfetto::protos::LegacyEventName>(iid, value); |
| } |
| |
| void AddInternedDebugAnnotationName( |
| uint32_t iid, |
| const std::string& value, |
| std::vector<perfetto::protos::TracePacket>* output) { |
| output->emplace_back(); |
| *output->back().mutable_interned_data()->add_debug_annotation_names() = |
| CreateInternedName<perfetto::protos::DebugAnnotationName>(iid, value); |
| } |
| |
| void AddInternedSourceLocation( |
| uint32_t iid, |
| const std::string& file, |
| const std::string& function, |
| std::vector<perfetto::protos::TracePacket>* output) { |
| output->emplace_back(); |
| auto* source = |
| output->back().mutable_interned_data()->add_source_locations(); |
| source->set_iid(iid); |
| source->set_file_name(file); |
| source->set_function_name(function); |
| } |
| |
| perfetto::protos::TrackEvent::LegacyEvent CreateLegacyEvent( |
| uint32_t name_iid, // interned LegacyEventName. |
| uint32_t flags, |
| int32_t phase, |
| int32_t pid = kPid, |
| int32_t tid = kTid) { |
| perfetto::protos::TrackEvent::LegacyEvent event; |
| event.set_name_iid(name_iid); |
| event.set_phase(phase); |
| if (pid != kPid) { |
| event.set_pid_override(pid); |
| } |
| if (tid != kTid) { |
| event.set_tid_override(tid); |
| } |
| |
| // Use |flags| to set legacy fields correctly. |
| if (flags & TRACE_EVENT_FLAG_HAS_ID) { |
| event.set_unscoped_id(kLegacyId); |
| } else if (flags & TRACE_EVENT_FLAG_HAS_LOCAL_ID) { |
| event.set_local_id(kLegacyId); |
| } else if (flags & TRACE_EVENT_FLAG_HAS_GLOBAL_ID) { |
| event.set_global_id(kLegacyId); |
| } |
| |
| if (event.id_case() != |
| perfetto::protos::TrackEvent::LegacyEvent::ID_NOT_SET) { |
| event.set_id_scope(kLegacyScope); |
| } |
| |
| if (flags & TRACE_EVENT_FLAG_ASYNC_TTS) { |
| event.set_use_async_tts(true); |
| } |
| |
| if (flags & TRACE_EVENT_FLAG_BIND_TO_ENCLOSING) { |
| event.set_bind_to_enclosing(true); |
| } |
| |
| uint32_t flow = |
| flags & (TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT); |
| switch (flow) { |
| case (TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT): |
| event.set_flow_direction( |
| perfetto::protos::TrackEvent::LegacyEvent::FLOW_INOUT); |
| break; |
| case TRACE_EVENT_FLAG_FLOW_IN: |
| event.set_flow_direction( |
| perfetto::protos::TrackEvent::LegacyEvent::FLOW_IN); |
| break; |
| case TRACE_EVENT_FLAG_FLOW_OUT: |
| event.set_flow_direction( |
| perfetto::protos::TrackEvent::LegacyEvent::FLOW_OUT); |
| break; |
| } |
| |
| // The rest of the fields are set to default/sane values. |
| if (phase == TRACE_EVENT_PHASE_COMPLETE) { |
| event.set_duration_us(kLegacyDuration); |
| event.set_thread_duration_us(kLegacyThreadDuration); |
| } else if (phase == TRACE_EVENT_PHASE_INSTANT) { |
| switch (flags & TRACE_EVENT_FLAG_SCOPE_MASK) { |
| case TRACE_EVENT_SCOPE_GLOBAL: |
| event.set_instant_event_scope(TrackEvent::LegacyEvent::SCOPE_GLOBAL); |
| break; |
| case TRACE_EVENT_SCOPE_PROCESS: |
| event.set_instant_event_scope(TrackEvent::LegacyEvent::SCOPE_PROCESS); |
| break; |
| case TRACE_EVENT_SCOPE_THREAD: |
| event.set_instant_event_scope(TrackEvent::LegacyEvent::SCOPE_THREAD); |
| break; |
| } |
| } |
| event.set_bind_id(kLegacyBindId); |
| |
| return event; |
| } |
| |
| std::string unparsed_trace_data_; |
| |
| private: |
| std::unique_ptr<TrackEventJSONExporter> json_trace_exporter_; |
| std::unique_ptr<trace_analyzer::TraceAnalyzer> trace_analyzer_; |
| std::unique_ptr<base::DictionaryValue> parsed_trace_data_; |
| }; |
| |
| TEST_F(TrackEventJsonExporterTest, EmptyProcessDescriptor) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| trace_analyzer::TraceEventVector events; |
| AddProcessDescriptorPacket( |
| /* cmds = */ {}, /* sort_index = */ base::nullopt, |
| ProcessDescriptor::PROCESS_UNSPECIFIED, &trace_packet_protos); |
| FinalizePackets(trace_packet_protos); |
| // No traceEvents or data was emitted but a process descriptor without extra |
| // data should just be an empty array and not cause crashes. |
| EXPECT_EQ("{\"traceEvents\":[]}", unparsed_trace_data_); |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, SortIndexProcessDescriptor) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| trace_analyzer::TraceEventVector events; |
| AddProcessDescriptorPacket(/* cmds = */ {}, /* sort_index = */ 2, |
| ProcessDescriptor::PROCESS_UNSPECIFIED, |
| &trace_packet_protos); |
| FinalizePackets(trace_packet_protos); |
| ASSERT_EQ(1u, |
| trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("process_sort_index"), |
| &events)); |
| EXPECT_EQ("process_sort_index", events[0]->name); |
| EXPECT_EQ("__metadata", events[0]->category); |
| EXPECT_EQ('M', events[0]->phase); |
| EXPECT_EQ(0, events[0]->timestamp); |
| ASSERT_TRUE(events[0]->HasArg("sort_index")); |
| EXPECT_EQ(2, events[0]->GetKnownArgAsInt("sort_index")); |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, ProcessTypeProcessDescriptor) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| trace_analyzer::TraceEventVector events; |
| AddProcessDescriptorPacket( |
| /* cmds = */ {}, /* sort_index = */ base::nullopt, |
| ProcessDescriptor::PROCESS_UNSPECIFIED, &trace_packet_protos); |
| FinalizePackets(trace_packet_protos); |
| |
| // UNSPECIFIED does not add a process_name metadata event. |
| EXPECT_EQ(0u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("process_name"), |
| &events)); |
| |
| for (int process_type = static_cast<int>(ProcessDescriptor::PROCESS_BROWSER); |
| process_type < |
| static_cast<int>(ProcessDescriptor::ChromeProcessType_ARRAYSIZE); |
| ++process_type) { |
| ASSERT_TRUE(ProcessDescriptor::ChromeProcessType_IsValid(process_type)); |
| events.clear(); |
| trace_packet_protos[0] |
| .mutable_process_descriptor() |
| ->set_chrome_process_type( |
| static_cast<ProcessDescriptor::ChromeProcessType>(process_type)); |
| FinalizePackets(trace_packet_protos); |
| EXPECT_EQ(1u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("process_name"), |
| &events)); |
| EXPECT_EQ("process_name", events[0]->name); |
| EXPECT_EQ("__metadata", events[0]->category); |
| EXPECT_EQ('M', events[0]->phase); |
| EXPECT_EQ(0, events[0]->timestamp); |
| ASSERT_TRUE(events[0]->HasArg("name")); |
| switch (static_cast<ProcessDescriptor::ChromeProcessType>(process_type)) { |
| case ProcessDescriptor::PROCESS_UNSPECIFIED: |
| ADD_FAILURE() << "Unspecified triggered a process_name event when it " |
| "shouldn't have. Name \"" |
| << events[0]->GetKnownArgAsString("name") << "\""; |
| break; |
| case ProcessDescriptor::PROCESS_BROWSER: |
| EXPECT_EQ("BROWSER", events[0]->GetKnownArgAsString("name")); |
| break; |
| case ProcessDescriptor::PROCESS_RENDERER: |
| EXPECT_EQ("RENDERER", events[0]->GetKnownArgAsString("name")); |
| break; |
| case ProcessDescriptor::PROCESS_UTILITY: |
| EXPECT_EQ("UTILITY", events[0]->GetKnownArgAsString("name")); |
| break; |
| case ProcessDescriptor::PROCESS_ZYGOTE: |
| EXPECT_EQ("ZYGOTE", events[0]->GetKnownArgAsString("name")); |
| break; |
| case ProcessDescriptor::PROCESS_SANDBOX_HELPER: |
| EXPECT_EQ("SANDBOX_HELPER", events[0]->GetKnownArgAsString("name")); |
| break; |
| case ProcessDescriptor::PROCESS_GPU: |
| EXPECT_EQ("GPU", events[0]->GetKnownArgAsString("name")); |
| break; |
| case ProcessDescriptor::PROCESS_PPAPI_PLUGIN: |
| EXPECT_EQ("PPAPI_PLUGIN", events[0]->GetKnownArgAsString("name")); |
| break; |
| case ProcessDescriptor::PROCESS_PPAPI_BROKER: |
| EXPECT_EQ("PPAPI_BROKER", events[0]->GetKnownArgAsString("name")); |
| break; |
| } |
| } |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, MultipleProcessDescriptors) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| trace_analyzer::TraceEventVector events; |
| // Sort index 2 + name BROWSER. |
| AddProcessDescriptorPacket(/* cmds = */ {}, /* sort_index = */ 2, |
| ProcessDescriptor::PROCESS_BROWSER, |
| &trace_packet_protos); |
| // We've already emitted the process metadata so all future ProcessDescriptors |
| // will not cause new events until a new sequence is hit (even on resets). |
| AddProcessDescriptorPacket(/* cmds = */ {}, /* sort_index = */ 3, |
| ProcessDescriptor::PROCESS_RENDERER, |
| &trace_packet_protos); |
| trace_packet_protos.back().set_incremental_state_cleared(true); |
| // Empty. |
| AddProcessDescriptorPacket( |
| /* cmds = */ {}, /* sort_index = */ base::nullopt, |
| ProcessDescriptor::PROCESS_UNSPECIFIED, &trace_packet_protos); |
| FinalizePackets(trace_packet_protos); |
| ASSERT_EQ(2u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_CATEGORY) == Query::String("__metadata"), |
| &events)); |
| for (size_t i = 0; i < events.size(); ++i) { |
| const auto* event = events[i]; |
| if (event->name == "process_name") { |
| EXPECT_EQ("BROWSER", event->GetKnownArgAsString("name")); |
| } else if (event->name == "process_sort_index") { |
| EXPECT_EQ(2, event->GetKnownArgAsInt("sort_index")); |
| } else { |
| ADD_FAILURE() << "Unexpected event name: " << event->name; |
| } |
| } |
| |
| // However if we put it on a new sequence then the metadata will be emitted |
| // again. |
| trace_packet_protos[1].set_trusted_packet_sequence_id(333); |
| FinalizePackets(trace_packet_protos); |
| |
| FinalizePackets(trace_packet_protos); |
| ASSERT_EQ(4u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_CATEGORY) == Query::String("__metadata"), |
| &events)); |
| for (size_t i = 0; i < 2; ++i) { |
| const auto* event = events[i]; |
| if (event->name == "process_name") { |
| EXPECT_EQ("BROWSER", event->GetKnownArgAsString("name")); |
| } else if (event->name == "process_sort_index") { |
| EXPECT_EQ(2, event->GetKnownArgAsInt("sort_index")); |
| } else { |
| ADD_FAILURE() << "Unexpected event name: " << event->name; |
| } |
| } |
| for (size_t i = 2; i < events.size(); ++i) { |
| const auto* event = events[i]; |
| if (event->name == "process_name") { |
| EXPECT_EQ("RENDERER", event->GetKnownArgAsString("name")); |
| } else if (event->name == "process_sort_index") { |
| EXPECT_EQ(3, event->GetKnownArgAsInt("sort_index")); |
| } else { |
| ADD_FAILURE() << "Unexpected event name: " << event->name; |
| } |
| } |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, EmptyThreadDescriptor) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| trace_analyzer::TraceEventVector events; |
| AddThreadDescriptorPacket(/* sort_index = */ base::nullopt, |
| ThreadDescriptor::THREAD_UNSPECIFIED, base::nullopt, |
| kReferenceTimeUs, kReferenceThreadTimeUs, |
| &trace_packet_protos); |
| FinalizePackets(trace_packet_protos); |
| // No traceEvents or data was emitted but a thread descriptor should be an |
| // empty array and not cause crashes. |
| EXPECT_EQ("{\"traceEvents\":[]}", unparsed_trace_data_); |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, SortIndexThreadDescriptor) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| trace_analyzer::TraceEventVector events; |
| AddThreadDescriptorPacket( |
| /* sort_index = */ 2, ThreadDescriptor::THREAD_UNSPECIFIED, base::nullopt, |
| kReferenceTimeUs, kReferenceThreadTimeUs, &trace_packet_protos); |
| FinalizePackets(trace_packet_protos); |
| ASSERT_EQ(1u, |
| trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("thread_sort_index"), |
| &events)); |
| EXPECT_EQ("thread_sort_index", events[0]->name); |
| EXPECT_EQ("__metadata", events[0]->category); |
| EXPECT_EQ('M', events[0]->phase); |
| EXPECT_EQ(0, events[0]->timestamp); |
| ASSERT_TRUE(events[0]->HasArg("sort_index")); |
| EXPECT_EQ(2, events[0]->GetKnownArgAsInt("sort_index")); |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, ThreadNameThreadDescriptor) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| trace_analyzer::TraceEventVector events; |
| AddThreadDescriptorPacket(/* sort_index = */ base::nullopt, |
| ThreadDescriptor::THREAD_UNSPECIFIED, kThreadName, |
| kReferenceTimeUs, kReferenceThreadTimeUs, |
| &trace_packet_protos); |
| FinalizePackets(trace_packet_protos); |
| ASSERT_EQ(1u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("thread_name"), |
| &events)); |
| EXPECT_EQ("thread_name", events[0]->name); |
| EXPECT_EQ("__metadata", events[0]->category); |
| EXPECT_EQ('M', events[0]->phase); |
| EXPECT_EQ(0, events[0]->timestamp); |
| ASSERT_TRUE(events[0]->HasArg("name")); |
| EXPECT_EQ(kThreadName, events[0]->GetKnownArgAsString("name")); |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, MultipleThreadDescriptors) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| trace_analyzer::TraceEventVector events; |
| AddThreadDescriptorPacket( |
| /* sort_index = */ 2, ThreadDescriptor::THREAD_UNSPECIFIED, kThreadName, |
| kReferenceTimeUs, kReferenceThreadTimeUs, &trace_packet_protos); |
| // This packet will be ignored because we've already emitted the sort_index of |
| // 2 and thread_name kThreadName so we suppress this metadata because it |
| // isn't supposed to have changed (even if reset). |
| ASSERT_NE("different_thread_name", kThreadName); |
| AddThreadDescriptorPacket( |
| /* sort_index = */ 3, ThreadDescriptor::THREAD_UNSPECIFIED, |
| "different_thread_name", kReferenceTimeUs, kReferenceThreadTimeUs, |
| &trace_packet_protos); |
| trace_packet_protos.back().set_incremental_state_cleared(true); |
| // Empty packet doesn't change anything. |
| AddThreadDescriptorPacket(/* sort_index = */ base::nullopt, |
| ThreadDescriptor::THREAD_UNSPECIFIED, base::nullopt, |
| kReferenceTimeUs, kReferenceThreadTimeUs, |
| &trace_packet_protos); |
| FinalizePackets(trace_packet_protos); |
| ASSERT_EQ(2u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_CATEGORY) == Query::String("__metadata"), |
| &events)); |
| for (size_t i = 0; i < events.size(); ++i) { |
| const auto* event = events[i]; |
| if (event->name == "thread_name") { |
| EXPECT_EQ(kThreadName, event->GetKnownArgAsString("name")); |
| } else if (event->name == "thread_sort_index") { |
| EXPECT_EQ(2, event->GetKnownArgAsInt("sort_index")); |
| } else { |
| ADD_FAILURE() << "Unexpected event name: " << event->name; |
| } |
| } |
| |
| // However if we put it on a new sequence then the metadata will be emitted |
| // again. |
| trace_packet_protos[1].set_trusted_packet_sequence_id(333); |
| FinalizePackets(trace_packet_protos); |
| |
| FinalizePackets(trace_packet_protos); |
| ASSERT_EQ(4u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_CATEGORY) == Query::String("__metadata"), |
| &events)); |
| for (size_t i = 0; i < 2; ++i) { |
| const auto* event = events[i]; |
| if (event->name == "thread_name") { |
| EXPECT_EQ(kThreadName, event->GetKnownArgAsString("name")); |
| } else if (event->name == "thread_sort_index") { |
| EXPECT_EQ(2, event->GetKnownArgAsInt("sort_index")); |
| } else { |
| ADD_FAILURE() << "Unexpected event name: " << event->name; |
| } |
| } |
| for (size_t i = 2; i < events.size(); ++i) { |
| const auto* event = events[i]; |
| if (event->name == "thread_name") { |
| EXPECT_EQ("different_thread_name", event->GetKnownArgAsString("name")); |
| } else if (event->name == "thread_sort_index") { |
| EXPECT_EQ(3, event->GetKnownArgAsInt("sort_index")); |
| } else { |
| ADD_FAILURE() << "Unexpected event name: " << event->name; |
| } |
| } |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, JustInternedData) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| AddInternedLegacyEventName(2, "legacy_event_name", &trace_packet_protos); |
| AddInternedEventCategory(2, "event_category", &trace_packet_protos); |
| trace_packet_protos.back().set_incremental_state_cleared(true); |
| AddInternedEventCategory(3, "event_category", &trace_packet_protos); |
| AddInternedDebugAnnotationName(4, "debug_annotation_name", |
| &trace_packet_protos); |
| AddInternedSourceLocation(1, "file_name", "function_name", |
| &trace_packet_protos); |
| FinalizePackets(trace_packet_protos); |
| // Interned data by itself does not call any trace events to be emitted. |
| EXPECT_EQ("{\"traceEvents\":[]}", unparsed_trace_data_); |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, LegacyEventBasicTest) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| trace_analyzer::TraceEventVector events; |
| |
| // Add the required intern state plus one extra unused interned string. |
| // Ensuring we reset the state with the first packet. |
| AddInternedLegacyEventName(2, "legacy_event_name_2", &trace_packet_protos); |
| trace_packet_protos.back().set_incremental_state_cleared(true); |
| AddInternedLegacyEventName(3, "legacy_event_name_3", &trace_packet_protos); |
| AddInternedEventCategory(3, "event_category_3", &trace_packet_protos); |
| AddInternedEventCategory(2, "event_category_2", &trace_packet_protos); |
| AddInternedEventCategory(4, "event_category_4", &trace_packet_protos); |
| |
| // Now we construct a Legacy event that overrides everything and only relies |
| // on interned data as needed. |
| trace_packet_protos.emplace_back(); |
| auto* track_event = trace_packet_protos.back().mutable_track_event(); |
| track_event->set_timestamp_absolute_us(4); |
| track_event->set_thread_time_absolute_us(5); |
| track_event->add_category_iids(3); |
| track_event->add_category_iids(4); |
| *track_event->mutable_legacy_event() = |
| CreateLegacyEvent(/* name_iid = */ 3, kLegacyFlags, kLegacyPhase, |
| /* pid = */ 7, /* tid = */ 8); |
| |
| FinalizePackets(trace_packet_protos); |
| |
| ASSERT_EQ( |
| 1u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("legacy_event_name_3"), |
| &events)); |
| EXPECT_EQ("legacy_event_name_3", events[0]->name); |
| EXPECT_EQ("event_category_3,event_category_4", events[0]->category); |
| EXPECT_EQ(4, events[0]->timestamp); |
| EXPECT_EQ(5, events[0]->thread_timestamp); |
| EXPECT_EQ(0, events[0]->duration); |
| EXPECT_EQ(0, events[0]->thread_duration); |
| EXPECT_EQ(kLegacyPhase, events[0]->phase); |
| EXPECT_EQ(kLegacyIdStr, events[0]->id); |
| EXPECT_EQ(kLegacyScope, events[0]->scope); |
| EXPECT_EQ(kLegacyBindIdStr, events[0]->bind_id); |
| EXPECT_FALSE(events[0]->flow_out); |
| EXPECT_FALSE(events[0]->flow_in); |
| EXPECT_TRUE(events[0]->local_id2.empty()); |
| EXPECT_TRUE(events[0]->global_id2.empty()); |
| EXPECT_EQ(7, events[0]->thread.process_id); |
| EXPECT_EQ(8, events[0]->thread.thread_id); |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, LegacyEventFilledInState) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| trace_analyzer::TraceEventVector events; |
| |
| // Now we construct a Legacy event however it relies on the ThreadDescriptor |
| // to provide the extra data needed to make a complete event. |
| trace_packet_protos.emplace_back(); |
| auto* track_event = trace_packet_protos.back().mutable_track_event(); |
| track_event->add_category_iids(3); |
| track_event->set_timestamp_delta_us(4); |
| track_event->set_thread_time_delta_us(6); |
| *track_event->mutable_legacy_event() = |
| CreateLegacyEvent(/* name_iid = */ 3, kLegacyFlags, kLegacyPhase); |
| |
| FinalizePackets(trace_packet_protos); |
| |
| // Since there was no ThreadDescriptor or interned data this event should be |
| // completely dropped, but to enable potentially partial trace exports we |
| // shouldn't expect a crash. |
| ASSERT_EQ( |
| 0u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("legacy_event_name_3"), |
| &events)); |
| |
| // This provides the pid & tid, as well as the timestamps reference points. |
| AddThreadDescriptorPacket(/* sort_index = */ base::nullopt, |
| ThreadDescriptor::THREAD_UNSPECIFIED, |
| /* thread_name = */ base::nullopt, kReferenceTimeUs, |
| kReferenceThreadTimeUs, &trace_packet_protos); |
| // To correctly use the state the thread descriptor has to come |
| // before so we swap the last two packets. However since we don't have the |
| // interned names yet this will DCHECK. |
| std::swap(trace_packet_protos[0], trace_packet_protos[1]); |
| EXPECT_DCHECK_DEATH(FinalizePackets(trace_packet_protos)); |
| |
| // Now with the interned data. |
| AddInternedLegacyEventName(3, "legacy_event_name_3", &trace_packet_protos); |
| AddInternedEventCategory(3, "event_category_3", &trace_packet_protos); |
| // Again swap the TrackEvent to the end. |
| std::swap(trace_packet_protos[1], trace_packet_protos[3]); |
| FinalizePackets(trace_packet_protos); |
| |
| ASSERT_EQ( |
| 1u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("legacy_event_name_3"), |
| &events)); |
| EXPECT_EQ("legacy_event_name_3", events[0]->name); |
| EXPECT_EQ("event_category_3", events[0]->category); |
| EXPECT_EQ(kReferenceTimeUs + 4, events[0]->timestamp); |
| EXPECT_EQ(kReferenceThreadTimeUs + 6, events[0]->thread_timestamp); |
| EXPECT_EQ(kPid, events[0]->thread.process_id); |
| EXPECT_EQ(kTid, events[0]->thread.thread_id); |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, LegacyEventTimestampDelta) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| trace_analyzer::TraceEventVector events; |
| |
| AddThreadDescriptorPacket(/* sort_index = */ base::nullopt, |
| ThreadDescriptor::THREAD_UNSPECIFIED, |
| /* thread_name = */ base::nullopt, kReferenceTimeUs, |
| kReferenceThreadTimeUs, &trace_packet_protos); |
| AddInternedLegacyEventName(3, "legacy_event_name_3", &trace_packet_protos); |
| AddInternedEventCategory(3, "event_category_3", &trace_packet_protos); |
| |
| trace_packet_protos.emplace_back(); |
| auto* track_event = trace_packet_protos.back().mutable_track_event(); |
| track_event->add_category_iids(3); |
| track_event->set_timestamp_delta_us(4); |
| track_event->set_thread_time_delta_us(6); |
| *track_event->mutable_legacy_event() = |
| CreateLegacyEvent(/* name_iid = */ 3, kLegacyFlags, kLegacyPhase); |
| trace_packet_protos.push_back(trace_packet_protos.back()); |
| trace_packet_protos.push_back(trace_packet_protos.back()); |
| trace_packet_protos.back().mutable_track_event()->set_timestamp_absolute_us( |
| 333); |
| trace_packet_protos.back().mutable_track_event()->set_thread_time_absolute_us( |
| 666); |
| FinalizePackets(trace_packet_protos); |
| |
| ASSERT_EQ( |
| 3u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("legacy_event_name_3"), |
| &events)); |
| EXPECT_EQ(kReferenceTimeUs + 4, events[0]->timestamp); |
| EXPECT_EQ(kReferenceThreadTimeUs + 6, events[0]->thread_timestamp); |
| EXPECT_EQ(kReferenceTimeUs + 4 * 2, events[1]->timestamp); |
| EXPECT_EQ(kReferenceThreadTimeUs + 6 * 2, events[1]->thread_timestamp); |
| EXPECT_EQ(333, events[2]->timestamp); |
| EXPECT_EQ(666, events[2]->thread_timestamp); |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, LegacyEventPhase) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| trace_analyzer::TraceEventVector events; |
| |
| AddThreadDescriptorPacket(/* sort_index = */ base::nullopt, |
| ThreadDescriptor::THREAD_UNSPECIFIED, |
| /* thread_name = */ base::nullopt, kReferenceTimeUs, |
| kReferenceThreadTimeUs, &trace_packet_protos); |
| AddInternedLegacyEventName(3, "legacy_event_name_3", &trace_packet_protos); |
| AddInternedEventCategory(3, "event_category_3", &trace_packet_protos); |
| |
| trace_packet_protos.emplace_back(); |
| auto* track_event = trace_packet_protos.back().mutable_track_event(); |
| track_event->add_category_iids(3); |
| track_event->set_timestamp_delta_us(4); |
| track_event->set_thread_time_delta_us(6); |
| |
| *track_event->mutable_legacy_event() = CreateLegacyEvent( |
| /* name_iid = */ 3, kLegacyFlags, TRACE_EVENT_PHASE_COMPLETE); |
| trace_packet_protos.push_back(trace_packet_protos.back()); |
| trace_packet_protos.back() |
| .mutable_track_event() |
| ->mutable_legacy_event() |
| ->set_phase(TRACE_EVENT_PHASE_INSTANT); |
| |
| FinalizePackets(trace_packet_protos); |
| |
| ASSERT_EQ( |
| 2u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("legacy_event_name_3"), |
| &events)); |
| EXPECT_EQ(TRACE_EVENT_PHASE_COMPLETE, events[0]->phase); |
| EXPECT_EQ(TRACE_EVENT_PHASE_INSTANT, events[1]->phase); |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, LegacyEventDuration) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| trace_analyzer::TraceEventVector events; |
| |
| AddThreadDescriptorPacket(/* sort_index = */ base::nullopt, |
| ThreadDescriptor::THREAD_UNSPECIFIED, |
| /* thread_name = */ base::nullopt, kReferenceTimeUs, |
| kReferenceThreadTimeUs, &trace_packet_protos); |
| AddInternedLegacyEventName(3, "legacy_event_name_3", &trace_packet_protos); |
| AddInternedEventCategory(3, "event_category_3", &trace_packet_protos); |
| |
| trace_packet_protos.emplace_back(); |
| auto* track_event = trace_packet_protos.back().mutable_track_event(); |
| track_event->add_category_iids(3); |
| track_event->set_timestamp_delta_us(4); |
| track_event->set_thread_time_delta_us(6); |
| |
| *track_event->mutable_legacy_event() = CreateLegacyEvent( |
| /* name_iid = */ 3, kLegacyFlags, TRACE_EVENT_PHASE_COMPLETE); |
| |
| FinalizePackets(trace_packet_protos); |
| |
| ASSERT_EQ( |
| 1u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("legacy_event_name_3"), |
| &events)); |
| EXPECT_EQ(kLegacyDuration, events[0]->duration); |
| EXPECT_EQ(kLegacyThreadDuration, events[0]->thread_duration); |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, LegacyEventId) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| trace_analyzer::TraceEventVector events; |
| |
| AddThreadDescriptorPacket(/* sort_index = */ base::nullopt, |
| ThreadDescriptor::THREAD_UNSPECIFIED, |
| /* thread_name = */ base::nullopt, kReferenceTimeUs, |
| kReferenceThreadTimeUs, &trace_packet_protos); |
| AddInternedLegacyEventName(3, "legacy_event_name_3", &trace_packet_protos); |
| AddInternedEventCategory(3, "event_category_3", &trace_packet_protos); |
| |
| trace_packet_protos.emplace_back(); |
| auto* track_event = trace_packet_protos.back().mutable_track_event(); |
| track_event->add_category_iids(3); |
| track_event->set_timestamp_delta_us(4); |
| track_event->set_thread_time_delta_us(6); |
| |
| *track_event->mutable_legacy_event() = CreateLegacyEvent( |
| /* name_iid = */ 3, TRACE_EVENT_FLAG_HAS_ID, |
| TRACE_EVENT_PHASE_MEMORY_DUMP); |
| |
| trace_packet_protos.push_back(trace_packet_protos.back()); |
| *trace_packet_protos.back().mutable_track_event()->mutable_legacy_event() = |
| CreateLegacyEvent( |
| /* name_iid = */ 3, TRACE_EVENT_FLAG_HAS_LOCAL_ID, |
| TRACE_EVENT_PHASE_MARK); |
| |
| trace_packet_protos.push_back(trace_packet_protos.back()); |
| *trace_packet_protos.back().mutable_track_event()->mutable_legacy_event() = |
| CreateLegacyEvent( |
| /* name_iid = */ 3, TRACE_EVENT_FLAG_HAS_GLOBAL_ID, |
| TRACE_EVENT_PHASE_MARK); |
| |
| trace_packet_protos.push_back(trace_packet_protos.back()); |
| *trace_packet_protos.back().mutable_track_event()->mutable_legacy_event() = |
| CreateLegacyEvent( |
| /* name_iid = */ 3, 0, TRACE_EVENT_PHASE_MARK); |
| FinalizePackets(trace_packet_protos); |
| |
| ASSERT_EQ( |
| 4u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("legacy_event_name_3"), |
| &events)); |
| EXPECT_EQ(kLegacyIdStr, events[0]->id); |
| EXPECT_TRUE(events[0]->local_id2.empty()); |
| EXPECT_TRUE(events[0]->global_id2.empty()); |
| EXPECT_TRUE(events[1]->id.empty()); |
| EXPECT_EQ(kLegacyIdStr, events[1]->local_id2); |
| EXPECT_TRUE(events[1]->global_id2.empty()); |
| EXPECT_TRUE(events[2]->id.empty()); |
| EXPECT_TRUE(events[2]->local_id2.empty()); |
| EXPECT_EQ(kLegacyIdStr, events[2]->global_id2); |
| EXPECT_TRUE(events[3]->id.empty()); |
| EXPECT_TRUE(events[3]->local_id2.empty()); |
| EXPECT_TRUE(events[3]->global_id2.empty()); |
| |
| // Because trace_analyzer only parses the respective ID fields when a |
| // corresponding flag is set we also do a regex based on each line to ensure |
| // it only has the correct type. |
| // |
| // First line shouldn't have id2. |
| EXPECT_THAT(unparsed_trace_data_, |
| ::testing::Not(::testing::ContainsRegex("^.*\"id2\".*\n"))); |
| // Second line should not have id or global id2. |
| EXPECT_THAT(unparsed_trace_data_, |
| ::testing::Not(::testing::ContainsRegex("^.*\n.*\"id\".*\n"))); |
| EXPECT_THAT(unparsed_trace_data_, ::testing::Not(::testing::ContainsRegex( |
| "^.*\n.*\"id2\":\\{\"global\".*\n"))); |
| // Third line should not have id or local id2. |
| EXPECT_THAT( |
| unparsed_trace_data_, |
| ::testing::Not(::testing::ContainsRegex("^.*\n.*\n.*\"id\".*\n"))); |
| EXPECT_THAT(unparsed_trace_data_, |
| ::testing::Not(::testing::ContainsRegex( |
| "^.*\n.*\n.*\"id2\":\\{\"local\".*\n"))); |
| // Fourth line should not have id or id2. |
| EXPECT_THAT( |
| unparsed_trace_data_, |
| ::testing::Not(::testing::ContainsRegex("^.*\n.*\n.*\n.*\"id.*"))); |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, LegacyEventIdScope) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| trace_analyzer::TraceEventVector events; |
| |
| AddThreadDescriptorPacket(/* sort_index = */ base::nullopt, |
| ThreadDescriptor::THREAD_UNSPECIFIED, |
| /* thread_name = */ base::nullopt, kReferenceTimeUs, |
| kReferenceThreadTimeUs, &trace_packet_protos); |
| AddInternedLegacyEventName(3, "legacy_event_name_3", &trace_packet_protos); |
| AddInternedEventCategory(3, "event_category_3", &trace_packet_protos); |
| |
| trace_packet_protos.emplace_back(); |
| auto* track_event = trace_packet_protos.back().mutable_track_event(); |
| track_event->add_category_iids(3); |
| track_event->set_timestamp_delta_us(4); |
| track_event->set_thread_time_delta_us(6); |
| |
| *track_event->mutable_legacy_event() = CreateLegacyEvent( |
| /* name_iid = */ 3, kLegacyFlags, kLegacyPhase); |
| track_event->mutable_legacy_event()->clear_id_scope(); |
| |
| FinalizePackets(trace_packet_protos); |
| |
| ASSERT_EQ( |
| 1u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("legacy_event_name_3"), |
| &events)); |
| EXPECT_TRUE(events[0]->scope.empty()); |
| |
| track_event->mutable_legacy_event()->set_id_scope(kLegacyScope); |
| FinalizePackets(trace_packet_protos); |
| |
| ASSERT_EQ( |
| 1u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("legacy_event_name_3"), |
| &events)); |
| EXPECT_EQ(kLegacyScope, events[0]->scope); |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, LegacyEventAsyncTts) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| trace_analyzer::TraceEventVector events; |
| |
| AddThreadDescriptorPacket(/* sort_index = */ base::nullopt, |
| ThreadDescriptor::THREAD_UNSPECIFIED, |
| /* thread_name = */ base::nullopt, kReferenceTimeUs, |
| kReferenceThreadTimeUs, &trace_packet_protos); |
| AddInternedLegacyEventName(3, "legacy_event_name_3", &trace_packet_protos); |
| AddInternedEventCategory(3, "event_category_3", &trace_packet_protos); |
| |
| trace_packet_protos.emplace_back(); |
| auto* track_event = trace_packet_protos.back().mutable_track_event(); |
| track_event->add_category_iids(3); |
| track_event->set_timestamp_delta_us(4); |
| track_event->set_thread_time_delta_us(6); |
| |
| *track_event->mutable_legacy_event() = CreateLegacyEvent( |
| /* name_iid = */ 3, kLegacyFlags, kLegacyPhase); |
| |
| FinalizePackets(trace_packet_protos); |
| |
| ASSERT_EQ( |
| 1u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("legacy_event_name_3"), |
| &events)); |
| EXPECT_THAT( |
| unparsed_trace_data_, |
| ::testing::Not(::testing::ContainsRegex(".*\"use_async_tts\":.*"))); |
| |
| // Now rewrite the legacy event with the TRACE_EVENT_FLAG_ASYNC_TTS |
| // flag. |
| *track_event->mutable_legacy_event() = CreateLegacyEvent( |
| /* name_iid = */ 3, kLegacyFlags | TRACE_EVENT_FLAG_ASYNC_TTS, |
| kLegacyPhase); |
| |
| FinalizePackets(trace_packet_protos); |
| |
| ASSERT_EQ( |
| 1u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("legacy_event_name_3"), |
| &events)); |
| EXPECT_THAT(unparsed_trace_data_, |
| ::testing::ContainsRegex(".*\"use_async_tts\":1.*")); |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, LegacyEventBindId) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| trace_analyzer::TraceEventVector events; |
| |
| AddThreadDescriptorPacket(/* sort_index = */ base::nullopt, |
| ThreadDescriptor::THREAD_UNSPECIFIED, |
| /* thread_name = */ base::nullopt, kReferenceTimeUs, |
| kReferenceThreadTimeUs, &trace_packet_protos); |
| AddInternedLegacyEventName(3, "legacy_event_name_3", &trace_packet_protos); |
| AddInternedEventCategory(3, "event_category_3", &trace_packet_protos); |
| |
| trace_packet_protos.emplace_back(); |
| auto* track_event = trace_packet_protos.back().mutable_track_event(); |
| track_event->add_category_iids(3); |
| track_event->set_timestamp_delta_us(4); |
| track_event->set_thread_time_delta_us(6); |
| |
| *track_event->mutable_legacy_event() = CreateLegacyEvent( |
| /* name_iid = */ 3, kLegacyFlags, kLegacyPhase); |
| track_event->mutable_legacy_event()->clear_bind_id(); |
| |
| FinalizePackets(trace_packet_protos); |
| |
| ASSERT_EQ( |
| 1u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("legacy_event_name_3"), |
| &events)); |
| EXPECT_TRUE(events[0]->bind_id.empty()); |
| |
| track_event->mutable_legacy_event()->set_bind_id(kLegacyBindId); |
| FinalizePackets(trace_packet_protos); |
| |
| ASSERT_EQ( |
| 1u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("legacy_event_name_3"), |
| &events)); |
| EXPECT_EQ(kLegacyBindIdStr, events[0]->bind_id); |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, LegacyEventBindToEnclosing) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| trace_analyzer::TraceEventVector events; |
| |
| AddThreadDescriptorPacket(/* sort_index = */ base::nullopt, |
| ThreadDescriptor::THREAD_UNSPECIFIED, |
| /* thread_name = */ base::nullopt, kReferenceTimeUs, |
| kReferenceThreadTimeUs, &trace_packet_protos); |
| AddInternedLegacyEventName(3, "legacy_event_name_3", &trace_packet_protos); |
| AddInternedEventCategory(3, "event_category_3", &trace_packet_protos); |
| |
| trace_packet_protos.emplace_back(); |
| auto* track_event = trace_packet_protos.back().mutable_track_event(); |
| track_event->add_category_iids(3); |
| track_event->set_timestamp_delta_us(4); |
| track_event->set_thread_time_delta_us(6); |
| |
| *track_event->mutable_legacy_event() = CreateLegacyEvent( |
| /* name_iid = */ 3, kLegacyFlags, kLegacyPhase); |
| |
| FinalizePackets(trace_packet_protos); |
| |
| ASSERT_EQ( |
| 1u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("legacy_event_name_3"), |
| &events)); |
| EXPECT_THAT(unparsed_trace_data_, |
| ::testing::Not(::testing::ContainsRegex(".*\"bp\":.*"))); |
| |
| // Now rewrite the legacy event with the TRACE_EVENT_FLAG_BIND_TO_ENCLOSING |
| // flag. |
| *track_event->mutable_legacy_event() = CreateLegacyEvent( |
| /* name_iid = */ 3, kLegacyFlags | TRACE_EVENT_FLAG_BIND_TO_ENCLOSING, |
| kLegacyPhase); |
| |
| FinalizePackets(trace_packet_protos); |
| |
| ASSERT_EQ( |
| 1u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("legacy_event_name_3"), |
| &events)); |
| EXPECT_THAT(unparsed_trace_data_, |
| ::testing::ContainsRegex(".*\"bp\":\"e\".*")); |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, LegacyEventFlowEvents) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| trace_analyzer::TraceEventVector events; |
| |
| AddThreadDescriptorPacket(/* sort_index = */ base::nullopt, |
| ThreadDescriptor::THREAD_UNSPECIFIED, |
| /* thread_name = */ base::nullopt, kReferenceTimeUs, |
| kReferenceThreadTimeUs, &trace_packet_protos); |
| AddInternedLegacyEventName(3, "legacy_event_name_3", &trace_packet_protos); |
| AddInternedEventCategory(3, "event_category_3", &trace_packet_protos); |
| |
| trace_packet_protos.emplace_back(); |
| auto* track_event = trace_packet_protos.back().mutable_track_event(); |
| track_event->add_category_iids(3); |
| track_event->set_timestamp_delta_us(4); |
| track_event->set_thread_time_delta_us(6); |
| |
| *track_event->mutable_legacy_event() = CreateLegacyEvent( |
| /* name_iid = */ 3, |
| kLegacyFlags | TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT, |
| kLegacyPhase); |
| |
| trace_packet_protos.push_back(trace_packet_protos.back()); |
| *trace_packet_protos.back().mutable_track_event()->mutable_legacy_event() = |
| CreateLegacyEvent( |
| /* name_iid = */ 3, kLegacyFlags | TRACE_EVENT_FLAG_FLOW_IN, |
| kLegacyPhase); |
| |
| trace_packet_protos.push_back(trace_packet_protos.back()); |
| *trace_packet_protos.back().mutable_track_event()->mutable_legacy_event() = |
| CreateLegacyEvent( |
| /* name_iid = */ 3, kLegacyFlags | TRACE_EVENT_FLAG_FLOW_OUT, |
| kLegacyPhase); |
| FinalizePackets(trace_packet_protos); |
| |
| ASSERT_EQ( |
| 3u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("legacy_event_name_3"), |
| &events)); |
| EXPECT_TRUE(events[0]->flow_in); |
| EXPECT_TRUE(events[0]->flow_out); |
| EXPECT_TRUE(events[1]->flow_in); |
| EXPECT_FALSE(events[1]->flow_out); |
| EXPECT_FALSE(events[2]->flow_in); |
| EXPECT_TRUE(events[2]->flow_out); |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, LegacyEventInstantEventScope) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| trace_analyzer::TraceEventVector events; |
| |
| AddThreadDescriptorPacket(/* sort_index = */ base::nullopt, |
| ThreadDescriptor::THREAD_UNSPECIFIED, |
| /* thread_name = */ base::nullopt, kReferenceTimeUs, |
| kReferenceThreadTimeUs, &trace_packet_protos); |
| AddInternedLegacyEventName(3, "legacy_event_name_3", &trace_packet_protos); |
| AddInternedEventCategory(3, "event_category_3", &trace_packet_protos); |
| |
| trace_packet_protos.emplace_back(); |
| auto* track_event = trace_packet_protos.back().mutable_track_event(); |
| track_event->add_category_iids(3); |
| track_event->set_timestamp_delta_us(4); |
| track_event->set_thread_time_delta_us(6); |
| |
| *track_event->mutable_legacy_event() = CreateLegacyEvent( |
| /* name_iid = */ 3, TRACE_EVENT_FLAG_HAS_ID | TRACE_EVENT_SCOPE_GLOBAL, |
| TRACE_EVENT_PHASE_INSTANT); |
| |
| trace_packet_protos.push_back(trace_packet_protos.back()); |
| *trace_packet_protos.back().mutable_track_event()->mutable_legacy_event() = |
| CreateLegacyEvent( |
| /* name_iid = */ 3, |
| TRACE_EVENT_FLAG_HAS_ID | TRACE_EVENT_SCOPE_PROCESS, |
| TRACE_EVENT_PHASE_INSTANT); |
| |
| trace_packet_protos.push_back(trace_packet_protos.back()); |
| *trace_packet_protos.back().mutable_track_event()->mutable_legacy_event() = |
| CreateLegacyEvent( |
| /* name_iid = */ 3, |
| TRACE_EVENT_FLAG_HAS_ID | TRACE_EVENT_SCOPE_THREAD, |
| TRACE_EVENT_PHASE_INSTANT); |
| trace_packet_protos.push_back(trace_packet_protos.back()); |
| trace_packet_protos.back() |
| .mutable_track_event() |
| ->mutable_legacy_event() |
| ->clear_instant_event_scope(); |
| FinalizePackets(trace_packet_protos); |
| |
| ASSERT_EQ( |
| 4u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("legacy_event_name_3"), |
| &events)); |
| // For whatever reason trace_analyzer() does not extract the instant event |
| // scope so look for it in the unparsed data in the order we added them. |
| EXPECT_THAT(unparsed_trace_data_, |
| ::testing::ContainsRegex(base::StringPrintf( |
| ".*\"s\":\"%c\".*\n" |
| ".*\"s\":\"%c\".*\n" |
| ".*\"s\":\"%c\".*\n" |
| ".*\"s\":\"g\".*", // UNSPECIFIED defaults to global. |
| TRACE_EVENT_SCOPE_NAME_GLOBAL, TRACE_EVENT_SCOPE_NAME_PROCESS, |
| TRACE_EVENT_SCOPE_NAME_THREAD))); |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, TaskExecutionAddedAsArgs) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| trace_analyzer::TraceEventVector events; |
| |
| AddThreadDescriptorPacket(/* sort_index = */ base::nullopt, |
| ThreadDescriptor::THREAD_UNSPECIFIED, |
| /* thread_name = */ base::nullopt, kReferenceTimeUs, |
| kReferenceThreadTimeUs, &trace_packet_protos); |
| AddInternedLegacyEventName(3, "legacy_event_name_3", &trace_packet_protos); |
| AddInternedEventCategory(3, "event_category_3", &trace_packet_protos); |
| trace_packet_protos.emplace_back(); |
| auto* track_event = trace_packet_protos.back().mutable_track_event(); |
| track_event->set_timestamp_absolute_us(4); |
| track_event->add_category_iids(3); |
| *track_event->mutable_legacy_event() = |
| CreateLegacyEvent(/* name_iid = */ 3, kLegacyFlags, kLegacyPhase); |
| |
| trace_packet_protos.back() |
| .mutable_track_event() |
| ->mutable_task_execution() |
| ->set_posted_from_iid(4); |
| |
| EXPECT_DCHECK_DEATH(FinalizePackets(trace_packet_protos)); |
| |
| AddInternedSourceLocation(4, "file_name", "function_name", |
| &trace_packet_protos); |
| std::swap(trace_packet_protos[3], trace_packet_protos[4]); |
| |
| FinalizePackets(trace_packet_protos); |
| |
| ASSERT_EQ( |
| 1u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("legacy_event_name_3"), |
| &events)); |
| ASSERT_TRUE(events[0]->HasArg("src_file")); |
| ASSERT_TRUE(events[0]->HasArg("src_func")); |
| EXPECT_EQ("file_name", events[0]->GetKnownArgAsString("src_file")); |
| EXPECT_EQ("function_name", events[0]->GetKnownArgAsString("src_func")); |
| |
| // A source location without function name converts into a single "src" arg. |
| trace_packet_protos[3] |
| .mutable_interned_data() |
| ->mutable_source_locations(0) |
| ->clear_function_name(); |
| FinalizePackets(trace_packet_protos); |
| |
| ASSERT_EQ( |
| 1u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("legacy_event_name_3"), |
| &events)); |
| ASSERT_TRUE(events[0]->HasArg("src")); |
| EXPECT_EQ("file_name", events[0]->GetKnownArgAsString("src")); |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, DebugAnnotationRequiresName) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| trace_analyzer::TraceEventVector events; |
| |
| AddThreadDescriptorPacket(/* sort_index = */ base::nullopt, |
| ThreadDescriptor::THREAD_UNSPECIFIED, |
| /* thread_name = */ base::nullopt, kReferenceTimeUs, |
| kReferenceThreadTimeUs, &trace_packet_protos); |
| AddInternedLegacyEventName(3, "legacy_event_name_3", &trace_packet_protos); |
| AddInternedEventCategory(3, "event_category_3", &trace_packet_protos); |
| trace_packet_protos.emplace_back(); |
| auto* track_event = trace_packet_protos.back().mutable_track_event(); |
| track_event->set_timestamp_absolute_us(4); |
| track_event->add_category_iids(3); |
| *track_event->mutable_legacy_event() = |
| CreateLegacyEvent(/* name_iid = */ 3, kLegacyFlags, kLegacyPhase, |
| /* pid = */ 7, /* tid = */ 8); |
| |
| auto* annotation = |
| trace_packet_protos.back().mutable_track_event()->add_debug_annotations(); |
| annotation->set_name_iid(2); |
| annotation->set_bool_value(true); |
| |
| EXPECT_DCHECK_DEATH(FinalizePackets(trace_packet_protos)); |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, DebugAnnotationBoolValue) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| trace_analyzer::TraceEventVector events; |
| |
| AddThreadDescriptorPacket(/* sort_index = */ base::nullopt, |
| ThreadDescriptor::THREAD_UNSPECIFIED, |
| /* thread_name = */ base::nullopt, kReferenceTimeUs, |
| kReferenceThreadTimeUs, &trace_packet_protos); |
| AddInternedLegacyEventName(3, "legacy_event_name_3", &trace_packet_protos); |
| AddInternedEventCategory(3, "event_category_3", &trace_packet_protos); |
| AddInternedDebugAnnotationName(2, "bool_2", &trace_packet_protos); |
| AddInternedDebugAnnotationName(3, "bool_3", &trace_packet_protos); |
| trace_packet_protos.emplace_back(); |
| auto* track_event = trace_packet_protos.back().mutable_track_event(); |
| track_event->set_timestamp_absolute_us(4); |
| track_event->add_category_iids(3); |
| *track_event->mutable_legacy_event() = |
| CreateLegacyEvent(/* name_iid = */ 3, kLegacyFlags, kLegacyPhase, |
| /* pid = */ 7, /* tid = */ 8); |
| |
| auto* annotation = |
| trace_packet_protos.back().mutable_track_event()->add_debug_annotations(); |
| annotation->set_name_iid(2); |
| annotation->set_bool_value(true); |
| annotation = |
| trace_packet_protos.back().mutable_track_event()->add_debug_annotations(); |
| annotation->set_name_iid(3); |
| annotation->set_bool_value(false); |
| |
| FinalizePackets(trace_packet_protos); |
| |
| ASSERT_EQ( |
| 1u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("legacy_event_name_3"), |
| &events)); |
| ASSERT_TRUE(events[0]->HasArg("bool_2")); |
| EXPECT_TRUE(events[0]->GetKnownArgAsBool("bool_2")); |
| ASSERT_TRUE(events[0]->HasArg("bool_3")); |
| EXPECT_FALSE(events[0]->GetKnownArgAsBool("bool_3")); |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, DebugAnnotationUintValue) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| trace_analyzer::TraceEventVector events; |
| |
| AddThreadDescriptorPacket(/* sort_index = */ base::nullopt, |
| ThreadDescriptor::THREAD_UNSPECIFIED, |
| /* thread_name = */ base::nullopt, kReferenceTimeUs, |
| kReferenceThreadTimeUs, &trace_packet_protos); |
| AddInternedLegacyEventName(3, "legacy_event_name_3", &trace_packet_protos); |
| AddInternedEventCategory(3, "event_category_3", &trace_packet_protos); |
| AddInternedDebugAnnotationName(2, "uint", &trace_packet_protos); |
| trace_packet_protos.emplace_back(); |
| auto* track_event = trace_packet_protos.back().mutable_track_event(); |
| track_event->set_timestamp_absolute_us(4); |
| track_event->add_category_iids(3); |
| *track_event->mutable_legacy_event() = |
| CreateLegacyEvent(/* name_iid = */ 3, kLegacyFlags, kLegacyPhase, |
| /* pid = */ 7, /* tid = */ 8); |
| |
| auto* annotation = |
| trace_packet_protos.back().mutable_track_event()->add_debug_annotations(); |
| annotation->set_name_iid(2); |
| annotation->set_uint_value(std::numeric_limits<uint64_t>::max()); |
| |
| FinalizePackets(trace_packet_protos); |
| |
| ASSERT_EQ( |
| 1u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("legacy_event_name_3"), |
| &events)); |
| ASSERT_TRUE(events[0]->HasArg("uint")); |
| EXPECT_EQ(std::numeric_limits<uint64_t>::max(), |
| events[0]->GetKnownArgAsDouble("uint")); |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, DebugAnnotationIntValue) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| trace_analyzer::TraceEventVector events; |
| |
| AddThreadDescriptorPacket(/* sort_index = */ base::nullopt, |
| ThreadDescriptor::THREAD_UNSPECIFIED, |
| /* thread_name = */ base::nullopt, kReferenceTimeUs, |
| kReferenceThreadTimeUs, &trace_packet_protos); |
| AddInternedLegacyEventName(3, "legacy_event_name_3", &trace_packet_protos); |
| AddInternedEventCategory(3, "event_category_3", &trace_packet_protos); |
| AddInternedDebugAnnotationName(2, "int", &trace_packet_protos); |
| trace_packet_protos.emplace_back(); |
| auto* track_event = trace_packet_protos.back().mutable_track_event(); |
| track_event->set_timestamp_absolute_us(4); |
| track_event->add_category_iids(3); |
| *track_event->mutable_legacy_event() = |
| CreateLegacyEvent(/* name_iid = */ 3, kLegacyFlags, kLegacyPhase, |
| /* pid = */ 7, /* tid = */ 8); |
| |
| auto* annotation = |
| trace_packet_protos.back().mutable_track_event()->add_debug_annotations(); |
| annotation->set_name_iid(2); |
| annotation->set_int_value(std::numeric_limits<int64_t>::max()); |
| |
| FinalizePackets(trace_packet_protos); |
| |
| ASSERT_EQ( |
| 1u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("legacy_event_name_3"), |
| &events)); |
| ASSERT_TRUE(events[0]->HasArg("int")); |
| EXPECT_EQ(std::numeric_limits<int64_t>::max(), |
| events[0]->GetKnownArgAsDouble("int")); |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, DebugAnnotationDoubleValue) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| trace_analyzer::TraceEventVector events; |
| |
| AddThreadDescriptorPacket(/* sort_index = */ base::nullopt, |
| ThreadDescriptor::THREAD_UNSPECIFIED, |
| /* thread_name = */ base::nullopt, kReferenceTimeUs, |
| kReferenceThreadTimeUs, &trace_packet_protos); |
| AddInternedLegacyEventName(3, "legacy_event_name_3", &trace_packet_protos); |
| AddInternedEventCategory(3, "event_category_3", &trace_packet_protos); |
| AddInternedDebugAnnotationName(1, "double_min", &trace_packet_protos); |
| AddInternedDebugAnnotationName(3, "double_max", &trace_packet_protos); |
| trace_packet_protos.emplace_back(); |
| auto* track_event = trace_packet_protos.back().mutable_track_event(); |
| track_event->set_timestamp_absolute_us(4); |
| track_event->add_category_iids(3); |
| *track_event->mutable_legacy_event() = |
| CreateLegacyEvent(/* name_iid = */ 3, kLegacyFlags, kLegacyPhase, |
| /* pid = */ 7, /* tid = */ 8); |
| |
| auto* annotation = |
| trace_packet_protos.back().mutable_track_event()->add_debug_annotations(); |
| annotation->set_name_iid(1); |
| annotation->set_double_value(std::numeric_limits<double>::min()); |
| |
| annotation = |
| trace_packet_protos.back().mutable_track_event()->add_debug_annotations(); |
| annotation->set_name_iid(3); |
| annotation->set_double_value(std::numeric_limits<double>::max()); |
| |
| FinalizePackets(trace_packet_protos); |
| |
| ASSERT_EQ( |
| 1u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("legacy_event_name_3"), |
| &events)); |
| |
| // NaN and +/- Inf aren't allowed by json. |
| ASSERT_TRUE(events[0]->HasArg("double_min")); |
| EXPECT_EQ(std::numeric_limits<double>::min(), |
| events[0]->GetKnownArgAsDouble("double_min")); |
| ASSERT_TRUE(events[0]->HasArg("double_max")); |
| EXPECT_EQ(std::numeric_limits<double>::max(), |
| events[0]->GetKnownArgAsDouble("double_max")); |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, DebugAnnotationStringValue) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| trace_analyzer::TraceEventVector events; |
| |
| AddThreadDescriptorPacket(/* sort_index = */ base::nullopt, |
| ThreadDescriptor::THREAD_UNSPECIFIED, |
| /* thread_name = */ base::nullopt, kReferenceTimeUs, |
| kReferenceThreadTimeUs, &trace_packet_protos); |
| AddInternedLegacyEventName(3, "legacy_event_name_3", &trace_packet_protos); |
| AddInternedEventCategory(3, "event_category_3", &trace_packet_protos); |
| AddInternedDebugAnnotationName(2, "string", &trace_packet_protos); |
| trace_packet_protos.emplace_back(); |
| auto* track_event = trace_packet_protos.back().mutable_track_event(); |
| track_event->set_timestamp_absolute_us(4); |
| track_event->add_category_iids(3); |
| *track_event->mutable_legacy_event() = |
| CreateLegacyEvent(/* name_iid = */ 3, kLegacyFlags, kLegacyPhase, |
| /* pid = */ 7, /* tid = */ 8); |
| |
| auto* annotation = |
| trace_packet_protos.back().mutable_track_event()->add_debug_annotations(); |
| annotation->set_name_iid(2); |
| annotation->set_string_value("foo"); |
| |
| FinalizePackets(trace_packet_protos); |
| |
| ASSERT_EQ( |
| 1u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("legacy_event_name_3"), |
| &events)); |
| ASSERT_TRUE(events[0]->HasArg("string")); |
| EXPECT_EQ("foo", events[0]->GetKnownArgAsString("string")); |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, DebugAnnotationPointerValue) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| trace_analyzer::TraceEventVector events; |
| |
| AddThreadDescriptorPacket(/* sort_index = */ base::nullopt, |
| ThreadDescriptor::THREAD_UNSPECIFIED, |
| /* thread_name = */ base::nullopt, kReferenceTimeUs, |
| kReferenceThreadTimeUs, &trace_packet_protos); |
| AddInternedLegacyEventName(3, "legacy_event_name_3", &trace_packet_protos); |
| AddInternedEventCategory(3, "event_category_3", &trace_packet_protos); |
| AddInternedDebugAnnotationName(2, "pointer", &trace_packet_protos); |
| trace_packet_protos.emplace_back(); |
| auto* track_event = trace_packet_protos.back().mutable_track_event(); |
| track_event->set_timestamp_absolute_us(4); |
| track_event->add_category_iids(3); |
| *track_event->mutable_legacy_event() = |
| CreateLegacyEvent(/* name_iid = */ 3, kLegacyFlags, kLegacyPhase, |
| /* pid = */ 7, /* tid = */ 8); |
| |
| auto* annotation = |
| trace_packet_protos.back().mutable_track_event()->add_debug_annotations(); |
| annotation->set_name_iid(2); |
| annotation->set_pointer_value(1); |
| |
| FinalizePackets(trace_packet_protos); |
| |
| ASSERT_EQ( |
| 1u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("legacy_event_name_3"), |
| &events)); |
| ASSERT_TRUE(events[0]->HasArg("pointer")); |
| EXPECT_EQ("0x1", events[0]->GetKnownArgAsString("pointer")); |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, DebugAnnotationComplexNestedValue) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| trace_analyzer::TraceEventVector events; |
| |
| AddThreadDescriptorPacket(/* sort_index = */ base::nullopt, |
| ThreadDescriptor::THREAD_UNSPECIFIED, |
| /* thread_name = */ base::nullopt, kReferenceTimeUs, |
| kReferenceThreadTimeUs, &trace_packet_protos); |
| AddInternedLegacyEventName(3, "legacy_event_name_3", &trace_packet_protos); |
| AddInternedEventCategory(3, "event_category_3", &trace_packet_protos); |
| AddInternedDebugAnnotationName(2, "top_level_dict", &trace_packet_protos); |
| trace_packet_protos.emplace_back(); |
| auto* track_event = trace_packet_protos.back().mutable_track_event(); |
| track_event->set_timestamp_absolute_us(4); |
| track_event->add_category_iids(3); |
| *track_event->mutable_legacy_event() = |
| CreateLegacyEvent(/* name_iid = */ 3, kLegacyFlags, kLegacyPhase, |
| /* pid = */ 7, /* tid = */ 8); |
| |
| auto* annotation = |
| trace_packet_protos.back().mutable_track_event()->add_debug_annotations(); |
| annotation->set_name_iid(2); |
| *annotation->mutable_nested_value() = NestedValue( |
| {{"arr0", NestedValue({NestedValue(int64_t(1)), NestedValue(bool(true)), |
| NestedValue({{"i2", NestedValue(int64_t(3))}})})}, |
| {"b0", NestedValue(bool(true))}, |
| {"d0", NestedValue(double(6.0))}, |
| {"dict0", |
| NestedValue({{"dict1", NestedValue({{"b2", NestedValue(bool(false))}})}, |
| {"i1", NestedValue(int64_t(2014))}, |
| {"s1", NestedValue(std::string("foo"))}})}, |
| {"i0", NestedValue(int64_t(2014))}, |
| {"s0", NestedValue(std::string("foo"))}}); |
| |
| FinalizePackets(trace_packet_protos); |
| |
| ASSERT_EQ( |
| 1u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("legacy_event_name_3"), |
| &events)); |
| ASSERT_TRUE(events[0]->HasArg("top_level_dict")); |
| auto value = events[0]->GetKnownArgAsValue("top_level_dict"); |
| ASSERT_TRUE(value); |
| ASSERT_TRUE(value->is_dict()); |
| EXPECT_EQ(6.0, value->FindKey("d0")->GetDouble()); |
| EXPECT_EQ(2014, value->FindKey("i0")->GetInt()); |
| EXPECT_EQ("foo", value->FindKey("s0")->GetString()); |
| |
| auto* arr0 = value->FindKey("arr0"); |
| ASSERT_TRUE(arr0); |
| ASSERT_TRUE(arr0->is_list()); |
| const auto& list0 = arr0->GetList(); |
| ASSERT_EQ(3u, list0.size()); |
| EXPECT_EQ(1, list0[0].GetInt()); |
| EXPECT_TRUE(list0[1].GetBool()); |
| const auto& arr0_dict1 = list0[2]; |
| ASSERT_TRUE(arr0_dict1.is_dict()); |
| EXPECT_EQ(3, arr0_dict1.FindKey("i2")->GetInt()); |
| |
| auto* dict0 = value->FindKey("dict0"); |
| ASSERT_TRUE(dict0); |
| EXPECT_EQ(2014, dict0->FindKey("i1")->GetInt()); |
| EXPECT_EQ("foo", dict0->FindKey("s1")->GetString()); |
| auto* dict0_dict1 = dict0->FindKey("dict1"); |
| ASSERT_TRUE(dict0_dict1); |
| EXPECT_FALSE(dict0_dict1->FindKey("b2")->GetBool()); |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, DebugAnnotationLegacyJsonValue) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| trace_analyzer::TraceEventVector events; |
| |
| AddThreadDescriptorPacket(/* sort_index = */ base::nullopt, |
| ThreadDescriptor::THREAD_UNSPECIFIED, |
| /* thread_name = */ base::nullopt, kReferenceTimeUs, |
| kReferenceThreadTimeUs, &trace_packet_protos); |
| AddInternedLegacyEventName(3, "legacy_event_name_3", &trace_packet_protos); |
| AddInternedEventCategory(3, "event_category_3", &trace_packet_protos); |
| AddInternedDebugAnnotationName(2, "legacy_json", &trace_packet_protos); |
| trace_packet_protos.emplace_back(); |
| auto* track_event = trace_packet_protos.back().mutable_track_event(); |
| track_event->set_timestamp_absolute_us(4); |
| track_event->add_category_iids(3); |
| *track_event->mutable_legacy_event() = |
| CreateLegacyEvent(/* name_iid = */ 3, kLegacyFlags, kLegacyPhase, |
| /* pid = */ 7, /* tid = */ 8); |
| |
| auto* annotation = |
| trace_packet_protos.back().mutable_track_event()->add_debug_annotations(); |
| annotation->set_name_iid(2); |
| annotation->set_legacy_json_value("{\"fooName\":\"fooValue\"}"); |
| |
| FinalizePackets(trace_packet_protos); |
| |
| ASSERT_EQ( |
| 1u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("legacy_event_name_3"), |
| &events)); |
| ASSERT_TRUE(events[0]->HasArg("legacy_json")); |
| auto value = events[0]->GetKnownArgAsValue("legacy_json"); |
| ASSERT_TRUE(value); |
| EXPECT_TRUE(value->is_dict()); |
| auto* sub_value = value->FindKey("fooName"); |
| ASSERT_TRUE(sub_value); |
| EXPECT_EQ("fooValue", sub_value->GetString()); |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, TestMetadata) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| |
| trace_packet_protos.emplace_back(); |
| { |
| auto* new_metadata = |
| trace_packet_protos.back().mutable_chrome_events()->add_metadata(); |
| new_metadata->set_name("int_metadata"); |
| new_metadata->set_int_value(42); |
| } |
| |
| { |
| auto* new_metadata = |
| trace_packet_protos.back().mutable_chrome_events()->add_metadata(); |
| new_metadata->set_name("string_metadata"); |
| new_metadata->set_string_value("met_val"); |
| } |
| |
| { |
| auto* new_metadata = |
| trace_packet_protos.back().mutable_chrome_events()->add_metadata(); |
| new_metadata->set_name("bool_metadata"); |
| new_metadata->set_bool_value(true); |
| } |
| |
| { |
| auto* new_metadata = |
| trace_packet_protos.back().mutable_chrome_events()->add_metadata(); |
| new_metadata->set_name("dict_metadata"); |
| new_metadata->set_json_value("{\"child_dict\": \"foo\"}"); |
| } |
| |
| FinalizePackets(trace_packet_protos); |
| |
| auto* metadata = parsed_trace_data()->FindKey("metadata"); |
| EXPECT_TRUE(metadata); |
| EXPECT_EQ(metadata->FindKey("int_metadata")->GetInt(), 42); |
| EXPECT_EQ(metadata->FindKey("string_metadata")->GetString(), "met_val"); |
| EXPECT_EQ(metadata->FindKey("bool_metadata")->GetBool(), true); |
| EXPECT_EQ( |
| metadata->FindKey("dict_metadata")->FindKey("child_dict")->GetString(), |
| "foo"); |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, TestLegacySystemFtrace) { |
| std::string ftrace = "#dummy data"; |
| |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| trace_packet_protos.emplace_back(); |
| trace_packet_protos.back().mutable_chrome_events()->add_legacy_ftrace_output( |
| ftrace); |
| FinalizePackets(trace_packet_protos); |
| |
| auto* sys_trace = parsed_trace_data()->FindKey("systemTraceEvents"); |
| EXPECT_TRUE(sys_trace); |
| EXPECT_EQ(sys_trace->GetString(), ftrace); |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, TestLegacySystemTraceEvents) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| |
| trace_packet_protos.emplace_back(); |
| auto* json_trace = trace_packet_protos.back() |
| .mutable_chrome_events() |
| ->add_legacy_json_trace(); |
| json_trace->set_type(perfetto::protos::ChromeLegacyJsonTrace::SYSTEM_TRACE); |
| json_trace->set_data( |
| "\"name\":\"MySysTrace\",\"content\":[" |
| "{\"pid\":10,\"tid\":11,\"ts\":23,\"ph\":\"I\"" |
| ",\"cat\":\"cat_name2\",\"name\":\"bar_name\"" |
| ",\"id2\":{\"global\":\"0x5\"},\"args\":{}}]"); |
| |
| FinalizePackets(trace_packet_protos); |
| |
| auto* sys_trace = parsed_trace_data()->FindKey("systemTraceEvents"); |
| EXPECT_TRUE(sys_trace); |
| EXPECT_EQ(sys_trace->FindKey("name")->GetString(), "MySysTrace"); |
| auto* content = sys_trace->FindKey("content"); |
| EXPECT_EQ(content->GetList().size(), 1u); |
| EXPECT_EQ(content->GetList()[0].FindKey("pid")->GetInt(), 10); |
| EXPECT_EQ(content->GetList()[0].FindKey("tid")->GetInt(), 11); |
| EXPECT_EQ(content->GetList()[0].FindKey("name")->GetString(), "bar_name"); |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, TestLegacyUserTrace) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| |
| trace_packet_protos.emplace_back(); |
| auto* json_trace = trace_packet_protos.back() |
| .mutable_chrome_events() |
| ->add_legacy_json_trace(); |
| json_trace->set_type(perfetto::protos::ChromeLegacyJsonTrace::USER_TRACE); |
| json_trace->set_data( |
| "{\"pid\":10,\"tid\":11,\"ts\":23,\"ph\":\"I\"" |
| ",\"cat\":\"cat_name2\",\"name\":\"bar_name\"" |
| ",\"id2\":{\"global\":\"0x5\"},\"args\":{}}"); |
| |
| FinalizePackets(trace_packet_protos); |
| |
| const trace_analyzer::TraceEvent* trace_event = trace_analyzer()->FindFirstOf( |
| trace_analyzer::Query(trace_analyzer::Query::EVENT_NAME) == |
| trace_analyzer::Query::String("bar_name")); |
| EXPECT_TRUE(trace_event); |
| |
| EXPECT_EQ(10, trace_event->thread.process_id); |
| EXPECT_EQ(11, trace_event->thread.thread_id); |
| EXPECT_EQ(23, trace_event->timestamp); |
| EXPECT_EQ('I', trace_event->phase); |
| EXPECT_EQ("bar_name", trace_event->name); |
| EXPECT_EQ("cat_name2", trace_event->category); |
| EXPECT_EQ("0x5", trace_event->global_id2); |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, TestTraceStats) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| |
| trace_packet_protos.emplace_back(); |
| // We are just checking that we correctly called the function provided by the |
| // base class. See json_trace_exporter_unittest for a more complete test. |
| trace_packet_protos.back().mutable_trace_stats(); |
| FinalizePackets(trace_packet_protos); |
| EXPECT_TRUE(base::StartsWith(unparsed_trace_data_, |
| "{\"traceEvents\":[]," |
| "\"metadata\":{\"perfetto_trace_stats\":{\"", |
| base::CompareCase::SENSITIVE)); |
| } |
| |
| TEST_F(TrackEventJsonExporterTest, ComplexLongSequenceWithDroppedPackets) { |
| std::vector<perfetto::protos::TracePacket> trace_packet_protos; |
| trace_analyzer::TraceEventVector events; |
| size_t idx = 0; |
| |
| // Sequence 1 is complete with no data loss and 3 events. 2 with delta |
| // timestamps and one with an absolute timestamps 1 us further than the delta |
| // events. |
| AddThreadDescriptorPacket(/* sort_index = */ base::nullopt, |
| ThreadDescriptor::THREAD_UNSPECIFIED, |
| /* thread_name = */ base::nullopt, kReferenceTimeUs, |
| kReferenceThreadTimeUs, &trace_packet_protos); |
| AddInternedLegacyEventName(1, "sequence_1", &trace_packet_protos); |
| AddInternedEventCategory(1, "event_category_1", &trace_packet_protos); |
| trace_packet_protos.emplace_back(); |
| auto* track_event = trace_packet_protos.back().mutable_track_event(); |
| track_event->add_category_iids(1); |
| track_event->set_timestamp_delta_us(4); |
| track_event->set_thread_time_delta_us(3); |
| *track_event->mutable_legacy_event() = |
| CreateLegacyEvent(/* name_iid = */ 1, kLegacyFlags, kLegacyPhase); |
| trace_packet_protos.push_back(trace_packet_protos.back()); |
| trace_packet_protos.push_back(trace_packet_protos.back()); |
| trace_packet_protos.back().mutable_track_event()->set_timestamp_absolute_us( |
| 333); |
| trace_packet_protos.back().mutable_track_event()->set_thread_time_absolute_us( |
| 666); |
| for (; idx < trace_packet_protos.size(); ++idx) { |
| trace_packet_protos[idx].set_trusted_packet_sequence_id(1); |
| } |
| |
| // Sequence 2 alternates between emitting an event dropping packets and |
| // clearing incremental state. |
| AddThreadDescriptorPacket(/* sort_index = */ base::nullopt, |
| ThreadDescriptor::THREAD_UNSPECIFIED, |
| /* thread_name = */ base::nullopt, kReferenceTimeUs, |
| kReferenceThreadTimeUs, &trace_packet_protos); |
| AddInternedLegacyEventName(2, "sequence_2", &trace_packet_protos); |
| AddInternedEventCategory(2, "event_category_2", &trace_packet_protos); |
| |
| trace_packet_protos.emplace_back(); |
| track_event = trace_packet_protos.back().mutable_track_event(); |
| track_event->add_category_iids(2); |
| track_event->set_timestamp_delta_us(4); |
| track_event->set_thread_time_delta_us(3); |
| *track_event->mutable_legacy_event() = |
| CreateLegacyEvent(/* name_iid = */ 2, kLegacyFlags, kLegacyPhase); |
| |
| // This event will be dropped. |
| trace_packet_protos.push_back(trace_packet_protos.back()); |
| trace_packet_protos.back().set_previous_packet_dropped(true); |
| |
| // Add a TraceStats packet, which shouldn't be dropped even though the |
| // incremental state was not cleared yet. |
| trace_packet_protos.emplace_back(); |
| trace_packet_protos.back().mutable_trace_stats(); |
| |
| // Reset the state. |
| AddThreadDescriptorPacket( |
| /* sort_index = */ base::nullopt, ThreadDescriptor::THREAD_UNSPECIFIED, |
| /* thread_name = */ base::nullopt, kReferenceTimeUs + 4 * 3, |
| kReferenceThreadTimeUs + 3 * 3, &trace_packet_protos); |
| trace_packet_protos.back().set_incremental_state_cleared(true); |
| AddInternedLegacyEventName(2, "sequence_2", &trace_packet_protos); |
| AddInternedEventCategory(2, "event_category_2", &trace_packet_protos); |
| |
| trace_packet_protos.emplace_back(); |
| *trace_packet_protos.back().mutable_track_event() = *track_event; |
| // This event will be dropped. |
| trace_packet_protos.push_back(trace_packet_protos.back()); |
| trace_packet_protos.back().set_previous_packet_dropped(true); |
| for (; idx < trace_packet_protos.size(); ++idx) { |
| trace_packet_protos[idx].set_trusted_packet_sequence_id(2); |
| } |
| |
| // Sequence 3 emits a single event to ensure that sequence 2 doesn't prevent |
| // these events from being emitted. |
| AddThreadDescriptorPacket(/* sort_index = */ base::nullopt, |
| ThreadDescriptor::THREAD_UNSPECIFIED, |
| /* thread_name = */ base::nullopt, kReferenceTimeUs, |
| kReferenceThreadTimeUs, &trace_packet_protos); |
| AddInternedLegacyEventName(3, "sequence_3", &trace_packet_protos); |
| AddInternedEventCategory(3, "event_category_3", &trace_packet_protos); |
| trace_packet_protos.emplace_back(); |
| track_event = trace_packet_protos.back().mutable_track_event(); |
| track_event->add_category_iids(3); |
| track_event->set_timestamp_delta_us(4); |
| track_event->set_thread_time_delta_us(3); |
| *track_event->mutable_legacy_event() = |
| CreateLegacyEvent(/* name_iid = */ 3, kLegacyFlags, kLegacyPhase); |
| for (; idx < trace_packet_protos.size(); ++idx) { |
| trace_packet_protos[idx].set_trusted_packet_sequence_id(3); |
| } |
| |
| FinalizePackets(trace_packet_protos); |
| |
| ASSERT_EQ(3u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("sequence_1"), |
| &events)); |
| EXPECT_EQ(kReferenceTimeUs + 4, events[0]->timestamp); |
| EXPECT_EQ(kReferenceThreadTimeUs + 3, events[0]->thread_timestamp); |
| EXPECT_EQ(kReferenceTimeUs + 4 * 2, events[1]->timestamp); |
| EXPECT_EQ(kReferenceThreadTimeUs + 3 * 2, events[1]->thread_timestamp); |
| EXPECT_EQ(333, events[2]->timestamp); |
| EXPECT_EQ(666, events[2]->thread_timestamp); |
| |
| ASSERT_EQ(2u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("sequence_2"), |
| &events)); |
| EXPECT_EQ(kReferenceTimeUs + 4, events[0]->timestamp); |
| EXPECT_EQ(kReferenceThreadTimeUs + 3, events[0]->thread_timestamp); |
| // When we reset we resent as if 2 packets had occurred in the middle. |
| EXPECT_EQ(kReferenceTimeUs + 4 * 4, events[1]->timestamp); |
| EXPECT_EQ(kReferenceThreadTimeUs + 3 * 4, events[1]->thread_timestamp); |
| |
| ASSERT_EQ(1u, trace_analyzer()->FindEvents( |
| Query(Query::EVENT_NAME) == Query::String("sequence_3"), |
| &events)); |
| EXPECT_EQ(kReferenceTimeUs + 4, events[0]->timestamp); |
| EXPECT_EQ(kReferenceThreadTimeUs + 3, events[0]->thread_timestamp); |
| |
| // We only verify that the TraceStats packet was not dropped. |
| EXPECT_THAT(unparsed_trace_data_, |
| testing::HasSubstr("\"perfetto_trace_stats\"")); |
| } |
| } // namespace |
| } // namespace tracing |
