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 "perfetto/ext/base/optional.h"
20 #include "perfetto/ext/base/string_utils.h"
21 #include "src/trace_processor/importers/common/event_tracker.h"
22 #include "src/trace_processor/importers/common/process_tracker.h"
23 #include "src/trace_processor/importers/common/slice_tracker.h"
24 #include "src/trace_processor/importers/common/track_tracker.h"
25 #include "src/trace_processor/importers/proto/async_track_set_tracker.h"
26 #include "src/trace_processor/storage/trace_storage.h"
27
28 namespace perfetto {
29 namespace trace_processor {
30
SystraceParser(TraceProcessorContext * ctx)31 SystraceParser::SystraceParser(TraceProcessorContext* ctx)
32 : context_(ctx),
33 lmk_id_(ctx->storage->InternString("mem.lmk")),
34 oom_score_adj_id_(ctx->storage->InternString("oom_score_adj")),
35 screen_state_id_(ctx->storage->InternString("ScreenState")),
36 cookie_id_(ctx->storage->InternString("cookie")) {}
37
38 SystraceParser::~SystraceParser() = default;
39
ParsePrintEvent(int64_t ts,uint32_t pid,base::StringView event)40 void SystraceParser::ParsePrintEvent(int64_t ts,
41 uint32_t pid,
42 base::StringView event) {
43 systrace_utils::SystraceTracePoint point{};
44 switch (ParseSystraceTracePoint(event, &point)) {
45 case systrace_utils::SystraceParseResult::kSuccess:
46 ParseSystracePoint(ts, pid, point);
47 break;
48 case systrace_utils::SystraceParseResult::kFailure:
49 context_->storage->IncrementStats(stats::systrace_parse_failure);
50 break;
51 case systrace_utils::SystraceParseResult::kUnsupported:
52 // Silently ignore unsupported results.
53 break;
54 }
55 }
56
ParseZeroEvent(int64_t ts,uint32_t pid,int32_t flag,base::StringView name,uint32_t,int64_t value)57 void SystraceParser::ParseZeroEvent(int64_t ts,
58 uint32_t pid,
59 int32_t flag,
60 base::StringView name,
61 uint32_t /* tgid */,
62 int64_t value) {
63 systrace_utils::SystraceTracePoint point{};
64 point.name = name;
65 point.int_value = value;
66
67 // Hardcode the tgid to 0 (i.e. no tgid available) because zero events can
68 // come from kernel threads and as we group kernel threads into the kthreadd
69 // process, we would want |point.tgid == kKthreaddPid|. However, we don't have
70 // acces to the ppid of this process so we have to not associate to any
71 // process and leave the resolution of process to other events.
72 // TODO(lalitm): remove this hack once we move kernel thread grouping to
73 // the UI.
74 point.tgid = 0;
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 ParseSystracePoint(ts, pid, point);
92 }
93
ParseTracingMarkWrite(int64_t ts,uint32_t pid,char trace_type,bool trace_begin,base::StringView trace_name,uint32_t,int64_t value)94 void SystraceParser::ParseTracingMarkWrite(int64_t ts,
95 uint32_t pid,
96 char trace_type,
97 bool trace_begin,
98 base::StringView trace_name,
99 uint32_t /* tgid */,
100 int64_t value) {
101 systrace_utils::SystraceTracePoint point{};
102 point.name = trace_name;
103
104 // Hardcode the tgid to 0 (i.e. no tgid available) because
105 // sde_tracing_mark_write events can come from kernel threads and because we
106 // group kernel threads into the kthreadd process, we would want |point.tgid
107 // == kKthreaddPid|. However, we don't have acces to the ppid of this process
108 // so we have to not associate to any process and leave the resolution of
109 // process to other events.
110 // TODO(lalitm): remove this hack once we move kernel thread grouping to
111 // the UI.
112 point.tgid = 0;
113
114 point.int_value = value;
115 // Some versions of this trace point fill trace_type with one of (B/E/C),
116 // others use the trace_begin boolean and only support begin/end events:
117 if (trace_type == 0) {
118 point.phase = trace_begin ? 'B' : 'E';
119 } else if (trace_type == 'B' || trace_type == 'E' || trace_type == 'C') {
120 point.phase = trace_type;
121 } else {
122 context_->storage->IncrementStats(stats::systrace_parse_failure);
123 return;
124 }
125
126 ParseSystracePoint(ts, pid, point);
127 }
128
ParseSystracePoint(int64_t ts,uint32_t pid,systrace_utils::SystraceTracePoint point)129 void SystraceParser::ParseSystracePoint(
130 int64_t ts,
131 uint32_t pid,
132 systrace_utils::SystraceTracePoint point) {
133 auto get_utid = [pid, &point, this]() {
134 if (point.tgid == 0)
135 return context_->process_tracker->GetOrCreateThread(pid);
136 return context_->process_tracker->UpdateThread(pid, point.tgid);
137 };
138
139 switch (point.phase) {
140 case 'B': {
141 StringId name_id = context_->storage->InternString(point.name);
142 UniqueTid utid = get_utid();
143 TrackId track_id = context_->track_tracker->InternThreadTrack(utid);
144 context_->slice_tracker->Begin(ts, track_id, kNullStringId /* cat */,
145 name_id);
146 PostProcessSpecialSliceBegin(ts, point.name);
147 break;
148 }
149
150 case 'E': {
151 // |point.tgid| can be 0 in older android versions where the end event
152 // would not contain the value.
153 UniqueTid utid;
154 if (point.tgid == 0) {
155 // If we haven't seen this thread before, there can't have been a Begin
156 // event for it so just ignore the event.
157 auto opt_utid = context_->process_tracker->GetThreadOrNull(pid);
158 if (!opt_utid)
159 break;
160 utid = *opt_utid;
161 } else {
162 utid = context_->process_tracker->UpdateThread(pid, point.tgid);
163 }
164 TrackId track_id = context_->track_tracker->InternThreadTrack(utid);
165 context_->slice_tracker->End(ts, track_id);
166 break;
167 }
168
169 case 'S':
170 case 'F': {
171 StringId name_id = context_->storage->InternString(point.name);
172 int64_t cookie = point.int_value;
173 UniquePid upid =
174 context_->process_tracker->GetOrCreateProcess(point.tgid);
175
176 auto track_set_id =
177 context_->async_track_set_tracker
178 ->InternAndroidLegacyUnnestableTrackSet(upid, name_id);
179
180 if (point.phase == 'S') {
181 // Historically, async slices on Android did not support nesting async
182 // slices (i.e. you could not have a stack of async slices). If clients
183 // were implemented correctly, we would simply be able to use the normal
184 // Begin method and we could rely on the traced code to never emit two
185 // 'S' events back to back on the same track.
186 // However, there exists buggy code in Android (in Wakelock class of
187 // PowerManager) which emits an arbitrary number of 'S' events and
188 // expects only the first one to be tracked. Moreover, this issue is
189 // compounded by an unfortunate implementation of async slices in
190 // Catapult (the legacy trace viewer) which simply tracks the details of
191 // the *most recent* emitted 'S' event which leads even more inaccurate
192 // behaviour. To support these quirks, we have the special 'unnestable'
193 // slice concept which implements workarounds for these very specific
194 // issues. No other code should ever use |BeginLegacyUnnestable|.
195 tables::SliceTable::Row row;
196 row.ts = ts;
197 row.track_id =
198 context_->async_track_set_tracker->Begin(track_set_id, cookie);
199 row.name = name_id;
200 context_->slice_tracker->BeginLegacyUnnestable(
201 row, [this, cookie](ArgsTracker::BoundInserter* inserter) {
202 inserter->AddArg(cookie_id_, Variadic::Integer(cookie));
203 });
204 } else {
205 TrackId track_id =
206 context_->async_track_set_tracker->End(track_set_id, cookie);
207 context_->slice_tracker->End(ts, track_id);
208 }
209 break;
210 }
211
212 case 'I': {
213 StringId name_id = context_->storage->InternString(point.name);
214 UniqueTid utid = get_utid();
215 TrackId track_id = context_->track_tracker->InternThreadTrack(utid);
216 context_->slice_tracker->Scoped(ts, track_id, kNullStringId, name_id, 0);
217 break;
218 }
219
220 case 'N':
221 case 'T':
222 case 'U': {
223 StringId name_id = context_->storage->InternString(point.name);
224 StringId track_name_id = context_->storage->InternString(point.str_value);
225 UniquePid upid =
226 context_->process_tracker->GetOrCreateProcess(point.tgid);
227 auto track_set_id =
228 context_->async_track_set_tracker->InternProcessTrackSet(
229 upid, track_name_id);
230
231 if (point.phase == 'N') {
232 TrackId track_id =
233 context_->async_track_set_tracker->Scoped(track_set_id, ts, 0);
234 context_->slice_tracker->Scoped(ts, track_id, kNullStringId, name_id,
235 0);
236 } else if (point.phase == 'T') {
237 TrackId track_id = context_->async_track_set_tracker->Begin(
238 track_set_id, point.int_value);
239 context_->slice_tracker->Begin(ts, track_id, kNullStringId, name_id);
240 } else if (point.phase == 'U') {
241 TrackId track_id = context_->async_track_set_tracker->End(
242 track_set_id, point.int_value);
243 context_->slice_tracker->End(ts, track_id);
244 }
245 break;
246 }
247
248 case 'C': {
249 // LMK events from userspace are hacked as counter events with the "value"
250 // of the counter representing the pid of the killed process which is
251 // reset to 0 once the kill is complete.
252 // Homogenise this with kernel LMK events as an instant event, ignoring
253 // the resets to 0.
254 if (point.name == "kill_one_process") {
255 auto killed_pid = static_cast<uint32_t>(point.int_value);
256 if (killed_pid != 0) {
257 UniquePid killed_upid =
258 context_->process_tracker->GetOrCreateProcess(killed_pid);
259 context_->event_tracker->PushInstant(ts, lmk_id_, killed_upid,
260 RefType::kRefUpid);
261 }
262 // TODO(lalitm): we should not add LMK events to the counters table
263 // once the UI has support for displaying instants.
264 } else if (point.name == "ScreenState") {
265 // Promote ScreenState to its own top level counter.
266 TrackId track =
267 context_->track_tracker->InternGlobalCounterTrack(screen_state_id_);
268 context_->event_tracker->PushCounter(
269 ts, static_cast<double>(point.int_value), track);
270 return;
271 }
272
273 StringId name_id = context_->storage->InternString(point.name);
274 TrackId track_id;
275 if (point.tgid == 0) {
276 // If tgid is 0 (likely because this is a kernel thread), we can do no
277 // better than using a thread track with the pid of the process.
278 UniqueTid utid = context_->process_tracker->GetOrCreateThread(pid);
279 track_id =
280 context_->track_tracker->InternThreadCounterTrack(name_id, utid);
281 } else {
282 // This is per upid on purpose. Some counters are pushed from arbitrary
283 // threads but are really per process.
284 UniquePid upid =
285 context_->process_tracker->GetOrCreateProcess(point.tgid);
286 track_id =
287 context_->track_tracker->InternProcessCounterTrack(name_id, upid);
288 }
289 context_->event_tracker->PushCounter(
290 ts, static_cast<double>(point.int_value), track_id);
291 }
292 }
293 }
294
PostProcessSpecialSliceBegin(int64_t ts,base::StringView name)295 void SystraceParser::PostProcessSpecialSliceBegin(int64_t ts,
296 base::StringView name) {
297 if (name.StartsWith("lmk,")) {
298 // LMK events introduced with http://aosp/1782391 are treated specially
299 // to parse the killed process oom_score_adj out of them.
300 // Format is 'lmk,pid,reason,oom adj,...'
301 std::vector<std::string> toks = base::SplitString(name.ToStdString(), ",");
302 if (toks.size() < 4) {
303 return;
304 }
305 auto killed_pid = base::StringToUInt32(toks[1]);
306 auto oom_score_adj = base::StringToInt32(toks[3]);
307 if (!killed_pid || !oom_score_adj) {
308 return;
309 }
310
311 UniquePid killed_upid =
312 context_->process_tracker->GetOrCreateProcess(*killed_pid);
313 // Add the oom score entry
314 TrackId track = context_->track_tracker->InternProcessCounterTrack(
315 oom_score_adj_id_, killed_upid);
316 context_->event_tracker->PushCounter(ts, *oom_score_adj, track);
317
318 // Add mem.lmk instant event for consistency with other methods.
319 context_->event_tracker->PushInstant(ts, lmk_id_, killed_upid,
320 RefType::kRefUpid);
321 }
322 }
323
324 } // namespace trace_processor
325 } // namespace perfetto
326