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/systrace/systrace_parser.h"
18
19 #include <cstdint>
20 #include <optional>
21 #include <string>
22 #include <vector>
23
24 #include "perfetto/ext/base/string_utils.h"
25 #include "perfetto/ext/base/string_view.h"
26 #include "src/trace_processor/importers/common/event_tracker.h"
27 #include "src/trace_processor/importers/common/process_tracker.h"
28 #include "src/trace_processor/importers/common/slice_tracker.h"
29 #include "src/trace_processor/importers/common/track_compressor.h"
30 #include "src/trace_processor/importers/common/track_tracker.h"
31 #include "src/trace_processor/importers/common/tracks.h"
32 #include "src/trace_processor/importers/common/tracks_common.h"
33 #include "src/trace_processor/importers/common/tracks_internal.h"
34 #include "src/trace_processor/storage/stats.h"
35 #include "src/trace_processor/storage/trace_storage.h"
36 #include "src/trace_processor/tables/slice_tables_py.h"
37 #include "src/trace_processor/types/variadic.h"
38
39 namespace perfetto::trace_processor {
40
SystraceParser(TraceProcessorContext * ctx)41 SystraceParser::SystraceParser(TraceProcessorContext* ctx)
42 : context_(ctx),
43 lmk_id_(ctx->storage->InternString("mem.lmk")),
44 cookie_id_(ctx->storage->InternString("cookie")),
45 utid_id_(ctx->storage->InternString("utid")),
46 end_utid_id_(ctx->storage->InternString("end_utid")) {}
47
48 SystraceParser::~SystraceParser() = default;
49
ParsePrintEvent(int64_t ts,uint32_t pid,base::StringView event)50 void SystraceParser::ParsePrintEvent(int64_t ts,
51 uint32_t pid,
52 base::StringView event) {
53 systrace_utils::SystraceTracePoint point{};
54 switch (ParseSystraceTracePoint(event, &point)) {
55 case systrace_utils::SystraceParseResult::kSuccess:
56 ParseSystracePoint(ts, pid, point);
57 break;
58 case systrace_utils::SystraceParseResult::kFailure:
59 context_->storage->IncrementStats(stats::systrace_parse_failure);
60 break;
61 case systrace_utils::SystraceParseResult::kUnsupported:
62 // Silently ignore unsupported results.
63 break;
64 }
65 }
66
ParseZeroEvent(int64_t ts,uint32_t pid,int32_t flag,base::StringView name,uint32_t tgid,int64_t value)67 void SystraceParser::ParseZeroEvent(int64_t ts,
68 uint32_t pid,
69 int32_t flag,
70 base::StringView name,
71 uint32_t tgid,
72 int64_t value) {
73 systrace_utils::SystraceTracePoint point{};
74 point.name = name;
75 point.int_value = value;
76 point.tgid = tgid;
77
78 // The value of these constants can be found in the msm-google kernel.
79 constexpr int32_t kSystraceEventBegin = 1 << 0;
80 constexpr int32_t kSystraceEventEnd = 1 << 1;
81 constexpr int32_t kSystraceEventInt64 = 1 << 2;
82
83 if ((flag & kSystraceEventBegin) != 0) {
84 point.phase = 'B';
85 } else if ((flag & kSystraceEventEnd) != 0) {
86 point.phase = 'E';
87 } else if ((flag & kSystraceEventInt64) != 0) {
88 point.phase = 'C';
89 } else {
90 context_->storage->IncrementStats(stats::systrace_parse_failure);
91 return;
92 }
93 // Note: for counter (C) events, we cannot assume that pid is within tgid.
94 // See ParseKernelTracingMarkWrite for rationale.
95 ParseSystracePoint(ts, pid, point);
96 }
97
ParseKernelTracingMarkWrite(int64_t ts,uint32_t pid,char trace_type,bool trace_begin,base::StringView trace_name,uint32_t tgid,int64_t value)98 void SystraceParser::ParseKernelTracingMarkWrite(int64_t ts,
99 uint32_t pid,
100 char trace_type,
101 bool trace_begin,
102 base::StringView trace_name,
103 uint32_t tgid,
104 int64_t value) {
105 systrace_utils::SystraceTracePoint point{};
106 point.name = trace_name;
107 point.int_value = value;
108 point.tgid = tgid;
109
110 // Some versions of this trace point fill trace_type with one of (B/E/C/I),
111 // others use the trace_begin boolean and only support begin/end events:
112 if (trace_type == 0) {
113 point.phase = trace_begin ? 'B' : 'E';
114 } else if (trace_type == 'B' || trace_type == 'E' || trace_type == 'C' ||
115 trace_type == 'I') {
116 point.phase = trace_type;
117 } else {
118 context_->storage->IncrementStats(stats::systrace_parse_failure);
119 return;
120 }
121
122 // Note: |pid| is the thread id of the emitting thread, |tgid| is taken from
123 // the event payload. The begin/end event kernel atrace macros seem well
124 // behaved (i.e. they always put current->tgid into the payload). However the
125 // counter events have cases where a placeholder/unrelated pid is used (e.g.
126 // 0, 1, or a specific kthread, see g2d_frame_* counters for an example).
127 //
128 // Further, the counter events expect to be grouped at the process (tgid)
129 // level (multiple distinct pids will be emitting values for the same
130 // logical counter).
131 //
132 // Therefore we must never assume that pid is within tgid for counter events,
133 // but still trust that the tgid value is for a valid process (which will
134 // usually fall onto swapper/init or some kthread) to have a
135 // process_counter_track for the counter values.
136 ParseSystracePoint(ts, pid, point);
137 }
138
139 // TODO(rsavitski): try to remove most special casing of tgid 0, as it is valid
140 // for kernel systrace points (due to systrace from interrupts).
141 // Note: ParseDpuTracingMarkWrite is further relying on tgid 0 hacks by setting
142 // that as the tgid for at least instant (I) events, but also overrides the
143 // value for B/E events.
ParseSystracePoint(int64_t ts,uint32_t pid,systrace_utils::SystraceTracePoint point)144 void SystraceParser::ParseSystracePoint(
145 int64_t ts,
146 uint32_t pid,
147 systrace_utils::SystraceTracePoint point) {
148 auto get_utid = [pid, &point, this]() {
149 if (point.tgid == 0)
150 return context_->process_tracker->GetOrCreateThread(pid);
151 return context_->process_tracker->UpdateThread(pid, point.tgid);
152 };
153
154 switch (point.phase) {
155 case 'B': {
156 StringId name_id = context_->storage->InternString(point.name);
157 UniqueTid utid = get_utid();
158 TrackId track_id = context_->track_tracker->InternThreadTrack(utid);
159 context_->slice_tracker->Begin(ts, track_id, kNullStringId /* cat */,
160 name_id);
161 PostProcessSpecialSliceBegin(ts, point.name);
162 break;
163 }
164
165 case 'E': {
166 // |point.tgid| can be 0 in older android versions where the end event
167 // would not contain the value.
168 UniqueTid utid;
169 if (point.tgid == 0) {
170 // If we haven't seen this thread before, there can't have been a Begin
171 // event for it so just ignore the event.
172 auto opt_utid = context_->process_tracker->GetThreadOrNull(pid);
173 if (!opt_utid)
174 break;
175 utid = *opt_utid;
176 } else {
177 utid = context_->process_tracker->UpdateThread(pid, point.tgid);
178 }
179 TrackId track_id = context_->track_tracker->InternThreadTrack(utid);
180 context_->slice_tracker->End(ts, track_id);
181 break;
182 }
183
184 case 'S':
185 case 'F': {
186 static constexpr auto kBlueprint = TrackCompressor::SliceBlueprint(
187 "atrace_async_slice",
188 tracks::DimensionBlueprints(tracks::kProcessDimensionBlueprint,
189 tracks::kNameFromTraceDimensionBlueprint),
190 tracks::DynamicNameBlueprint());
191
192 StringId name_id = context_->storage->InternString(point.name);
193 int64_t cookie = point.int_value;
194 UniquePid upid =
195 context_->process_tracker->GetOrCreateProcess(point.tgid);
196
197 if (point.phase == 'S') {
198 // Historically, async slices on Android did not support nesting async
199 // slices (i.e. you could not have a stack of async slices). If clients
200 // were implemented correctly, we would simply be able to use the normal
201 // Begin method and we could rely on the traced code to never emit two
202 // 'S' events back to back on the same track.
203 // However, there exists buggy code in Android (in Wakelock class of
204 // PowerManager) which emits an arbitrary number of 'S' events and
205 // expects only the first one to be tracked. Moreover, this issue is
206 // compounded by an unfortunate implementation of async slices in
207 // Catapult (the legacy trace viewer) which simply tracks the details of
208 // the *most recent* emitted 'S' event which leads even more inaccurate
209 // behaviour. To support these quirks, we have the special 'unnestable'
210 // slice concept which implements workarounds for these very specific
211 // issues. No other code should ever use |BeginLegacyUnnestable|.
212 tables::SliceTable::Row row;
213 row.ts = ts;
214 row.track_id = context_->track_compressor->InternBegin(
215 kBlueprint, tracks::Dimensions(upid, point.name), cookie,
216 tracks::DynamicName(name_id));
217 row.name = name_id;
218 context_->slice_tracker->BeginLegacyUnnestable(
219 row, [this, cookie](ArgsTracker::BoundInserter* inserter) {
220 inserter->AddArg(cookie_id_, Variadic::Integer(cookie));
221 });
222 } else {
223 TrackId track_id = context_->track_compressor->InternEnd(
224 kBlueprint, tracks::Dimensions(upid, point.name), cookie,
225 tracks::DynamicName(name_id));
226 context_->slice_tracker->End(ts, track_id);
227 }
228 break;
229 }
230
231 case 'I': {
232 StringId name_id = context_->storage->InternString(point.name);
233 UniqueTid utid = get_utid();
234 TrackId track_id = context_->track_tracker->InternThreadTrack(utid);
235 context_->slice_tracker->Scoped(ts, track_id, kNullStringId, name_id, 0);
236 break;
237 }
238
239 case 'N':
240 case 'G':
241 case 'H': {
242 StringId name_id = context_->storage->InternString(point.name);
243 StringId track_name_id = context_->storage->InternString(point.str_value);
244
245 // Promote DeviceStateChanged to its own top level track.
246 if (point.str_value == "DeviceStateChanged" && point.phase == 'N') {
247 TrackId track_id = context_->track_tracker->InternTrack(
248 tracks::kAndroidDeviceStateBlueprint);
249 context_->slice_tracker->Scoped(ts, track_id, kNullStringId, name_id,
250 0);
251 break;
252 }
253
254 static constexpr auto kBlueprint = TrackCompressor::SliceBlueprint(
255 "atrace_async_slice_for_track",
256 tracks::Dimensions(tracks::kProcessDimensionBlueprint,
257 tracks::kNameFromTraceDimensionBlueprint),
258 tracks::DynamicNameBlueprint());
259
260 UniquePid upid =
261 context_->process_tracker->GetOrCreateProcess(point.tgid);
262 if (point.phase == 'N') {
263 TrackId track_id = context_->track_compressor->InternScoped(
264 kBlueprint, tracks::Dimensions(upid, point.str_value), ts, 0,
265 tracks::DynamicName(track_name_id));
266 auto utid = context_->process_tracker->GetOrCreateThread(pid);
267 context_->slice_tracker->Scoped(
268 ts, track_id, kNullStringId, name_id, 0,
269 [this, utid](ArgsTracker::BoundInserter* inserter) {
270 inserter->AddArg(utid_id_, Variadic::UnsignedInteger(utid),
271 ArgsTracker::UpdatePolicy::kSkipIfExists);
272 });
273 } else if (point.phase == 'G') {
274 TrackId track_id = context_->track_compressor->InternBegin(
275 kBlueprint, tracks::Dimensions(upid, point.str_value),
276 point.int_value, tracks::DynamicName(track_name_id));
277 auto utid = context_->process_tracker->GetOrCreateThread(pid);
278 context_->slice_tracker->Begin(
279 ts, track_id, kNullStringId, name_id,
280 [this, utid](ArgsTracker::BoundInserter* inserter) {
281 inserter->AddArg(utid_id_, Variadic::UnsignedInteger(utid),
282 ArgsTracker::UpdatePolicy::kSkipIfExists);
283 });
284 } else if (point.phase == 'H') {
285 TrackId track_id = context_->track_compressor->InternEnd(
286 kBlueprint, tracks::Dimensions(upid, point.str_value),
287 point.int_value, tracks::DynamicName(track_name_id));
288 auto utid = context_->process_tracker->GetOrCreateThread(pid);
289 context_->slice_tracker->End(
290 ts, track_id, {}, {},
291 [this, utid](ArgsTracker::BoundInserter* inserter) {
292 inserter->AddArg(end_utid_id_, Variadic::UnsignedInteger(utid),
293 ArgsTracker::UpdatePolicy::kSkipIfExists);
294 });
295 }
296 break;
297 }
298
299 // Warning: counter event handling must never assume that the |pid| thread
300 // is within the |tgid| process due to kernel systrace quirks. If you need
301 // to change this, update ParseKernelTracingMarkWrite and ParseZeroEvent to
302 // pretend that pid is the same as tgid for C events.
303 case 'C': {
304 // LMK events from userspace are hacked as counter events with the "value"
305 // of the counter representing the pid of the killed process which is
306 // reset to 0 once the kill is complete.
307 // Homogenise this with kernel LMK events as an instant event, ignoring
308 // the resets to 0.
309 if (point.name == "kill_one_process") {
310 auto killed_pid = static_cast<uint32_t>(point.int_value);
311 if (killed_pid != 0) {
312 UniquePid killed_upid =
313 context_->process_tracker->GetOrCreateProcess(killed_pid);
314 TrackId track = context_->track_tracker->InternTrack(
315 tracks::kAndroidLmkBlueprint, tracks::Dimensions(killed_upid));
316 context_->slice_tracker->Scoped(ts, track, kNullStringId, lmk_id_, 0);
317 }
318 // TODO(lalitm): we should not add LMK events to the counters table
319 // once the UI has support for displaying instants.
320 } else if (point.name == "ScreenState") {
321 // Promote ScreenState to its own top level counter.
322 TrackId track = context_->track_tracker->InternTrack(
323 tracks::kAndroidScreenStateBlueprint);
324 context_->event_tracker->PushCounter(
325 ts, static_cast<double>(point.int_value), track);
326 return;
327 } else if (point.name.StartsWith("battery_stats.")) {
328 // Promote battery_stats conters to global tracks.
329 TrackId track = context_->track_tracker->InternTrack(
330 tracks::kAndroidBatteryStatsBlueprint,
331 tracks::Dimensions(point.name));
332 context_->event_tracker->PushCounter(
333 ts, static_cast<double>(point.int_value), track);
334 return;
335 }
336
337 // This is per upid on purpose. Some long-standing counters are pushed
338 // from arbitrary threads but expect to be per process (b/123560328).
339 // This affects both userspace and kernel counters.
340 UniquePid upid =
341 context_->process_tracker->GetOrCreateProcess(point.tgid);
342 auto opt_utid = context_->process_tracker->GetThreadOrNull(pid);
343 TrackId track_id = context_->track_tracker->InternTrack(
344 tracks::kAndroidAtraceCounterBlueprint,
345 tracks::Dimensions(upid, point.name));
346 context_->event_tracker->PushCounter(
347 ts, static_cast<double>(point.int_value), track_id,
348 [this, opt_utid](ArgsTracker::BoundInserter* inserter) {
349 if (opt_utid) {
350 inserter->AddArg(utid_id_, Variadic::UnsignedInteger(*opt_utid),
351 ArgsTracker::UpdatePolicy::kSkipIfExists);
352 }
353 });
354 }
355 }
356 }
357
PostProcessSpecialSliceBegin(int64_t ts,base::StringView name)358 void SystraceParser::PostProcessSpecialSliceBegin(int64_t ts,
359 base::StringView name) {
360 if (name.StartsWith("lmk,")) {
361 // LMK events introduced with http://aosp/1782391 are treated specially
362 // to parse the killed process oom_score_adj out of them.
363 // Format is 'lmk,pid,reason,oom adj,...'
364 std::vector<std::string> toks = base::SplitString(name.ToStdString(), ",");
365 if (toks.size() < 4) {
366 return;
367 }
368 auto killed_pid = base::StringToUInt32(toks[1]);
369 auto oom_score_adj = base::StringToInt32(toks[3]);
370 if (!killed_pid || !oom_score_adj) {
371 return;
372 }
373
374 UniquePid killed_upid =
375 context_->process_tracker->GetOrCreateProcess(*killed_pid);
376
377 // Add the oom score entry
378 TrackId counter_track = context_->track_tracker->InternTrack(
379 tracks::kOomScoreAdjBlueprint, tracks::Dimensions(killed_upid));
380 context_->event_tracker->PushCounter(ts, *oom_score_adj, counter_track);
381
382 // Add mem.lmk instant event for consistency with other methods.
383 TrackId track = context_->track_tracker->InternTrack(
384 tracks::kAndroidLmkBlueprint, tracks::Dimensions(killed_upid));
385 context_->slice_tracker->Scoped(ts, track, kNullStringId, lmk_id_, 0);
386 }
387 }
388
389 } // namespace perfetto::trace_processor
390