1 /*
2 * Copyright (C) 2019 The Android Open Source Project
3 *
4 * Licensed under the Apache License, Version 2.0 (the "License");
5 * you may not use this file except in compliance with the License.
6 * You may obtain a copy of the License at
7 *
8 * http://www.apache.org/licenses/LICENSE-2.0
9 *
10 * Unless required by applicable law or agreed to in writing, software
11 * distributed under the License is distributed on an "AS IS" BASIS,
12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13 * See the License for the specific language governing permissions and
14 * limitations under the License.
15 */
16
17 #include "src/trace_processor/importers/proto/track_event_parser.h"
18
19 #include <iostream>
20 #include <string>
21
22 #include "perfetto/base/logging.h"
23 #include "perfetto/ext/base/optional.h"
24 #include "perfetto/ext/base/string_writer.h"
25 #include "perfetto/trace_processor/status.h"
26 #include "src/trace_processor/importers/common/args_tracker.h"
27 #include "src/trace_processor/importers/common/args_translation_table.h"
28 #include "src/trace_processor/importers/common/event_tracker.h"
29 #include "src/trace_processor/importers/common/flow_tracker.h"
30 #include "src/trace_processor/importers/common/process_tracker.h"
31 #include "src/trace_processor/importers/common/track_tracker.h"
32 #include "src/trace_processor/importers/json/json_utils.h"
33 #include "src/trace_processor/importers/proto/packet_sequence_state.h"
34 #include "src/trace_processor/importers/proto/track_event_tracker.h"
35 #include "src/trace_processor/util/debug_annotation_parser.h"
36 #include "src/trace_processor/util/proto_to_args_parser.h"
37 #include "src/trace_processor/util/status_macros.h"
38
39 #include "protos/perfetto/trace/extension_descriptor.pbzero.h"
40 #include "protos/perfetto/trace/interned_data/interned_data.pbzero.h"
41 #include "protos/perfetto/trace/track_event/chrome_compositor_scheduler_state.pbzero.h"
42 #include "protos/perfetto/trace/track_event/chrome_histogram_sample.pbzero.h"
43 #include "protos/perfetto/trace/track_event/chrome_legacy_ipc.pbzero.h"
44 #include "protos/perfetto/trace/track_event/chrome_process_descriptor.pbzero.h"
45 #include "protos/perfetto/trace/track_event/chrome_thread_descriptor.pbzero.h"
46 #include "protos/perfetto/trace/track_event/counter_descriptor.pbzero.h"
47 #include "protos/perfetto/trace/track_event/debug_annotation.pbzero.h"
48 #include "protos/perfetto/trace/track_event/log_message.pbzero.h"
49 #include "protos/perfetto/trace/track_event/process_descriptor.pbzero.h"
50 #include "protos/perfetto/trace/track_event/source_location.pbzero.h"
51 #include "protos/perfetto/trace/track_event/task_execution.pbzero.h"
52 #include "protos/perfetto/trace/track_event/thread_descriptor.pbzero.h"
53 #include "protos/perfetto/trace/track_event/track_descriptor.pbzero.h"
54 #include "protos/perfetto/trace/track_event/track_event.pbzero.h"
55
56 namespace perfetto {
57 namespace trace_processor {
58
59 namespace {
60 using BoundInserter = ArgsTracker::BoundInserter;
61 using protos::pbzero::TrackEvent;
62 using LegacyEvent = TrackEvent::LegacyEvent;
63 using protozero::ConstBytes;
64
65 // Slices which have been opened but haven't been closed yet will be marked
66 // with these placeholder values.
67 constexpr int64_t kPendingThreadDuration = -1;
68 constexpr int64_t kPendingThreadInstructionDelta = -1;
69
70 class TrackEventArgsParser : public util::ProtoToArgsParser::Delegate {
71 public:
TrackEventArgsParser(BoundInserter & inserter,TraceStorage & storage,PacketSequenceStateGeneration & sequence_state,ArgsTranslationTable & args_translation_table)72 TrackEventArgsParser(BoundInserter& inserter,
73 TraceStorage& storage,
74 PacketSequenceStateGeneration& sequence_state,
75 ArgsTranslationTable& args_translation_table)
76 : inserter_(inserter),
77 storage_(storage),
78 sequence_state_(sequence_state),
79 args_translation_table_(args_translation_table) {}
80
81 ~TrackEventArgsParser() override;
82
83 using Key = util::ProtoToArgsParser::Key;
84
AddInteger(const Key & key,int64_t value)85 void AddInteger(const Key& key, int64_t value) final {
86 inserter_.AddArg(storage_.InternString(base::StringView(key.flat_key)),
87 storage_.InternString(base::StringView(key.key)),
88 Variadic::Integer(value));
89 }
AddUnsignedInteger(const Key & key,uint64_t value)90 void AddUnsignedInteger(const Key& key, uint64_t value) final {
91 if (args_translation_table_.TranslateUnsignedIntegerArg(key, value,
92 inserter_)) {
93 return;
94 }
95 inserter_.AddArg(storage_.InternString(base::StringView(key.flat_key)),
96 storage_.InternString(base::StringView(key.key)),
97 Variadic::UnsignedInteger(value));
98 }
AddString(const Key & key,const protozero::ConstChars & value)99 void AddString(const Key& key, const protozero::ConstChars& value) final {
100 inserter_.AddArg(storage_.InternString(base::StringView(key.flat_key)),
101 storage_.InternString(base::StringView(key.key)),
102 Variadic::String(storage_.InternString(value)));
103 }
AddDouble(const Key & key,double value)104 void AddDouble(const Key& key, double value) final {
105 inserter_.AddArg(storage_.InternString(base::StringView(key.flat_key)),
106 storage_.InternString(base::StringView(key.key)),
107 Variadic::Real(value));
108 }
AddPointer(const Key & key,const void * value)109 void AddPointer(const Key& key, const void* value) final {
110 inserter_.AddArg(storage_.InternString(base::StringView(key.flat_key)),
111 storage_.InternString(base::StringView(key.key)),
112 Variadic::Pointer(reinterpret_cast<uintptr_t>(value)));
113 }
AddBoolean(const Key & key,bool value)114 void AddBoolean(const Key& key, bool value) final {
115 inserter_.AddArg(storage_.InternString(base::StringView(key.flat_key)),
116 storage_.InternString(base::StringView(key.key)),
117 Variadic::Boolean(value));
118 }
AddJson(const Key & key,const protozero::ConstChars & value)119 bool AddJson(const Key& key, const protozero::ConstChars& value) final {
120 auto json_value = json::ParseJsonString(value);
121 if (!json_value)
122 return false;
123 return json::AddJsonValueToArgs(*json_value, base::StringView(key.flat_key),
124 base::StringView(key.key), &storage_,
125 &inserter_);
126 }
AddNull(const Key & key)127 void AddNull(const Key& key) final {
128 inserter_.AddArg(storage_.InternString(base::StringView(key.flat_key)),
129 storage_.InternString(base::StringView(key.key)),
130 Variadic::Null());
131 }
132
GetArrayEntryIndex(const std::string & array_key)133 size_t GetArrayEntryIndex(const std::string& array_key) final {
134 return inserter_.GetNextArrayEntryIndex(
135 storage_.InternString(base::StringView(array_key)));
136 }
137
IncrementArrayEntryIndex(const std::string & array_key)138 size_t IncrementArrayEntryIndex(const std::string& array_key) final {
139 return inserter_.IncrementArrayEntryIndex(
140 storage_.InternString(base::StringView(array_key)));
141 }
142
GetInternedMessageView(uint32_t field_id,uint64_t iid)143 InternedMessageView* GetInternedMessageView(uint32_t field_id,
144 uint64_t iid) final {
145 return sequence_state_.GetInternedMessageView(field_id, iid);
146 }
147
148 private:
149 BoundInserter& inserter_;
150 TraceStorage& storage_;
151 PacketSequenceStateGeneration& sequence_state_;
152 ArgsTranslationTable& args_translation_table_;
153 };
154
155 TrackEventArgsParser::~TrackEventArgsParser() = default;
156
MaybeParseSourceLocation(std::string prefix,const protozero::Field & field,util::ProtoToArgsParser::Delegate & delegate)157 base::Optional<base::Status> MaybeParseSourceLocation(
158 std::string prefix,
159 const protozero::Field& field,
160 util::ProtoToArgsParser::Delegate& delegate) {
161 auto* decoder = delegate.GetInternedMessage(
162 protos::pbzero::InternedData::kSourceLocations, field.as_uint64());
163 if (!decoder) {
164 // Lookup failed fall back on default behaviour which will just put
165 // the source_location_iid into the args table.
166 return base::nullopt;
167 }
168
169 delegate.AddString(util::ProtoToArgsParser::Key(prefix + ".file_name"),
170 decoder->file_name());
171 delegate.AddString(util::ProtoToArgsParser::Key(prefix + ".function_name"),
172 decoder->function_name());
173 delegate.AddInteger(util::ProtoToArgsParser::Key(prefix + ".line_number"),
174 decoder->line_number());
175
176 return base::OkStatus();
177 }
178
179 } // namespace
180
181 class TrackEventParser::EventImporter {
182 public:
EventImporter(TrackEventParser * parser,int64_t ts,TrackEventData * event_data,ConstBytes blob)183 EventImporter(TrackEventParser* parser,
184 int64_t ts,
185 TrackEventData* event_data,
186 ConstBytes blob)
187 : context_(parser->context_),
188 track_event_tracker_(parser->track_event_tracker_),
189 storage_(context_->storage.get()),
190 parser_(parser),
191 ts_(ts),
192 event_data_(event_data),
193 sequence_state_(event_data->sequence_state.get()),
194 blob_(std::move(blob)),
195 event_(blob_),
196 legacy_event_(event_.legacy_event()),
197 defaults_(event_data->sequence_state->GetTrackEventDefaults()) {}
198
Import()199 util::Status Import() {
200 // TODO(eseckler): This legacy event field will eventually be replaced by
201 // fields in TrackEvent itself.
202 if (PERFETTO_UNLIKELY(!event_.type() && !legacy_event_.has_phase()))
203 return util::ErrStatus("TrackEvent without type or phase");
204
205 category_id_ = ParseTrackEventCategory();
206 name_id_ = ParseTrackEventName();
207
208 RETURN_IF_ERROR(ParseTrackAssociation());
209
210 // Counter-type events don't support arguments (those are on the
211 // CounterDescriptor instead). All they have is a |{double_,}counter_value|.
212 if (event_.type() == TrackEvent::TYPE_COUNTER) {
213 ParseCounterEvent();
214 return util::OkStatus();
215 }
216
217 // If we have legacy thread time / instruction count fields, also parse them
218 // into the counters tables.
219 ParseLegacyThreadTimeAndInstructionsAsCounters();
220
221 // Parse extra counter values before parsing the actual event. This way, we
222 // can update the slice's thread time / instruction count fields based on
223 // these counter values and also parse them as slice attributes / arguments.
224 ParseExtraCounterValues();
225
226 // TODO(eseckler): Replace phase with type and remove handling of
227 // legacy_event_.phase() once it is no longer used by producers.
228 char phase = static_cast<char>(ParsePhaseOrType());
229
230 switch (phase) {
231 case 'B': // TRACE_EVENT_PHASE_BEGIN.
232 return ParseThreadBeginEvent();
233 case 'E': // TRACE_EVENT_PHASE_END.
234 return ParseThreadEndEvent();
235 case 'X': // TRACE_EVENT_PHASE_COMPLETE.
236 return ParseThreadCompleteEvent();
237 case 's': // TRACE_EVENT_PHASE_FLOW_BEGIN.
238 case 't': // TRACE_EVENT_PHASE_FLOW_STEP.
239 case 'f': // TRACE_EVENT_PHASE_FLOW_END.
240 return ParseFlowEventV1(phase);
241 case 'i':
242 case 'I': // TRACE_EVENT_PHASE_INSTANT.
243 case 'R': // TRACE_EVENT_PHASE_MARK.
244 return ParseThreadInstantEvent(phase);
245 case 'b': // TRACE_EVENT_PHASE_NESTABLE_ASYNC_BEGIN
246 case 'S':
247 return ParseAsyncBeginEvent(phase);
248 case 'e': // TRACE_EVENT_PHASE_NESTABLE_ASYNC_END
249 case 'F':
250 return ParseAsyncEndEvent();
251 case 'n': // TRACE_EVENT_PHASE_NESTABLE_ASYNC_INSTANT
252 return ParseAsyncInstantEvent();
253 case 'T':
254 case 'p':
255 return ParseAsyncStepEvent(phase);
256 case 'M': // TRACE_EVENT_PHASE_METADATA (process and thread names).
257 return ParseMetadataEvent();
258 default:
259 // Other events are proxied via the raw table for JSON export.
260 return ParseLegacyEventAsRawEvent();
261 }
262 }
263
264 private:
ParseTrackEventCategory()265 StringId ParseTrackEventCategory() {
266 StringId category_id = kNullStringId;
267
268 std::vector<uint64_t> category_iids;
269 for (auto it = event_.category_iids(); it; ++it) {
270 category_iids.push_back(*it);
271 }
272 std::vector<protozero::ConstChars> category_strings;
273 for (auto it = event_.categories(); it; ++it) {
274 category_strings.push_back(*it);
275 }
276
277 // If there's a single category, we can avoid building a concatenated
278 // string.
279 if (PERFETTO_LIKELY(category_iids.size() == 1 &&
280 category_strings.empty())) {
281 auto* decoder = sequence_state_->LookupInternedMessage<
282 protos::pbzero::InternedData::kEventCategoriesFieldNumber,
283 protos::pbzero::EventCategory>(category_iids[0]);
284 if (decoder) {
285 category_id = storage_->InternString(decoder->name());
286 } else {
287 char buffer[32];
288 base::StringWriter writer(buffer, sizeof(buffer));
289 writer.AppendLiteral("unknown(");
290 writer.AppendUnsignedInt(category_iids[0]);
291 writer.AppendChar(')');
292 category_id = storage_->InternString(writer.GetStringView());
293 }
294 } else if (category_iids.empty() && category_strings.size() == 1) {
295 category_id = storage_->InternString(category_strings[0]);
296 } else if (category_iids.size() + category_strings.size() > 1) {
297 // We concatenate the category strings together since we currently only
298 // support a single "cat" column.
299 // TODO(eseckler): Support multi-category events in the table schema.
300 std::string categories;
301 for (uint64_t iid : category_iids) {
302 auto* decoder = sequence_state_->LookupInternedMessage<
303 protos::pbzero::InternedData::kEventCategoriesFieldNumber,
304 protos::pbzero::EventCategory>(iid);
305 if (!decoder)
306 continue;
307 base::StringView name = decoder->name();
308 if (!categories.empty())
309 categories.append(",");
310 categories.append(name.data(), name.size());
311 }
312 for (const protozero::ConstChars& cat : category_strings) {
313 if (!categories.empty())
314 categories.append(",");
315 categories.append(cat.data, cat.size);
316 }
317 if (!categories.empty())
318 category_id = storage_->InternString(base::StringView(categories));
319 }
320
321 return category_id;
322 }
323
ParseTrackEventName()324 StringId ParseTrackEventName() {
325 uint64_t name_iid = event_.name_iid();
326 if (!name_iid)
327 name_iid = legacy_event_.name_iid();
328
329 if (PERFETTO_LIKELY(name_iid)) {
330 auto* decoder = sequence_state_->LookupInternedMessage<
331 protos::pbzero::InternedData::kEventNamesFieldNumber,
332 protos::pbzero::EventName>(name_iid);
333 if (decoder)
334 return storage_->InternString(decoder->name());
335 } else if (event_.has_name()) {
336 return storage_->InternString(event_.name());
337 }
338
339 return kNullStringId;
340 }
341
ParseTrackAssociation()342 util::Status ParseTrackAssociation() {
343 TrackTracker* track_tracker = context_->track_tracker.get();
344 ProcessTracker* procs = context_->process_tracker.get();
345
346 // Consider track_uuid from the packet and TrackEventDefaults, fall back to
347 // the default descriptor track (uuid 0).
348 track_uuid_ = event_.has_track_uuid()
349 ? event_.track_uuid()
350 : (defaults_ && defaults_->has_track_uuid()
351 ? defaults_->track_uuid()
352 : 0u);
353
354 // Determine track from track_uuid specified in either TrackEvent or
355 // TrackEventDefaults. If a non-default track is not set, we either:
356 // a) fall back to the track specified by the sequence's (or event's) pid
357 // + tid (only in case of legacy tracks/events, i.e. events that don't
358 // specify an explicit track uuid or use legacy event phases instead of
359 // TrackEvent types), or
360 // b) a default track.
361 if (track_uuid_) {
362 base::Optional<TrackId> opt_track_id =
363 track_event_tracker_->GetDescriptorTrack(track_uuid_, name_id_);
364 if (!opt_track_id) {
365 track_event_tracker_->ReserveDescriptorChildTrack(track_uuid_,
366 /*parent_uuid=*/0,
367 name_id_);
368 opt_track_id =
369 track_event_tracker_->GetDescriptorTrack(track_uuid_, name_id_);
370 }
371 track_id_ = *opt_track_id;
372
373 auto thread_track_row =
374 storage_->thread_track_table().id().IndexOf(track_id_);
375 if (thread_track_row) {
376 utid_ = storage_->thread_track_table().utid()[*thread_track_row];
377 upid_ = storage_->thread_table().upid()[*utid_];
378 } else {
379 auto process_track_row =
380 storage_->process_track_table().id().IndexOf(track_id_);
381 if (process_track_row) {
382 upid_ = storage_->process_track_table().upid()[*process_track_row];
383 if (sequence_state_->state()->pid_and_tid_valid()) {
384 uint32_t pid =
385 static_cast<uint32_t>(sequence_state_->state()->pid());
386 uint32_t tid =
387 static_cast<uint32_t>(sequence_state_->state()->tid());
388 UniqueTid utid_candidate = procs->UpdateThread(tid, pid);
389 if (storage_->thread_table().upid()[utid_candidate] == upid_)
390 legacy_passthrough_utid_ = utid_candidate;
391 }
392 } else {
393 auto* tracks = context_->storage->mutable_track_table();
394 auto track_index = tracks->id().IndexOf(track_id_);
395 if (track_index) {
396 const StringPool::Id& id = tracks->name()[*track_index];
397 if (id.is_null())
398 tracks->mutable_name()->Set(*track_index, name_id_);
399 }
400
401 if (sequence_state_->state()->pid_and_tid_valid()) {
402 uint32_t pid =
403 static_cast<uint32_t>(sequence_state_->state()->pid());
404 uint32_t tid =
405 static_cast<uint32_t>(sequence_state_->state()->tid());
406 legacy_passthrough_utid_ = procs->UpdateThread(tid, pid);
407 }
408 }
409 }
410 } else {
411 bool pid_tid_state_valid = sequence_state_->state()->pid_and_tid_valid();
412
413 // We have a 0-value |track_uuid|. Nevertheless, we should only fall back
414 // if we have either no |track_uuid| specified at all or |track_uuid| was
415 // set explicitly to 0 (e.g. to override a default track_uuid) and we have
416 // a legacy phase. Events with real phases should use |track_uuid| to
417 // specify a different track (or use the pid/tid_override fields).
418 bool fallback_to_legacy_pid_tid_tracks =
419 (!event_.has_track_uuid() || !event_.has_type()) &&
420 pid_tid_state_valid;
421
422 // Always allow fallback if we have a process override.
423 fallback_to_legacy_pid_tid_tracks |= legacy_event_.has_pid_override();
424
425 // A thread override requires a valid pid.
426 fallback_to_legacy_pid_tid_tracks |=
427 legacy_event_.has_tid_override() && pid_tid_state_valid;
428
429 if (fallback_to_legacy_pid_tid_tracks) {
430 uint32_t pid = static_cast<uint32_t>(sequence_state_->state()->pid());
431 uint32_t tid = static_cast<uint32_t>(sequence_state_->state()->tid());
432 if (legacy_event_.has_pid_override()) {
433 pid = static_cast<uint32_t>(legacy_event_.pid_override());
434 tid = static_cast<uint32_t>(-1);
435 }
436 if (legacy_event_.has_tid_override())
437 tid = static_cast<uint32_t>(legacy_event_.tid_override());
438
439 utid_ = procs->UpdateThread(tid, pid);
440 upid_ = storage_->thread_table().upid()[*utid_];
441 track_id_ = track_tracker->InternThreadTrack(*utid_);
442 } else {
443 track_id_ = track_event_tracker_->GetOrCreateDefaultDescriptorTrack();
444 }
445 }
446
447 if (!legacy_event_.has_phase())
448 return util::OkStatus();
449
450 // Legacy phases may imply a different track than the one specified by
451 // the fallback (or default track uuid) above.
452 switch (legacy_event_.phase()) {
453 case 'b':
454 case 'e':
455 case 'n':
456 case 'S':
457 case 'T':
458 case 'p':
459 case 'F': {
460 // Intern tracks for legacy async events based on legacy event ids.
461 int64_t source_id = 0;
462 bool source_id_is_process_scoped = false;
463 if (legacy_event_.has_unscoped_id()) {
464 source_id = static_cast<int64_t>(legacy_event_.unscoped_id());
465 } else if (legacy_event_.has_global_id()) {
466 source_id = static_cast<int64_t>(legacy_event_.global_id());
467 } else if (legacy_event_.has_local_id()) {
468 if (!upid_) {
469 return util::ErrStatus(
470 "TrackEvent with local_id without process association");
471 }
472
473 source_id = static_cast<int64_t>(legacy_event_.local_id());
474 source_id_is_process_scoped = true;
475 } else {
476 return util::ErrStatus("Async LegacyEvent without ID");
477 }
478
479 // Catapult treats nestable async events of different categories with
480 // the same ID as separate tracks. We replicate the same behavior
481 // here. For legacy async events, it uses different tracks based on
482 // event names.
483 const bool legacy_async =
484 legacy_event_.phase() == 'S' || legacy_event_.phase() == 'T' ||
485 legacy_event_.phase() == 'p' || legacy_event_.phase() == 'F';
486 StringId id_scope = legacy_async ? name_id_ : category_id_;
487 if (legacy_event_.has_id_scope()) {
488 std::string concat = storage_->GetString(category_id_).ToStdString() +
489 ":" + legacy_event_.id_scope().ToStdString();
490 id_scope = storage_->InternString(base::StringView(concat));
491 }
492
493 track_id_ = context_->track_tracker->InternLegacyChromeAsyncTrack(
494 name_id_, upid_ ? *upid_ : 0, source_id,
495 source_id_is_process_scoped, id_scope);
496 legacy_passthrough_utid_ = utid_;
497 break;
498 }
499 case 'i':
500 case 'I': {
501 // Intern tracks for global or process-scoped legacy instant events.
502 switch (legacy_event_.instant_event_scope()) {
503 case LegacyEvent::SCOPE_UNSPECIFIED:
504 case LegacyEvent::SCOPE_THREAD:
505 // Thread-scoped legacy instant events already have the right
506 // track based on the tid/pid of the sequence.
507 if (!utid_) {
508 return util::ErrStatus(
509 "Thread-scoped instant event without thread association");
510 }
511 break;
512 case LegacyEvent::SCOPE_GLOBAL:
513 track_id_ = context_->track_tracker
514 ->GetOrCreateLegacyChromeGlobalInstantTrack();
515 legacy_passthrough_utid_ = utid_;
516 utid_ = base::nullopt;
517 break;
518 case LegacyEvent::SCOPE_PROCESS:
519 if (!upid_) {
520 return util::ErrStatus(
521 "Process-scoped instant event without process association");
522 }
523
524 track_id_ =
525 context_->track_tracker->InternLegacyChromeProcessInstantTrack(
526 *upid_);
527 legacy_passthrough_utid_ = utid_;
528 utid_ = base::nullopt;
529 break;
530 }
531 break;
532 }
533 default:
534 break;
535 }
536
537 return util::OkStatus();
538 }
539
ParsePhaseOrType()540 int32_t ParsePhaseOrType() {
541 if (legacy_event_.has_phase())
542 return legacy_event_.phase();
543
544 switch (event_.type()) {
545 case TrackEvent::TYPE_SLICE_BEGIN:
546 return utid_ ? 'B' : 'b';
547 case TrackEvent::TYPE_SLICE_END:
548 return utid_ ? 'E' : 'e';
549 case TrackEvent::TYPE_INSTANT:
550 return utid_ ? 'i' : 'n';
551 default:
552 PERFETTO_ELOG("unexpected event type %d", event_.type());
553 return 0;
554 }
555 }
556
ParseCounterEvent()557 void ParseCounterEvent() {
558 // Tokenizer ensures that TYPE_COUNTER events are associated with counter
559 // tracks and have values.
560 PERFETTO_DCHECK(storage_->counter_track_table().id().IndexOf(track_id_));
561 PERFETTO_DCHECK(event_.has_counter_value() ||
562 event_.has_double_counter_value());
563
564 context_->event_tracker->PushCounter(
565 ts_, static_cast<double>(event_data_->counter_value), track_id_);
566 }
567
ParseLegacyThreadTimeAndInstructionsAsCounters()568 void ParseLegacyThreadTimeAndInstructionsAsCounters() {
569 if (!utid_)
570 return;
571 // When these fields are set, we don't expect TrackDescriptor-based counters
572 // for thread time or instruction count for this thread in the trace, so we
573 // intern separate counter tracks based on name + utid. Note that we cannot
574 // import the counter values from the end of a complete event, because the
575 // EventTracker expects counters to be pushed in order of their timestamps.
576 // One more reason to switch to split begin/end events.
577 if (event_data_->thread_timestamp) {
578 TrackId track_id = context_->track_tracker->InternThreadCounterTrack(
579 parser_->counter_name_thread_time_id_, *utid_);
580 context_->event_tracker->PushCounter(
581 ts_, static_cast<double>(*event_data_->thread_timestamp), track_id);
582 }
583 if (event_data_->thread_instruction_count) {
584 TrackId track_id = context_->track_tracker->InternThreadCounterTrack(
585 parser_->counter_name_thread_instruction_count_id_, *utid_);
586 context_->event_tracker->PushCounter(
587 ts_, static_cast<double>(*event_data_->thread_instruction_count),
588 track_id);
589 }
590 }
591
ParseExtraCounterValues()592 void ParseExtraCounterValues() {
593 if (!event_.has_extra_counter_values() &&
594 !event_.has_extra_double_counter_values()) {
595 return;
596 }
597
598 // Add integer extra counter values.
599 size_t index = 0;
600 protozero::RepeatedFieldIterator<uint64_t> track_uuid_it;
601 if (event_.has_extra_counter_track_uuids()) {
602 track_uuid_it = event_.extra_counter_track_uuids();
603 } else if (defaults_ && defaults_->has_extra_counter_track_uuids()) {
604 track_uuid_it = defaults_->extra_counter_track_uuids();
605 }
606 for (auto value_it = event_.extra_counter_values(); value_it;
607 ++value_it, ++track_uuid_it, ++index) {
608 AddExtraCounterValue(track_uuid_it, index);
609 }
610
611 // Add double extra counter values.
612 track_uuid_it = protozero::RepeatedFieldIterator<uint64_t>();
613 if (event_.has_extra_double_counter_track_uuids()) {
614 track_uuid_it = event_.extra_double_counter_track_uuids();
615 } else if (defaults_ && defaults_->has_extra_double_counter_track_uuids()) {
616 track_uuid_it = defaults_->extra_double_counter_track_uuids();
617 }
618 for (auto value_it = event_.extra_double_counter_values(); value_it;
619 ++value_it, ++track_uuid_it, ++index) {
620 AddExtraCounterValue(track_uuid_it, index);
621 }
622 }
623
AddExtraCounterValue(protozero::RepeatedFieldIterator<uint64_t> track_uuid_it,size_t index)624 void AddExtraCounterValue(
625 protozero::RepeatedFieldIterator<uint64_t> track_uuid_it,
626 size_t index) {
627 // Tokenizer ensures that there aren't more values than uuids, that we
628 // don't have more values than kMaxNumExtraCounters and that the
629 // track_uuids are for valid counter tracks.
630 PERFETTO_DCHECK(track_uuid_it);
631 PERFETTO_DCHECK(index < TrackEventData::kMaxNumExtraCounters);
632
633 base::Optional<TrackId> track_id =
634 track_event_tracker_->GetDescriptorTrack(*track_uuid_it);
635 base::Optional<uint32_t> counter_row =
636 storage_->counter_track_table().id().IndexOf(*track_id);
637
638 double value = event_data_->extra_counter_values[index];
639 context_->event_tracker->PushCounter(ts_, value, *track_id);
640
641 // Also import thread_time and thread_instruction_count counters into
642 // slice columns to simplify JSON export.
643 StringId counter_name =
644 storage_->counter_track_table().name()[*counter_row];
645 if (counter_name == parser_->counter_name_thread_time_id_) {
646 event_data_->thread_timestamp = static_cast<int64_t>(value);
647 } else if (counter_name ==
648 parser_->counter_name_thread_instruction_count_id_) {
649 event_data_->thread_instruction_count = static_cast<int64_t>(value);
650 }
651 }
652
ParseThreadBeginEvent()653 util::Status ParseThreadBeginEvent() {
654 if (!utid_) {
655 return util::ErrStatus(
656 "TrackEvent with phase B without thread association");
657 }
658
659 auto* thread_slices = storage_->mutable_thread_slice_table();
660 auto opt_slice_id = context_->slice_tracker->BeginTyped(
661 thread_slices, MakeThreadSliceRow(),
662 [this](BoundInserter* inserter) { ParseTrackEventArgs(inserter); });
663
664 if (opt_slice_id.has_value()) {
665 MaybeParseFlowEvents(opt_slice_id.value());
666 }
667
668 return util::OkStatus();
669 }
670
ParseThreadEndEvent()671 util::Status ParseThreadEndEvent() {
672 if (!utid_) {
673 return util::ErrStatus(
674 "TrackEvent with phase E without thread association");
675 }
676
677 auto opt_slice_id = context_->slice_tracker->End(
678 ts_, track_id_, category_id_, name_id_,
679 [this](BoundInserter* inserter) { ParseTrackEventArgs(inserter); });
680 if (opt_slice_id.has_value()) {
681 auto* thread_slices = storage_->mutable_thread_slice_table();
682 auto maybe_row = thread_slices->id().IndexOf(*opt_slice_id);
683 PERFETTO_DCHECK(maybe_row.has_value());
684 auto tts = thread_slices->thread_ts()[*maybe_row];
685 if (tts) {
686 PERFETTO_DCHECK(event_data_->thread_timestamp);
687 thread_slices->mutable_thread_dur()->Set(
688 *maybe_row, *event_data_->thread_timestamp - *tts);
689 }
690 auto tic = thread_slices->thread_instruction_count()[*maybe_row];
691 if (tic) {
692 PERFETTO_DCHECK(event_data_->thread_instruction_count);
693 thread_slices->mutable_thread_instruction_delta()->Set(
694 *maybe_row, *event_data_->thread_instruction_count - *tic);
695 }
696 MaybeParseFlowEvents(opt_slice_id.value());
697 }
698
699 return util::OkStatus();
700 }
701
ParseThreadCompleteEvent()702 util::Status ParseThreadCompleteEvent() {
703 if (!utid_) {
704 return util::ErrStatus(
705 "TrackEvent with phase X without thread association");
706 }
707
708 auto duration_ns = legacy_event_.duration_us() * 1000;
709 if (duration_ns < 0)
710 return util::ErrStatus("TrackEvent with phase X with negative duration");
711
712 auto* thread_slices = storage_->mutable_thread_slice_table();
713 tables::ThreadSliceTable::Row row = MakeThreadSliceRow();
714 row.dur = duration_ns;
715 if (legacy_event_.has_thread_duration_us()) {
716 row.thread_dur = legacy_event_.thread_duration_us() * 1000;
717 }
718 if (legacy_event_.has_thread_instruction_delta()) {
719 row.thread_instruction_delta = legacy_event_.thread_instruction_delta();
720 }
721 auto opt_slice_id = context_->slice_tracker->ScopedTyped(
722 thread_slices, std::move(row),
723 [this](BoundInserter* inserter) { ParseTrackEventArgs(inserter); });
724
725 if (opt_slice_id.has_value()) {
726 MaybeParseFlowEvents(opt_slice_id.value());
727 }
728
729 return util::OkStatus();
730 }
731
GetLegacyEventId()732 base::Optional<uint64_t> GetLegacyEventId() {
733 if (legacy_event_.has_unscoped_id())
734 return legacy_event_.unscoped_id();
735 // TODO(andrewbb): Catapult doesn't support global_id and local_id on flow
736 // events. We could add support in trace processor (e.g. because there seem
737 // to be some callsites supplying local_id in chromium), but we would have
738 // to consider the process ID for local IDs and use a separate ID scope for
739 // global_id and unscoped_id.
740 return base::nullopt;
741 }
742
ParseFlowEventV1(char phase)743 util::Status ParseFlowEventV1(char phase) {
744 auto opt_source_id = GetLegacyEventId();
745 if (!opt_source_id) {
746 storage_->IncrementStats(stats::flow_invalid_id);
747 return util::ErrStatus("Invalid id for flow event v1");
748 }
749 FlowId flow_id = context_->flow_tracker->GetFlowIdForV1Event(
750 opt_source_id.value(), category_id_, name_id_);
751 switch (phase) {
752 case 's':
753 context_->flow_tracker->Begin(track_id_, flow_id);
754 break;
755 case 't':
756 context_->flow_tracker->Step(track_id_, flow_id);
757 break;
758 case 'f':
759 context_->flow_tracker->End(track_id_, flow_id,
760 legacy_event_.bind_to_enclosing(),
761 /* close_flow = */ false);
762 break;
763 }
764 return util::OkStatus();
765 }
766
MaybeParseTrackEventFlows(SliceId slice_id)767 void MaybeParseTrackEventFlows(SliceId slice_id) {
768 if (event_.has_flow_ids()) {
769 auto it = event_.flow_ids();
770 for (; it; ++it) {
771 FlowId flow_id = *it;
772 if (!context_->flow_tracker->IsActive(flow_id)) {
773 context_->flow_tracker->Begin(slice_id, flow_id);
774 continue;
775 }
776 context_->flow_tracker->Step(slice_id, flow_id);
777 }
778 }
779 if (event_.has_terminating_flow_ids()) {
780 auto it = event_.terminating_flow_ids();
781 for (; it; ++it) {
782 FlowId flow_id = *it;
783 if (!context_->flow_tracker->IsActive(flow_id)) {
784 // If we should terminate a flow, do not begin a new one if it's not
785 // active already.
786 continue;
787 }
788 context_->flow_tracker->End(slice_id, flow_id,
789 /* close_flow = */ true);
790 }
791 }
792 }
793
MaybeParseFlowEventV2(SliceId slice_id)794 void MaybeParseFlowEventV2(SliceId slice_id) {
795 if (!legacy_event_.has_bind_id()) {
796 return;
797 }
798 if (!legacy_event_.has_flow_direction()) {
799 storage_->IncrementStats(stats::flow_without_direction);
800 return;
801 }
802
803 auto bind_id = legacy_event_.bind_id();
804 switch (legacy_event_.flow_direction()) {
805 case LegacyEvent::FLOW_OUT:
806 context_->flow_tracker->Begin(slice_id, bind_id);
807 break;
808 case LegacyEvent::FLOW_INOUT:
809 context_->flow_tracker->Step(slice_id, bind_id);
810 break;
811 case LegacyEvent::FLOW_IN:
812 context_->flow_tracker->End(slice_id, bind_id,
813 /* close_flow = */ false);
814 break;
815 default:
816 storage_->IncrementStats(stats::flow_without_direction);
817 }
818 }
819
MaybeParseFlowEvents(SliceId slice_id)820 void MaybeParseFlowEvents(SliceId slice_id) {
821 MaybeParseFlowEventV2(slice_id);
822 MaybeParseTrackEventFlows(slice_id);
823 }
824
ParseThreadInstantEvent(char phase)825 util::Status ParseThreadInstantEvent(char phase) {
826 // Handle instant events as slices with zero duration, so that they end
827 // up nested underneath their parent slices.
828 int64_t duration_ns = 0;
829 int64_t tidelta = 0;
830 base::Optional<tables::SliceTable::Id> opt_slice_id;
831 auto args_inserter = [this, phase](BoundInserter* inserter) {
832 ParseTrackEventArgs(inserter);
833 // For legacy MARK event, add phase for JSON exporter.
834 if (phase == 'R') {
835 std::string phase_string(1, static_cast<char>(phase));
836 StringId phase_id = storage_->InternString(phase_string.c_str());
837 inserter->AddArg(parser_->legacy_event_phase_key_id_,
838 Variadic::String(phase_id));
839 }
840 };
841 if (utid_) {
842 auto* thread_slices = storage_->mutable_thread_slice_table();
843 tables::ThreadSliceTable::Row row = MakeThreadSliceRow();
844 row.dur = duration_ns;
845 if (event_data_->thread_timestamp) {
846 row.thread_dur = duration_ns;
847 }
848 if (event_data_->thread_instruction_count) {
849 row.thread_instruction_delta = tidelta;
850 }
851 opt_slice_id = context_->slice_tracker->ScopedTyped(
852 thread_slices, row, std::move(args_inserter));
853 } else {
854 opt_slice_id = context_->slice_tracker->Scoped(
855 ts_, track_id_, category_id_, name_id_, duration_ns,
856 std::move(args_inserter));
857 }
858 if (!opt_slice_id.has_value()) {
859 return util::OkStatus();
860 }
861 MaybeParseFlowEvents(opt_slice_id.value());
862 return util::OkStatus();
863 }
864
ParseAsyncBeginEvent(char phase)865 util::Status ParseAsyncBeginEvent(char phase) {
866 auto args_inserter = [this, phase](BoundInserter* inserter) {
867 ParseTrackEventArgs(inserter);
868
869 if (phase == 'b')
870 return;
871 PERFETTO_DCHECK(phase == 'S');
872 // For legacy ASYNC_BEGIN, add phase for JSON exporter.
873 std::string phase_string(1, static_cast<char>(phase));
874 StringId phase_id = storage_->InternString(phase_string.c_str());
875 inserter->AddArg(parser_->legacy_event_phase_key_id_,
876 Variadic::String(phase_id));
877 };
878 auto opt_slice_id = context_->slice_tracker->Begin(
879 ts_, track_id_, category_id_, name_id_, args_inserter);
880 if (!opt_slice_id.has_value()) {
881 return util::OkStatus();
882 }
883 MaybeParseFlowEvents(opt_slice_id.value());
884 // For the time being, we only create vtrack slice rows if we need to
885 // store thread timestamps/counters.
886 if (legacy_event_.use_async_tts()) {
887 auto* vtrack_slices = storage_->mutable_virtual_track_slices();
888 PERFETTO_DCHECK(!vtrack_slices->slice_count() ||
889 vtrack_slices->slice_ids().back() < opt_slice_id.value());
890 int64_t tts =
891 event_data_->thread_timestamp ? *event_data_->thread_timestamp : 0;
892 int64_t tic = event_data_->thread_instruction_count
893 ? *event_data_->thread_instruction_count
894 : 0;
895 vtrack_slices->AddVirtualTrackSlice(opt_slice_id.value(), tts,
896 kPendingThreadDuration, tic,
897 kPendingThreadInstructionDelta);
898 }
899 return util::OkStatus();
900 }
901
ParseAsyncEndEvent()902 util::Status ParseAsyncEndEvent() {
903 auto opt_slice_id = context_->slice_tracker->End(
904 ts_, track_id_, category_id_, name_id_,
905 [this](BoundInserter* inserter) { ParseTrackEventArgs(inserter); });
906 if (!opt_slice_id.has_value())
907 return util::OkStatus();
908 MaybeParseFlowEvents(opt_slice_id.value());
909 if (legacy_event_.use_async_tts()) {
910 auto* vtrack_slices = storage_->mutable_virtual_track_slices();
911 int64_t tts =
912 event_data_->thread_timestamp ? *event_data_->thread_timestamp : 0;
913 int64_t tic = event_data_->thread_instruction_count
914 ? *event_data_->thread_instruction_count
915 : 0;
916 vtrack_slices->UpdateThreadDeltasForSliceId(opt_slice_id.value(), tts,
917 tic);
918 }
919 return util::OkStatus();
920 }
921
ParseAsyncStepEvent(char phase)922 util::Status ParseAsyncStepEvent(char phase) {
923 // Parse step events as instant events. Reconstructing the begin/end times
924 // of the child slice would be too complicated, see b/178540838. For JSON
925 // export, we still record the original step's phase in an arg.
926 int64_t duration_ns = 0;
927 context_->slice_tracker->Scoped(
928 ts_, track_id_, category_id_, name_id_, duration_ns,
929 [this, phase](BoundInserter* inserter) {
930 ParseTrackEventArgs(inserter);
931
932 PERFETTO_DCHECK(phase == 'T' || phase == 'p');
933 std::string phase_string(1, static_cast<char>(phase));
934 StringId phase_id = storage_->InternString(phase_string.c_str());
935 inserter->AddArg(parser_->legacy_event_phase_key_id_,
936 Variadic::String(phase_id));
937 });
938 // Step events don't support thread timestamps, so no need to add a row to
939 // virtual_track_slices.
940 return util::OkStatus();
941 }
942
ParseAsyncInstantEvent()943 util::Status ParseAsyncInstantEvent() {
944 // Handle instant events as slices with zero duration, so that they end
945 // up nested underneath their parent slices.
946 int64_t duration_ns = 0;
947 int64_t tidelta = 0;
948 auto opt_slice_id = context_->slice_tracker->Scoped(
949 ts_, track_id_, category_id_, name_id_, duration_ns,
950 [this](BoundInserter* inserter) { ParseTrackEventArgs(inserter); });
951 if (!opt_slice_id.has_value()) {
952 return util::OkStatus();
953 }
954 MaybeParseFlowEvents(opt_slice_id.value());
955 if (legacy_event_.use_async_tts()) {
956 auto* vtrack_slices = storage_->mutable_virtual_track_slices();
957 PERFETTO_DCHECK(!vtrack_slices->slice_count() ||
958 vtrack_slices->slice_ids().back() < opt_slice_id.value());
959 int64_t tts =
960 event_data_->thread_timestamp ? *event_data_->thread_timestamp : 0;
961 int64_t tic = event_data_->thread_instruction_count
962 ? *event_data_->thread_instruction_count
963 : 0;
964 vtrack_slices->AddVirtualTrackSlice(opt_slice_id.value(), tts,
965 duration_ns, tic, tidelta);
966 }
967 return util::OkStatus();
968 }
969
ParseMetadataEvent()970 util::Status ParseMetadataEvent() {
971 ProcessTracker* procs = context_->process_tracker.get();
972
973 if (name_id_ == kNullStringId)
974 return util::ErrStatus("Metadata event without name");
975
976 // Parse process and thread names from correspondingly named events.
977 NullTermStringView event_name = storage_->GetString(name_id_);
978 PERFETTO_DCHECK(event_name.data());
979 if (strcmp(event_name.c_str(), "thread_name") == 0) {
980 if (!utid_) {
981 return util::ErrStatus(
982 "thread_name metadata event without thread association");
983 }
984
985 auto it = event_.debug_annotations();
986 if (!it) {
987 return util::ErrStatus(
988 "thread_name metadata event without debug annotations");
989 }
990 protos::pbzero::DebugAnnotation::Decoder annotation(*it);
991 auto thread_name = annotation.string_value();
992 if (!thread_name.size)
993 return util::OkStatus();
994 auto thread_name_id = storage_->InternString(thread_name);
995 procs->UpdateThreadNameByUtid(
996 *utid_, thread_name_id,
997 ThreadNamePriority::kTrackDescriptorThreadType);
998 return util::OkStatus();
999 }
1000 if (strcmp(event_name.c_str(), "process_name") == 0) {
1001 if (!upid_) {
1002 return util::ErrStatus(
1003 "process_name metadata event without process association");
1004 }
1005
1006 auto it = event_.debug_annotations();
1007 if (!it) {
1008 return util::ErrStatus(
1009 "process_name metadata event without debug annotations");
1010 }
1011 protos::pbzero::DebugAnnotation::Decoder annotation(*it);
1012 auto process_name = annotation.string_value();
1013 if (!process_name.size)
1014 return util::OkStatus();
1015 auto process_name_id =
1016 storage_->InternString(base::StringView(process_name));
1017 // Don't override system-provided names.
1018 procs->SetProcessNameIfUnset(*upid_, process_name_id);
1019 return util::OkStatus();
1020 }
1021 // Other metadata events are proxied via the raw table for JSON export.
1022 ParseLegacyEventAsRawEvent();
1023 return util::OkStatus();
1024 }
1025
ParseLegacyEventAsRawEvent()1026 util::Status ParseLegacyEventAsRawEvent() {
1027 if (!utid_)
1028 return util::ErrStatus("raw legacy event without thread association");
1029
1030 RawId id = storage_->mutable_raw_table()
1031 ->Insert({ts_, parser_->raw_legacy_event_id_, 0, *utid_})
1032 .id;
1033
1034 ArgsTracker args(context_);
1035 auto inserter = args.AddArgsTo(id);
1036
1037 inserter
1038 .AddArg(parser_->legacy_event_category_key_id_,
1039 Variadic::String(category_id_))
1040 .AddArg(parser_->legacy_event_name_key_id_, Variadic::String(name_id_));
1041
1042 std::string phase_string(1, static_cast<char>(legacy_event_.phase()));
1043 StringId phase_id = storage_->InternString(phase_string.c_str());
1044 inserter.AddArg(parser_->legacy_event_phase_key_id_,
1045 Variadic::String(phase_id));
1046
1047 if (legacy_event_.has_duration_us()) {
1048 inserter.AddArg(parser_->legacy_event_duration_ns_key_id_,
1049 Variadic::Integer(legacy_event_.duration_us() * 1000));
1050 }
1051
1052 if (event_data_->thread_timestamp) {
1053 inserter.AddArg(parser_->legacy_event_thread_timestamp_ns_key_id_,
1054 Variadic::Integer(*event_data_->thread_timestamp));
1055 if (legacy_event_.has_thread_duration_us()) {
1056 inserter.AddArg(
1057 parser_->legacy_event_thread_duration_ns_key_id_,
1058 Variadic::Integer(legacy_event_.thread_duration_us() * 1000));
1059 }
1060 }
1061
1062 if (event_data_->thread_instruction_count) {
1063 inserter.AddArg(
1064 parser_->legacy_event_thread_instruction_count_key_id_,
1065 Variadic::Integer(*event_data_->thread_instruction_count));
1066 if (legacy_event_.has_thread_instruction_delta()) {
1067 inserter.AddArg(
1068 parser_->legacy_event_thread_instruction_delta_key_id_,
1069 Variadic::Integer(legacy_event_.thread_instruction_delta()));
1070 }
1071 }
1072
1073 if (legacy_event_.use_async_tts()) {
1074 inserter.AddArg(parser_->legacy_event_use_async_tts_key_id_,
1075 Variadic::Boolean(true));
1076 }
1077
1078 bool has_id = false;
1079 if (legacy_event_.has_unscoped_id()) {
1080 // Unscoped ids are either global or local depending on the phase. Pass
1081 // them through as unscoped IDs to JSON export to preserve this behavior.
1082 inserter.AddArg(parser_->legacy_event_unscoped_id_key_id_,
1083 Variadic::UnsignedInteger(legacy_event_.unscoped_id()));
1084 has_id = true;
1085 } else if (legacy_event_.has_global_id()) {
1086 inserter.AddArg(parser_->legacy_event_global_id_key_id_,
1087 Variadic::UnsignedInteger(legacy_event_.global_id()));
1088 has_id = true;
1089 } else if (legacy_event_.has_local_id()) {
1090 inserter.AddArg(parser_->legacy_event_local_id_key_id_,
1091 Variadic::UnsignedInteger(legacy_event_.local_id()));
1092 has_id = true;
1093 }
1094
1095 if (has_id && legacy_event_.has_id_scope() &&
1096 legacy_event_.id_scope().size) {
1097 inserter.AddArg(
1098 parser_->legacy_event_id_scope_key_id_,
1099 Variadic::String(storage_->InternString(legacy_event_.id_scope())));
1100 }
1101
1102 // No need to parse legacy_event.instant_event_scope() because we import
1103 // instant events into the slice table.
1104
1105 ParseTrackEventArgs(&inserter);
1106 return util::OkStatus();
1107 }
1108
ParseTrackEventArgs(BoundInserter * inserter)1109 void ParseTrackEventArgs(BoundInserter* inserter) {
1110 auto log_errors = [this](util::Status status) {
1111 if (status.ok())
1112 return;
1113 // Log error but continue parsing the other args.
1114 storage_->IncrementStats(stats::track_event_parser_errors);
1115 PERFETTO_DLOG("ParseTrackEventArgs error: %s", status.c_message());
1116 };
1117
1118 if (event_.has_source_location_iid()) {
1119 log_errors(AddSourceLocationArgs(event_.source_location_iid(), inserter));
1120 }
1121
1122 if (event_.has_task_execution()) {
1123 log_errors(ParseTaskExecutionArgs(event_.task_execution(), inserter));
1124 }
1125 if (event_.has_log_message()) {
1126 log_errors(ParseLogMessage(event_.log_message(), inserter));
1127 }
1128 if (event_.has_chrome_histogram_sample()) {
1129 log_errors(
1130 ParseHistogramName(event_.chrome_histogram_sample(), inserter));
1131 }
1132
1133 TrackEventArgsParser args_writer(*inserter, *storage_, *sequence_state_,
1134 *context_->args_translation_table);
1135 int unknown_extensions = 0;
1136 log_errors(parser_->args_parser_.ParseMessage(
1137 blob_, ".perfetto.protos.TrackEvent", &parser_->reflect_fields_,
1138 args_writer, &unknown_extensions));
1139 if (unknown_extensions > 0) {
1140 context_->storage->IncrementStats(stats::unknown_extension_fields,
1141 unknown_extensions);
1142 }
1143
1144 {
1145 auto key = parser_->args_parser_.EnterDictionary("debug");
1146 util::DebugAnnotationParser parser(parser_->args_parser_);
1147 for (auto it = event_.debug_annotations(); it; ++it) {
1148 log_errors(parser.Parse(*it, args_writer));
1149 }
1150 }
1151
1152 if (legacy_passthrough_utid_) {
1153 inserter->AddArg(parser_->legacy_event_passthrough_utid_id_,
1154 Variadic::UnsignedInteger(*legacy_passthrough_utid_),
1155 ArgsTracker::UpdatePolicy::kSkipIfExists);
1156 }
1157 }
1158
ParseTaskExecutionArgs(ConstBytes task_execution,BoundInserter * inserter)1159 util::Status ParseTaskExecutionArgs(ConstBytes task_execution,
1160 BoundInserter* inserter) {
1161 protos::pbzero::TaskExecution::Decoder task(task_execution);
1162 uint64_t iid = task.posted_from_iid();
1163 if (!iid)
1164 return util::ErrStatus("TaskExecution with invalid posted_from_iid");
1165
1166 auto* decoder = sequence_state_->LookupInternedMessage<
1167 protos::pbzero::InternedData::kSourceLocationsFieldNumber,
1168 protos::pbzero::SourceLocation>(iid);
1169 if (!decoder)
1170 return util::ErrStatus("TaskExecution with invalid posted_from_iid");
1171
1172 StringId file_name_id = kNullStringId;
1173 StringId function_name_id = kNullStringId;
1174 uint32_t line_number = 0;
1175
1176 file_name_id = storage_->InternString(decoder->file_name());
1177 function_name_id = storage_->InternString(decoder->function_name());
1178 line_number = decoder->line_number();
1179
1180 inserter->AddArg(parser_->task_file_name_args_key_id_,
1181 Variadic::String(file_name_id));
1182 inserter->AddArg(parser_->task_function_name_args_key_id_,
1183 Variadic::String(function_name_id));
1184 inserter->AddArg(parser_->task_line_number_args_key_id_,
1185 Variadic::UnsignedInteger(line_number));
1186 return util::OkStatus();
1187 }
1188
AddSourceLocationArgs(uint64_t iid,BoundInserter * inserter)1189 util::Status AddSourceLocationArgs(uint64_t iid, BoundInserter* inserter) {
1190 if (!iid)
1191 return util::ErrStatus("SourceLocation with invalid iid");
1192
1193 auto* decoder = sequence_state_->LookupInternedMessage<
1194 protos::pbzero::InternedData::kSourceLocationsFieldNumber,
1195 protos::pbzero::SourceLocation>(iid);
1196 if (!decoder)
1197 return util::ErrStatus("SourceLocation with invalid iid");
1198
1199 StringId file_name_id = kNullStringId;
1200 StringId function_name_id = kNullStringId;
1201 uint32_t line_number = 0;
1202
1203 file_name_id = storage_->InternString(decoder->file_name());
1204 function_name_id = storage_->InternString(decoder->function_name());
1205 line_number = decoder->line_number();
1206
1207 inserter->AddArg(parser_->source_location_file_name_key_id_,
1208 Variadic::String(file_name_id));
1209 inserter->AddArg(parser_->source_location_function_name_key_id_,
1210 Variadic::String(function_name_id));
1211 inserter->AddArg(parser_->source_location_line_number_key_id_,
1212 Variadic::UnsignedInteger(line_number));
1213 return util::OkStatus();
1214 }
1215
ParseLogMessage(ConstBytes blob,BoundInserter * inserter)1216 util::Status ParseLogMessage(ConstBytes blob, BoundInserter* inserter) {
1217 if (!utid_)
1218 return util::ErrStatus("LogMessage without thread association");
1219
1220 protos::pbzero::LogMessage::Decoder message(blob);
1221
1222 StringId log_message_id = kNullStringId;
1223
1224 auto* decoder = sequence_state_->LookupInternedMessage<
1225 protos::pbzero::InternedData::kLogMessageBodyFieldNumber,
1226 protos::pbzero::LogMessageBody>(message.body_iid());
1227 if (!decoder)
1228 return util::ErrStatus("LogMessage with invalid body_iid");
1229
1230 log_message_id = storage_->InternString(decoder->body());
1231
1232 // TODO(nicomazz): LogMessage also contains the source of the message (file
1233 // and line number). Android logs doesn't support this so far.
1234 storage_->mutable_android_log_table()->Insert(
1235 {ts_, *utid_,
1236 /*priority*/ 0,
1237 /*tag_id*/ kNullStringId, // TODO(nicomazz): Abuse tag_id to display
1238 // "file_name:line_number".
1239 log_message_id});
1240
1241 inserter->AddArg(parser_->log_message_body_key_id_,
1242 Variadic::String(log_message_id));
1243 // TODO(nicomazz): Add the source location as an argument.
1244 return util::OkStatus();
1245 }
1246
ParseHistogramName(ConstBytes blob,BoundInserter * inserter)1247 util::Status ParseHistogramName(ConstBytes blob, BoundInserter* inserter) {
1248 protos::pbzero::ChromeHistogramSample::Decoder sample(blob);
1249 if (!sample.has_name_iid())
1250 return util::OkStatus();
1251
1252 if (sample.has_name()) {
1253 return util::ErrStatus(
1254 "name is already set for ChromeHistogramSample: only one of name and "
1255 "name_iid can be set.");
1256 }
1257
1258 auto* decoder = sequence_state_->LookupInternedMessage<
1259 protos::pbzero::InternedData::kHistogramNamesFieldNumber,
1260 protos::pbzero::HistogramName>(sample.name_iid());
1261 if (!decoder)
1262 return util::ErrStatus("HistogramName with invalid name_iid");
1263
1264 inserter->AddArg(parser_->histogram_name_key_id_,
1265 Variadic::String(storage_->InternString(decoder->name())));
1266 return util::OkStatus();
1267 }
1268
MakeThreadSliceRow()1269 tables::ThreadSliceTable::Row MakeThreadSliceRow() {
1270 tables::ThreadSliceTable::Row row;
1271 row.ts = ts_;
1272 row.track_id = track_id_;
1273 row.category = category_id_;
1274 row.name = name_id_;
1275 row.thread_ts = event_data_->thread_timestamp;
1276 row.thread_dur = base::nullopt;
1277 row.thread_instruction_count = event_data_->thread_instruction_count;
1278 row.thread_instruction_delta = base::nullopt;
1279 return row;
1280 }
1281
1282 TraceProcessorContext* context_;
1283 TrackEventTracker* track_event_tracker_;
1284 TraceStorage* storage_;
1285 TrackEventParser* parser_;
1286 int64_t ts_;
1287 TrackEventData* event_data_;
1288 PacketSequenceStateGeneration* sequence_state_;
1289 ConstBytes blob_;
1290 TrackEvent::Decoder event_;
1291 LegacyEvent::Decoder legacy_event_;
1292 protos::pbzero::TrackEventDefaults::Decoder* defaults_;
1293
1294 // Importing state.
1295 StringId category_id_;
1296 StringId name_id_;
1297 uint64_t track_uuid_;
1298 TrackId track_id_;
1299 base::Optional<UniqueTid> utid_;
1300 base::Optional<UniqueTid> upid_;
1301 // All events in legacy JSON require a thread ID, but for some types of
1302 // events (e.g. async events or process/global-scoped instants), we don't
1303 // store it in the slice/track model. To pass the utid through to the json
1304 // export, we store it in an arg.
1305 base::Optional<UniqueTid> legacy_passthrough_utid_;
1306 };
1307
TrackEventParser(TraceProcessorContext * context,TrackEventTracker * track_event_tracker)1308 TrackEventParser::TrackEventParser(TraceProcessorContext* context,
1309 TrackEventTracker* track_event_tracker)
1310 : args_parser_(*context->descriptor_pool_.get()),
1311 context_(context),
1312 track_event_tracker_(track_event_tracker),
1313 counter_name_thread_time_id_(
1314 context->storage->InternString("thread_time")),
1315 counter_name_thread_instruction_count_id_(
1316 context->storage->InternString("thread_instruction_count")),
1317 task_file_name_args_key_id_(
1318 context->storage->InternString("task.posted_from.file_name")),
1319 task_function_name_args_key_id_(
1320 context->storage->InternString("task.posted_from.function_name")),
1321 task_line_number_args_key_id_(
1322 context->storage->InternString("task.posted_from.line_number")),
1323 log_message_body_key_id_(
1324 context->storage->InternString("track_event.log_message")),
1325 source_location_function_name_key_id_(
1326 context->storage->InternString("source.function_name")),
1327 source_location_file_name_key_id_(
1328 context->storage->InternString("source.file_name")),
1329 source_location_line_number_key_id_(
1330 context->storage->InternString("source.line_number")),
1331 raw_legacy_event_id_(
1332 context->storage->InternString("track_event.legacy_event")),
1333 legacy_event_passthrough_utid_id_(
1334 context->storage->InternString("legacy_event.passthrough_utid")),
1335 legacy_event_category_key_id_(
1336 context->storage->InternString("legacy_event.category")),
1337 legacy_event_name_key_id_(
1338 context->storage->InternString("legacy_event.name")),
1339 legacy_event_phase_key_id_(
1340 context->storage->InternString("legacy_event.phase")),
1341 legacy_event_duration_ns_key_id_(
1342 context->storage->InternString("legacy_event.duration_ns")),
1343 legacy_event_thread_timestamp_ns_key_id_(
1344 context->storage->InternString("legacy_event.thread_timestamp_ns")),
1345 legacy_event_thread_duration_ns_key_id_(
1346 context->storage->InternString("legacy_event.thread_duration_ns")),
1347 legacy_event_thread_instruction_count_key_id_(
1348 context->storage->InternString(
1349 "legacy_event.thread_instruction_count")),
1350 legacy_event_thread_instruction_delta_key_id_(
1351 context->storage->InternString(
1352 "legacy_event.thread_instruction_delta")),
1353 legacy_event_use_async_tts_key_id_(
1354 context->storage->InternString("legacy_event.use_async_tts")),
1355 legacy_event_unscoped_id_key_id_(
1356 context->storage->InternString("legacy_event.unscoped_id")),
1357 legacy_event_global_id_key_id_(
1358 context->storage->InternString("legacy_event.global_id")),
1359 legacy_event_local_id_key_id_(
1360 context->storage->InternString("legacy_event.local_id")),
1361 legacy_event_id_scope_key_id_(
1362 context->storage->InternString("legacy_event.id_scope")),
1363 legacy_event_bind_id_key_id_(
1364 context->storage->InternString("legacy_event.bind_id")),
1365 legacy_event_bind_to_enclosing_key_id_(
1366 context->storage->InternString("legacy_event.bind_to_enclosing")),
1367 legacy_event_flow_direction_key_id_(
1368 context->storage->InternString("legacy_event.flow_direction")),
1369 histogram_name_key_id_(
1370 context->storage->InternString("chrome_histogram_sample.name")),
1371 flow_direction_value_in_id_(context->storage->InternString("in")),
1372 flow_direction_value_out_id_(context->storage->InternString("out")),
1373 flow_direction_value_inout_id_(context->storage->InternString("inout")),
1374 chrome_legacy_ipc_class_args_key_id_(
1375 context->storage->InternString("legacy_ipc.class")),
1376 chrome_legacy_ipc_line_args_key_id_(
1377 context->storage->InternString("legacy_ipc.line")),
1378 chrome_host_app_package_name_id_(
1379 context->storage->InternString("chrome.host_app_package_name")),
1380 chrome_crash_trace_id_name_id_(
1381 context->storage->InternString("chrome.crash_trace_id")),
1382 chrome_process_label_flat_key_id_(
1383 context->storage->InternString("chrome.process_label")),
1384 chrome_string_lookup_(context->storage.get()),
1385 counter_unit_ids_{{kNullStringId, context_->storage->InternString("ns"),
1386 context_->storage->InternString("count"),
1387 context_->storage->InternString("bytes")}} {
1388 // Switch |source_location_iid| into its interned data variant.
1389 args_parser_.AddParsingOverrideForField(
1390 "begin_impl_frame_args.current_args.source_location_iid",
1391 [](const protozero::Field& field,
__anon389a66560b02(const protozero::Field& field, util::ProtoToArgsParser::Delegate& delegate) 1392 util::ProtoToArgsParser::Delegate& delegate) {
1393 return MaybeParseSourceLocation("begin_impl_frame_args.current_args",
1394 field, delegate);
1395 });
1396 args_parser_.AddParsingOverrideForField(
1397 "begin_impl_frame_args.last_args.source_location_iid",
1398 [](const protozero::Field& field,
__anon389a66560c02(const protozero::Field& field, util::ProtoToArgsParser::Delegate& delegate) 1399 util::ProtoToArgsParser::Delegate& delegate) {
1400 return MaybeParseSourceLocation("begin_impl_frame_args.last_args",
1401 field, delegate);
1402 });
1403 args_parser_.AddParsingOverrideForField(
1404 "begin_frame_observer_state.last_begin_frame_args.source_location_iid",
1405 [](const protozero::Field& field,
__anon389a66560d02(const protozero::Field& field, util::ProtoToArgsParser::Delegate& delegate) 1406 util::ProtoToArgsParser::Delegate& delegate) {
1407 return MaybeParseSourceLocation(
1408 "begin_frame_observer_state.last_begin_frame_args", field,
1409 delegate);
1410 });
1411 args_parser_.AddParsingOverrideForField(
1412 "chrome_memory_pressure_notification.creation_location_iid",
1413 [](const protozero::Field& field,
__anon389a66560e02(const protozero::Field& field, util::ProtoToArgsParser::Delegate& delegate) 1414 util::ProtoToArgsParser::Delegate& delegate) {
1415 return MaybeParseSourceLocation("chrome_memory_pressure_notification",
1416 field, delegate);
1417 });
1418
1419 // Parse DebugAnnotations.
1420 args_parser_.AddParsingOverrideForType(
1421 ".perfetto.protos.DebugAnnotation",
1422 [&](util::ProtoToArgsParser::ScopedNestedKeyContext& key,
1423 const protozero::ConstBytes& data,
__anon389a66560f02(util::ProtoToArgsParser::ScopedNestedKeyContext& key, const protozero::ConstBytes& data, util::ProtoToArgsParser::Delegate& delegate) 1424 util::ProtoToArgsParser::Delegate& delegate) {
1425 // Do not add "debug_annotations" to the final key.
1426 key.RemoveFieldSuffix();
1427 util::DebugAnnotationParser annotation_parser(args_parser_);
1428 return annotation_parser.Parse(data, delegate);
1429 });
1430
1431 for (uint16_t index : kReflectFields) {
1432 reflect_fields_.push_back(index);
1433 }
1434 }
1435
ParseTrackDescriptor(protozero::ConstBytes track_descriptor)1436 void TrackEventParser::ParseTrackDescriptor(
1437 protozero::ConstBytes track_descriptor) {
1438 protos::pbzero::TrackDescriptor::Decoder decoder(track_descriptor);
1439
1440 // Ensure that the track and its parents are resolved. This may start a new
1441 // process and/or thread (i.e. new upid/utid).
1442 TrackId track_id = *track_event_tracker_->GetDescriptorTrack(decoder.uuid());
1443
1444 if (decoder.has_thread()) {
1445 UniqueTid utid = ParseThreadDescriptor(decoder.thread());
1446 if (decoder.has_chrome_thread())
1447 ParseChromeThreadDescriptor(utid, decoder.chrome_thread());
1448 } else if (decoder.has_process()) {
1449 UniquePid upid = ParseProcessDescriptor(decoder.process());
1450 if (decoder.has_chrome_process())
1451 ParseChromeProcessDescriptor(upid, decoder.chrome_process());
1452 } else if (decoder.has_counter()) {
1453 ParseCounterDescriptor(track_id, decoder.counter());
1454 }
1455
1456 // Override the name with the most recent name seen (after sorting by ts).
1457 if (decoder.has_name()) {
1458 auto* tracks = context_->storage->mutable_track_table();
1459 StringId name_id = context_->storage->InternString(decoder.name());
1460 tracks->mutable_name()->Set(*tracks->id().IndexOf(track_id), name_id);
1461 }
1462 }
1463
ParseProcessDescriptor(protozero::ConstBytes process_descriptor)1464 UniquePid TrackEventParser::ParseProcessDescriptor(
1465 protozero::ConstBytes process_descriptor) {
1466 protos::pbzero::ProcessDescriptor::Decoder decoder(process_descriptor);
1467 UniquePid upid = context_->process_tracker->GetOrCreateProcess(
1468 static_cast<uint32_t>(decoder.pid()));
1469 if (decoder.has_process_name() && decoder.process_name().size) {
1470 // Don't override system-provided names.
1471 context_->process_tracker->SetProcessNameIfUnset(
1472 upid, context_->storage->InternString(decoder.process_name()));
1473 }
1474 if (decoder.has_start_timestamp_ns() && decoder.start_timestamp_ns() > 0) {
1475 context_->process_tracker->SetStartTsIfUnset(upid,
1476 decoder.start_timestamp_ns());
1477 }
1478 // TODO(skyostil): Remove parsing for legacy chrome_process_type field.
1479 if (decoder.has_chrome_process_type()) {
1480 StringId name_id =
1481 chrome_string_lookup_.GetProcessName(decoder.chrome_process_type());
1482 // Don't override system-provided names.
1483 context_->process_tracker->SetProcessNameIfUnset(upid, name_id);
1484 }
1485 int label_index = 0;
1486 for (auto it = decoder.process_labels(); it; it++) {
1487 StringId label_id = context_->storage->InternString(*it);
1488 std::string key = "chrome.process_label[";
1489 key.append(std::to_string(label_index++));
1490 key.append("]");
1491 context_->process_tracker->AddArgsTo(upid).AddArg(
1492 chrome_process_label_flat_key_id_,
1493 context_->storage->InternString(base::StringView(key)),
1494 Variadic::String(label_id));
1495 }
1496 return upid;
1497 }
1498
ParseChromeProcessDescriptor(UniquePid upid,protozero::ConstBytes chrome_process_descriptor)1499 void TrackEventParser::ParseChromeProcessDescriptor(
1500 UniquePid upid,
1501 protozero::ConstBytes chrome_process_descriptor) {
1502 protos::pbzero::ChromeProcessDescriptor::Decoder decoder(
1503 chrome_process_descriptor);
1504
1505 StringId name_id =
1506 chrome_string_lookup_.GetProcessName(decoder.process_type());
1507 // Don't override system-provided names.
1508 context_->process_tracker->SetProcessNameIfUnset(upid, name_id);
1509
1510 ArgsTracker::BoundInserter process_args =
1511 context_->process_tracker->AddArgsTo(upid);
1512 if (decoder.has_host_app_package_name()) {
1513 process_args.AddArg(chrome_host_app_package_name_id_,
1514 Variadic::String(context_->storage->InternString(
1515 decoder.host_app_package_name())));
1516 }
1517 if (decoder.has_crash_trace_id()) {
1518 process_args.AddArg(chrome_crash_trace_id_name_id_,
1519 Variadic::UnsignedInteger(decoder.crash_trace_id()));
1520 }
1521 }
1522
ParseThreadDescriptor(protozero::ConstBytes thread_descriptor)1523 UniqueTid TrackEventParser::ParseThreadDescriptor(
1524 protozero::ConstBytes thread_descriptor) {
1525 protos::pbzero::ThreadDescriptor::Decoder decoder(thread_descriptor);
1526 UniqueTid utid = context_->process_tracker->UpdateThread(
1527 static_cast<uint32_t>(decoder.tid()),
1528 static_cast<uint32_t>(decoder.pid()));
1529 StringId name_id = kNullStringId;
1530 if (decoder.has_thread_name() && decoder.thread_name().size) {
1531 name_id = context_->storage->InternString(decoder.thread_name());
1532 } else if (decoder.has_chrome_thread_type()) {
1533 // TODO(skyostil): Remove parsing for legacy chrome_thread_type field.
1534 name_id = chrome_string_lookup_.GetThreadName(decoder.chrome_thread_type());
1535 }
1536 context_->process_tracker->UpdateThreadNameByUtid(
1537 utid, name_id, ThreadNamePriority::kTrackDescriptor);
1538 return utid;
1539 }
1540
ParseChromeThreadDescriptor(UniqueTid utid,protozero::ConstBytes chrome_thread_descriptor)1541 void TrackEventParser::ParseChromeThreadDescriptor(
1542 UniqueTid utid,
1543 protozero::ConstBytes chrome_thread_descriptor) {
1544 protos::pbzero::ChromeThreadDescriptor::Decoder decoder(
1545 chrome_thread_descriptor);
1546 if (!decoder.has_thread_type())
1547 return;
1548
1549 StringId name_id = chrome_string_lookup_.GetThreadName(decoder.thread_type());
1550 context_->process_tracker->UpdateThreadNameByUtid(
1551 utid, name_id, ThreadNamePriority::kTrackDescriptorThreadType);
1552 }
1553
ParseCounterDescriptor(TrackId track_id,protozero::ConstBytes counter_descriptor)1554 void TrackEventParser::ParseCounterDescriptor(
1555 TrackId track_id,
1556 protozero::ConstBytes counter_descriptor) {
1557 using protos::pbzero::CounterDescriptor;
1558
1559 CounterDescriptor::Decoder decoder(counter_descriptor);
1560 auto* counter_tracks = context_->storage->mutable_counter_track_table();
1561
1562 size_t unit_index = static_cast<size_t>(decoder.unit());
1563 if (unit_index >= counter_unit_ids_.size())
1564 unit_index = CounterDescriptor::UNIT_UNSPECIFIED;
1565
1566 auto opt_track_idx = counter_tracks->id().IndexOf(track_id);
1567 if (!opt_track_idx) {
1568 context_->storage->IncrementStats(stats::track_event_parser_errors);
1569 return;
1570 }
1571
1572 auto track_idx = *opt_track_idx;
1573
1574 switch (decoder.type()) {
1575 case CounterDescriptor::COUNTER_UNSPECIFIED:
1576 break;
1577 case CounterDescriptor::COUNTER_THREAD_TIME_NS:
1578 unit_index = CounterDescriptor::UNIT_TIME_NS;
1579 counter_tracks->mutable_name()->Set(track_idx,
1580 counter_name_thread_time_id_);
1581 break;
1582 case CounterDescriptor::COUNTER_THREAD_INSTRUCTION_COUNT:
1583 unit_index = CounterDescriptor::UNIT_COUNT;
1584 counter_tracks->mutable_name()->Set(
1585 track_idx, counter_name_thread_instruction_count_id_);
1586 break;
1587 }
1588
1589 counter_tracks->mutable_unit()->Set(track_idx, counter_unit_ids_[unit_index]);
1590 }
1591
ParseTrackEvent(int64_t ts,TrackEventData * event_data,ConstBytes blob)1592 void TrackEventParser::ParseTrackEvent(int64_t ts,
1593 TrackEventData* event_data,
1594 ConstBytes blob) {
1595 util::Status status =
1596 EventImporter(this, ts, event_data, std::move(blob)).Import();
1597 if (!status.ok()) {
1598 context_->storage->IncrementStats(stats::track_event_parser_errors);
1599 PERFETTO_DLOG("ParseTrackEvent error: %s", status.c_message());
1600 }
1601 }
1602
1603 } // namespace trace_processor
1604 } // namespace perfetto
1605