1 /*
2 * Copyright (C) 2018 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/proto_trace_parser.h"
18
19 #include <string.h>
20
21 #include <cinttypes>
22 #include <string>
23
24 #include "perfetto/base/logging.h"
25 #include "perfetto/ext/base/metatrace_events.h"
26 #include "perfetto/ext/base/string_view.h"
27 #include "perfetto/ext/base/string_writer.h"
28 #include "perfetto/ext/base/utils.h"
29 #include "perfetto/ext/base/uuid.h"
30 #include "perfetto/trace_processor/status.h"
31
32 #include "src/trace_processor/importers/common/args_tracker.h"
33 #include "src/trace_processor/importers/common/clock_tracker.h"
34 #include "src/trace_processor/importers/common/event_tracker.h"
35 #include "src/trace_processor/importers/common/process_tracker.h"
36 #include "src/trace_processor/importers/common/slice_tracker.h"
37 #include "src/trace_processor/importers/common/track_tracker.h"
38 #include "src/trace_processor/importers/config.descriptor.h"
39 #include "src/trace_processor/importers/ftrace/ftrace_module.h"
40 #include "src/trace_processor/importers/proto/metadata_tracker.h"
41 #include "src/trace_processor/importers/proto/packet_sequence_state.h"
42 #include "src/trace_processor/storage/metadata.h"
43 #include "src/trace_processor/storage/stats.h"
44 #include "src/trace_processor/timestamped_trace_piece.h"
45 #include "src/trace_processor/types/trace_processor_context.h"
46 #include "src/trace_processor/types/variadic.h"
47 #include "src/trace_processor/util/descriptors.h"
48 #include "src/trace_processor/util/protozero_to_text.h"
49
50 #include "protos/perfetto/common/builtin_clock.pbzero.h"
51 #include "protos/perfetto/common/trace_stats.pbzero.h"
52 #include "protos/perfetto/config/trace_config.pbzero.h"
53 #include "protos/perfetto/trace/chrome/chrome_trace_event.pbzero.h"
54 #include "protos/perfetto/trace/interned_data/interned_data.pbzero.h"
55 #include "protos/perfetto/trace/perfetto/perfetto_metatrace.pbzero.h"
56 #include "protos/perfetto/trace/trace.pbzero.h"
57 #include "protos/perfetto/trace/trace_packet.pbzero.h"
58
59 namespace perfetto {
60 namespace trace_processor {
61
ProtoTraceParser(TraceProcessorContext * context)62 ProtoTraceParser::ProtoTraceParser(TraceProcessorContext* context)
63 : context_(context),
64 metatrace_id_(context->storage->InternString("metatrace")),
65 data_name_id_(context->storage->InternString("data")),
66 raw_chrome_metadata_event_id_(
67 context->storage->InternString("chrome_event.metadata")),
68 raw_chrome_legacy_system_trace_event_id_(
69 context->storage->InternString("chrome_event.legacy_system_trace")),
70 raw_chrome_legacy_user_trace_event_id_(
71 context->storage->InternString("chrome_event.legacy_user_trace")) {
72 // TODO(140860736): Once we support null values for
73 // stack_profile_frame.symbol_set_id remove this hack
74 context_->storage->mutable_symbol_table()->Insert(
75 {0, kNullStringId, kNullStringId, 0});
76 }
77
78 ProtoTraceParser::~ProtoTraceParser() = default;
79
ParseTracePacket(int64_t ts,TimestampedTracePiece ttp)80 void ProtoTraceParser::ParseTracePacket(int64_t ts, TimestampedTracePiece ttp) {
81 const TracePacketData* data = nullptr;
82 if (ttp.type == TimestampedTracePiece::Type::kTracePacket) {
83 data = &ttp.packet_data;
84 } else {
85 PERFETTO_DCHECK(ttp.type == TimestampedTracePiece::Type::kTrackEvent);
86 data = ttp.track_event_data.get();
87 }
88
89 const TraceBlobView& blob = data->packet;
90 protos::pbzero::TracePacket::Decoder packet(blob.data(), blob.length());
91
92 ParseTracePacketImpl(ts, ttp, data->sequence_state.get(), packet);
93
94 // TODO(lalitm): maybe move this to the flush method in the trace processor
95 // once we have it. This may reduce performance in the ArgsTracker though so
96 // needs to be handled carefully.
97 context_->args_tracker->Flush();
98 PERFETTO_DCHECK(!packet.bytes_left());
99 }
100
ParseTracePacketImpl(int64_t ts,const TimestampedTracePiece & ttp,PacketSequenceStateGeneration *,const protos::pbzero::TracePacket::Decoder & packet)101 void ProtoTraceParser::ParseTracePacketImpl(
102 int64_t ts,
103 const TimestampedTracePiece& ttp,
104 PacketSequenceStateGeneration* /*sequence_state*/,
105 const protos::pbzero::TracePacket::Decoder& packet) {
106 // Chrome doesn't honor the one-of in TracePacket for this field and sets it
107 // together with chrome_metadata, which is handled by a module. Thus, we have
108 // to parse this field before the modules get to parse other fields.
109 // TODO(crbug/1194914): Move this back after the modules (or into a separate
110 // module) once the Chrome-side fix has propagated into all release channels.
111 if (packet.has_chrome_events()) {
112 ParseChromeEvents(ts, packet.chrome_events());
113 }
114
115 // TODO(eseckler): Propagate statuses from modules.
116 auto& modules = context_->modules_by_field;
117 for (uint32_t field_id = 1; field_id < modules.size(); ++field_id) {
118 if (!modules[field_id].empty() && packet.Get(field_id).valid()) {
119 for (ProtoImporterModule* module : modules[field_id])
120 module->ParsePacket(packet, ttp, field_id);
121 return;
122 }
123 }
124
125 if (packet.has_trace_stats())
126 ParseTraceStats(packet.trace_stats());
127
128 if (packet.has_perfetto_metatrace()) {
129 ParseMetatraceEvent(ts, packet.perfetto_metatrace());
130 }
131
132 if (packet.has_trace_config()) {
133 ParseTraceConfig(packet.trace_config());
134 }
135 }
136
ParseFtracePacket(uint32_t cpu,int64_t,TimestampedTracePiece ttp)137 void ProtoTraceParser::ParseFtracePacket(uint32_t cpu,
138 int64_t /*ts*/,
139 TimestampedTracePiece ttp) {
140 PERFETTO_DCHECK(ttp.type == TimestampedTracePiece::Type::kFtraceEvent ||
141 ttp.type == TimestampedTracePiece::Type::kInlineSchedSwitch ||
142 ttp.type == TimestampedTracePiece::Type::kInlineSchedWaking);
143 PERFETTO_DCHECK(context_->ftrace_module);
144 context_->ftrace_module->ParseFtracePacket(cpu, ttp);
145
146 // TODO(lalitm): maybe move this to the flush method in the trace processor
147 // once we have it. This may reduce performance in the ArgsTracker though so
148 // needs to be handled carefully.
149 context_->args_tracker->Flush();
150 }
151
ParseTraceStats(ConstBytes blob)152 void ProtoTraceParser::ParseTraceStats(ConstBytes blob) {
153 protos::pbzero::TraceStats::Decoder evt(blob.data, blob.size);
154 auto* storage = context_->storage.get();
155 storage->SetStats(stats::traced_producers_connected,
156 static_cast<int64_t>(evt.producers_connected()));
157 storage->SetStats(stats::traced_data_sources_registered,
158 static_cast<int64_t>(evt.data_sources_registered()));
159 storage->SetStats(stats::traced_data_sources_seen,
160 static_cast<int64_t>(evt.data_sources_seen()));
161 storage->SetStats(stats::traced_tracing_sessions,
162 static_cast<int64_t>(evt.tracing_sessions()));
163 storage->SetStats(stats::traced_total_buffers,
164 static_cast<int64_t>(evt.total_buffers()));
165 storage->SetStats(stats::traced_chunks_discarded,
166 static_cast<int64_t>(evt.chunks_discarded()));
167 storage->SetStats(stats::traced_patches_discarded,
168 static_cast<int64_t>(evt.patches_discarded()));
169 storage->SetStats(stats::traced_flushes_requested,
170 static_cast<int64_t>(evt.flushes_requested()));
171 storage->SetStats(stats::traced_flushes_succeeded,
172 static_cast<int64_t>(evt.flushes_succeeded()));
173 storage->SetStats(stats::traced_flushes_failed,
174 static_cast<int64_t>(evt.flushes_failed()));
175 switch (evt.final_flush_outcome()) {
176 case protos::pbzero::TraceStats::FINAL_FLUSH_SUCCEEDED:
177 storage->IncrementStats(stats::traced_final_flush_succeeded, 1);
178 break;
179 case protos::pbzero::TraceStats::FINAL_FLUSH_FAILED:
180 storage->IncrementStats(stats::traced_final_flush_failed, 1);
181 break;
182 case protos::pbzero::TraceStats::FINAL_FLUSH_UNSPECIFIED:
183 break;
184 }
185
186 int buf_num = 0;
187 for (auto it = evt.buffer_stats(); it; ++it, ++buf_num) {
188 protos::pbzero::TraceStats::BufferStats::Decoder buf(*it);
189 storage->SetIndexedStats(stats::traced_buf_buffer_size, buf_num,
190 static_cast<int64_t>(buf.buffer_size()));
191 storage->SetIndexedStats(stats::traced_buf_bytes_written, buf_num,
192 static_cast<int64_t>(buf.bytes_written()));
193 storage->SetIndexedStats(stats::traced_buf_bytes_overwritten, buf_num,
194 static_cast<int64_t>(buf.bytes_overwritten()));
195 storage->SetIndexedStats(stats::traced_buf_bytes_read, buf_num,
196 static_cast<int64_t>(buf.bytes_read()));
197 storage->SetIndexedStats(stats::traced_buf_padding_bytes_written, buf_num,
198 static_cast<int64_t>(buf.padding_bytes_written()));
199 storage->SetIndexedStats(stats::traced_buf_padding_bytes_cleared, buf_num,
200 static_cast<int64_t>(buf.padding_bytes_cleared()));
201 storage->SetIndexedStats(stats::traced_buf_chunks_written, buf_num,
202 static_cast<int64_t>(buf.chunks_written()));
203 storage->SetIndexedStats(stats::traced_buf_chunks_rewritten, buf_num,
204 static_cast<int64_t>(buf.chunks_rewritten()));
205 storage->SetIndexedStats(stats::traced_buf_chunks_overwritten, buf_num,
206 static_cast<int64_t>(buf.chunks_overwritten()));
207 storage->SetIndexedStats(stats::traced_buf_chunks_discarded, buf_num,
208 static_cast<int64_t>(buf.chunks_discarded()));
209 storage->SetIndexedStats(stats::traced_buf_chunks_read, buf_num,
210 static_cast<int64_t>(buf.chunks_read()));
211 storage->SetIndexedStats(
212 stats::traced_buf_chunks_committed_out_of_order, buf_num,
213 static_cast<int64_t>(buf.chunks_committed_out_of_order()));
214 storage->SetIndexedStats(stats::traced_buf_write_wrap_count, buf_num,
215 static_cast<int64_t>(buf.write_wrap_count()));
216 storage->SetIndexedStats(stats::traced_buf_patches_succeeded, buf_num,
217 static_cast<int64_t>(buf.patches_succeeded()));
218 storage->SetIndexedStats(stats::traced_buf_patches_failed, buf_num,
219 static_cast<int64_t>(buf.patches_failed()));
220 storage->SetIndexedStats(stats::traced_buf_readaheads_succeeded, buf_num,
221 static_cast<int64_t>(buf.readaheads_succeeded()));
222 storage->SetIndexedStats(stats::traced_buf_readaheads_failed, buf_num,
223 static_cast<int64_t>(buf.readaheads_failed()));
224 storage->SetIndexedStats(stats::traced_buf_abi_violations, buf_num,
225 static_cast<int64_t>(buf.abi_violations()));
226 storage->SetIndexedStats(
227 stats::traced_buf_trace_writer_packet_loss, buf_num,
228 static_cast<int64_t>(buf.trace_writer_packet_loss()));
229 }
230 }
231
ParseChromeEvents(int64_t ts,ConstBytes blob)232 void ProtoTraceParser::ParseChromeEvents(int64_t ts, ConstBytes blob) {
233 TraceStorage* storage = context_->storage.get();
234 protos::pbzero::ChromeEventBundle::Decoder bundle(blob.data, blob.size);
235 ArgsTracker args(context_);
236 if (bundle.has_metadata()) {
237 RawId id = storage->mutable_raw_table()
238 ->Insert({ts, raw_chrome_metadata_event_id_, 0, 0})
239 .id;
240 auto inserter = args.AddArgsTo(id);
241
242 uint32_t bundle_index =
243 context_->metadata_tracker->IncrementChromeMetadataBundleCount();
244
245 // The legacy untyped metadata is proxied via a special event in the raw
246 // table to JSON export.
247 for (auto it = bundle.metadata(); it; ++it) {
248 protos::pbzero::ChromeMetadata::Decoder metadata(*it);
249 Variadic value;
250 if (metadata.has_string_value()) {
251 value =
252 Variadic::String(storage->InternString(metadata.string_value()));
253 } else if (metadata.has_int_value()) {
254 value = Variadic::Integer(metadata.int_value());
255 } else if (metadata.has_bool_value()) {
256 value = Variadic::Integer(metadata.bool_value());
257 } else if (metadata.has_json_value()) {
258 value = Variadic::Json(storage->InternString(metadata.json_value()));
259 } else {
260 context_->storage->IncrementStats(stats::empty_chrome_metadata);
261 continue;
262 }
263
264 StringId name_id = storage->InternString(metadata.name());
265 args.AddArgsTo(id).AddArg(name_id, value);
266
267 char buffer[2048];
268 base::StringWriter writer(buffer, sizeof(buffer));
269 writer.AppendString("cr-");
270 // If we have data from multiple Chrome instances, append a suffix
271 // to differentiate them.
272 if (bundle_index > 1) {
273 writer.AppendUnsignedInt(bundle_index);
274 writer.AppendChar('-');
275 }
276 writer.AppendString(metadata.name());
277
278 auto metadata_id = storage->InternString(writer.GetStringView());
279 context_->metadata_tracker->SetDynamicMetadata(metadata_id, value);
280 }
281 }
282
283 if (bundle.has_legacy_ftrace_output()) {
284 RawId id =
285 storage->mutable_raw_table()
286 ->Insert({ts, raw_chrome_legacy_system_trace_event_id_, 0, 0})
287 .id;
288
289 std::string data;
290 for (auto it = bundle.legacy_ftrace_output(); it; ++it) {
291 data += (*it).ToStdString();
292 }
293 Variadic value =
294 Variadic::String(storage->InternString(base::StringView(data)));
295 args.AddArgsTo(id).AddArg(data_name_id_, value);
296 }
297
298 if (bundle.has_legacy_json_trace()) {
299 for (auto it = bundle.legacy_json_trace(); it; ++it) {
300 protos::pbzero::ChromeLegacyJsonTrace::Decoder legacy_trace(*it);
301 if (legacy_trace.type() !=
302 protos::pbzero::ChromeLegacyJsonTrace::USER_TRACE) {
303 continue;
304 }
305 RawId id =
306 storage->mutable_raw_table()
307 ->Insert({ts, raw_chrome_legacy_user_trace_event_id_, 0, 0})
308 .id;
309 Variadic value =
310 Variadic::String(storage->InternString(legacy_trace.data()));
311 args.AddArgsTo(id).AddArg(data_name_id_, value);
312 }
313 }
314 }
315
ParseMetatraceEvent(int64_t ts,ConstBytes blob)316 void ProtoTraceParser::ParseMetatraceEvent(int64_t ts, ConstBytes blob) {
317 protos::pbzero::PerfettoMetatrace::Decoder event(blob.data, blob.size);
318 auto utid = context_->process_tracker->GetOrCreateThread(event.thread_id());
319
320 StringId cat_id = metatrace_id_;
321 StringId name_id = kNullStringId;
322 char fallback[64];
323
324 // This function inserts the args from the proto into the args table.
325 // Args inserted with the same key multiple times are treated as an array:
326 // this function correctly creates the key and flat key for each arg array.
327 auto args_fn = [this, &event](ArgsTracker::BoundInserter* inserter) {
328 using Arg = std::pair<StringId, StringId>;
329
330 // First, get a list of all the args so we can group them by key.
331 std::vector<Arg> interned;
332 for (auto it = event.args(); it; ++it) {
333 protos::pbzero::PerfettoMetatrace::Arg::Decoder arg_proto(*it);
334 StringId key = context_->storage->InternString(arg_proto.key());
335 StringId value = context_->storage->InternString(arg_proto.value());
336 interned.emplace_back(key, value);
337 }
338
339 // We stable sort insted of sorting here to avoid changing the order of the
340 // args in arrays.
341 std::stable_sort(interned.begin(), interned.end(),
342 [](const Arg& a, const Arg& b) {
343 return a.first.raw_id() < b.second.raw_id();
344 });
345
346 // Compute the correct key for each arg, possibly adding an index to
347 // the end of the key if needed.
348 char buffer[2048];
349 uint32_t current_idx = 0;
350 for (auto it = interned.begin(); it != interned.end(); ++it) {
351 auto next = it + 1;
352 StringId key = it->first;
353 StringId next_key = next == interned.end() ? kNullStringId : next->first;
354
355 if (key != next_key && current_idx == 0) {
356 inserter->AddArg(key, Variadic::String(it->second));
357 } else {
358 constexpr size_t kMaxIndexSize = 20;
359 base::StringView key_str = context_->storage->GetString(key);
360 if (key_str.size() >= sizeof(buffer) - kMaxIndexSize) {
361 PERFETTO_DLOG("Ignoring arg with unreasonbly large size");
362 continue;
363 }
364
365 base::StringWriter writer(buffer, sizeof(buffer));
366 writer.AppendString(key_str);
367 writer.AppendChar('[');
368 writer.AppendUnsignedInt(current_idx);
369 writer.AppendChar(']');
370
371 StringId new_key =
372 context_->storage->InternString(writer.GetStringView());
373 inserter->AddArg(key, new_key, Variadic::String(it->second));
374
375 current_idx = key == next_key ? current_idx + 1 : 0;
376 }
377 }
378 };
379
380 if (event.has_event_id() || event.has_event_name()) {
381 if (event.has_event_id()) {
382 auto eid = event.event_id();
383 if (eid < metatrace::EVENTS_MAX) {
384 name_id = context_->storage->InternString(metatrace::kEventNames[eid]);
385 } else {
386 sprintf(fallback, "Event %d", eid);
387 name_id = context_->storage->InternString(fallback);
388 }
389 } else {
390 name_id = context_->storage->InternString(event.event_name());
391 }
392 TrackId track_id = context_->track_tracker->InternThreadTrack(utid);
393 context_->slice_tracker->Scoped(
394 ts, track_id, cat_id, name_id,
395 static_cast<int64_t>(event.event_duration_ns()), args_fn);
396 } else if (event.has_counter_id() || event.has_counter_name()) {
397 if (event.has_counter_id()) {
398 auto cid = event.counter_id();
399 if (cid < metatrace::COUNTERS_MAX) {
400 name_id =
401 context_->storage->InternString(metatrace::kCounterNames[cid]);
402 } else {
403 sprintf(fallback, "Counter %d", cid);
404 name_id = context_->storage->InternString(fallback);
405 }
406 } else {
407 name_id = context_->storage->InternString(event.counter_name());
408 }
409 TrackId track =
410 context_->track_tracker->InternThreadCounterTrack(name_id, utid);
411 auto opt_id =
412 context_->event_tracker->PushCounter(ts, event.counter_value(), track);
413 if (opt_id) {
414 auto inserter = context_->args_tracker->AddArgsTo(*opt_id);
415 args_fn(&inserter);
416 }
417 }
418
419 if (event.has_overruns())
420 context_->storage->IncrementStats(stats::metatrace_overruns);
421 }
422
ParseTraceConfig(ConstBytes blob)423 void ProtoTraceParser::ParseTraceConfig(ConstBytes blob) {
424 protos::pbzero::TraceConfig::Decoder trace_config(blob.data, blob.size);
425
426 // TODO(eseckler): Propagate statuses from modules.
427 for (auto& module : context_->modules) {
428 module->ParseTraceConfig(trace_config);
429 }
430
431 int64_t uuid_msb = trace_config.trace_uuid_msb();
432 int64_t uuid_lsb = trace_config.trace_uuid_lsb();
433 if (uuid_msb != 0 || uuid_lsb != 0) {
434 base::Uuid uuid(uuid_lsb, uuid_msb);
435 std::string str = uuid.ToPrettyString();
436 StringId id = context_->storage->InternString(base::StringView(str));
437 context_->metadata_tracker->SetMetadata(metadata::trace_uuid,
438 Variadic::String(id));
439 context_->uuid_found_in_trace = true;
440 }
441
442 if (trace_config.has_unique_session_name()) {
443 StringId id = context_->storage->InternString(
444 base::StringView(trace_config.unique_session_name()));
445 context_->metadata_tracker->SetMetadata(metadata::unique_session_name,
446 Variadic::String(id));
447 }
448
449 DescriptorPool pool;
450 pool.AddFromFileDescriptorSet(kConfigDescriptor.data(),
451 kConfigDescriptor.size());
452
453 std::string text = protozero_to_text::ProtozeroToText(
454 pool, ".perfetto.protos.TraceConfig", blob,
455 protozero_to_text::kIncludeNewLines);
456 StringId id = context_->storage->InternString(base::StringView(text));
457 context_->metadata_tracker->SetMetadata(metadata::trace_config_pbtxt,
458 Variadic::String(id));
459 }
460
461 } // namespace trace_processor
462 } // namespace perfetto
463