processor: Fix ordering of async begin/end events in JSON export
Catapult expects begin/end events to be ordered correctly, i.e.
children's begin/end events before the parent's end.
This adds buffering logic to ExportJson to accomplish this.
Bug: 130786269
Change-Id: If149512004c1e6ec514bd3493770abfc428dd434
diff --git a/src/trace_processor/export_json.cc b/src/trace_processor/export_json.cc
index 4e08f1e..de9d02c 100644
--- a/src/trace_processor/export_json.cc
+++ b/src/trace_processor/export_json.cc
@@ -26,8 +26,10 @@
#include <json/value.h>
#include <json/writer.h>
#include <stdio.h>
+
#include <cstring>
-#include <vector>
+#include <deque>
+#include <limits>
#include "perfetto/ext/base/string_splitter.h"
#include "src/trace_processor/metadata.h"
@@ -107,33 +109,26 @@
if (label_filter_ && !label_filter_("traceEvents"))
return;
- if (!first_event_)
- output_->AppendString(",\n");
+ // Pop end events with smaller or equal timestamps.
+ PopEndEvents(event["ts"].asInt64());
- Json::FastWriter writer;
- writer.omitEndingLineFeed();
+ DoWriteEvent(event);
+ }
- ArgumentNameFilterPredicate argument_name_filter;
- bool strip_args =
- argument_filter_ &&
- !argument_filter_(event["cat"].asCString(), event["name"].asCString(),
- &argument_name_filter);
- if ((strip_args || argument_name_filter) && event.isMember("args")) {
- Json::Value event_copy = event;
- if (strip_args) {
- event_copy["args"] = kStrippedArgument;
- } else {
- auto& args = event_copy["args"];
- for (const auto& member : event["args"].getMemberNames()) {
- if (!argument_name_filter(member.c_str()))
- args[member] = kStrippedArgument;
- }
- }
- output_->AppendString(writer.write(event_copy));
- } else {
- output_->AppendString(writer.write(event));
- }
- first_event_ = false;
+ void PushEndEvent(const Json::Value& event) {
+ if (label_filter_ && !label_filter_("traceEvents"))
+ return;
+
+ // Pop any end events that end before the new one.
+ PopEndEvents(event["ts"].asInt64() - 1);
+
+ // Catapult doesn't handle out-of-order begin/end events well, especially
+ // when their timestamps are the same, but their order is incorrect. Since
+ // our events are sorted by begin timestamp, we only have to reorder end
+ // events. We do this by buffering them into a stack, so that both begin &
+ // end events of potential child events have been emitted before we emit the
+ // end of a parent event.
+ end_events_.push_back(event);
}
void WriteMetadataEvent(const char* metadata_type,
@@ -226,6 +221,8 @@
}
void WriteFooter() {
+ PopEndEvents(std::numeric_limits<int64_t>::max());
+
// Filter metadata entries.
if (metadata_filter_) {
for (const auto& member : metadata_.getMemberNames()) {
@@ -266,6 +263,46 @@
output_->AppendString("}");
}
+ void DoWriteEvent(const Json::Value& event) {
+ if (!first_event_)
+ output_->AppendString(",\n");
+
+ Json::FastWriter writer;
+ writer.omitEndingLineFeed();
+
+ ArgumentNameFilterPredicate argument_name_filter;
+ bool strip_args =
+ argument_filter_ &&
+ !argument_filter_(event["cat"].asCString(), event["name"].asCString(),
+ &argument_name_filter);
+ if ((strip_args || argument_name_filter) && event.isMember("args")) {
+ Json::Value event_copy = event;
+ if (strip_args) {
+ event_copy["args"] = kStrippedArgument;
+ } else {
+ auto& args = event_copy["args"];
+ for (const auto& member : event["args"].getMemberNames()) {
+ if (!argument_name_filter(member.c_str()))
+ args[member] = kStrippedArgument;
+ }
+ }
+ output_->AppendString(writer.write(event_copy));
+ } else {
+ output_->AppendString(writer.write(event));
+ }
+ first_event_ = false;
+ }
+
+ void PopEndEvents(int64_t max_ts) {
+ while (!end_events_.empty()) {
+ int64_t ts = end_events_.back()["ts"].asInt64();
+ if (ts > max_ts)
+ break;
+ DoWriteEvent(end_events_.back());
+ end_events_.pop_back();
+ }
+ }
+
OutputWriter* output_;
ArgumentFilterPredicate argument_filter_;
MetadataFilterPredicate metadata_filter_;
@@ -275,6 +312,7 @@
Json::Value metadata_;
std::string system_trace_data_;
std::string user_trace_data_;
+ std::deque<Json::Value> end_events_;
};
std::string PrintUint64(uint64_t x) {
@@ -664,7 +702,7 @@
(thread_instruction_count + thread_instruction_delta));
}
event["args"].clear();
- writer->WriteCommonEvent(event);
+ writer->PushEndEvent(event);
}
}
} else {
diff --git a/src/trace_processor/export_json_unittest.cc b/src/trace_processor/export_json_unittest.cc
index c3bfabc..a14f789 100644
--- a/src/trace_processor/export_json_unittest.cc
+++ b/src/trace_processor/export_json_unittest.cc
@@ -780,18 +780,20 @@
EXPECT_EQ(event["name"].asString(), kName);
}
-TEST_F(ExportJsonTest, AsyncEvent) {
+TEST_F(ExportJsonTest, AsyncEvents) {
const int64_t kTimestamp = 10000000;
const int64_t kDuration = 100000;
const int64_t kProcessID = 100;
const char* kCategory = "cat";
const char* kName = "name";
+ const char* kName2 = "name2";
const char* kArgName = "arg_name";
const int kArgValue = 123;
UniquePid upid = context_.storage->AddEmptyProcess(kProcessID);
StringId cat_id = context_.storage->InternString(base::StringView(kCategory));
StringId name_id = context_.storage->InternString(base::StringView(kName));
+ StringId name2_id = context_.storage->InternString(base::StringView(kName2));
constexpr int64_t kSourceId = 235;
TrackId track = context_.track_tracker->InternLegacyChromeAsyncTrack(
@@ -810,6 +812,10 @@
ArgSetId args = context_.storage->mutable_args()->AddArgSet({arg}, 0, 1);
context_.storage->mutable_slice_table()->mutable_arg_set_id()->Set(0, args);
+ // Child event with same timestamps as first one.
+ context_.storage->mutable_slice_table()->Insert(
+ {kTimestamp, kDuration, track.value, cat_id, name2_id, 0, 0, 0});
+
base::TempFile temp_file = base::TempFile::Create();
FILE* output = fopen(temp_file.path().c_str(), "w+");
util::Status status = ExportJson(context_.storage.get(), output);
@@ -817,30 +823,54 @@
EXPECT_TRUE(status.ok());
Json::Value result = ToJsonValue(ReadFile(output));
- EXPECT_EQ(result["traceEvents"].size(), 2u);
+ EXPECT_EQ(result["traceEvents"].size(), 4u);
- Json::Value begin_event = result["traceEvents"][0];
- EXPECT_EQ(begin_event["ph"].asString(), "b");
- EXPECT_EQ(begin_event["ts"].asInt64(), kTimestamp / 1000);
- EXPECT_EQ(begin_event["pid"].asInt64(), kProcessID);
- EXPECT_EQ(begin_event["id2"]["local"].asString(), "0xeb");
- EXPECT_EQ(begin_event["cat"].asString(), kCategory);
- EXPECT_EQ(begin_event["name"].asString(), kName);
- EXPECT_EQ(begin_event["args"][kArgName].asInt(), kArgValue);
- EXPECT_FALSE(begin_event.isMember("tts"));
- EXPECT_FALSE(begin_event.isMember("use_async_tts"));
+ Json::Value begin_event1 = result["traceEvents"][0];
+ EXPECT_EQ(begin_event1["ph"].asString(), "b");
+ EXPECT_EQ(begin_event1["ts"].asInt64(), kTimestamp / 1000);
+ EXPECT_EQ(begin_event1["pid"].asInt64(), kProcessID);
+ EXPECT_EQ(begin_event1["id2"]["local"].asString(), "0xeb");
+ EXPECT_EQ(begin_event1["cat"].asString(), kCategory);
+ EXPECT_EQ(begin_event1["name"].asString(), kName);
+ EXPECT_EQ(begin_event1["args"][kArgName].asInt(), kArgValue);
+ EXPECT_FALSE(begin_event1.isMember("tts"));
+ EXPECT_FALSE(begin_event1.isMember("use_async_tts"));
- Json::Value end_event = result["traceEvents"][1];
- EXPECT_EQ(end_event["ph"].asString(), "e");
- EXPECT_EQ(end_event["ts"].asInt64(), (kTimestamp + kDuration) / 1000);
- EXPECT_EQ(end_event["pid"].asInt64(), kProcessID);
- EXPECT_EQ(end_event["id2"]["local"].asString(), "0xeb");
- EXPECT_EQ(end_event["cat"].asString(), kCategory);
- EXPECT_EQ(end_event["name"].asString(), kName);
- EXPECT_TRUE(end_event["args"].isObject());
- EXPECT_EQ(end_event["args"].size(), 0u);
- EXPECT_FALSE(end_event.isMember("tts"));
- EXPECT_FALSE(end_event.isMember("use_async_tts"));
+ Json::Value begin_event2 = result["traceEvents"][1];
+ EXPECT_EQ(begin_event2["ph"].asString(), "b");
+ EXPECT_EQ(begin_event2["ts"].asInt64(), kTimestamp / 1000);
+ EXPECT_EQ(begin_event2["pid"].asInt64(), kProcessID);
+ EXPECT_EQ(begin_event2["id2"]["local"].asString(), "0xeb");
+ EXPECT_EQ(begin_event2["cat"].asString(), kCategory);
+ EXPECT_EQ(begin_event2["name"].asString(), kName2);
+ EXPECT_TRUE(begin_event2["args"].isObject());
+ EXPECT_EQ(begin_event2["args"].size(), 0u);
+ EXPECT_FALSE(begin_event2.isMember("tts"));
+ EXPECT_FALSE(begin_event2.isMember("use_async_tts"));
+
+ Json::Value end_event2 = result["traceEvents"][3];
+ EXPECT_EQ(end_event2["ph"].asString(), "e");
+ EXPECT_EQ(end_event2["ts"].asInt64(), (kTimestamp + kDuration) / 1000);
+ EXPECT_EQ(end_event2["pid"].asInt64(), kProcessID);
+ EXPECT_EQ(end_event2["id2"]["local"].asString(), "0xeb");
+ EXPECT_EQ(end_event2["cat"].asString(), kCategory);
+ EXPECT_EQ(end_event2["name"].asString(), kName);
+ EXPECT_TRUE(end_event2["args"].isObject());
+ EXPECT_EQ(end_event2["args"].size(), 0u);
+ EXPECT_FALSE(end_event2.isMember("tts"));
+ EXPECT_FALSE(end_event2.isMember("use_async_tts"));
+
+ Json::Value end_event1 = result["traceEvents"][3];
+ EXPECT_EQ(end_event1["ph"].asString(), "e");
+ EXPECT_EQ(end_event1["ts"].asInt64(), (kTimestamp + kDuration) / 1000);
+ EXPECT_EQ(end_event1["pid"].asInt64(), kProcessID);
+ EXPECT_EQ(end_event1["id2"]["local"].asString(), "0xeb");
+ EXPECT_EQ(end_event1["cat"].asString(), kCategory);
+ EXPECT_EQ(end_event1["name"].asString(), kName);
+ EXPECT_TRUE(end_event1["args"].isObject());
+ EXPECT_EQ(end_event1["args"].size(), 0u);
+ EXPECT_FALSE(end_event1.isMember("tts"));
+ EXPECT_FALSE(end_event1.isMember("use_async_tts"));
}
TEST_F(ExportJsonTest, AsyncEventWithThreadTimestamp) {
