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