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/json/json_trace_parser_impl.h"
18
19 #include <cstdint>
20 #include <cstring>
21 #include <optional>
22 #include <string>
23 #include <utility>
24
25 #include "perfetto/base/logging.h"
26 #include "perfetto/base/status.h"
27 #include "perfetto/ext/base/hash.h"
28 #include "perfetto/ext/base/string_utils.h"
29 #include "perfetto/ext/base/string_view.h"
30 #include "src/trace_processor/importers/common/event_tracker.h"
31 #include "src/trace_processor/importers/common/flow_tracker.h"
32 #include "src/trace_processor/importers/common/legacy_v8_cpu_profile_tracker.h"
33 #include "src/trace_processor/importers/common/parser_types.h"
34 #include "src/trace_processor/importers/common/process_tracker.h"
35 #include "src/trace_processor/importers/common/slice_tracker.h"
36 #include "src/trace_processor/importers/common/track_tracker.h"
37 #include "src/trace_processor/importers/common/tracks.h"
38 #include "src/trace_processor/importers/common/tracks_common.h"
39 #include "src/trace_processor/importers/common/tracks_internal.h"
40 #include "src/trace_processor/importers/json/json_utils.h"
41 #include "src/trace_processor/importers/systrace/systrace_line.h"
42 #include "src/trace_processor/storage/stats.h"
43 #include "src/trace_processor/storage/trace_storage.h"
44 #include "src/trace_processor/tables/slice_tables_py.h"
45 #include "src/trace_processor/types/trace_processor_context.h"
46 #include "src/trace_processor/types/variadic.h"
47
48 namespace perfetto::trace_processor {
49
50 namespace {
51
MaybeExtractFlowIdentifier(const Json::Value & value,bool version2)52 std::optional<uint64_t> MaybeExtractFlowIdentifier(const Json::Value& value,
53 bool version2) {
54 std::string id_key = (version2 ? "bind_id" : "id");
55 if (!value.isMember(id_key))
56 return std::nullopt;
57 const auto& id = value[id_key];
58 if (id.isNumeric())
59 return id.asUInt64();
60 if (!id.isString())
61 return std::nullopt;
62 const char* c_string = id.asCString();
63 return base::CStringToUInt64(c_string, 16);
64 }
65
66 } // namespace
67
JsonTraceParserImpl(TraceProcessorContext * context)68 JsonTraceParserImpl::JsonTraceParserImpl(TraceProcessorContext* context)
69 : context_(context), systrace_line_parser_(context) {}
70
71 JsonTraceParserImpl::~JsonTraceParserImpl() = default;
72
ParseSystraceLine(int64_t,SystraceLine line)73 void JsonTraceParserImpl::ParseSystraceLine(int64_t, SystraceLine line) {
74 systrace_line_parser_.ParseLine(line);
75 }
76
ParseJsonPacket(int64_t timestamp,std::string string_value)77 void JsonTraceParserImpl::ParseJsonPacket(int64_t timestamp,
78 std::string string_value) {
79 PERFETTO_DCHECK(json::IsJsonSupported());
80
81 auto opt_value = json::ParseJsonString(base::StringView(string_value));
82 if (!opt_value) {
83 context_->storage->IncrementStats(stats::json_parser_failure);
84 return;
85 }
86
87 ProcessTracker* procs = context_->process_tracker.get();
88 TraceStorage* storage = context_->storage.get();
89 SliceTracker* slice_tracker = context_->slice_tracker.get();
90 FlowTracker* flow_tracker = context_->flow_tracker.get();
91
92 const Json::Value& value = *opt_value;
93 const auto& ph = value["ph"];
94 if (!ph.isString())
95 return;
96 char phase = *ph.asCString();
97
98 std::optional<uint32_t> opt_pid;
99 if (value.isMember("pid")) {
100 if (value["pid"].isString()) {
101 // If the pid is a string, treat raw id of the interned string as the pid.
102 // This "hack" which allows emitting "quick-and-dirty" compact JSON
103 // traces: relying on these traces for production is necessarily brittle
104 // as it is not a part of the actual spec.
105 const char* proc_name = value["pid"].asCString();
106 opt_pid = storage->InternString(proc_name).raw_id();
107 procs->SetProcessMetadata(*opt_pid, std::nullopt, proc_name,
108 base::StringView());
109 } else {
110 opt_pid = json::CoerceToUint32(value["pid"]);
111 }
112 }
113
114 std::optional<uint32_t> opt_tid;
115 if (value.isMember("tid")) {
116 if (value["tid"].isString()) {
117 // See the comment for |pid| string handling above: the same applies here.
118 StringId thread_name_id = storage->InternString(value["tid"].asCString());
119 opt_tid = thread_name_id.raw_id();
120 procs->UpdateThreadName(*opt_tid, thread_name_id,
121 ThreadNamePriority::kOther);
122 } else {
123 opt_tid = json::CoerceToUint32(value["tid"]);
124 }
125 }
126
127 uint32_t pid = opt_pid.value_or(0);
128 uint32_t tid = opt_tid.value_or(pid);
129 UniqueTid utid = procs->UpdateThread(tid, pid);
130
131 std::string id = value.isMember("id") ? value["id"].asString() : "";
132
133 base::StringView cat = value.isMember("cat") && value["cat"].isString()
134 ? base::StringView(value["cat"].asCString())
135 : base::StringView();
136 StringId cat_id = storage->InternString(cat);
137
138 base::StringView name = value.isMember("name")
139 ? base::StringView(value["name"].asCString())
140 : base::StringView();
141 StringId name_id = name.empty() ? kNullStringId : storage->InternString(name);
142
143 auto args_inserter = [this, &value](ArgsTracker::BoundInserter* inserter) {
144 if (value.isMember("args")) {
145 json::AddJsonValueToArgs(value["args"], /* flat_key = */ "args",
146 /* key = */ "args", context_->storage.get(),
147 inserter);
148 }
149 };
150
151 // Only used for 'B', 'E', and 'X' events so wrap in lambda so it gets
152 // ignored in other cases. This lambda is only safe to call within the
153 // scope of this function due to the capture by reference.
154 StringId slice_name_id =
155 name_id == kNullStringId ? storage->InternString("[No name]") : name_id;
156 switch (phase) {
157 case 'B': { // TRACE_EVENT_BEGIN.
158 TrackId track_id = context_->track_tracker->InternThreadTrack(utid);
159 auto slice_id = slice_tracker->Begin(timestamp, track_id, cat_id,
160 slice_name_id, args_inserter);
161 if (slice_id) {
162 if (auto thread_ts = json::CoerceToTs(value["tts"]); thread_ts) {
163 auto rr =
164 context_->storage->mutable_slice_table()->FindById(*slice_id);
165 rr->set_thread_ts(*thread_ts);
166 }
167 }
168 MaybeAddFlow(track_id, value);
169 break;
170 }
171 case 'E': { // TRACE_EVENT_END.
172 TrackId track_id = context_->track_tracker->InternThreadTrack(utid);
173 auto opt_slice_id = slice_tracker->End(timestamp, track_id, cat_id,
174 name_id, args_inserter);
175 // Now try to update thread_dur if we have a tts field.
176 auto opt_tts = json::CoerceToTs(value["tts"]);
177 if (opt_slice_id.has_value() && opt_tts) {
178 auto* slice = storage->mutable_slice_table();
179 auto rr = *slice->FindById(*opt_slice_id);
180 if (auto start_tts = rr.thread_ts(); start_tts) {
181 rr.set_thread_dur(*opt_tts - *start_tts);
182 }
183 }
184 break;
185 }
186 case 'b':
187 case 'e':
188 case 'n': {
189 Json::Value id2 = value.isMember("id2") ? value["id2"] : Json::Value();
190 std::string local = id2.isMember("local") ? id2["local"].asString() : "";
191 std::string global =
192 id2.isMember("global") ? id2["global"].asString() : "";
193 if (!opt_pid || (id.empty() && global.empty() && local.empty())) {
194 context_->storage->IncrementStats(stats::json_parser_failure);
195 break;
196 }
197 UniquePid upid = context_->process_tracker->GetOrCreateProcess(pid);
198 TrackId track_id;
199 if (!id.empty() || !global.empty()) {
200 const std::string& real_id = id.empty() ? global : id;
201 int64_t cookie = static_cast<int64_t>(
202 base::Hasher::Combine(cat_id.raw_id(), real_id));
203 track_id = context_->track_tracker->InternLegacyAsyncTrack(
204 name_id, upid, cookie, false /* source_id_is_process_scoped */,
205 kNullStringId /* source_scope */);
206 } else {
207 PERFETTO_DCHECK(!local.empty());
208 int64_t cookie =
209 static_cast<int64_t>(base::Hasher::Combine(cat_id.raw_id(), local));
210 track_id = context_->track_tracker->InternLegacyAsyncTrack(
211 name_id, upid, cookie, true /* source_id_is_process_scoped */,
212 kNullStringId /* source_scope */);
213 }
214
215 if (phase == 'b') {
216 slice_tracker->Begin(timestamp, track_id, cat_id, slice_name_id,
217 args_inserter);
218 MaybeAddFlow(track_id, value);
219 } else if (phase == 'e') {
220 slice_tracker->End(timestamp, track_id, cat_id, name_id, args_inserter);
221 // We don't handle tts here as we do in the 'E'
222 // case above as it's not well defined for aysnc slices.
223 } else {
224 context_->slice_tracker->Scoped(timestamp, track_id, cat_id, name_id, 0,
225 args_inserter);
226 MaybeAddFlow(track_id, value);
227 }
228 break;
229 }
230 case 'X': { // TRACE_EVENT (scoped event).
231 std::optional<int64_t> opt_dur = json::CoerceToTs(value["dur"]);
232 if (!opt_dur.has_value())
233 return;
234 TrackId track_id = context_->track_tracker->InternThreadTrack(utid);
235 auto slice_id = slice_tracker->Scoped(
236 timestamp, track_id, cat_id, slice_name_id, *opt_dur, args_inserter);
237 if (slice_id) {
238 auto rr = context_->storage->mutable_slice_table()->FindById(*slice_id);
239 if (auto thread_ts = json::CoerceToTs(value["tts"]); thread_ts) {
240 rr->set_thread_ts(*thread_ts);
241 }
242 if (auto thread_dur = json::CoerceToTs(value["tdur"]); thread_dur) {
243 rr->set_thread_dur(*thread_dur);
244 }
245 }
246 MaybeAddFlow(track_id, value);
247 break;
248 }
249 case 'C': { // TRACE_EVENT_COUNTER
250 auto args = value["args"];
251 if (!args.isObject()) {
252 context_->storage->IncrementStats(stats::json_parser_failure);
253 break;
254 }
255
256 std::string counter_name_prefix = name.ToStdString();
257 if (!id.empty()) {
258 counter_name_prefix += " id: " + id;
259 }
260
261 for (auto it = args.begin(); it != args.end(); ++it) {
262 double counter;
263 if (it->isString()) {
264 auto opt = base::CStringToDouble(it->asCString());
265 if (!opt.has_value()) {
266 context_->storage->IncrementStats(stats::json_parser_failure);
267 continue;
268 }
269 counter = opt.value();
270 } else if (it->isNumeric()) {
271 counter = it->asDouble();
272 } else {
273 context_->storage->IncrementStats(stats::json_parser_failure);
274 continue;
275 }
276 std::string counter_name = counter_name_prefix + " " + it.name();
277 StringId nid = context_->storage->InternString(counter_name);
278 context_->event_tracker->PushProcessCounterForThread(
279 EventTracker::JsonCounter{nid}, timestamp, counter, utid);
280 }
281 break;
282 }
283 case 'R':
284 case 'I':
285 case 'i': { // TRACE_EVENT_INSTANT
286 base::StringView scope;
287 if (value.isMember("s")) {
288 scope = value["s"].asCString();
289 }
290
291 TrackId track_id;
292 if (scope == "g") {
293 track_id = context_->track_tracker->InternTrack(
294 tracks::kLegacyGlobalInstantsBlueprint, tracks::Dimensions(),
295 tracks::BlueprintName(),
296 [this](ArgsTracker::BoundInserter& inserter) {
297 inserter.AddArg(
298 context_->storage->InternString("source"),
299 Variadic::String(context_->storage->InternString("chrome")));
300 });
301 } else if (scope == "p") {
302 if (!opt_pid) {
303 context_->storage->IncrementStats(stats::json_parser_failure);
304 break;
305 }
306 UniquePid upid = context_->process_tracker->GetOrCreateProcess(pid);
307 track_id = context_->track_tracker->InternTrack(
308 tracks::kChromeProcessInstantBlueprint, tracks::Dimensions(upid),
309 tracks::BlueprintName(),
310 [this](ArgsTracker::BoundInserter& inserter) {
311 inserter.AddArg(
312 context_->storage->InternString("source"),
313 Variadic::String(context_->storage->InternString("chrome")));
314 });
315 } else if (scope == "t" || scope.data() == nullptr) {
316 if (!opt_tid) {
317 context_->storage->IncrementStats(stats::json_parser_failure);
318 break;
319 }
320 track_id = context_->track_tracker->InternThreadTrack(utid);
321 auto slice_id = slice_tracker->Scoped(timestamp, track_id, cat_id,
322 slice_name_id, 0, args_inserter);
323 if (slice_id) {
324 if (auto thread_ts = json::CoerceToTs(value["tts"]); thread_ts) {
325 auto rr =
326 context_->storage->mutable_slice_table()->FindById(*slice_id);
327 rr->set_thread_ts(*thread_ts);
328 }
329 }
330 break;
331 } else {
332 context_->storage->IncrementStats(stats::json_parser_failure);
333 break;
334 }
335 context_->slice_tracker->Scoped(timestamp, track_id, cat_id, name_id, 0,
336 args_inserter);
337 break;
338 }
339 case 's': { // TRACE_EVENT_FLOW_START
340 TrackId track_id = context_->track_tracker->InternThreadTrack(utid);
341 auto opt_source_id =
342 MaybeExtractFlowIdentifier(value, /* version2 = */ false);
343 if (opt_source_id) {
344 FlowId flow_id = flow_tracker->GetFlowIdForV1Event(
345 opt_source_id.value(), cat_id, name_id);
346 flow_tracker->Begin(track_id, flow_id);
347 } else {
348 context_->storage->IncrementStats(stats::flow_invalid_id);
349 }
350 break;
351 }
352 case 't': { // TRACE_EVENT_FLOW_STEP
353 TrackId track_id = context_->track_tracker->InternThreadTrack(utid);
354 auto opt_source_id =
355 MaybeExtractFlowIdentifier(value, /* version2 = */ false);
356 if (opt_source_id) {
357 FlowId flow_id = flow_tracker->GetFlowIdForV1Event(
358 opt_source_id.value(), cat_id, name_id);
359 flow_tracker->Step(track_id, flow_id);
360 } else {
361 context_->storage->IncrementStats(stats::flow_invalid_id);
362 }
363 break;
364 }
365 case 'f': { // TRACE_EVENT_FLOW_END
366 TrackId track_id = context_->track_tracker->InternThreadTrack(utid);
367 auto opt_source_id =
368 MaybeExtractFlowIdentifier(value, /* version2 = */ false);
369 if (opt_source_id) {
370 FlowId flow_id = flow_tracker->GetFlowIdForV1Event(
371 opt_source_id.value(), cat_id, name_id);
372 bool bind_enclosing_slice =
373 value.isMember("bp") && strcmp(value["bp"].asCString(), "e") == 0;
374 flow_tracker->End(track_id, flow_id, bind_enclosing_slice,
375 /* close_flow = */ false);
376 } else {
377 context_->storage->IncrementStats(stats::flow_invalid_id);
378 }
379 break;
380 }
381 case 'M': { // Metadata events (process and thread names).
382 if (name == "thread_name" && !value["args"]["name"].empty()) {
383 const char* thread_name = value["args"]["name"].asCString();
384 auto thread_name_id = context_->storage->InternString(thread_name);
385 procs->UpdateThreadName(tid, thread_name_id,
386 ThreadNamePriority::kOther);
387 break;
388 }
389 if (name == "process_name" && !value["args"]["name"].empty()) {
390 const char* proc_name = value["args"]["name"].asCString();
391 procs->SetProcessMetadata(pid, std::nullopt, proc_name,
392 base::StringView());
393 break;
394 }
395 }
396 }
397 }
398
MaybeAddFlow(TrackId track_id,const Json::Value & event)399 void JsonTraceParserImpl::MaybeAddFlow(TrackId track_id,
400 const Json::Value& event) {
401 PERFETTO_DCHECK(json::IsJsonSupported());
402 auto opt_bind_id = MaybeExtractFlowIdentifier(event, /* version2 = */ true);
403 if (opt_bind_id) {
404 FlowTracker* flow_tracker = context_->flow_tracker.get();
405 bool flow_out = event.isMember("flow_out") && event["flow_out"].asBool();
406 bool flow_in = event.isMember("flow_in") && event["flow_in"].asBool();
407 if (flow_in && flow_out) {
408 flow_tracker->Step(track_id, opt_bind_id.value());
409 } else if (flow_out) {
410 flow_tracker->Begin(track_id, opt_bind_id.value());
411 } else if (flow_in) {
412 // bind_enclosing_slice is always true for v2 flow events
413 flow_tracker->End(track_id, opt_bind_id.value(), true,
414 /* close_flow = */ false);
415 } else {
416 context_->storage->IncrementStats(stats::flow_without_direction);
417 }
418 }
419 }
420
ParseLegacyV8ProfileEvent(int64_t ts,LegacyV8CpuProfileEvent event)421 void JsonTraceParserImpl::ParseLegacyV8ProfileEvent(
422 int64_t ts,
423 LegacyV8CpuProfileEvent event) {
424 base::Status status = context_->legacy_v8_cpu_profile_tracker->AddSample(
425 ts, event.session_id, event.pid, event.tid, event.callsite_id);
426 if (!status.ok()) {
427 context_->storage->IncrementStats(
428 stats::legacy_v8_cpu_profile_invalid_sample);
429 }
430 context_->args_tracker->Flush();
431 }
432
433 } // namespace perfetto::trace_processor
434