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_utils.h"
27 #include "perfetto/ext/base/string_view.h"
28 #include "perfetto/ext/base/string_writer.h"
29 #include "perfetto/ext/base/uuid.h"
30
31 #include "src/trace_processor/importers/common/args_tracker.h"
32 #include "src/trace_processor/importers/common/event_tracker.h"
33 #include "src/trace_processor/importers/common/metadata_tracker.h"
34 #include "src/trace_processor/importers/common/parser_types.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/ftrace/ftrace_module.h"
39 #include "src/trace_processor/importers/proto/packet_sequence_state.h"
40 #include "src/trace_processor/importers/proto/track_event_module.h"
41 #include "src/trace_processor/storage/metadata.h"
42 #include "src/trace_processor/storage/stats.h"
43 #include "src/trace_processor/types/trace_processor_context.h"
44 #include "src/trace_processor/types/variadic.h"
45
46 #include "protos/perfetto/common/trace_stats.pbzero.h"
47 #include "protos/perfetto/config/trace_config.pbzero.h"
48 #include "protos/perfetto/trace/chrome/chrome_trace_event.pbzero.h"
49 #include "protos/perfetto/trace/perfetto/perfetto_metatrace.pbzero.h"
50 #include "protos/perfetto/trace/trace_packet.pbzero.h"
51
52 namespace perfetto {
53 namespace trace_processor {
54
ProtoTraceParser(TraceProcessorContext * context)55 ProtoTraceParser::ProtoTraceParser(TraceProcessorContext* context)
56 : context_(context),
57 metatrace_id_(context->storage->InternString("metatrace")),
58 data_name_id_(context->storage->InternString("data")),
59 raw_chrome_metadata_event_id_(
60 context->storage->InternString("chrome_event.metadata")),
61 raw_chrome_legacy_system_trace_event_id_(
62 context->storage->InternString("chrome_event.legacy_system_trace")),
63 raw_chrome_legacy_user_trace_event_id_(
64 context->storage->InternString("chrome_event.legacy_user_trace")),
65 missing_metatrace_interned_string_id_(
66 context->storage->InternString("MISSING STRING")) {}
67
68 ProtoTraceParser::~ProtoTraceParser() = default;
69
ParseTracePacket(int64_t ts,TracePacketData data)70 void ProtoTraceParser::ParseTracePacket(int64_t ts, TracePacketData data) {
71 const TraceBlobView& blob = data.packet;
72 protos::pbzero::TracePacket::Decoder packet(blob.data(), blob.length());
73 // TODO(eseckler): Propagate statuses from modules.
74 auto& modules = context_->modules_by_field;
75 for (uint32_t field_id = 1; field_id < modules.size(); ++field_id) {
76 if (!modules[field_id].empty() && packet.Get(field_id).valid()) {
77 for (ProtoImporterModule* global_module :
78 context_->modules_for_all_fields) {
79 global_module->ParseTracePacketData(packet, ts, data, field_id);
80 }
81 for (ProtoImporterModule* module : modules[field_id])
82 module->ParseTracePacketData(packet, ts, data, field_id);
83 return;
84 }
85 }
86
87 if (packet.has_trace_stats())
88 ParseTraceStats(packet.trace_stats());
89
90 if (packet.has_chrome_events()) {
91 ParseChromeEvents(ts, packet.chrome_events());
92 }
93
94 if (packet.has_perfetto_metatrace()) {
95 ParseMetatraceEvent(ts, packet.perfetto_metatrace());
96 }
97
98 if (packet.has_trace_config()) {
99 // TODO(eseckler): Propagate statuses from modules.
100 protos::pbzero::TraceConfig::Decoder config(packet.trace_config());
101 for (auto& module : context_->modules) {
102 module->ParseTraceConfig(config);
103 }
104 }
105 }
106
ParseTrackEvent(int64_t ts,TrackEventData data)107 void ProtoTraceParser::ParseTrackEvent(int64_t ts, TrackEventData data) {
108 const TraceBlobView& blob = data.trace_packet_data.packet;
109 protos::pbzero::TracePacket::Decoder packet(blob.data(), blob.length());
110 context_->track_module->ParseTrackEventData(packet, ts, data);
111 context_->args_tracker->Flush();
112 }
113
ParseFtraceEvent(uint32_t cpu,int64_t ts,TracePacketData data)114 void ProtoTraceParser::ParseFtraceEvent(uint32_t cpu,
115 int64_t ts,
116 TracePacketData data) {
117 PERFETTO_DCHECK(context_->ftrace_module);
118 context_->ftrace_module->ParseFtraceEventData(cpu, ts, data);
119
120 // TODO(lalitm): maybe move this to the flush method in the trace processor
121 // once we have it. This may reduce performance in the ArgsTracker though so
122 // needs to be handled carefully.
123 context_->args_tracker->Flush();
124 }
125
ParseInlineSchedSwitch(uint32_t cpu,int64_t ts,InlineSchedSwitch data)126 void ProtoTraceParser::ParseInlineSchedSwitch(uint32_t cpu,
127 int64_t ts,
128 InlineSchedSwitch data) {
129 PERFETTO_DCHECK(context_->ftrace_module);
130 context_->ftrace_module->ParseInlineSchedSwitch(cpu, ts, data);
131
132 // TODO(lalitm): maybe move this to the flush method in the trace processor
133 // once we have it. This may reduce performance in the ArgsTracker though so
134 // needs to be handled carefully.
135 context_->args_tracker->Flush();
136 }
137
ParseInlineSchedWaking(uint32_t cpu,int64_t ts,InlineSchedWaking data)138 void ProtoTraceParser::ParseInlineSchedWaking(uint32_t cpu,
139 int64_t ts,
140 InlineSchedWaking data) {
141 PERFETTO_DCHECK(context_->ftrace_module);
142 context_->ftrace_module->ParseInlineSchedWaking(cpu, ts, data);
143
144 // TODO(lalitm): maybe move this to the flush method in the trace processor
145 // once we have it. This may reduce performance in the ArgsTracker though so
146 // needs to be handled carefully.
147 context_->args_tracker->Flush();
148 }
149
ParseTraceStats(ConstBytes blob)150 void ProtoTraceParser::ParseTraceStats(ConstBytes blob) {
151 protos::pbzero::TraceStats::Decoder evt(blob.data, blob.size);
152 auto* storage = context_->storage.get();
153 storage->SetStats(stats::traced_producers_connected,
154 static_cast<int64_t>(evt.producers_connected()));
155 storage->SetStats(stats::traced_producers_seen,
156 static_cast<int64_t>(evt.producers_seen()));
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
323 for (auto it = event.interned_strings(); it; ++it) {
324 protos::pbzero::PerfettoMetatrace::InternedString::Decoder interned_string(
325 it->data(), it->size());
326 metatrace_interned_strings_.Insert(
327 interned_string.iid(),
328 context_->storage->InternString(interned_string.value()));
329 }
330
331 // This function inserts the args from the proto into the args table.
332 // Args inserted with the same key multiple times are treated as an array:
333 // this function correctly creates the key and flat key for each arg array.
334 auto args_fn = [this, &event](ArgsTracker::BoundInserter* inserter) {
335 using Arg = std::pair<StringId, StringId>;
336
337 // First, get a list of all the args so we can group them by key.
338 std::vector<Arg> interned;
339 for (auto it = event.args(); it; ++it) {
340 protos::pbzero::PerfettoMetatrace::Arg::Decoder arg_proto(*it);
341 StringId key;
342 if (arg_proto.has_key_iid()) {
343 key = GetMetatraceInternedString(arg_proto.key_iid());
344 } else {
345 key = context_->storage->InternString(arg_proto.key());
346 }
347 StringId value;
348 if (arg_proto.has_value_iid()) {
349 value = GetMetatraceInternedString(arg_proto.value_iid());
350 } else {
351 value = context_->storage->InternString(arg_proto.value());
352 }
353 interned.emplace_back(key, value);
354 }
355
356 // We stable sort insted of sorting here to avoid changing the order of the
357 // args in arrays.
358 std::stable_sort(interned.begin(), interned.end(),
359 [](const Arg& a, const Arg& b) {
360 return a.first.raw_id() < b.first.raw_id();
361 });
362
363 // Compute the correct key for each arg, possibly adding an index to
364 // the end of the key if needed.
365 char buffer[2048];
366 uint32_t current_idx = 0;
367 for (auto it = interned.begin(); it != interned.end(); ++it) {
368 auto next = it + 1;
369 StringId key = it->first;
370 StringId next_key = next == interned.end() ? kNullStringId : next->first;
371
372 if (key != next_key && current_idx == 0) {
373 inserter->AddArg(key, Variadic::String(it->second));
374 } else {
375 constexpr size_t kMaxIndexSize = 20;
376 NullTermStringView key_str = context_->storage->GetString(key);
377 if (key_str.size() >= sizeof(buffer) - kMaxIndexSize) {
378 PERFETTO_DLOG("Ignoring arg with unreasonbly large size");
379 continue;
380 }
381
382 base::StackString<2048> array_key("%s[%u]", key_str.c_str(),
383 current_idx);
384 StringId new_key =
385 context_->storage->InternString(array_key.string_view());
386 inserter->AddArg(key, new_key, Variadic::String(it->second));
387
388 current_idx = key == next_key ? current_idx + 1 : 0;
389 }
390 }
391 };
392
393 if (event.has_event_id() || event.has_event_name() ||
394 event.has_event_name_iid()) {
395 if (event.has_event_id()) {
396 auto eid = event.event_id();
397 if (eid < metatrace::EVENTS_MAX) {
398 name_id = context_->storage->InternString(metatrace::kEventNames[eid]);
399 } else {
400 base::StackString<64> fallback("Event %d", eid);
401 name_id = context_->storage->InternString(fallback.string_view());
402 }
403 } else if (event.has_event_name_iid()) {
404 name_id = GetMetatraceInternedString(event.event_name_iid());
405 } else {
406 name_id = context_->storage->InternString(event.event_name());
407 }
408 TrackId track_id = context_->track_tracker->InternThreadTrack(utid);
409 context_->slice_tracker->Scoped(
410 ts, track_id, cat_id, name_id,
411 static_cast<int64_t>(event.event_duration_ns()), args_fn);
412 } else if (event.has_counter_id() || event.has_counter_name()) {
413 if (event.has_counter_id()) {
414 auto cid = event.counter_id();
415 if (cid < metatrace::COUNTERS_MAX) {
416 name_id =
417 context_->storage->InternString(metatrace::kCounterNames[cid]);
418 } else {
419 base::StackString<64> fallback("Counter %d", cid);
420 name_id = context_->storage->InternString(fallback.string_view());
421 }
422 } else {
423 name_id = context_->storage->InternString(event.counter_name());
424 }
425 TrackId track =
426 context_->track_tracker->InternThreadCounterTrack(name_id, utid);
427 auto opt_id =
428 context_->event_tracker->PushCounter(ts, event.counter_value(), track);
429 if (opt_id) {
430 auto inserter = context_->args_tracker->AddArgsTo(*opt_id);
431 args_fn(&inserter);
432 }
433 }
434
435 if (event.has_overruns())
436 context_->storage->IncrementStats(stats::metatrace_overruns);
437 }
438
GetMetatraceInternedString(uint64_t iid)439 StringId ProtoTraceParser::GetMetatraceInternedString(uint64_t iid) {
440 StringId* maybe_id = metatrace_interned_strings_.Find(iid);
441 if (!maybe_id)
442 return missing_metatrace_interned_string_id_;
443 return *maybe_id;
444 }
445
446 } // namespace trace_processor
447 } // namespace perfetto
448