processor: Parse TrackEvent's thread instruction count fields
Plumbs the thread instruction count / delta fields from tokenizer via
sorter through to parser.
Bug: 130786981
Change-Id: Ia49fada7548a5e8575c4461939812b79b4e61569
diff --git a/src/trace_processor/proto_incremental_state.h b/src/trace_processor/proto_incremental_state.h
index e902641..38a6645 100644
--- a/src/trace_processor/proto_incremental_state.h
+++ b/src/trace_processor/proto_incremental_state.h
@@ -118,6 +118,12 @@
return track_event_thread_timestamp_ns_;
}
+ int64_t IncrementAndGetTrackEventThreadInstructionCount(int64_t delta) {
+ PERFETTO_DCHECK(IsTrackEventStateValid());
+ track_event_thread_instruction_count_ += delta;
+ return track_event_thread_instruction_count_;
+ }
+
void OnPacketLoss() {
packet_loss_ = true;
thread_descriptor_seen_ = false;
@@ -128,12 +134,14 @@
void SetThreadDescriptor(int32_t pid,
int32_t tid,
int64_t timestamp_ns,
- int64_t thread_timestamp_ns) {
+ int64_t thread_timestamp_ns,
+ int64_t thread_instruction_count) {
thread_descriptor_seen_ = true;
pid_ = pid;
tid_ = tid;
track_event_timestamp_ns_ = timestamp_ns;
track_event_thread_timestamp_ns_ = thread_timestamp_ns;
+ track_event_thread_instruction_count_ = thread_instruction_count;
}
bool IsIncrementalStateValid() const { return !packet_loss_; }
@@ -164,10 +172,11 @@
int32_t pid_ = 0;
int32_t tid_ = 0;
- // Current wall/thread timestamps used as reference for the next TrackEvent
- // delta timestamp.
+ // Current wall/thread timestamps/counters used as reference for the next
+ // TrackEvent delta timestamp.
int64_t track_event_timestamp_ns_ = 0;
int64_t track_event_thread_timestamp_ns_ = 0;
+ int64_t track_event_thread_instruction_count_ = 0;
InternedDataMap<protos::pbzero::EventCategory> event_categories_;
InternedDataMap<protos::pbzero::LegacyEventName> legacy_event_names_;
diff --git a/src/trace_processor/proto_trace_parser.cc b/src/trace_processor/proto_trace_parser.cc
index b47500a..d5a6eb0 100644
--- a/src/trace_processor/proto_trace_parser.cc
+++ b/src/trace_processor/proto_trace_parser.cc
@@ -200,8 +200,9 @@
namespace {
// Slices which have been opened but haven't been closed yet will be marked
-// with this placeholder value.
+// with these placeholder values.
constexpr int64_t kPendingThreadDuration = -1;
+constexpr int64_t kPendingThreadInstructionDelta = -1;
} // namespace
} // namespace
@@ -265,6 +266,12 @@
context->storage->InternString("legacy_event.thread_timestamp_ns")),
legacy_event_thread_duration_ns_key_id_(
context->storage->InternString("legacy_event.thread_duration_ns")),
+ legacy_event_thread_instruction_count_key_id_(
+ context->storage->InternString(
+ "legacy_event.thread_instruction_count")),
+ legacy_event_thread_instruction_delta_key_id_(
+ context->storage->InternString(
+ "legacy_event.thread_instruction_delta")),
legacy_event_use_async_tts_key_id_(
context->storage->InternString("legacy_event.use_async_tts")),
legacy_event_global_id_key_id_(
@@ -413,8 +420,8 @@
ParseSystemInfo(packet.system_info());
if (packet.has_track_event()) {
- ParseTrackEvent(ts, ttp.thread_timestamp, ttp.packet_sequence_state,
- packet.track_event());
+ ParseTrackEvent(ts, ttp.thread_timestamp, ttp.thread_instruction_count,
+ ttp.packet_sequence_state, packet.track_event());
}
if (packet.has_chrome_benchmark_metadata()) {
@@ -1522,6 +1529,7 @@
void ProtoTraceParser::ParseTrackEvent(
int64_t ts,
int64_t tts,
+ int64_t ticount,
ProtoIncrementalState::PacketSequenceState* sequence_state,
ConstBytes blob) {
protos::pbzero::TrackEvent::Decoder event(blob.data, blob.size);
@@ -1628,8 +1636,6 @@
}
}
- // TODO(eseckler): Handle thread instruction counts.
-
auto args_callback = [this, &event, &sequence_state](
ArgsTracker* args_tracker, RowId row_id) {
for (auto it = event.debug_annotations(); it; ++it) {
@@ -1674,9 +1680,8 @@
thread_slices->slice_ids().back() <
opt_slice_id.value());
thread_slices->AddThreadSlice(opt_slice_id.value(), tts,
- kPendingThreadDuration,
- /*thread_instruction_count=*/0,
- /*thread_instruction_delta=*/0);
+ kPendingThreadDuration, ticount,
+ kPendingThreadInstructionDelta);
}
break;
}
@@ -1685,8 +1690,8 @@
ts, utid, RefType::kRefUtid, category_id, name_id, args_callback);
if (opt_slice_id.has_value()) {
auto* thread_slices = storage->mutable_thread_slices();
- thread_slices->UpdateThreadDurationForSliceId(opt_slice_id.value(),
- tts);
+ thread_slices->UpdateThreadDeltasForSliceId(opt_slice_id.value(), tts,
+ ticount);
}
break;
}
@@ -1704,9 +1709,8 @@
opt_slice_id.value());
auto thread_duration_ns = legacy_event.thread_duration_us() * 1000;
thread_slices->AddThreadSlice(opt_slice_id.value(), tts,
- thread_duration_ns,
- /*thread_instruction_count=*/0,
- /*thread_instruction_delta=*/0);
+ thread_duration_ns, ticount,
+ legacy_event.thread_instruction_delta());
}
break;
}
@@ -1715,6 +1719,7 @@
// Handle instant events as slices with zero duration, so that they end
// up nested underneath their parent slices.
int64_t duration_ns = 0;
+ int64_t tidelta = 0;
switch (legacy_event.instant_event_scope()) {
case LegacyEvent::SCOPE_UNSPECIFIED:
@@ -1728,9 +1733,7 @@
thread_slices->slice_ids().back() <
opt_slice_id.value());
thread_slices->AddThreadSlice(opt_slice_id.value(), tts,
- duration_ns,
- /*thread_instruction_count=*/0,
- /*thread_instruction_delta=*/0);
+ duration_ns, ticount, tidelta);
}
break;
}
@@ -1767,9 +1770,8 @@
vtrack_slices->slice_ids().back() <
opt_slice_id.value());
vtrack_slices->AddVirtualTrackSlice(opt_slice_id.value(), tts,
- kPendingThreadDuration,
- /*thread_instruction_count=*/0,
- /*thread_instruction_delta=*/0);
+ kPendingThreadDuration, ticount,
+ kPendingThreadInstructionDelta);
}
break;
}
@@ -1781,8 +1783,8 @@
name_id, args_callback);
if (legacy_event.use_async_tts() && opt_slice_id.has_value()) {
auto* vtrack_slices = storage->mutable_virtual_track_slices();
- vtrack_slices->UpdateThreadDurationForSliceId(opt_slice_id.value(),
- tts);
+ vtrack_slices->UpdateThreadDeltasForSliceId(opt_slice_id.value(), tts,
+ ticount);
}
break;
}
@@ -1790,6 +1792,7 @@
// Handle instant events as slices with zero duration, so that they end up
// nested underneath their parent slices.
int64_t duration_ns = 0;
+ int64_t tidelta = 0;
TrackId track_id = context_->virtual_track_tracker->GetOrCreateTrack(
{vtrack_scope, vtrack_upid, id, id_scope}, name_id);
auto opt_slice_id =
@@ -1801,9 +1804,7 @@
vtrack_slices->slice_ids().back() <
opt_slice_id.value());
vtrack_slices->AddVirtualTrackSlice(opt_slice_id.value(), tts,
- duration_ns,
- /*thread_instruction_count=*/0,
- /*thread_instruction_delta=*/0);
+ duration_ns, ticount, tidelta);
}
break;
}
@@ -1838,13 +1839,13 @@
break;
}
// Other metadata events are proxied via the raw table for JSON export.
- ParseLegacyEventAsRawEvent(ts, tts, utid, category_id, name_id,
+ ParseLegacyEventAsRawEvent(ts, tts, ticount, utid, category_id, name_id,
legacy_event, args_callback);
break;
}
default: {
// Other events are proxied via the raw table for JSON export.
- ParseLegacyEventAsRawEvent(ts, tts, utid, category_id, name_id,
+ ParseLegacyEventAsRawEvent(ts, tts, ticount, utid, category_id, name_id,
legacy_event, args_callback);
}
}
@@ -1853,6 +1854,7 @@
void ProtoTraceParser::ParseLegacyEventAsRawEvent(
int64_t ts,
int64_t tts,
+ int64_t ticount,
UniqueTid utid,
StringId category_id,
StringId name_id,
@@ -1887,7 +1889,16 @@
}
}
- // TODO(eseckler): Handle thread_instruction_count/delta.
+ if (ticount) {
+ args.AddArg(row_id, legacy_event_thread_instruction_count_key_id_,
+ legacy_event_thread_instruction_count_key_id_,
+ Variadic::Integer(tts));
+ if (legacy_event.has_thread_instruction_delta()) {
+ args.AddArg(row_id, legacy_event_thread_instruction_delta_key_id_,
+ legacy_event_thread_instruction_delta_key_id_,
+ Variadic::Integer(legacy_event.thread_instruction_delta()));
+ }
+ }
if (legacy_event.use_async_tts()) {
args.AddArg(row_id, legacy_event_use_async_tts_key_id_,
diff --git a/src/trace_processor/proto_trace_parser.h b/src/trace_processor/proto_trace_parser.h
index 83aca1c..5cc032a 100644
--- a/src/trace_processor/proto_trace_parser.h
+++ b/src/trace_processor/proto_trace_parser.h
@@ -100,11 +100,13 @@
void ParseSystemInfo(ConstBytes);
void ParseTrackEvent(int64_t ts,
int64_t tts,
+ int64_t ticount,
ProtoIncrementalState::PacketSequenceState*,
ConstBytes);
void ParseLegacyEventAsRawEvent(
int64_t ts,
int64_t tts,
+ int64_t ticount,
UniqueTid utid,
StringId category_id,
StringId name_id,
@@ -171,6 +173,8 @@
const StringId legacy_event_duration_ns_key_id_;
const StringId legacy_event_thread_timestamp_ns_key_id_;
const StringId legacy_event_thread_duration_ns_key_id_;
+ const StringId legacy_event_thread_instruction_count_key_id_;
+ const StringId legacy_event_thread_instruction_delta_key_id_;
const StringId legacy_event_use_async_tts_key_id_;
const StringId legacy_event_global_id_key_id_;
const StringId legacy_event_local_id_key_id_;
diff --git a/src/trace_processor/proto_trace_parser_unittest.cc b/src/trace_processor/proto_trace_parser_unittest.cc
index 0f72816..0185b31 100644
--- a/src/trace_processor/proto_trace_parser_unittest.cc
+++ b/src/trace_processor/proto_trace_parser_unittest.cc
@@ -741,13 +741,15 @@
thread_desc->set_tid(16);
thread_desc->set_reference_timestamp_us(1000);
thread_desc->set_reference_thread_time_us(2000);
+ thread_desc->set_reference_thread_instruction_count(3000);
}
{
auto* packet = trace_.add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* event = packet->set_track_event();
- event->set_timestamp_delta_us(10); // absolute: 1010.
- event->set_thread_time_delta_us(5); // absolute: 2005.
+ event->set_timestamp_delta_us(10); // absolute: 1010.
+ event->set_thread_time_delta_us(5); // absolute: 2005.
+ event->set_thread_instruction_count_delta(20); // absolute: 3020.
event->add_category_iids(1);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(1);
@@ -767,6 +769,7 @@
auto* event = packet->set_track_event();
event->set_timestamp_absolute_us(1040);
event->set_thread_time_absolute_us(2030);
+ event->set_thread_instruction_count_absolute(3100);
event->add_category_iids(1);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(1);
@@ -788,8 +791,9 @@
auto* packet = trace_.add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* event = packet->set_track_event();
- event->set_timestamp_delta_us(10); // absolute: 1020.
- event->set_thread_time_delta_us(5); // absolute: 2010.
+ event->set_timestamp_delta_us(10); // absolute: 1020.
+ event->set_thread_time_delta_us(5); // absolute: 2010.
+ event->set_thread_instruction_count_delta(20); // absolute: 3040.
event->add_category_iids(1);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(1);
@@ -801,13 +805,15 @@
auto* event = packet->set_track_event();
event->set_timestamp_absolute_us(1005);
event->set_thread_time_absolute_us(2003);
+ event->set_thread_instruction_count_absolute(3010);
event->add_category_iids(2);
event->add_category_iids(3);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(2);
legacy_event->set_phase('X');
- legacy_event->set_duration_us(23); // absolute end: 1028.
- legacy_event->set_thread_duration_us(12); // absolute end: 2015.
+ legacy_event->set_duration_us(23); // absolute end: 1028.
+ legacy_event->set_thread_duration_us(12); // absolute end: 2015.
+ legacy_event->set_thread_instruction_delta(50); // absolute end: 3060.
auto* interned_data = packet->set_interned_data();
auto cat2 = interned_data->add_event_categories();
@@ -877,12 +883,18 @@
EXPECT_EQ(storage_->thread_slices().slice_ids()[0], 0u);
EXPECT_EQ(storage_->thread_slices().thread_timestamp_ns()[0], 2003000);
EXPECT_EQ(storage_->thread_slices().thread_duration_ns()[0], 12000);
+ EXPECT_EQ(storage_->thread_slices().thread_instruction_counts()[0], 3010);
+ EXPECT_EQ(storage_->thread_slices().thread_instruction_deltas()[0], 50);
EXPECT_EQ(storage_->thread_slices().slice_ids()[1], 1u);
EXPECT_EQ(storage_->thread_slices().thread_timestamp_ns()[1], 2005000);
EXPECT_EQ(storage_->thread_slices().thread_duration_ns()[1], 5000);
+ EXPECT_EQ(storage_->thread_slices().thread_instruction_counts()[1], 3020);
+ EXPECT_EQ(storage_->thread_slices().thread_instruction_deltas()[1], 20);
EXPECT_EQ(storage_->thread_slices().slice_ids()[2], 2u);
EXPECT_EQ(storage_->thread_slices().thread_timestamp_ns()[2], 2030000);
EXPECT_EQ(storage_->thread_slices().thread_duration_ns()[2], 0);
+ EXPECT_EQ(storage_->thread_slices().thread_instruction_counts()[2], 3100);
+ EXPECT_EQ(storage_->thread_slices().thread_instruction_deltas()[2], 0);
}
TEST_F(ProtoTraceParserTest, TrackEventAsyncEvents) {
@@ -898,13 +910,15 @@
thread_desc->set_tid(16);
thread_desc->set_reference_timestamp_us(1000);
thread_desc->set_reference_thread_time_us(2000);
+ thread_desc->set_reference_thread_instruction_count(3000);
}
{
auto* packet = trace_.add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* event = packet->set_track_event();
- event->set_timestamp_delta_us(10); // absolute: 1010.
- event->set_thread_time_delta_us(5); // absolute: 2005.
+ event->set_timestamp_delta_us(10); // absolute: 1010.
+ event->set_thread_time_delta_us(5); // absolute: 2005.
+ event->set_thread_instruction_count_delta(20); // absolute: 3020.
event->add_category_iids(1);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(1);
@@ -924,8 +938,9 @@
auto* packet = trace_.add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* event = packet->set_track_event();
- event->set_timestamp_delta_us(10); // absolute: 1020.
- event->set_thread_time_delta_us(5); // absolute: 2010.
+ event->set_timestamp_delta_us(10); // absolute: 1020.
+ event->set_thread_time_delta_us(5); // absolute: 2010.
+ event->set_thread_instruction_count_delta(20); // absolute: 3040.
event->add_category_iids(1);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(1);
@@ -1011,6 +1026,10 @@
EXPECT_EQ(storage_->virtual_track_slices().slice_ids()[0], 0u);
EXPECT_EQ(storage_->virtual_track_slices().thread_timestamp_ns()[0], 2005000);
EXPECT_EQ(storage_->virtual_track_slices().thread_duration_ns()[0], 5000);
+ EXPECT_EQ(storage_->virtual_track_slices().thread_instruction_counts()[0],
+ 3020);
+ EXPECT_EQ(storage_->virtual_track_slices().thread_instruction_deltas()[0],
+ 20);
}
TEST_F(ProtoTraceParserTest, TrackEventWithoutIncrementalStateReset) {
diff --git a/src/trace_processor/proto_trace_tokenizer.cc b/src/trace_processor/proto_trace_tokenizer.cc
index 3b42613..14b969c 100644
--- a/src/trace_processor/proto_trace_tokenizer.cc
+++ b/src/trace_processor/proto_trace_tokenizer.cc
@@ -382,7 +382,8 @@
state->SetThreadDescriptor(
thread_descriptor_decoder.pid(), thread_descriptor_decoder.tid(),
thread_descriptor_decoder.reference_timestamp_us() * 1000,
- thread_descriptor_decoder.reference_thread_time_us() * 1000);
+ thread_descriptor_decoder.reference_thread_time_us() * 1000,
+ thread_descriptor_decoder.reference_thread_instruction_count());
base::StringView name;
if (thread_descriptor_decoder.has_thread_name()) {
@@ -454,6 +455,10 @@
protos::pbzero::TrackEvent::kThreadTimeDeltaUsFieldNumber;
constexpr auto kThreadTimeAbsoluteUsFieldNumber =
protos::pbzero::TrackEvent::kThreadTimeAbsoluteUsFieldNumber;
+ constexpr auto kThreadInstructionCountDeltaFieldNumber =
+ protos::pbzero::TrackEvent::kThreadInstructionCountDeltaFieldNumber;
+ constexpr auto kThreadInstructionCountAbsoluteFieldNumber =
+ protos::pbzero::TrackEvent::kThreadInstructionCountAbsoluteFieldNumber;
if (PERFETTO_UNLIKELY(!packet_decoder.has_trusted_packet_sequence_id())) {
PERFETTO_ELOG("TrackEvent packet without trusted_packet_sequence_id");
@@ -477,6 +482,7 @@
int64_t timestamp;
int64_t thread_timestamp = 0;
+ int64_t thread_instructions = 0;
if (auto ts_delta_field =
event_decoder.FindField(kTimestampDeltaUsFieldNumber)) {
@@ -502,7 +508,19 @@
thread_timestamp = tt_absolute_field.as_int64() * 1000;
}
- context_->sorter->PushTrackEventPacket(timestamp, thread_timestamp, state,
+ if (auto ti_delta_field =
+ event_decoder.FindField(kThreadInstructionCountDeltaFieldNumber)) {
+ thread_instructions =
+ state->IncrementAndGetTrackEventThreadInstructionCount(
+ ti_delta_field.as_int64());
+ } else if (auto ti_absolute_field = event_decoder.FindField(
+ kThreadInstructionCountAbsoluteFieldNumber)) {
+ // One-off absolute timestamps don't affect delta computation.
+ thread_instructions = ti_absolute_field.as_int64();
+ }
+
+ context_->sorter->PushTrackEventPacket(timestamp, thread_timestamp,
+ thread_instructions, state,
std::move(packet));
}
diff --git a/src/trace_processor/trace_sorter.h b/src/trace_processor/trace_sorter.h
index 32d2097..bfca6bf 100644
--- a/src/trace_processor/trace_sorter.h
+++ b/src/trace_processor/trace_sorter.h
@@ -77,6 +77,7 @@
ProtoIncrementalState::PacketSequenceState* sequence_state)
: TimestampedTracePiece(ts,
/*thread_ts=*/0,
+ /*thread_instructions=*/0,
idx,
std::move(tbv),
/*value=*/nullptr,
@@ -86,6 +87,7 @@
TimestampedTracePiece(int64_t ts, uint64_t idx, TraceBlobView tbv)
: TimestampedTracePiece(ts,
/*thread_ts=*/0,
+ /*thread_instructions=*/0,
idx,
std::move(tbv),
/*value=*/nullptr,
@@ -97,6 +99,7 @@
std::unique_ptr<Json::Value> value)
: TimestampedTracePiece(ts,
/*thread_ts=*/0,
+ /*thread_instructions=*/0,
idx,
// TODO(dproy): Stop requiring TraceBlobView in
// TimestampedTracePiece.
@@ -111,6 +114,7 @@
std::unique_ptr<FuchsiaProviderView> fpv)
: TimestampedTracePiece(ts,
/*thread_ts=*/0,
+ /*thread_instructions=*/0,
idx,
std::move(tbv),
/*value=*/nullptr,
@@ -120,11 +124,13 @@
TimestampedTracePiece(
int64_t ts,
int64_t thread_ts,
+ int64_t thread_instructions,
uint64_t idx,
TraceBlobView tbv,
ProtoIncrementalState::PacketSequenceState* sequence_state)
: TimestampedTracePiece(ts,
thread_ts,
+ thread_instructions,
idx,
std::move(tbv),
/*value=*/nullptr,
@@ -134,6 +140,7 @@
TimestampedTracePiece(
int64_t ts,
int64_t thread_ts,
+ int64_t thread_instructions,
uint64_t idx,
TraceBlobView tbv,
std::unique_ptr<Json::Value> value,
@@ -144,6 +151,7 @@
packet_sequence_state(sequence_state),
timestamp(ts),
thread_timestamp(thread_ts),
+ thread_instruction_count(thread_instructions),
packet_idx_(idx),
blob_view(std::move(tbv)) {}
@@ -167,6 +175,7 @@
int64_t timestamp;
int64_t thread_timestamp;
+ int64_t thread_instruction_count;
uint64_t packet_idx_;
TraceBlobView blob_view;
};
@@ -218,10 +227,12 @@
inline void PushTrackEventPacket(
int64_t timestamp,
int64_t thread_time,
+ int64_t thread_instruction_count,
ProtoIncrementalState::PacketSequenceState* state,
TraceBlobView packet) {
auto* queue = GetQueue(0);
- queue->Append(TimestampedTracePiece(timestamp, thread_time, packet_idx_++,
+ queue->Append(TimestampedTracePiece(timestamp, thread_time,
+ thread_instruction_count, packet_idx_++,
std::move(packet), state));
MaybeExtractEvents(queue);
}
diff --git a/src/trace_processor/trace_storage.h b/src/trace_processor/trace_storage.h
index d65b435..f3d8f7b 100644
--- a/src/trace_processor/trace_storage.h
+++ b/src/trace_processor/trace_storage.h
@@ -414,11 +414,15 @@
return base::nullopt;
}
- void UpdateThreadDurationForSliceId(uint32_t slice_id,
- int64_t end_thread_timestamp_ns) {
+ void UpdateThreadDeltasForSliceId(uint32_t slice_id,
+ int64_t end_thread_timestamp_ns,
+ int64_t end_thread_instruction_count) {
uint32_t row = *FindRowForSliceId(slice_id);
int64_t begin_ns = thread_timestamp_ns_[row];
thread_duration_ns_[row] = end_thread_timestamp_ns - begin_ns;
+ int64_t begin_ticount = thread_instruction_counts_[row];
+ thread_instruction_deltas_[row] =
+ end_thread_instruction_count - begin_ticount;
}
private:
@@ -471,11 +475,15 @@
return base::nullopt;
}
- void UpdateThreadDurationForSliceId(uint32_t slice_id,
- int64_t end_thread_timestamp_ns) {
+ void UpdateThreadDeltasForSliceId(uint32_t slice_id,
+ int64_t end_thread_timestamp_ns,
+ int64_t end_thread_instruction_count) {
uint32_t row = *FindRowForSliceId(slice_id);
int64_t begin_ns = thread_timestamp_ns_[row];
thread_duration_ns_[row] = end_thread_timestamp_ns - begin_ns;
+ int64_t begin_ticount = thread_instruction_counts_[row];
+ thread_instruction_deltas_[row] =
+ end_thread_instruction_count - begin_ticount;
}
private: