• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
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