processor: Export LegacyEvent raw events as JSON
Adds support for exporting raw events with "track_event.legacy_event"
name to the json exporter. We use these raw events for pass-through of
legacy event types not natively supported in the trace processor
tables.
Bug: 130786269
Change-Id: I5c6018c8245703b4804d3b1e6f09fc6897e21212
diff --git a/src/trace_processor/export_json.cc b/src/trace_processor/export_json.cc
index ba505c3..2e7c279 100644
--- a/src/trace_processor/export_json.cc
+++ b/src/trace_processor/export_json.cc
@@ -19,6 +19,7 @@
#include <json/value.h>
#include <json/writer.h>
#include <stdio.h>
+#include <cstring>
#include "perfetto/ext/base/string_splitter.h"
#include "src/trace_processor/export_json.h"
@@ -120,8 +121,7 @@
class ArgsBuilder {
public:
- explicit ArgsBuilder(const TraceStorage* storage)
- : string_pool_(&storage->string_pool()) {
+ explicit ArgsBuilder(const TraceStorage* storage) : storage_(storage) {
const TraceStorage::Args& args = storage->args();
Json::Value empty_value(Json::objectValue);
if (args.args_count() == 0) {
@@ -131,7 +131,7 @@
args_sets_.resize(args.set_ids().back() + 1, empty_value);
for (size_t i = 0; i < args.args_count(); ++i) {
ArgSetId set_id = args.set_ids()[i];
- const char* key = string_pool_->Get(args.keys()[i]).c_str();
+ const char* key = storage_->GetString(args.keys()[i]).c_str();
Variadic value = args.arg_values()[i];
AppendArg(set_id, key, VariadicToJson(value));
}
@@ -150,7 +150,7 @@
case Variadic::kUint:
return Json::UInt64(variadic.uint_value);
case Variadic::kString:
- return string_pool_->Get(variadic.string_value).c_str();
+ return storage_->GetString(variadic.string_value).c_str();
case Variadic::kReal:
return variadic.real_value;
case Variadic::kPointer:
@@ -160,7 +160,8 @@
case Variadic::kJson:
Json::Reader reader;
Json::Value result;
- reader.parse(string_pool_->Get(variadic.string_value).c_str(), result);
+ reader.parse(storage_->GetString(variadic.string_value).c_str(),
+ result);
return result;
}
PERFETTO_FATAL("Not reached"); // For gcc.
@@ -218,17 +219,16 @@
}
}
- const StringPool* string_pool_;
+ const TraceStorage* storage_;
std::vector<Json::Value> args_sets_;
};
ResultCode ExportThreadNames(const TraceStorage* storage,
TraceFormatWriter* writer) {
- const StringPool& string_pool = storage->string_pool();
for (UniqueTid i = 1; i < storage->thread_count(); ++i) {
auto thread = storage->GetThread(i);
if (thread.name_id > 0) {
- const char* thread_name = string_pool.Get(thread.name_id).c_str();
+ const char* thread_name = storage->GetString(thread.name_id).c_str();
uint32_t pid = thread.upid ? storage->GetProcess(*thread.upid).pid : 0;
writer->WriteMetadataEvent("thread_name", thread_name, thread.tid, pid);
}
@@ -238,11 +238,10 @@
ResultCode ExportProcessNames(const TraceStorage* storage,
TraceFormatWriter* writer) {
- const StringPool& string_pool = storage->string_pool();
for (UniquePid i = 1; i < storage->process_count(); ++i) {
auto process = storage->GetProcess(i);
if (process.name_id > 0) {
- const char* process_name = string_pool.Get(process.name_id).c_str();
+ const char* process_name = storage->GetString(process.name_id).c_str();
writer->WriteMetadataEvent("process_name", process_name, 0, process.pid);
}
}
@@ -250,17 +249,16 @@
}
ResultCode ExportSlices(const TraceStorage* storage,
+ const ArgsBuilder& args_builder,
TraceFormatWriter* writer) {
- const StringPool& string_pool = storage->string_pool();
- ArgsBuilder args_builder(storage);
const auto& slices = storage->nestable_slices();
for (uint32_t i = 0; i < slices.slice_count(); ++i) {
Json::Value event;
event["ts"] = Json::Int64(slices.start_ns()[i] / 1000);
- event["cat"] = string_pool.Get(slices.categories()[i]).c_str();
- event["name"] = string_pool.Get(slices.names()[i]).c_str();
+ event["cat"] = storage->GetString(slices.categories()[i]).c_str();
+ event["name"] = storage->GetString(slices.names()[i]).c_str();
event["pid"] = 0;
- Json::Value args = args_builder.GetArgs(slices.arg_set_ids()[i]);
+ const Json::Value& args = args_builder.GetArgs(slices.arg_set_ids()[i]);
if (!args.empty()) {
event["args"] = args;
}
@@ -416,9 +414,138 @@
return kResultOk;
}
+ResultCode ExportRawEvents(const TraceStorage* storage,
+ const ArgsBuilder& args_builder,
+ TraceFormatWriter* writer) {
+ base::Optional<StringId> raw_legacy_event_key_id =
+ storage->string_pool().GetId("track_event.legacy_event");
+ if (!raw_legacy_event_key_id)
+ return kResultOk;
+
+ const char kLegacyEventArgsKey[] = "legacy_event";
+ const char kLegacyEventCategoryKey[] = "category";
+ const char kLegacyEventNameKey[] = "name";
+ const char kLegacyEventPhaseKey[] = "phase";
+ const char kLegacyEventDurationNsKey[] = "duration_ns";
+ const char kLegacyEventThreadTimestampNsKey[] = "thread_timestamp_ns";
+ const char kLegacyEventThreadDurationNsKey[] = "thread_duration_ns";
+ const char kLegacyEventThreadInstructionCountKey[] =
+ "thread_instruction_count";
+ const char kLegacyEventThreadInstructionDeltaKey[] =
+ "thread_instruction_delta";
+ const char kLegacyEventUseAsyncTtsKey[] = "use_async_tts";
+ const char kLegacyEventGlobalIdKey[] = "global_id";
+ const char kLegacyEventLocalIdKey[] = "local_id";
+ const char kLegacyEventIdScopeKey[] = "id_scope";
+ const char kLegacyEventBindIdKey[] = "bind_id";
+ const char kLegacyEventBindToEnclosingKey[] = "bind_to_enclosing";
+ const char kLegacyEventFlowDirectionKey[] = "flow_direction";
+ const char kFlowDirectionValueIn[] = "in";
+ const char kFlowDirectionValueOut[] = "out";
+ const char kFlowDirectionValueInout[] = "inout";
+
+ const auto& events = storage->raw_events();
+ for (uint32_t i = 0; i < events.raw_event_count(); ++i) {
+ if (events.name_ids()[i] != *raw_legacy_event_key_id)
+ continue;
+
+ Json::Value event;
+ event["ts"] = Json::Int64(events.timestamps()[i] / 1000);
+
+ UniqueTid utid = static_cast<UniqueTid>(events.utids()[i]);
+ auto thread = storage->GetThread(utid);
+ event["tid"] = thread.tid;
+ if (thread.upid) {
+ event["pid"] = storage->GetProcess(*thread.upid).pid;
+ }
+
+ // Raw legacy events store all other params in the arg set. Make a copy of
+ // the converted args here and remove these params.
+ Json::Value args = args_builder.GetArgs(events.arg_set_ids()[i]);
+ Json::Value legacy_args = args.removeMember(kLegacyEventArgsKey);
+
+ PERFETTO_DCHECK(legacy_args.isMember(kLegacyEventCategoryKey));
+ event["cat"] = legacy_args[kLegacyEventCategoryKey];
+
+ PERFETTO_DCHECK(legacy_args.isMember(kLegacyEventNameKey));
+ event["name"] = legacy_args[kLegacyEventNameKey];
+
+ PERFETTO_DCHECK(legacy_args.isMember(kLegacyEventPhaseKey));
+ event["ph"] = legacy_args[kLegacyEventPhaseKey];
+
+ if (legacy_args.isMember(kLegacyEventDurationNsKey)) {
+ event["dur"] = legacy_args[kLegacyEventDurationNsKey].asInt64() / 1000;
+ }
+
+ if (legacy_args.isMember(kLegacyEventThreadTimestampNsKey)) {
+ event["tts"] =
+ legacy_args[kLegacyEventThreadTimestampNsKey].asInt64() / 1000;
+ }
+
+ if (legacy_args.isMember(kLegacyEventThreadDurationNsKey)) {
+ event["tdur"] =
+ legacy_args[kLegacyEventThreadDurationNsKey].asInt64() / 1000;
+ }
+
+ if (legacy_args.isMember(kLegacyEventThreadInstructionCountKey)) {
+ event["ticount"] = legacy_args[kLegacyEventThreadInstructionCountKey];
+ }
+
+ if (legacy_args.isMember(kLegacyEventThreadInstructionDeltaKey)) {
+ event["tidelta"] = legacy_args[kLegacyEventThreadInstructionDeltaKey];
+ }
+
+ if (legacy_args.isMember(kLegacyEventUseAsyncTtsKey)) {
+ event["use_async_tts"] = legacy_args[kLegacyEventUseAsyncTtsKey];
+ }
+
+ if (legacy_args.isMember(kLegacyEventGlobalIdKey)) {
+ event["id2"]["global"] =
+ PrintUint64(legacy_args[kLegacyEventGlobalIdKey].asUInt64());
+ }
+
+ if (legacy_args.isMember(kLegacyEventLocalIdKey)) {
+ event["id2"]["local"] =
+ PrintUint64(legacy_args[kLegacyEventLocalIdKey].asUInt64());
+ }
+
+ if (legacy_args.isMember(kLegacyEventIdScopeKey)) {
+ event["scope"] = legacy_args[kLegacyEventIdScopeKey];
+ }
+
+ if (legacy_args.isMember(kLegacyEventBindIdKey)) {
+ event["bind_id"] =
+ PrintUint64(legacy_args[kLegacyEventBindIdKey].asUInt64());
+ }
+
+ if (legacy_args.isMember(kLegacyEventBindToEnclosingKey)) {
+ event["bp"] = "e";
+ }
+
+ if (legacy_args.isMember(kLegacyEventFlowDirectionKey)) {
+ const char* val = legacy_args[kLegacyEventFlowDirectionKey].asCString();
+ if (strcmp(val, kFlowDirectionValueIn) == 0) {
+ event["flow_in"] = true;
+ } else if (strcmp(val, kFlowDirectionValueOut) == 0) {
+ event["flow_out"] = true;
+ } else {
+ PERFETTO_DCHECK(strcmp(val, kFlowDirectionValueInout) == 0);
+ event["flow_in"] = true;
+ event["flow_out"] = true;
+ }
+ }
+
+ if (!args.empty()) {
+ event["args"] = args;
+ }
+
+ writer->WriteCommonEvent(event);
+ }
+ return kResultOk;
+}
+
ResultCode ExportMetadata(const TraceStorage* storage,
TraceFormatWriter* writer) {
- const StringPool& string_pool = storage->string_pool();
const auto& trace_metadata = storage->metadata();
const auto& keys = trace_metadata.keys();
const auto& values = trace_metadata.values();
@@ -429,12 +556,12 @@
case metadata::benchmark_description:
writer->AppendTelemetryMetadataString(
"benchmarkDescriptions",
- string_pool.Get(values[pos].string_value).c_str());
+ storage->GetString(values[pos].string_value).c_str());
break;
case metadata::benchmark_name:
writer->AppendTelemetryMetadataString(
- "benchmarks", string_pool.Get(values[pos].string_value).c_str());
+ "benchmarks", storage->GetString(values[pos].string_value).c_str());
break;
case metadata::benchmark_start_time_us:
@@ -451,12 +578,12 @@
case metadata::benchmark_label:
writer->AppendTelemetryMetadataString(
- "labels", string_pool.Get(values[pos].string_value).c_str());
+ "labels", storage->GetString(values[pos].string_value).c_str());
break;
case metadata::benchmark_story_name:
writer->AppendTelemetryMetadataString(
- "stories", string_pool.Get(values[pos].string_value).c_str());
+ "stories", storage->GetString(values[pos].string_value).c_str());
break;
case metadata::benchmark_story_run_index:
@@ -471,7 +598,7 @@
case metadata::benchmark_story_tags: // repeated
writer->AppendTelemetryMetadataString(
- "storyTags", string_pool.Get(values[pos].string_value).c_str());
+ "storyTags", storage->GetString(values[pos].string_value).c_str());
break;
default:
@@ -486,6 +613,7 @@
ResultCode ExportJson(const TraceStorage* storage, FILE* output) {
TraceFormatWriter writer(output);
+ ArgsBuilder args_builder(storage);
ResultCode code = ExportThreadNames(storage, &writer);
if (code != kResultOk)
@@ -495,7 +623,11 @@
if (code != kResultOk)
return code;
- code = ExportSlices(storage, &writer);
+ code = ExportSlices(storage, args_builder, &writer);
+ if (code != kResultOk)
+ return code;
+
+ code = ExportRawEvents(storage, args_builder, &writer);
if (code != kResultOk)
return code;
diff --git a/src/trace_processor/export_json_unittest.cc b/src/trace_processor/export_json_unittest.cc
index fef2f3f..8e5a289 100644
--- a/src/trace_processor/export_json_unittest.cc
+++ b/src/trace_processor/export_json_unittest.cc
@@ -17,6 +17,8 @@
#include "src/trace_processor/export_json.h"
#include "perfetto/ext/base/temp_file.h"
+#include "src/trace_processor/args_tracker.h"
+#include "src/trace_processor/trace_processor_context.h"
#include <gmock/gmock.h>
#include <gtest/gtest.h>
@@ -761,6 +763,104 @@
EXPECT_EQ(event["args"][kArgName].asInt(), kArgValue);
}
+TEST(ExportJsonTest, RawEvent) {
+ const int64_t kTimestamp = 10000000;
+ const int64_t kDuration = 10000;
+ const int64_t kThreadTimestamp = 20000000;
+ const int64_t kThreadDuration = 20000;
+ const int64_t kThreadInstructionCount = 30000000;
+ const int64_t kThreadInstructionDelta = 30000;
+ const int64_t kProcessID = 100;
+ const int64_t kThreadID = 200;
+ const char* kCategory = "cat";
+ const char* kName = "name";
+ const char* kPhase = "?";
+ const uint64_t kGlobalId = 0xaaffaaffaaffaaff;
+ const char* kIdScope = "my_id";
+ const uint64_t kBindId = 0xaa00aa00aa00aa00;
+ const char* kFlowDirection = "inout";
+ const char* kArgName = "arg_name";
+ const int kArgValue = 123;
+
+ TraceProcessorContext context;
+ context.storage.reset(new TraceStorage());
+ TraceStorage* storage = context.storage.get();
+
+ UniquePid upid = storage->AddEmptyProcess(kProcessID);
+ UniqueTid utid = storage->AddEmptyThread(kThreadID);
+ storage->GetMutableThread(utid)->upid = upid;
+
+ RowId row_id = storage->mutable_raw_events()->AddRawEvent(
+ kTimestamp, storage->InternString("track_event.legacy_event"), /*cpu=*/0,
+ utid);
+
+ ArgsTracker args(&context);
+ auto add_arg = [&](const char* key, Variadic value) {
+ StringId key_id = storage->InternString(key);
+ args.AddArg(row_id, key_id, key_id, value);
+ };
+
+ StringId cat_id = storage->InternString(base::StringView(kCategory));
+ add_arg("legacy_event.category", Variadic::String(cat_id));
+ StringId name_id = storage->InternString(base::StringView(kName));
+ add_arg("legacy_event.name", Variadic::String(name_id));
+ StringId phase_id = storage->InternString(base::StringView(kPhase));
+ add_arg("legacy_event.phase", Variadic::String(phase_id));
+
+ add_arg("legacy_event.duration_ns", Variadic::Integer(kDuration));
+ add_arg("legacy_event.thread_timestamp_ns",
+ Variadic::Integer(kThreadTimestamp));
+ add_arg("legacy_event.thread_duration_ns",
+ Variadic::Integer(kThreadDuration));
+ add_arg("legacy_event.thread_instruction_count",
+ Variadic::Integer(kThreadInstructionCount));
+ add_arg("legacy_event.thread_instruction_delta",
+ Variadic::Integer(kThreadInstructionDelta));
+ add_arg("legacy_event.use_async_tts", Variadic::Boolean(true));
+ add_arg("legacy_event.global_id", Variadic::UnsignedInteger(kGlobalId));
+ StringId scope_id = storage->InternString(base::StringView(kIdScope));
+ add_arg("legacy_event.id_scope", Variadic::String(scope_id));
+ add_arg("legacy_event.bind_id", Variadic::UnsignedInteger(kBindId));
+ add_arg("legacy_event.bind_to_enclosing", Variadic::Boolean(true));
+ StringId flow_direction_id = storage->InternString(kFlowDirection);
+ add_arg("legacy_event.flow_direction", Variadic::String(flow_direction_id));
+
+ add_arg(kArgName, Variadic::Integer(kArgValue));
+
+ args.Flush();
+
+ base::TempFile temp_file = base::TempFile::Create();
+ FILE* output = fopen(temp_file.path().c_str(), "w+");
+ int code = ExportJson(storage, output);
+
+ EXPECT_EQ(code, kResultOk);
+
+ Json::Reader reader;
+ Json::Value result;
+ EXPECT_TRUE(reader.parse(ReadFile(output), result));
+ EXPECT_EQ(result["traceEvents"].size(), 1u);
+
+ Json::Value event = result["traceEvents"][0];
+ EXPECT_EQ(event["ph"].asString(), kPhase);
+ EXPECT_EQ(event["ts"].asInt64(), kTimestamp / 1000);
+ EXPECT_EQ(event["dur"].asInt64(), kDuration / 1000);
+ EXPECT_EQ(event["tts"].asInt64(), kThreadTimestamp / 1000);
+ EXPECT_EQ(event["tdur"].asInt64(), kThreadDuration / 1000);
+ EXPECT_EQ(event["ticount"].asInt64(), kThreadInstructionCount);
+ EXPECT_EQ(event["tidelta"].asInt64(), kThreadInstructionDelta);
+ EXPECT_EQ(event["tid"].asUInt(), kThreadID);
+ EXPECT_EQ(event["cat"].asString(), kCategory);
+ EXPECT_EQ(event["name"].asString(), kName);
+ EXPECT_EQ(event["use_async_tts"].asInt(), 1);
+ EXPECT_EQ(event["id2"]["global"].asString(), "0xaaffaaffaaffaaff");
+ EXPECT_EQ(event["scope"].asString(), kIdScope);
+ EXPECT_EQ(event["bind_id"].asString(), "0xaa00aa00aa00aa00");
+ EXPECT_EQ(event["bp"].asString(), "e");
+ EXPECT_EQ(event["flow_in"].asBool(), true);
+ EXPECT_EQ(event["flow_out"].asBool(), true);
+ EXPECT_EQ(event["args"][kArgName].asInt(), kArgValue);
+}
+
} // namespace
} // namespace json
} // namespace trace_processor
diff --git a/src/trace_processor/proto_trace_parser.cc b/src/trace_processor/proto_trace_parser.cc
index cf00dee..2b7d217 100644
--- a/src/trace_processor/proto_trace_parser.cc
+++ b/src/trace_processor/proto_trace_parser.cc
@@ -1875,8 +1875,11 @@
legacy_event_category_key_id_, Variadic::String(category_id));
args.AddArg(row_id, legacy_event_name_key_id_, legacy_event_name_key_id_,
Variadic::String(name_id));
+
+ std::string phase_string(1, static_cast<char>(legacy_event.phase()));
+ StringId phase_id = context_->storage->InternString(phase_string.c_str());
args.AddArg(row_id, legacy_event_phase_key_id_, legacy_event_phase_key_id_,
- Variadic::Integer(legacy_event.phase()));
+ Variadic::String(phase_id));
if (legacy_event.has_duration_us()) {
args.AddArg(row_id, legacy_event_duration_ns_key_id_,
@@ -1971,6 +1974,9 @@
legacy_event_flow_direction_key_id_, Variadic::String(value));
}
+ // No need to parse legacy_event.instant_event_scope() because we import
+ // instant events into the slice table.
+
args_callback(&args, row_id);
}
diff --git a/src/trace_processor/proto_trace_parser_unittest.cc b/src/trace_processor/proto_trace_parser_unittest.cc
index 7f83415..c67e98a 100644
--- a/src/trace_processor/proto_trace_parser_unittest.cc
+++ b/src/trace_processor/proto_trace_parser_unittest.cc
@@ -1613,8 +1613,6 @@
EXPECT_CALL(*process_, UpdateThread(16, 15)).WillOnce(Return(1));
- InSequence in_sequence; // Below slices should be sorted by timestamp.
-
EXPECT_CALL(*storage_, InternString(base::StringView("cat1")))
.WillOnce(Return(1));
EXPECT_CALL(*storage_, InternString(base::StringView("ev1")))
@@ -1622,9 +1620,10 @@
EXPECT_CALL(*storage_, InternString(base::StringView("scope1")))
.Times(2)
.WillRepeatedly(Return(3));
-
- EXPECT_CALL(*storage_, InternString(base::StringView("debug.an1")))
+ EXPECT_CALL(*storage_, InternString(base::StringView("?")))
.WillOnce(Return(4));
+ EXPECT_CALL(*storage_, InternString(base::StringView("debug.an1")))
+ .WillOnce(Return(5));
context_.sorter->ExtractEventsForced();
@@ -1647,7 +1646,7 @@
EXPECT_TRUE(HasArg(1u, storage_->InternString("legacy_event.name"),
Variadic::String(2u)));
EXPECT_TRUE(HasArg(1u, storage_->InternString("legacy_event.phase"),
- Variadic::Integer('?')));
+ Variadic::String(4u)));
EXPECT_TRUE(HasArg(1u, storage_->InternString("legacy_event.duration_ns"),
Variadic::Integer(23000)));
EXPECT_TRUE(HasArg(1u,
@@ -1669,7 +1668,7 @@
Variadic::Boolean(true)));
EXPECT_TRUE(HasArg(1u, storage_->InternString("legacy_event.flow_direction"),
Variadic::String(storage_->InternString("inout"))));
- EXPECT_TRUE(HasArg(1u, 4u, Variadic::UnsignedInteger(10u)));
+ EXPECT_TRUE(HasArg(1u, 5u, Variadic::UnsignedInteger(10u)));
}
TEST_F(ProtoTraceParserTest, LoadChromeBenchmarkMetadata) {
diff --git a/src/trace_processor/string_pool.h b/src/trace_processor/string_pool.h
index f5acdc7..5d1a295 100644
--- a/src/trace_processor/string_pool.h
+++ b/src/trace_processor/string_pool.h
@@ -17,6 +17,7 @@
#ifndef SRC_TRACE_PROCESSOR_STRING_POOL_H_
#define SRC_TRACE_PROCESSOR_STRING_POOL_H_
+#include "perfetto/ext/base/optional.h"
#include "perfetto/ext/base/paged_memory.h"
#include "src/trace_processor/null_term_string_view.h"
@@ -77,6 +78,19 @@
return InsertString(str, hash);
}
+ base::Optional<Id> GetId(base::StringView str) const {
+ if (str.data() == nullptr)
+ return 0u;
+
+ auto hash = str.Hash();
+ auto id_it = string_index_.find(hash);
+ if (id_it != string_index_.end()) {
+ PERFETTO_DCHECK(Get(id_it->second) == str);
+ return id_it->second;
+ }
+ return base::nullopt;
+ }
+
NullTermStringView Get(Id id) const {
if (id == 0)
return NullTermStringView();
