Commit 71b956ec authored by Stephen Nusko's avatar Stephen Nusko Committed by Commit Bot

Implement the new track_event json exporter.

This will process perfetto::TracePacket sequences and output the data in
the old legacy json trace format used by chromium.

Change-Id: I8facc1b7371e66c0f444ed6010b379ac407b5c0f
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1514834
Commit-Queue: Stephen Nusko <nuskos@chromium.org>
Auto-Submit: Stephen Nusko <nuskos@chromium.org>
Reviewed-by: default avatarEric Seckler <eseckler@chromium.org>
Cr-Commit-Position: refs/heads/master@{#644758}
parent 9d7ff2e8
......@@ -25,6 +25,8 @@ source_set("lib") {
"perfetto/perfetto_tracing_coordinator.h",
"perfetto/producer_host.cc",
"perfetto/producer_host.h",
"perfetto/track_event_json_exporter.cc",
"perfetto/track_event_json_exporter.h",
"recorder.cc",
"recorder.h",
"tracing_service.cc",
......@@ -112,6 +114,7 @@ source_set("tests") {
"perfetto/perfetto_tracing_coordinator_unittest.cc",
"perfetto/test_utils.cc",
"perfetto/test_utils.h",
"perfetto/track_event_json_exporter_unittest.cc",
]
deps += [
......
......@@ -13,7 +13,6 @@
namespace tracing {
namespace {
using TraceEvent = ::base::trace_event::TraceEvent;
const char* GetStringFromStringTable(
const std::unordered_map<int, std::string>& string_table,
int index) {
......@@ -22,132 +21,7 @@ const char* GetStringFromStringTable(
return it->second.c_str();
}
void AppendProtoArrayAsJSON(std::string* out,
const perfetto::protos::ChromeTracedValue& array);
void AppendProtoDictAsJSON(std::string* out,
const perfetto::protos::ChromeTracedValue& dict);
void AppendProtoValueAsJSON(std::string* out,
const perfetto::protos::ChromeTracedValue& value) {
base::trace_event::TraceEvent::TraceValue json_value;
if (value.has_int_value()) {
json_value.as_int = value.int_value();
TraceEvent::AppendValueAsJSON(TRACE_VALUE_TYPE_INT, json_value, out);
} else if (value.has_double_value()) {
json_value.as_double = value.double_value();
TraceEvent::AppendValueAsJSON(TRACE_VALUE_TYPE_DOUBLE, json_value, out);
} else if (value.has_bool_value()) {
json_value.as_bool = value.bool_value();
TraceEvent::AppendValueAsJSON(TRACE_VALUE_TYPE_BOOL, json_value, out);
} else if (value.has_string_value()) {
json_value.as_string = value.string_value().c_str();
TraceEvent::AppendValueAsJSON(TRACE_VALUE_TYPE_STRING, json_value, out);
} else if (value.has_nested_type()) {
if (value.nested_type() == perfetto::protos::ChromeTracedValue::ARRAY) {
AppendProtoArrayAsJSON(out, value);
return;
} else if (value.nested_type() ==
perfetto::protos::ChromeTracedValue::DICT) {
AppendProtoDictAsJSON(out, value);
} else {
NOTREACHED();
}
} else {
NOTREACHED();
}
}
void AppendProtoArrayAsJSON(std::string* out,
const perfetto::protos::ChromeTracedValue& array) {
out->append("[");
bool is_first_entry = true;
for (auto& value : array.array_values()) {
if (!is_first_entry) {
out->append(",");
} else {
is_first_entry = false;
}
AppendProtoValueAsJSON(out, value);
}
out->append("]");
}
void AppendProtoDictAsJSON(std::string* out,
const perfetto::protos::ChromeTracedValue& dict) {
out->append("{");
DCHECK_EQ(dict.dict_keys_size(), dict.dict_values_size());
for (int i = 0; i < dict.dict_keys_size(); ++i) {
if (i != 0) {
out->append(",");
}
base::EscapeJSONString(dict.dict_keys(i), true, out);
out->append(":");
AppendProtoValueAsJSON(out, dict.dict_values(i));
}
out->append("}");
}
void OutputJSONFromArgumentValue(
const perfetto::protos::ChromeTraceEvent::Arg& arg,
std::string* out) {
TraceEvent::TraceValue value;
if (arg.has_bool_value()) {
value.as_bool = arg.bool_value();
TraceEvent::AppendValueAsJSON(TRACE_VALUE_TYPE_BOOL, value, out);
return;
}
if (arg.has_uint_value()) {
value.as_uint = arg.uint_value();
TraceEvent::AppendValueAsJSON(TRACE_VALUE_TYPE_UINT, value, out);
return;
}
if (arg.has_int_value()) {
value.as_int = arg.int_value();
TraceEvent::AppendValueAsJSON(TRACE_VALUE_TYPE_INT, value, out);
return;
}
if (arg.has_double_value()) {
value.as_double = arg.double_value();
TraceEvent::AppendValueAsJSON(TRACE_VALUE_TYPE_DOUBLE, value, out);
return;
}
if (arg.has_pointer_value()) {
value.as_pointer = reinterpret_cast<void*>(arg.pointer_value());
TraceEvent::AppendValueAsJSON(TRACE_VALUE_TYPE_POINTER, value, out);
return;
}
if (arg.has_string_value()) {
std::string str = arg.string_value();
value.as_string = &str[0];
TraceEvent::AppendValueAsJSON(TRACE_VALUE_TYPE_STRING, value, out);
return;
}
if (arg.has_json_value()) {
*out += arg.json_value();
return;
}
if (arg.has_traced_value()) {
AppendProtoDictAsJSON(out, arg.traced_value());
return;
}
NOTREACHED();
}
} // namespace
ChromeEventBundleJsonExporter::ChromeEventBundleJsonExporter(
......@@ -248,7 +122,7 @@ void ChromeEventBundleJsonExporter::ConstructTraceEventJSONWithBuilder(
auto* maybe_arg = args_builder->MaybeAddArg(arg_name);
if (maybe_arg) {
OutputJSONFromArgumentValue(arg, maybe_arg->mutable_out());
OutputJSONFromArgumentProto(arg, maybe_arg->mutable_out());
}
}
// Do not add anything to |trace_event_builder| unless you destroy
......
......@@ -19,10 +19,170 @@ namespace tracing {
namespace {
using TraceEvent = ::base::trace_event::TraceEvent;
constexpr size_t kTraceEventBufferSizeInBytes = 100 * 1024;
template <typename Nested>
void AppendProtoArrayAsJSON(std::string* out, const Nested& array);
template <typename Nested>
void AppendProtoDictAsJSON(std::string* out, const Nested& dict);
template <typename Nested>
void AppendProtoValueAsJSON(std::string* out, const Nested& value) {
base::trace_event::TraceEvent::TraceValue json_value;
if (value.has_int_value()) {
json_value.as_int = value.int_value();
TraceEvent::AppendValueAsJSON(TRACE_VALUE_TYPE_INT, json_value, out);
} else if (value.has_double_value()) {
json_value.as_double = value.double_value();
TraceEvent::AppendValueAsJSON(TRACE_VALUE_TYPE_DOUBLE, json_value, out);
} else if (value.has_bool_value()) {
json_value.as_bool = value.bool_value();
TraceEvent::AppendValueAsJSON(TRACE_VALUE_TYPE_BOOL, json_value, out);
} else if (value.has_string_value()) {
json_value.as_string = value.string_value().c_str();
TraceEvent::AppendValueAsJSON(TRACE_VALUE_TYPE_STRING, json_value, out);
} else if (value.has_nested_type()) {
if (value.nested_type() == Nested::ARRAY) {
AppendProtoArrayAsJSON(out, value);
return;
} else if (value.nested_type() == Nested::DICT) {
AppendProtoDictAsJSON(out, value);
} else {
NOTREACHED();
}
} else {
NOTREACHED();
}
}
template <typename Nested>
void AppendProtoArrayAsJSON(std::string* out, const Nested& array) {
out->append("[");
bool is_first_entry = true;
for (auto& value : array.array_values()) {
if (!is_first_entry) {
out->append(",");
} else {
is_first_entry = false;
}
AppendProtoValueAsJSON(out, value);
}
out->append("]");
}
template <typename Nested>
void AppendProtoDictAsJSON(std::string* out, const Nested& dict) {
out->append("{");
DCHECK_EQ(dict.dict_keys_size(), dict.dict_values_size());
for (int i = 0; i < dict.dict_keys_size(); ++i) {
if (i != 0) {
out->append(",");
}
base::EscapeJSONString(dict.dict_keys(i), true, out);
out->append(":");
AppendProtoValueAsJSON(out, dict.dict_values(i));
}
out->append("}");
}
template <typename Value, typename Nested>
void OutputJSONFromArgumentValue(const Value& arg,
const base::Optional<Nested>& nested,
const base::Optional<std::string>& json_value,
std::string* out) {
TraceEvent::TraceValue value;
if (arg.has_bool_value()) {
value.as_bool = arg.bool_value();
TraceEvent::AppendValueAsJSON(TRACE_VALUE_TYPE_BOOL, value, out);
return;
}
if (arg.has_uint_value()) {
value.as_uint = arg.uint_value();
TraceEvent::AppendValueAsJSON(TRACE_VALUE_TYPE_UINT, value, out);
return;
}
if (arg.has_int_value()) {
value.as_int = arg.int_value();
TraceEvent::AppendValueAsJSON(TRACE_VALUE_TYPE_INT, value, out);
return;
}
if (arg.has_double_value()) {
value.as_double = arg.double_value();
TraceEvent::AppendValueAsJSON(TRACE_VALUE_TYPE_DOUBLE, value, out);
return;
}
if (arg.has_pointer_value()) {
value.as_pointer = reinterpret_cast<void*>(arg.pointer_value());
TraceEvent::AppendValueAsJSON(TRACE_VALUE_TYPE_POINTER, value, out);
return;
}
if (arg.has_string_value()) {
std::string str = arg.string_value();
value.as_string = &str[0];
TraceEvent::AppendValueAsJSON(TRACE_VALUE_TYPE_STRING, value, out);
return;
}
if (json_value) {
*out += *json_value;
return;
}
if (nested) {
AppendProtoDictAsJSON(out, nested.value());
return;
}
NOTREACHED();
}
} // namespace
void OutputJSONFromArgumentProto(
const perfetto::protos::ChromeTraceEvent::Arg& arg,
std::string* out) {
base::Optional<perfetto::protos::ChromeTracedValue> traced_value;
if (arg.has_traced_value()) {
traced_value = arg.traced_value();
}
base::Optional<std::string> json_value;
if (arg.has_json_value()) {
json_value = arg.json_value();
}
OutputJSONFromArgumentValue<perfetto::protos::ChromeTraceEvent::Arg,
perfetto::protos::ChromeTracedValue>(
arg, traced_value, json_value, out);
}
void OutputJSONFromArgumentProto(const perfetto::protos::DebugAnnotation& arg,
std::string* out) {
base::Optional<perfetto::protos::DebugAnnotation::NestedValue> nested_value;
if (arg.has_nested_value()) {
nested_value = arg.nested_value();
}
base::Optional<std::string> json_value;
if (arg.has_legacy_json_value()) {
json_value = arg.legacy_json_value();
}
OutputJSONFromArgumentValue<perfetto::protos::DebugAnnotation,
perfetto::protos::DebugAnnotation::NestedValue>(
arg, nested_value, json_value, out);
}
JSONTraceExporter::JSONTraceExporter(
ArgumentFilterPredicate argument_filter_predicate,
OnTraceEventJSONCallback callback)
......@@ -106,12 +266,12 @@ void JSONTraceExporter::AddChromeLegacyJSONTrace(
DCHECK(!json_trace.data().empty());
switch (json_trace.type()) {
case perfetto::protos::ChromeLegacyJsonTrace::USER_TRACE:
*AddJSONTraceEvent() += json_trace.data();
return;
case perfetto::protos::ChromeLegacyJsonTrace::SYSTEM_TRACE:
if (!ShouldOutputTraceEvents()) {
return;
}
*AddJSONTraceEvent() += json_trace.data();
return;
case perfetto::protos::ChromeLegacyJsonTrace::SYSTEM_TRACE:
if (legacy_system_trace_events_.empty()) {
legacy_system_trace_events_ = "{";
} else {
......@@ -371,6 +531,9 @@ JSONTraceExporter::ScopedJSONTraceEventAppender::ScopedJSONTraceEventAppender(
JSONTraceExporter::ScopedJSONTraceEventAppender&& move) {
out_ = move.out_;
phase_ = move.phase_;
added_args_ = move.added_args_;
event_name_ = std::move(move.event_name_);
category_group_name_ = std::move(move.category_group_name_);
argument_filter_predicate_ = std::move(move.argument_filter_predicate_);
// We null out the string so that the destructor knows not to append the
// closing brace for the json.
......
......@@ -21,12 +21,20 @@ namespace perfetto {
namespace protos {
class ChromeLegacyJsonTrace;
class ChromeMetadata;
class ChromeTraceEvent_Arg;
class DebugAnnotation;
class TraceStats;
} // namespace protos
} // namespace perfetto
namespace tracing {
void OutputJSONFromArgumentProto(
const perfetto::protos::ChromeTraceEvent_Arg& arg,
std::string* out);
void OutputJSONFromArgumentProto(const perfetto::protos::DebugAnnotation& arg,
std::string* out);
// Converts proto-encoded trace data into the legacy JSON trace format.
// Conversion happens on-the-fly as new trace packets are received.
class JSONTraceExporter {
......
// 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 <cinttypes>
#include "base/strings/string_util.h"
#include "base/trace_event/common/trace_event_common.h"
#include "third_party/perfetto/protos/perfetto/trace/chrome/chrome_trace_packet.pb.h"
namespace tracing {
namespace {
using ::perfetto::protos::ChromeTracePacket;
using ::perfetto::protos::TrackEvent;
const std::string& GetInternedName(
uint32_t iid,
const std::unordered_map<uint32_t, std::string>& interned) {
auto iter = interned.find(iid);
DCHECK(iter != interned.end());
return iter->second;
}
} // namespace
TrackEventJSONExporter::TrackEventJSONExporter(
JSONTraceExporter::ArgumentFilterPredicate argument_filter_predicate,
JSONTraceExporter::OnTraceEventJSONCallback callback)
: JSONTraceExporter(std::move(argument_filter_predicate),
std::move(callback)),
current_state_(0) {}
TrackEventJSONExporter::~TrackEventJSONExporter() {}
void TrackEventJSONExporter::ProcessPackets(
const std::vector<perfetto::TracePacket>& packets) {
for (auto& encoded_packet : packets) {
// These are perfetto::TracePackets, but ChromeTracePacket is a mirror that
// reduces binary bloat and only has the fields we are interested in. So
// Decode the serialized proto as a ChromeTracePacket.
perfetto::protos::ChromeTracePacket packet;
bool decoded = encoded_packet.Decode(&packet);
DCHECK(decoded);
// If this is a different packet_sequence_id we have to reset all our state
// and wait for the first state_clear before emitting anything.
if (packet.trusted_packet_sequence_id() !=
current_state_.trusted_packet_sequence_id) {
StartNewState(packet.trusted_packet_sequence_id(),
packet.incremental_state_cleared());
} else if (packet.incremental_state_cleared()) {
ResetIncrementalState();
} else if (packet.previous_packet_dropped()) {
// If we've lost packets we can no longer trust any timestamp data and
// other state which might have been dropped. We will keep skipping events
// until we start a new sequence.
LOG_IF(ERROR, current_state_.incomplete)
<< "Previous packet was dropped. Skipping TraceEvents until reset or "
<< "new sequence.";
current_state_.incomplete = true;
}
if (current_state_.incomplete) {
continue;
}
// Now we process the data from the packet. First by getting the interned
// strings out and processed.
if (packet.has_interned_data()) {
HandleInternedData(packet);
}
// These are all oneof fields below so only one should be true.
if (packet.has_track_event()) {
HandleTrackEvent(packet);
} else if (packet.has_chrome_events()) {
HandleChromeEvents(packet);
} else if (packet.has_thread_descriptor()) {
HandleThreadDescriptor(packet);
} else if (packet.has_process_descriptor()) {
HandleProcessDescriptor(packet);
} else if (packet.has_trace_stats()) {
SetTraceStatsMetadata(packet.trace_stats());
} else {
}
// If none of the above matched this packet was emitted by the service or
// some other producer. And as a result has no equivalent in the old trace
// format so we ignore it.
}
}
TrackEventJSONExporter::ProducerWriterState::ProducerWriterState(
uint32_t sequence_id)
: ProducerWriterState(sequence_id, false, false, true) {}
TrackEventJSONExporter::ProducerWriterState::ProducerWriterState(
uint32_t sequence_id,
bool emitted_process,
bool emitted_thread,
bool incomplete)
: trusted_packet_sequence_id(sequence_id),
emitted_process_metadata(emitted_process),
emitted_thread_metadata(emitted_thread),
incomplete(incomplete) {}
TrackEventJSONExporter::ProducerWriterState::~ProducerWriterState() {}
void TrackEventJSONExporter::StartNewState(uint32_t trusted_packet_sequence_id,
bool state_cleared) {
current_state_ = ProducerWriterState{
trusted_packet_sequence_id, /* emitted_process = */ false,
/* emitted_thread = */ false, /* incomplete = */ !state_cleared};
}
void TrackEventJSONExporter::ResetIncrementalState() {
current_state_ =
ProducerWriterState{current_state_.trusted_packet_sequence_id,
current_state_.emitted_process_metadata,
current_state_.emitted_thread_metadata,
/* incomplete = */ false};
}
int64_t TrackEventJSONExporter::ComputeTimeUs(const TrackEvent& event) {
switch (event.timestamp_case()) {
case TrackEvent::kTimestampAbsoluteUs:
return event.timestamp_absolute_us();
case TrackEvent::kTimestampDeltaUs:
DCHECK(current_state_.time_us != -1);
current_state_.time_us += event.timestamp_delta_us();
return current_state_.time_us;
case TrackEvent::TIMESTAMP_NOT_SET:
DLOG(FATAL) << "Event has no timestamp this shouldn't be possible";
return -1;
}
}
base::Optional<int64_t> TrackEventJSONExporter::ComputeThreadTimeUs(
const TrackEvent& event) {
switch (event.thread_time_case()) {
case TrackEvent::kThreadTimeAbsoluteUs:
return event.thread_time_absolute_us();
case TrackEvent::kThreadTimeDeltaUs:
DCHECK(current_state_.thread_time_us != -1);
current_state_.thread_time_us += event.thread_time_delta_us();
return current_state_.thread_time_us;
case TrackEvent::THREAD_TIME_NOT_SET:
return base::nullopt;
}
}
void TrackEventJSONExporter::HandleInternedData(
const ChromeTracePacket& packet) {
DCHECK(packet.has_interned_data());
const auto& data = packet.interned_data();
// Even if the interned data was reset we should not change the values in the
// interned data.
for (const auto& event_cat : data.event_categories()) {
auto iter = current_state_.interned_event_categories_.insert(
std::make_pair(event_cat.iid(), event_cat.name()));
DCHECK(iter.second || iter.first->second == event_cat.name());
}
for (const auto& event_name : data.legacy_event_names()) {
auto iter = current_state_.interned_legacy_event_names_.insert(
std::make_pair(event_name.iid(), event_name.name()));
DCHECK(iter.second || iter.first->second == event_name.name());
}
for (const auto& debug_name : data.debug_annotation_names()) {
auto iter = current_state_.interned_debug_annotation_names_.insert(
std::make_pair(debug_name.iid(), debug_name.name()));
DCHECK(iter.second || iter.first->second == debug_name.name());
}
for (const auto& src_loc : data.source_locations()) {
auto iter = current_state_.interned_source_locations_.insert(std::make_pair(
src_loc.iid(),
std::make_pair(src_loc.file_name(), src_loc.function_name())));
DCHECK(iter.second ||
(iter.first->second.first == src_loc.file_name() &&
iter.first->second.second == src_loc.function_name()));
}
}
void TrackEventJSONExporter::HandleProcessDescriptor(
const ChromeTracePacket& packet) {
DCHECK(packet.has_process_descriptor());
const auto& process = packet.process_descriptor();
// Save the current state we need for future packets.
current_state_.pid = process.pid();
// If we aren't outputting traceEvents then we don't need to look at the
// metadata that might need to be emitted.
if (!ShouldOutputTraceEvents()) {
return;
}
// Prevent duplicates by only emitting the metadata once.
if (current_state_.emitted_process_metadata) {
return;
}
current_state_.emitted_process_metadata = true;
if (!process.cmdline().empty()) {
NOTIMPLEMENTED();
}
if (process.has_legacy_sort_index()) {
auto event_builder =
AddTraceEvent("process_sort_index", "__metadata", 'M', 0,
current_state_.pid, current_state_.pid);
auto args_builder = event_builder.BuildArgs();
auto* add_arg = args_builder->MaybeAddArg("sort_index");
if (add_arg) {
add_arg->AppendF("%" PRId32, process.legacy_sort_index());
}
}
const auto emit_process_name = [this](const char* name) {
auto event_builder = AddTraceEvent("process_name", "__metadata", 'M', 0,
current_state_.pid, current_state_.pid);
auto args_builder = event_builder.BuildArgs();
auto* add_arg = args_builder->MaybeAddArg("name");
if (add_arg) {
add_arg->AppendF("\"%s\"", name);
}
};
switch (process.chrome_process_type()) {
case perfetto::protos::ProcessDescriptor::PROCESS_UNSPECIFIED:
// This process does not have a name.
break;
case perfetto::protos::ProcessDescriptor::PROCESS_BROWSER:
emit_process_name("BROWSER");
break;
case perfetto::protos::ProcessDescriptor::PROCESS_RENDERER:
emit_process_name("RENDERER");
break;
case perfetto::protos::ProcessDescriptor::PROCESS_UTILITY:
emit_process_name("UTILITY");
break;
case perfetto::protos::ProcessDescriptor::PROCESS_ZYGOTE:
emit_process_name("ZYGOTE");
break;
case perfetto::protos::ProcessDescriptor::PROCESS_SANDBOX_HELPER:
emit_process_name("SANDBOX_HELPER");
break;
case perfetto::protos::ProcessDescriptor::PROCESS_GPU:
emit_process_name("GPU");
break;
case perfetto::protos::ProcessDescriptor::PROCESS_PPAPI_PLUGIN:
emit_process_name("PPAPI_PLUGIN");
break;
case perfetto::protos::ProcessDescriptor::PROCESS_PPAPI_BROKER:
emit_process_name("PPAPI_BROKER");
break;
}
}
void TrackEventJSONExporter::HandleThreadDescriptor(
const ChromeTracePacket& packet) {
DCHECK(packet.has_thread_descriptor());
const auto& thread = packet.thread_descriptor();
// Save the current state we need for future packets.
current_state_.pid = thread.pid();
current_state_.tid = thread.tid();
current_state_.time_us = thread.reference_timestamp_us();
current_state_.thread_time_us = thread.reference_thread_time_us();
// If we aren't outputting traceEvents then we don't need to look at the
// metadata that might need to be emitted.
if (!ShouldOutputTraceEvents()) {
return;
}
// Prevent duplicates by only emitting the metadata once.
if (current_state_.emitted_thread_metadata) {
return;
}
current_state_.emitted_thread_metadata = true;
if (thread.has_legacy_sort_index()) {
auto event_builder =
AddTraceEvent("thread_sort_index", "__metadata", 'M', 0,
current_state_.pid, current_state_.tid);
auto args_builder = event_builder.BuildArgs();
auto* add_arg = args_builder->MaybeAddArg("sort_index");
if (add_arg) {
add_arg->AppendF("%" PRId32, thread.legacy_sort_index());
}
}
const auto emit_thread_name = [this](const char* name) {
auto event_builder = AddTraceEvent("thread_name", "__metadata", 'M', 0,
current_state_.pid, current_state_.tid);
auto args_builder = event_builder.BuildArgs();
auto* add_arg = args_builder->MaybeAddArg("name");
if (add_arg) {
add_arg->AppendF("\"%s\"", name);
}
};
switch (thread.chrome_thread_type()) {
// TODO(nuskos): As we add more thread types we will add handling here to
// switch the enum to a string and call |emit_thread_name()|
case perfetto::protos::ThreadDescriptor::THREAD_UNSPECIFIED:
// No thread type enum so check to see if a explicit thread name was
// provided..
if (thread.has_thread_name()) {
emit_thread_name(thread.thread_name().c_str());
}
break;
}
}
void TrackEventJSONExporter::HandleChromeEvents(
const perfetto::protos::ChromeTracePacket& packet) {
DCHECK(packet.has_chrome_events());
const auto& chrome_events = packet.chrome_events();
DCHECK(chrome_events.trace_events().empty())
<< "Found trace_events inside a ChromeEventBundle. This shouldn't "
<< "happen when emitting TrackEvents.";
for (const auto& metadata : chrome_events.metadata()) {
AddChromeMetadata(metadata);
}
for (const auto& legacy_ftrace : chrome_events.legacy_ftrace_output()) {
AddLegacyFtrace(legacy_ftrace);
}
for (const auto& legacy_json_trace : chrome_events.legacy_json_trace()) {
AddChromeLegacyJSONTrace(legacy_json_trace);
}
}
void TrackEventJSONExporter::HandleTrackEvent(const ChromeTracePacket& packet) {
DCHECK(packet.has_track_event());
// If we aren't outputting traceEvents nothing in a TrackEvent currently will
// be needed so just return early.
if (!ShouldOutputTraceEvents()) {
return;
}
const auto& track = packet.track_event();
// Get the time data out of the TrackEvent.
int64_t timestamp_us = ComputeTimeUs(track);
DCHECK(timestamp_us != -1);
base::Optional<int64_t> thread_time_us = ComputeThreadTimeUs(track);
std::vector<base::StringPiece> all_categories;
all_categories.reserve(track.category_iids().size());
for (const auto& cat_iid : track.category_iids()) {
const std::string& name =
GetInternedName(cat_iid, current_state_.interned_event_categories_);
all_categories.push_back(name);
}
const std::string joined_categories = base::JoinString(all_categories, ",");
DCHECK(track.has_legacy_event()) << "required field legacy_event missing";
auto maybe_builder =
HandleLegacyEvent(track.legacy_event(), joined_categories, timestamp_us);
if (!maybe_builder) {
return;
}
auto& builder = *maybe_builder;
if (thread_time_us) {
builder.AddThreadTimestamp(*thread_time_us);
}
// Now we add args from both |task_execution| and |debug_annotations|. Recall
// that |args_builder| must run its deconstructer before any other fields in
// traceEvents are added. Therefore do not do anything below this comment but
// add args.
auto args_builder = builder.BuildArgs();
for (const auto& debug_annotation : track.debug_annotations()) {
HandleDebugAnnotation(debug_annotation, args_builder.get());
}
if (track.has_task_execution()) {
HandleTaskExecution(track.task_execution(), args_builder.get());
}
}
void TrackEventJSONExporter::HandleDebugAnnotation(
const perfetto::protos::DebugAnnotation& debug_annotation,
ArgumentBuilder* args_builder) {
const std::string& name =
GetInternedName(debug_annotation.name_iid(),
current_state_.interned_debug_annotation_names_);
auto* maybe_arg = args_builder->MaybeAddArg(name);
if (!maybe_arg) {
return;
}
OutputJSONFromArgumentProto(debug_annotation, maybe_arg->mutable_out());
}
void TrackEventJSONExporter::HandleTaskExecution(
const perfetto::protos::TaskExecution& task,
ArgumentBuilder* args_builder) {
auto iter =
current_state_.interned_source_locations_.find(task.posted_from_iid());
DCHECK(iter != current_state_.interned_source_locations_.end());
auto* maybe_arg = args_builder->MaybeAddArg("src_file");
if (maybe_arg) {
maybe_arg->AppendF("\"%s\"", iter->second.first.c_str());
}
maybe_arg = args_builder->MaybeAddArg("src_func");
if (maybe_arg) {
maybe_arg->AppendF("\"%s\"", iter->second.second.c_str());
}
}
base::Optional<JSONTraceExporter::ScopedJSONTraceEventAppender>
TrackEventJSONExporter::HandleLegacyEvent(const TrackEvent::LegacyEvent& event,
const std::string& categories,
int64_t timestamp_us) {
DCHECK(event.name_iid());
DCHECK(event.phase());
// Determine which pid and tid to use.
int32_t pid =
event.pid_override() == 0 ? current_state_.pid : event.pid_override();
int32_t tid =
event.tid_override() == 0 ? current_state_.tid : event.tid_override();
const std::string& name = GetInternedName(
event.name_iid(), current_state_.interned_legacy_event_names_);
// Build the actual json output, if we are missing the interned name we just
// use the interned ID.
auto builder = AddTraceEvent(name.c_str(), categories.c_str(), event.phase(),
timestamp_us, pid, tid);
if (event.bind_id() > 0) {
builder.AddBindId(event.bind_id());
}
if (event.duration_us() > 0) {
builder.AddDuration(event.duration_us());
}
if (event.thread_duration_us() > 0) {
builder.AddThreadDuration(event.thread_duration_us());
}
// For flags and ID we need to determine all possible flag bits and set them
// correctly.
uint32_t flags = 0;
base::Optional<uint32_t> id;
switch (event.id_case()) {
case TrackEvent::LegacyEvent::kUnscopedId:
flags |= TRACE_EVENT_FLAG_HAS_ID;
id = event.unscoped_id();
break;
case TrackEvent::LegacyEvent::kLocalId:
flags |= TRACE_EVENT_FLAG_HAS_LOCAL_ID;
id = event.local_id();
break;
case TrackEvent::LegacyEvent::kGlobalId:
flags |= TRACE_EVENT_FLAG_HAS_GLOBAL_ID;
id = event.global_id();
break;
case TrackEvent::LegacyEvent::ID_NOT_SET:
break;
}
if (event.use_async_tts()) {
flags |= TRACE_EVENT_FLAG_ASYNC_TTS;
}
if (event.bind_to_enclosing()) {
flags |= TRACE_EVENT_FLAG_BIND_TO_ENCLOSING;
}
switch (event.flow_direction()) {
case TrackEvent::LegacyEvent::FLOW_IN:
flags |= TRACE_EVENT_FLAG_FLOW_IN;
break;
case TrackEvent::LegacyEvent::FLOW_OUT:
flags |= TRACE_EVENT_FLAG_FLOW_OUT;
break;
case TrackEvent::LegacyEvent::FLOW_INOUT:
flags |= TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT;
break;
case TrackEvent::LegacyEvent::FLOW_UNSPECIFIED:
break;
}
switch (event.instant_event_scope()) {
case TrackEvent::LegacyEvent::SCOPE_GLOBAL:
flags |= TRACE_EVENT_SCOPE_GLOBAL;
break;
case TrackEvent::LegacyEvent::SCOPE_PROCESS:
flags |= TRACE_EVENT_SCOPE_PROCESS;
break;
case TrackEvent::LegacyEvent::SCOPE_THREAD:
flags |= TRACE_EVENT_SCOPE_THREAD;
break;
case TrackEvent::LegacyEvent::SCOPE_UNSPECIFIED:
break;
}
// If we have no flags there is nothing to do.
if (flags > 0) {
builder.AddFlags(flags, id, event.id_scope());
}
return builder;
}
} // namespace tracing
// 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.
#ifndef SERVICES_TRACING_PERFETTO_TRACK_EVENT_JSON_EXPORTER_H_
#define SERVICES_TRACING_PERFETTO_TRACK_EVENT_JSON_EXPORTER_H_
#include <string>
#include <unordered_map>
#include "services/tracing/perfetto/json_trace_exporter.h"
namespace perfetto {
namespace protos {
class ChromeTracePacket;
class DebugAnnotation;
class TaskExecution;
class TrackEvent;
class TrackEvent_LegacyEvent;
} // namespace protos
} // namespace perfetto
namespace tracing {
class TrackEventJSONExporter : public JSONTraceExporter {
public:
TrackEventJSONExporter(ArgumentFilterPredicate argument_filter_predicate,
OnTraceEventJSONCallback callback);
~TrackEventJSONExporter() override;
protected:
void ProcessPackets(
const std::vector<perfetto::TracePacket>& packets) override;
private:
struct ProducerWriterState {
ProducerWriterState(uint32_t sequence_id);
ProducerWriterState(uint32_t sequence_id,
bool emitted_process,
bool emitted_thread,
bool incomplete);
~ProducerWriterState();
// 0 is an invalid sequence_id.
uint32_t trusted_packet_sequence_id = 0;
int32_t pid = -1;
int32_t tid = -1;
int64_t time_us = -1;
int64_t thread_time_us = -1;
// We only want to add metadata events about the process or threads once.
// This is to prevent duplicate events in the json since the packets
// containing this data are periodically emitted and so would occur
// frequently if not suppressed.
bool emitted_process_metadata = false;
bool emitted_thread_metadata = false;
// Until we see a TracePacket that will initialize our state we will skip
// all data besides stateful information. Once we've been reset on the same
// sequence or started a new sequence this will become false and we will
// start emitting events again.
bool incomplete = true;
std::unordered_map<uint32_t, std::string> interned_event_categories_;
std::unordered_map<uint32_t, std::pair<std::string, std::string>>
interned_source_locations_;
std::unordered_map<uint32_t, std::string> interned_legacy_event_names_;
std::unordered_map<uint32_t, std::string> interned_debug_annotation_names_;
};
// Packet sequences are given in order so when we encounter a new one we need
// to reset all the interned state and per sequence info.
void StartNewState(uint32_t trusted_packet_sequence_id, bool state_cleared);
// When we encounter a request to reset our incremental state this will clear
// out the |current_state_| leaving only the required persistent data (like
// |emitted_process_metadata|) the same.
void ResetIncrementalState();
// Given our |current_state_| and an |event| we determine the timestamp (or
// thread timestamp) we should output to the json.
int64_t ComputeTimeUs(const perfetto::protos::TrackEvent& event);
base::Optional<int64_t> ComputeThreadTimeUs(
const perfetto::protos::TrackEvent& event);
// Gather all the interned strings of different types.
void HandleInternedData(const perfetto::protos::ChromeTracePacket& packet);
// New typed messages that are part of the oneof in TracePacket.
void HandleProcessDescriptor(
const perfetto::protos::ChromeTracePacket& packet);
void HandleThreadDescriptor(
const perfetto::protos::ChromeTracePacket& packet);
void HandleChromeEvents(const perfetto::protos::ChromeTracePacket& packet);
void HandleTrackEvent(const perfetto::protos::ChromeTracePacket& packet);
// New typed args handlers go here. Used inside HandleTrackEvent to process
// args.
void HandleDebugAnnotation(
const perfetto::protos::DebugAnnotation& debug_annotation,
ArgumentBuilder* args_builder);
void HandleTaskExecution(const perfetto::protos::TaskExecution& task,
ArgumentBuilder* args_builder);
// Used to handle the LegacyEvent message found inside the TrackEvent proto.
base::Optional<ScopedJSONTraceEventAppender> HandleLegacyEvent(
const perfetto::protos::TrackEvent_LegacyEvent& event,
const std::string& categories,
int64_t timestamp_us);
// Tracks all the interned state in the current sequence.
ProducerWriterState current_state_;
};
} // namespace tracing
#endif // SERVICES_TRACING_PERFETTO_TRACK_EVENT_JSON_EXPORTER_H_
// 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(const std::string& json,
base::DictionaryValue* metadata,
bool has_more) {
CHECK(!has_more);
unparsed_trace_data_ = json;
parsed_trace_data_ =
base::DictionaryValue::From(base::JSONReader::ReadDeprecated(json));
ASSERT_TRUE(parsed_trace_data_) << "Couldn't parse json: \n" << json;
// 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(),
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"));
}
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();
trace_packet_protos.back().set_incremental_state_cleared(true);
{
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);
trace_packet_protos.back().set_incremental_state_cleared(true);
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();
trace_packet_protos.back().set_incremental_state_cleared(true);
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();
trace_packet_protos.back().set_incremental_state_cleared(true);
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();
trace_packet_protos.back().set_incremental_state_cleared(true);
// 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);
// 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);
}
} // namespace
} // namespace tracing
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment