xref: /aosp_15_r20/external/perfetto/src/trace_processor/importers/systrace/systrace_parser.cc (revision 6dbdd20afdafa5e3ca9b8809fa73465d530080dc) 
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