1 /*
2 * Copyright (C) 2019 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/proto/graphics_frame_event_parser.h"
18
19 #include <algorithm>
20 #include <cstddef>
21 #include <cstdint>
22 #include <optional>
23 #include <string>
24 #include <utility>
25 #include <variant>
26
27 #include "perfetto/base/logging.h"
28 #include "perfetto/ext/base/string_utils.h"
29 #include "perfetto/ext/base/string_view.h"
30 #include "src/trace_processor/importers/common/args_tracker.h"
31 #include "src/trace_processor/importers/common/event_tracker.h"
32 #include "src/trace_processor/importers/common/slice_tracker.h"
33 #include "src/trace_processor/importers/common/track_tracker.h"
34 #include "src/trace_processor/importers/common/tracks.h"
35 #include "src/trace_processor/importers/common/tracks_common.h"
36 #include "src/trace_processor/storage/stats.h"
37 #include "src/trace_processor/storage/trace_storage.h"
38 #include "src/trace_processor/tables/slice_tables_py.h"
39 #include "src/trace_processor/types/trace_processor_context.h"
40 #include "src/trace_processor/types/variadic.h"
41
42 #include "protos/perfetto/trace/android/graphics_frame_event.pbzero.h"
43
44 namespace perfetto::trace_processor {
45
46 namespace {
47
48 constexpr char kQueueLostMessage[] =
49 "Missing queue event. The slice is now a bit extended than it might "
50 "actually have been";
51
52 constexpr auto kGraphicFrameEventBlueprint = tracks::SliceBlueprint(
53 "graphics_frame_event",
54 tracks::DimensionBlueprints(tracks::kNameFromTraceDimensionBlueprint),
55 tracks::DynamicNameBlueprint());
56
57 } // namespace
58
GraphicsFrameEventParser(TraceProcessorContext * context)59 GraphicsFrameEventParser::GraphicsFrameEventParser(
60 TraceProcessorContext* context)
61 : context_(context),
62 unknown_event_name_id_(context->storage->InternString("unknown_event")),
63 no_layer_name_name_id_(context->storage->InternString("no_layer_name")),
64 layer_name_key_id_(context->storage->InternString("layer_name")),
65 queue_lost_message_id_(context->storage->InternString(kQueueLostMessage)),
66 frame_number_id_(context->storage->InternString("frame_number")),
67 queue_to_acquire_time_id_(
68 context->storage->InternString("queue_to_acquire_time")),
69 acquire_to_latch_time_id_(
70 context->storage->InternString("acquire_to_latch_time")),
71 latch_to_present_time_id_(
72 context->storage->InternString("latch_to_present_time")),
73 event_type_name_ids_{
74 {context->storage->InternString(
75 "unspecified_event") /* UNSPECIFIED */,
76 context->storage->InternString("Dequeue") /* DEQUEUE */,
77 context->storage->InternString("Queue") /* QUEUE */,
78 context->storage->InternString("Post") /* POST */,
79 context->storage->InternString(
80 "AcquireFenceSignaled") /* ACQUIRE_FENCE */,
81 context->storage->InternString("Latch") /* LATCH */,
82 context->storage->InternString(
83 "HWCCompositionQueued") /* HWC_COMPOSITION_QUEUED */,
84 context->storage->InternString(
85 "FallbackComposition") /* FALLBACK_COMPOSITION */,
86 context->storage->InternString(
87 "PresentFenceSignaled") /* PRESENT_FENCE */,
88 context->storage->InternString(
89 "ReleaseFenceSignaled") /* RELEASE_FENCE */,
90 context->storage->InternString("Modify") /* MODIFY */,
91 context->storage->InternString("Detach") /* DETACH */,
92 context->storage->InternString("Attach") /* ATTACH */,
93 context->storage->InternString("Cancel") /* CANCEL */}} {}
94
ParseGraphicsFrameEvent(int64_t timestamp,ConstBytes blob)95 void GraphicsFrameEventParser::ParseGraphicsFrameEvent(int64_t timestamp,
96 ConstBytes blob) {
97 protos::pbzero::GraphicsFrameEvent::Decoder frame_event(blob);
98 if (!frame_event.has_buffer_event()) {
99 return;
100 }
101
102 protos::pbzero::GraphicsFrameEvent::BufferEvent::Decoder event(
103 frame_event.buffer_event());
104 if (!event.has_buffer_id()) {
105 context_->storage->IncrementStats(
106 stats::graphics_frame_event_parser_errors);
107 return;
108 }
109
110 // Use buffer id + layer name as key because sometimes the same buffer can be
111 // used by different layers.
112 StringId layer_name_id;
113 StringId event_key;
114 if (event.has_layer_name()) {
115 layer_name_id = context_->storage->InternString(event.layer_name());
116 base::StackString<1024> key_str("%u%.*s", event.buffer_id(),
117 int(event.layer_name().size),
118 event.layer_name().data);
119 event_key = context_->storage->InternString(key_str.string_view());
120 } else {
121 layer_name_id = no_layer_name_name_id_;
122 event_key = context_->storage->InternString(
123 base::StackString<1024>("%u", event.buffer_id()).string_view());
124 }
125
126 CreateBufferEvent(timestamp, event, layer_name_id, event_key);
127 CreatePhaseEvent(timestamp, event, layer_name_id, event_key);
128 }
129
CreateBufferEvent(int64_t timestamp,const GraphicsFrameEventDecoder & event,StringId layer_name_id,StringId event_key)130 void GraphicsFrameEventParser::CreateBufferEvent(
131 int64_t timestamp,
132 const GraphicsFrameEventDecoder& event,
133 StringId layer_name_id,
134 StringId event_key) {
135 auto* it = buffer_event_map_.Insert(event_key, {}).first;
136 switch (event.type()) {
137 case GraphicsFrameEvent::DEQUEUE:
138 break;
139 case GraphicsFrameEvent::ACQUIRE_FENCE:
140 it->acquire_ts = timestamp;
141 break;
142 case GraphicsFrameEvent::QUEUE:
143 it->queue_ts = timestamp;
144 break;
145 case GraphicsFrameEvent::LATCH:
146 it->latch_ts = timestamp;
147 break;
148 default:
149 context_->storage->IncrementStats(
150 stats::graphics_frame_event_parser_errors);
151 break;
152 }
153 bool prev_is_dequeue = it->is_most_recent_dequeue_;
154 it->is_most_recent_dequeue_ =
155 event.type() ==
156 protos::pbzero::GraphicsFrameEvent::BufferEventType::DEQUEUE;
157
158 StringId event_name_id;
159 if (event.has_type() &&
160 static_cast<uint32_t>(event.type()) < event_type_name_ids_.size()) {
161 event_name_id = event_type_name_ids_[static_cast<uint32_t>(event.type())];
162 } else {
163 event_name_id = unknown_event_name_id_;
164 }
165
166 base::StackString<4096> track_name("Buffer: %u %.*s", event.buffer_id(),
167 int(event.layer_name().size),
168 event.layer_name().data);
169 TrackId track_id = context_->track_tracker->InternTrack(
170 kGraphicFrameEventBlueprint, tracks::Dimensions(track_name.string_view()),
171 tracks::DynamicName(
172 context_->storage->InternString(track_name.string_view())));
173
174 // Update the frame number for the previous dequeue event.
175 uint32_t frame_number = event.has_frame_number() ? event.frame_number() : 0;
176 if (event.type() == GraphicsFrameEvent::QUEUE && prev_is_dequeue) {
177 context_->slice_tracker->AddArgs(
178 track_id, kNullStringId, kNullStringId,
179 [&](ArgsTracker::BoundInserter* inserter) {
180 inserter->AddArg(frame_number_id_, Variadic::Integer(frame_number));
181 });
182 }
183
184 const int64_t duration =
185 event.has_duration_ns() ? static_cast<int64_t>(event.duration_ns()) : 0;
186 context_->slice_tracker->Scoped(
187 timestamp, track_id, kNullStringId, event_name_id, duration,
188 [&](ArgsTracker::BoundInserter* inserter) {
189 inserter->AddArg(frame_number_id_, Variadic::Integer(frame_number));
190 inserter->AddArg(layer_name_key_id_, Variadic::String(layer_name_id));
191 inserter->AddArg(
192 queue_to_acquire_time_id_,
193 Variadic::Integer(std::max(it->acquire_ts - it->queue_ts,
194 static_cast<int64_t>(0))));
195 inserter->AddArg(acquire_to_latch_time_id_,
196 Variadic::Integer(it->latch_ts - it->acquire_ts));
197 inserter->AddArg(latch_to_present_time_id_,
198 Variadic::Integer(timestamp - it->latch_ts));
199 });
200 }
201
202 // Here we convert the buffer events into Phases(slices)
203 // APP: Dequeue to Queue
204 // Wait for GPU: Queue to Acquire
205 // SurfaceFlinger (SF): Latch to Present
206 // Display: Present to next Present (of the same layer)
CreatePhaseEvent(int64_t timestamp,const GraphicsFrameEventDecoder & event,StringId layer_name_id,StringId event_key)207 void GraphicsFrameEventParser::CreatePhaseEvent(
208 int64_t timestamp,
209 const GraphicsFrameEventDecoder& event,
210 StringId layer_name_id,
211 StringId event_key) {
212 auto* slices = context_->storage->mutable_slice_table();
213 auto [it, inserted] = phase_event_map_.Insert(event_key, {});
214 switch (event.type()) {
215 case GraphicsFrameEvent::DEQUEUE: {
216 if (auto* d = std::get_if<DequeueInfo>(&it->most_recent_event)) {
217 // Error handling
218 auto rr = d->slice_row.ToRowReference(slices);
219 rr.set_name(context_->storage->InternString("0"));
220 context_->slice_tracker->AddArgs(
221 rr.track_id(), kNullStringId, kNullStringId,
222 [&](ArgsTracker::BoundInserter* inserter) {
223 inserter->AddArg(frame_number_id_, Variadic::Integer(0));
224 });
225 it->most_recent_event = std::monostate();
226 }
227
228 base::StackString<1024> track_name("APP_%u %.*s", event.buffer_id(),
229 int(event.layer_name().size),
230 event.layer_name().data);
231 TrackId track_id = context_->track_tracker->InternTrack(
232 kGraphicFrameEventBlueprint,
233 tracks::Dimensions(track_name.string_view()),
234 tracks::DynamicName(
235 context_->storage->InternString(track_name.string_view())));
236 auto res = InsertPhaseSlice(timestamp, event, track_id, layer_name_id);
237 if (res) {
238 it->most_recent_event = DequeueInfo{*res, timestamp};
239 }
240 break;
241 }
242 case GraphicsFrameEvent::QUEUE: {
243 if (auto* d = std::get_if<DequeueInfo>(&it->most_recent_event)) {
244 auto slice_rr = d->slice_row.ToRowReference(slices);
245 context_->slice_tracker->End(
246 timestamp, slice_rr.track_id(), kNullStringId, kNullStringId,
247 [&](ArgsTracker::BoundInserter* inserter) {
248 inserter->AddArg(frame_number_id_,
249 Variadic::Integer(event.frame_number()));
250 });
251
252 // Set the name of the slice to be the frame number since dequeue did
253 // not have a frame number at that time.
254 slice_rr.set_name(context_->storage->InternString(
255 std::to_string(event.frame_number())));
256
257 // The AcquireFence might be signaled before receiving a QUEUE event
258 // sometimes. In that case, we shouldn't start a slice.
259 if (it->last_acquire_ts && *it->last_acquire_ts > d->timestamp) {
260 it->most_recent_event = std::monostate();
261 return;
262 }
263 }
264 base::StackString<1024> track_name("GPU_%u %.*s", event.buffer_id(),
265 int(event.layer_name().size),
266 event.layer_name().data);
267 StringId track_name_id =
268 context_->storage->InternString(track_name.string_view());
269 TrackId track_id = context_->track_tracker->InternTrack(
270 kGraphicFrameEventBlueprint,
271 tracks::Dimensions(track_name.string_view()),
272 tracks::DynamicName(track_name_id));
273 InsertPhaseSlice(timestamp, event, track_id, layer_name_id);
274 it->most_recent_event = QueueInfo{track_id};
275 break;
276 }
277 case GraphicsFrameEvent::ACQUIRE_FENCE: {
278 if (auto* q = std::get_if<QueueInfo>(&it->most_recent_event)) {
279 context_->slice_tracker->End(timestamp, q->track);
280 it->most_recent_event = std::monostate();
281 }
282 it->last_acquire_ts = timestamp;
283 break;
284 }
285 case GraphicsFrameEvent::LATCH: {
286 // b/157578286 - Sometimes Queue event goes missing. To prevent having a
287 // wrong slice info, we try to close any existing APP slice.
288 if (auto* d = std::get_if<DequeueInfo>(&it->most_recent_event)) {
289 auto rr = d->slice_row.ToRowReference(slices);
290 rr.set_name(context_->storage->InternString("0"));
291 context_->slice_tracker->AddArgs(
292 rr.track_id(), kNullStringId, kNullStringId,
293 [&](ArgsTracker::BoundInserter* inserter) {
294 inserter->AddArg(frame_number_id_, Variadic::Integer(0));
295 });
296 }
297 base::StackString<1024> track_name("SF_%u %.*s", event.buffer_id(),
298 int(event.layer_name().size),
299 event.layer_name().data);
300 TrackId track_id = context_->track_tracker->InternTrack(
301 kGraphicFrameEventBlueprint,
302 tracks::Dimensions(track_name.string_view()),
303 tracks::DynamicName(
304 context_->storage->InternString(track_name.string_view())));
305 InsertPhaseSlice(timestamp, event, track_id, layer_name_id);
306 it->most_recent_event = LatchInfo{track_id};
307 break;
308 }
309 case GraphicsFrameEvent::PRESENT_FENCE: {
310 if (auto* l = std::get_if<LatchInfo>(&it->most_recent_event)) {
311 context_->slice_tracker->End(timestamp, l->track);
312 it->most_recent_event = std::monostate();
313 }
314 auto [d_it, d_inserted] = display_map_.Insert(layer_name_id, {});
315 if (d_it) {
316 context_->slice_tracker->End(timestamp, *d_it);
317 }
318 base::StackString<1024> track_name("Display_%.*s",
319 int(event.layer_name().size),
320 event.layer_name().data);
321 TrackId track_id = context_->track_tracker->InternTrack(
322 kGraphicFrameEventBlueprint,
323 tracks::Dimensions(track_name.string_view()),
324 tracks::DynamicName(
325 context_->storage->InternString(track_name.string_view())));
326 InsertPhaseSlice(timestamp, event, track_id, layer_name_id);
327 *d_it = track_id;
328 break;
329 }
330 default:
331 break;
332 }
333 }
334
335 std::optional<GraphicsFrameEventParser::SliceRowNumber>
InsertPhaseSlice(int64_t timestamp,const GraphicsFrameEventDecoder & event,TrackId track_id,StringId layer_name_id)336 GraphicsFrameEventParser::InsertPhaseSlice(
337 int64_t timestamp,
338 const GraphicsFrameEventDecoder& event,
339 TrackId track_id,
340 StringId layer_name_id) {
341 // If the frame_number is known, set it as the name of the slice.
342 // If not known (DEQUEUE), set the name as the timestamp.
343 // Timestamp is chosen here because the stack_id is hashed based on the name
344 // of the slice. To not have any conflicting stack_id with any of the
345 // existing slices, we use timestamp as the temporary name.
346 StringId slice_name;
347 if (event.frame_number() != 0) {
348 slice_name =
349 context_->storage->InternString(std::to_string(event.frame_number()));
350 } else {
351 slice_name = context_->storage->InternString(std::to_string(timestamp));
352 }
353 auto slice_id = context_->slice_tracker->Begin(
354 timestamp, track_id, kNullStringId, slice_name,
355 [&](ArgsTracker::BoundInserter* inserter) {
356 inserter->AddArg(frame_number_id_,
357 Variadic::Integer(event.frame_number()));
358 inserter->AddArg(layer_name_key_id_, Variadic::String(layer_name_id));
359 });
360 if (slice_id) {
361 return context_->storage->slice_table().FindById(*slice_id)->ToRowNumber();
362 }
363 return std::nullopt;
364 }
365
366 } // namespace perfetto::trace_processor
367