processor: Resolve descriptor track names during tokenization as well I'm about to switch "EarlyJava" events in chrome to use descriptor tracks for thread time. These events will have timestamps that precede any track descriptors' timestamps. So the parser will not see the track descriptor before the events. In order to import the thread time from the extra_counter_values into the thread-time column used by the JSON export, we need to know the thread time track's name at the time of parsing the event. Thus, this patch adds the track name to the track reservation and sets it initially when resolving a descriptor track, too. The parser will still later update the track names from descriptors in the sorted-by-ts order. Change-Id: Ia8f5303aaa4c5c317537ff78e271d9199893d1cd
diff --git a/src/trace_processor/export_json_unittest.cc b/src/trace_processor/export_json_unittest.cc index d0e8ad5..ef15834 100644 --- a/src/trace_processor/export_json_unittest.cc +++ b/src/trace_processor/export_json_unittest.cc
@@ -740,7 +740,7 @@ {kTimestamp2, 0, track2, cat_id, name_id, 0, 0, 0}); // Async event track. - context_.track_tracker->ReserveDescriptorChildTrack(1234, 0); + context_.track_tracker->ReserveDescriptorChildTrack(1234, 0, kNullStringId); TrackId track3 = *context_.track_tracker->GetDescriptorTrack(1234); context_.args_tracker->Flush(); // Flush track args. context_.storage->mutable_slice_table()->Insert(
diff --git a/src/trace_processor/importers/common/track_tracker.cc b/src/trace_processor/importers/common/track_tracker.cc index d4e357f..788296d 100644 --- a/src/trace_processor/importers/common/track_tracker.cc +++ b/src/trace_processor/importers/common/track_tracker.cc
@@ -190,11 +190,13 @@ } void TrackTracker::ReserveDescriptorProcessTrack(uint64_t uuid, + StringId name, uint32_t pid, int64_t timestamp) { DescriptorTrackReservation reservation; reservation.min_timestamp = timestamp; reservation.pid = pid; + reservation.name = name; std::map<uint64_t, DescriptorTrackReservation>::iterator it; bool inserted; @@ -219,6 +221,7 @@ void TrackTracker::ReserveDescriptorThreadTrack(uint64_t uuid, uint64_t parent_uuid, + StringId name, uint32_t pid, uint32_t tid, int64_t timestamp) { @@ -227,6 +230,7 @@ reservation.parent_uuid = parent_uuid; reservation.pid = pid; reservation.tid = tid; + reservation.name = name; std::map<uint64_t, DescriptorTrackReservation>::iterator it; bool inserted; @@ -251,6 +255,7 @@ void TrackTracker::ReserveDescriptorCounterTrack(uint64_t uuid, uint64_t parent_uuid, + StringId name, StringId category, int64_t unit_multiplier, bool is_incremental, @@ -258,6 +263,7 @@ DescriptorTrackReservation reservation; reservation.parent_uuid = parent_uuid; reservation.is_counter = true; + reservation.name = name; reservation.category = category; reservation.unit_multiplier = unit_multiplier; reservation.is_incremental = is_incremental; @@ -282,9 +288,11 @@ } void TrackTracker::ReserveDescriptorChildTrack(uint64_t uuid, - uint64_t parent_uuid) { + uint64_t parent_uuid, + StringId name) { DescriptorTrackReservation reservation; reservation.parent_uuid = parent_uuid; + reservation.name = name; std::map<uint64_t, DescriptorTrackReservation>::iterator it; bool inserted; @@ -326,6 +334,17 @@ uint64_t uuid, const DescriptorTrackReservation& reservation, std::vector<uint64_t>* descendent_uuids) { + auto set_track_name_and_return = [this, &reservation](TrackId track_id) { + // Initialize the track name here, so that, if a name was given in the + // reservation, it is set immediately after resolution takes place. + if (reservation.name != kNullStringId) { + auto* tracks = context_->storage->mutable_track_table(); + tracks->mutable_name()->Set(*tracks->id().IndexOf(track_id), + reservation.name); + } + return track_id; + }; + static constexpr size_t kMaxAncestors = 10; // Try to resolve any parent tracks recursively, too. @@ -393,7 +412,7 @@ descriptor_uuids_by_utid_[utid] = uuid; } - return InternThreadTrack(utid); + return set_track_name_and_return(InternThreadTrack(utid)); } if (reservation.pid) { @@ -419,7 +438,7 @@ descriptor_uuids_by_upid_[upid] = uuid; } - return InternProcessTrack(upid); + return set_track_name_and_return(InternProcessTrack(upid)); } base::Optional<TrackId> track_id; @@ -506,7 +525,7 @@ if (reservation.category != kNullStringId) { args.AddArg(category_key_, Variadic::String(reservation.category)); } - return *track_id; + return set_track_name_and_return(*track_id); } TrackId TrackTracker::GetOrCreateDefaultDescriptorTrack() { @@ -518,13 +537,9 @@ return *track_id; // Otherwise reserve a new track and resolve it. - ReserveDescriptorChildTrack(kDefaultDescriptorTrackUuid, /*parent_uuid=*/0); - track_id = GetDescriptorTrack(kDefaultDescriptorTrackUuid); - - auto* tracks = context_->storage->mutable_track_table(); - tracks->mutable_name()->Set(*tracks->id().IndexOf(*track_id), + ReserveDescriptorChildTrack(kDefaultDescriptorTrackUuid, /*parent_uuid=*/0, default_descriptor_track_name_); - return *track_id; + return *GetDescriptorTrack(kDefaultDescriptorTrackUuid); } TrackId TrackTracker::GetOrCreateTriggerTrack() {
diff --git a/src/trace_processor/importers/common/track_tracker.h b/src/trace_processor/importers/common/track_tracker.h index 2f3b59c..c4bd3c7 100644 --- a/src/trace_processor/importers/common/track_tracker.h +++ b/src/trace_processor/importers/common/track_tracker.h
@@ -71,6 +71,7 @@ // upon the first call to GetDescriptorTrack() with the same |uuid|. At this // time, |pid| will also be resolved to a |upid|. void ReserveDescriptorProcessTrack(uint64_t uuid, + StringId name, uint32_t pid, int64_t timestamp); @@ -84,6 +85,7 @@ // time, |pid| will also be resolved to a |upid|. void ReserveDescriptorThreadTrack(uint64_t uuid, uint64_t parent_uuid, + StringId name, uint32_t pid, uint32_t tid, int64_t timestamp); @@ -97,7 +99,9 @@ // the same |uuid|. If |parent_uuid| is 0, the track will become a global // track. Otherwise, it will become a new track of the same type as its parent // track. - void ReserveDescriptorChildTrack(uint64_t uuid, uint64_t parent_uuid); + void ReserveDescriptorChildTrack(uint64_t uuid, + uint64_t parent_uuid, + StringId name); // Associate a counter-type TrackDescriptor track identified by the given // |uuid| with a parent track (usually a process or thread track). This is @@ -117,6 +121,7 @@ // process/thread as its parent track. void ReserveDescriptorCounterTrack(uint64_t uuid, uint64_t parent_uuid, + StringId name, StringId category, int64_t unit_multiplier, bool is_incremental, @@ -217,6 +222,7 @@ base::Optional<uint32_t> pid; base::Optional<uint32_t> tid; int64_t min_timestamp = 0; // only set if |pid| and/or |tid| is set. + StringId name = kNullStringId; // For counter tracks. bool is_counter = false; @@ -229,8 +235,8 @@ // Whether |other| is a valid descriptor for this track reservation. A track // should always remain nested underneath its original parent. bool IsForSameTrack(const DescriptorTrackReservation& other) { - // Note that |min_timestamp| and |last_value| are ignored for this - // comparison. + // Note that |min_timestamp|, |latest_value|, and |name| are ignored for + // this comparison. return std::tie(parent_uuid, pid, tid, is_counter, category, unit_multiplier, is_incremental, packet_sequence_id) == std::tie(other.parent_uuid, pid, tid, is_counter, category,
diff --git a/src/trace_processor/importers/proto/proto_trace_parser_unittest.cc b/src/trace_processor/importers/proto/proto_trace_parser_unittest.cc index 81c9982..7d76854 100644 --- a/src/trace_processor/importers/proto/proto_trace_parser_unittest.cc +++ b/src/trace_processor/importers/proto/proto_trace_parser_unittest.cc
@@ -54,6 +54,7 @@ #include "protos/perfetto/trace/sys_stats/sys_stats.pbzero.h" #include "protos/perfetto/trace/trace.pbzero.h" #include "protos/perfetto/trace/trace_packet.pbzero.h" +#include "protos/perfetto/trace/track_event/counter_descriptor.pbzero.h" #include "protos/perfetto/trace/track_event/debug_annotation.pbzero.h" #include "protos/perfetto/trace/track_event/log_message.pbzero.h" #include "protos/perfetto/trace/track_event/process_descriptor.pbzero.h" @@ -1444,6 +1445,110 @@ EXPECT_EQ(storage_->thread_slices().thread_instruction_deltas()[1], 0); } +TEST_F(ProtoTraceParserTest, TrackEventWithResortedCounterDescriptor) { + context_.sorter.reset(new TraceSorter( + CreateParser(), std::numeric_limits<int64_t>::max() /*window size*/)); + + // Descriptors with timestamps after the event below. They will be tokenized + // in the order they appear here, but then resorted before parsing to appear + // after the events below. + { + auto* packet = trace_.add_packet(); + packet->set_trusted_packet_sequence_id(1); + packet->set_incremental_state_cleared(true); + packet->set_timestamp(3000); + auto* track_desc = packet->set_track_descriptor(); + track_desc->set_uuid(1); + auto* thread_desc = track_desc->set_thread(); + thread_desc->set_pid(5); + thread_desc->set_tid(1); + thread_desc->set_thread_name("t1"); + // Default to track for "t1" and an extra counter for thread time. + auto* track_event_defaults = + packet->set_trace_packet_defaults()->set_track_event_defaults(); + track_event_defaults->set_track_uuid(1); + // Thread-time counter track defined below. + track_event_defaults->add_extra_counter_track_uuids(10); + } + { + auto* packet = trace_.add_packet(); + packet->set_trusted_packet_sequence_id(1); + packet->set_timestamp(3000); + auto* track_desc = packet->set_track_descriptor(); + track_desc->set_uuid(10); + track_desc->set_parent_uuid(1); + auto* counter = track_desc->set_counter(); + counter->set_type( + protos::pbzero::CounterDescriptor::COUNTER_THREAD_TIME_NS); + counter->set_unit_multiplier(1000); // provided in us. + counter->set_is_incremental(true); + } + { + // Event with timestamps before the descriptors above. The thread time + // counter values should still be imported as counter values and as args for + // JSON export. Should appear on default track "t1" with + // extra_counter_values for "c1". + auto* packet = trace_.add_packet(); + packet->set_trusted_packet_sequence_id(1); + packet->set_sequence_flags( + protos::pbzero::TracePacket::SEQ_NEEDS_INCREMENTAL_STATE); + packet->set_timestamp(1000); + auto* event = packet->set_track_event(); + event->add_categories("cat1"); + event->set_name("ev1"); + event->set_type(protos::pbzero::TrackEvent::TYPE_SLICE_BEGIN); + event->add_extra_counter_values(1000); // absolute: 1000000. + } + { + // End for "ev1". + auto* packet = trace_.add_packet(); + packet->set_trusted_packet_sequence_id(1); + packet->set_timestamp(1100); + auto* event = packet->set_track_event(); + event->set_type(protos::pbzero::TrackEvent::TYPE_SLICE_END); + event->add_extra_counter_values(10); // absolute: 1010000. + } + + EXPECT_CALL(*process_, UpdateThread(1, 5)).WillRepeatedly(Return(1)); + + tables::ThreadTable::Row t1(16); + t1.upid = 1u; + storage_->mutable_thread_table()->Insert(t1); + + Tokenize(); + + StringId cat_1 = storage_->InternString("cat1"); + StringId ev_1 = storage_->InternString("ev1"); + + InSequence in_sequence; // Below slices should be sorted by timestamp. + + EXPECT_CALL(*event_, + PushCounter(1000, testing::DoubleEq(1000000), TrackId{1})); + EXPECT_CALL(*slice_, Begin(1000, TrackId{0}, cat_1, ev_1, _)) + .WillOnce(Return(0u)); + + EXPECT_CALL(*event_, + PushCounter(1100, testing::DoubleEq(1010000), TrackId{1})); + EXPECT_CALL(*slice_, End(1100, TrackId{0}, kNullStringId, kNullStringId, _)) + .WillOnce(Return(0u)); + + EXPECT_CALL(*process_, + SetThreadNameIfUnset(1u, storage_->InternString("t1"))); + + context_.sorter->ExtractEventsForced(); + + // First track is thread time track, second is "t1". + EXPECT_EQ(storage_->track_table().row_count(), 2u); + EXPECT_EQ(storage_->thread_track_table().row_count(), 1u); + EXPECT_EQ(storage_->thread_track_table().utid()[0], 1u); + + // Counter values should also be imported into thread slices. + EXPECT_EQ(storage_->thread_slices().slice_count(), 1u); + EXPECT_EQ(storage_->thread_slices().slice_ids()[0], 0u); + EXPECT_EQ(storage_->thread_slices().thread_timestamp_ns()[0], 1000000); + EXPECT_EQ(storage_->thread_slices().thread_duration_ns()[0], 10000); +} + TEST_F(ProtoTraceParserTest, TrackEventWithoutIncrementalStateReset) { context_.sorter.reset(new TraceSorter( CreateParser(), std::numeric_limits<int64_t>::max() /*window size*/));
diff --git a/src/trace_processor/importers/proto/track_event_parser.cc b/src/trace_processor/importers/proto/track_event_parser.cc index 5a098d8..af0275c 100644 --- a/src/trace_processor/importers/proto/track_event_parser.cc +++ b/src/trace_processor/importers/proto/track_event_parser.cc
@@ -283,7 +283,7 @@ track_tracker->GetDescriptorTrack(track_uuid_); if (!opt_track_id) { track_tracker->ReserveDescriptorChildTrack(track_uuid_, - /*parent_uuid=*/0); + /*parent_uuid=*/0, name_id_); opt_track_id = track_tracker->GetDescriptorTrack(track_uuid_); } track_id_ = *opt_track_id; @@ -1324,6 +1324,7 @@ ParseCounterDescriptor(track_id, decoder.counter()); } + // Override the name with the most recent name seen (after sorting by ts). if (decoder.has_name()) { auto* tracks = context_->storage->mutable_track_table(); StringId name_id = context_->storage->InternString(decoder.name());
diff --git a/src/trace_processor/importers/proto/track_event_tokenizer.cc b/src/trace_processor/importers/proto/track_event_tokenizer.cc index 165eeff..ec5630d 100644 --- a/src/trace_processor/importers/proto/track_event_tokenizer.cc +++ b/src/trace_processor/importers/proto/track_event_tokenizer.cc
@@ -40,8 +40,16 @@ namespace perfetto { namespace trace_processor { +namespace { +using protos::pbzero::CounterDescriptor; +} + TrackEventTokenizer::TrackEventTokenizer(TraceProcessorContext* context) - : context_(context) {} + : context_(context), + counter_name_thread_time_id_( + context_->storage->InternString("thread_time")), + counter_name_thread_instruction_count_id_( + context_->storage->InternString("thread_instruction_count")) {} ModuleResult TrackEventTokenizer::TokenizeTrackDescriptorPacket( PacketSequenceState* state, @@ -57,6 +65,10 @@ return ModuleResult::Handled(); } + StringId name_id = kNullStringId; + if (track.has_name()) + name_id = context_->storage->InternString(track.name()); + if (track.has_thread()) { protos::pbzero::ThreadDescriptor::Decoder thread(track.thread()); @@ -73,7 +85,8 @@ } context_->track_tracker->ReserveDescriptorThreadTrack( - track.uuid(), track.parent_uuid(), static_cast<uint32_t>(thread.pid()), + track.uuid(), track.parent_uuid(), name_id, + static_cast<uint32_t>(thread.pid()), static_cast<uint32_t>(thread.tid()), packet_timestamp); } else if (track.has_process()) { protos::pbzero::ProcessDescriptor::Decoder process(track.process()); @@ -86,7 +99,8 @@ } context_->track_tracker->ReserveDescriptorProcessTrack( - track.uuid(), static_cast<uint32_t>(process.pid()), packet_timestamp); + track.uuid(), name_id, static_cast<uint32_t>(process.pid()), + packet_timestamp); } else if (track.has_counter()) { protos::pbzero::CounterDescriptor::Decoder counter(track.counter()); @@ -105,13 +119,32 @@ } } + // TODO(eseckler): Intern counter tracks for specific counter types like + // thread time, so that the same counter can be referred to from tracks with + // different uuids. (Chrome may emit thread time values on behalf of other + // threads, in which case it has to use absolute values on a different + // track_uuid. Right now these absolute values are imported onto a separate + // counter track than the other thread's regular thread time values.) + if (name_id == kNullStringId) { + switch (counter.type()) { + case CounterDescriptor::COUNTER_UNSPECIFIED: + break; + case CounterDescriptor::COUNTER_THREAD_TIME_NS: + name_id = counter_name_thread_time_id_; + break; + case CounterDescriptor::COUNTER_THREAD_INSTRUCTION_COUNT: + name_id = counter_name_thread_instruction_count_id_; + break; + } + } + context_->track_tracker->ReserveDescriptorCounterTrack( - track.uuid(), track.parent_uuid(), category_id, + track.uuid(), track.parent_uuid(), name_id, category_id, counter.unit_multiplier(), counter.is_incremental(), packet.trusted_packet_sequence_id()); } else { - context_->track_tracker->ReserveDescriptorChildTrack(track.uuid(), - track.parent_uuid()); + context_->track_tracker->ReserveDescriptorChildTrack( + track.uuid(), track.parent_uuid(), name_id); } // Let ProtoTraceTokenizer forward the packet to the parser.
diff --git a/src/trace_processor/importers/proto/track_event_tokenizer.h b/src/trace_processor/importers/proto/track_event_tokenizer.h index 0f914db..6657a48 100644 --- a/src/trace_processor/importers/proto/track_event_tokenizer.h +++ b/src/trace_processor/importers/proto/track_event_tokenizer.h
@@ -61,6 +61,9 @@ const protos::pbzero::ThreadDescriptor_Decoder&); TraceProcessorContext* context_; + + const StringId counter_name_thread_time_id_; + const StringId counter_name_thread_instruction_count_id_; }; } // namespace trace_processor