• 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 <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