xref: /aosp_15_r20/external/perfetto/src/trace_processor/importers/proto/graphics_frame_event_parser.cc (revision 6dbdd20afdafa5e3ca9b8809fa73465d530080dc) 
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 
24 #include "perfetto/base/logging.h"
25 #include "perfetto/ext/base/string_view.h"
26 #include "perfetto/ext/base/string_writer.h"
27 #include "perfetto/ext/base/utils.h"
28 #include "protos/perfetto/trace/android/graphics_frame_event.pbzero.h"
29 #include "src/trace_processor/importers/common/event_tracker.h"
30 #include "src/trace_processor/importers/common/slice_tracker.h"
31 #include "src/trace_processor/importers/common/track_tracker.h"
32 #include "src/trace_processor/storage/stats.h"
33 #include "src/trace_processor/storage/trace_storage.h"
34 #include "src/trace_processor/tables/slice_tables_py.h"
35 #include "src/trace_processor/tables/track_tables_py.h"
36 #include "src/trace_processor/types/trace_processor_context.h"
37 
38 namespace perfetto::trace_processor {
39 
40 constexpr char kQueueLostMessage[] =
41     "Missing queue event. The slice is now a bit extended than it might "
42     "actually have been";
GraphicsFrameEventParser(TraceProcessorContext * context)43 GraphicsFrameEventParser::GraphicsFrameEventParser(
44     TraceProcessorContext* context)
45     : context_(context),
46       graphics_event_scope_id_(
47           context->storage->InternString("graphics_frame_event")),
48       unknown_event_name_id_(context->storage->InternString("unknown_event")),
49       no_layer_name_name_id_(context->storage->InternString("no_layer_name")),
50       layer_name_key_id_(context->storage->InternString("layer_name")),
51       event_type_name_ids_{
52           {context->storage->InternString(
53                "unspecified_event") /* UNSPECIFIED */,
54            context->storage->InternString("Dequeue") /* DEQUEUE */,
55            context->storage->InternString("Queue") /* QUEUE */,
56            context->storage->InternString("Post") /* POST */,
57            context->storage->InternString(
58                "AcquireFenceSignaled") /* ACQUIRE_FENCE */,
59            context->storage->InternString("Latch") /* LATCH */,
60            context->storage->InternString(
61                "HWCCompositionQueued") /* HWC_COMPOSITION_QUEUED */,
62            context->storage->InternString(
63                "FallbackComposition") /* FALLBACK_COMPOSITION */,
64            context->storage->InternString(
65                "PresentFenceSignaled") /* PRESENT_FENCE */,
66            context->storage->InternString(
67                "ReleaseFenceSignaled") /* RELEASE_FENCE */,
68            context->storage->InternString("Modify") /* MODIFY */,
69            context->storage->InternString("Detach") /* DETACH */,
70            context->storage->InternString("Attach") /* ATTACH */,
71            context->storage->InternString("Cancel") /* CANCEL */}},
72       queue_lost_message_id_(
73           context->storage->InternString(kQueueLostMessage)) {}
74 
CreateBufferEvent(int64_t timestamp,GraphicsFrameEventDecoder & event)75 bool GraphicsFrameEventParser::CreateBufferEvent(
76     int64_t timestamp,
77     GraphicsFrameEventDecoder& event) {
78   if (!event.has_buffer_id()) {
79     context_->storage->IncrementStats(
80         stats::graphics_frame_event_parser_errors);
81     PERFETTO_ELOG("GraphicsFrameEvent with missing buffer id field.");
82     return false;
83   }
84 
85   // Use buffer id + layer name as key because sometimes the same buffer can be
86   // used by different layers.
87   char event_key_buffer[4096];
88   base::StringWriter event_key_str(event_key_buffer,
89                                    base::ArraySize(event_key_buffer));
90   const uint32_t buffer_id = event.buffer_id();
91   StringId layer_name_id;
92   event_key_str.AppendUnsignedInt(buffer_id);
93 
94   if (event.has_layer_name()) {
95     layer_name_id = context_->storage->InternString(event.layer_name());
96     event_key_str.AppendString(base::StringView(event.layer_name()));
97   } else {
98     layer_name_id = no_layer_name_name_id_;
99   }
100   StringId event_key =
101       context_->storage->InternString(event_key_str.GetStringView());
102 
103   StringId event_name_id = unknown_event_name_id_;
104   if (event.has_type()) {
105     const auto type = static_cast<size_t>(event.type());
106     if (type < event_type_name_ids_.size()) {
107       event_name_id = event_type_name_ids_[type];
108       graphics_frame_stats_map_[event_key][type] = timestamp;
109     } else {
110       context_->storage->IncrementStats(
111           stats::graphics_frame_event_parser_errors);
112       PERFETTO_ELOG("GraphicsFrameEvent with unknown type %zu.", type);
113     }
114   } else {
115     context_->storage->IncrementStats(
116         stats::graphics_frame_event_parser_errors);
117     PERFETTO_ELOG("GraphicsFrameEvent with missing type field.");
118   }
119 
120   char buffer[4096];
121   base::StringWriter track_name(buffer, base::ArraySize(buffer));
122   track_name.AppendLiteral("Buffer: ");
123   track_name.AppendUnsignedInt(buffer_id);
124   track_name.AppendLiteral(" ");
125   track_name.AppendString(base::StringView(event.layer_name()));
126 
127   const StringId track_name_id =
128       context_->storage->InternString(track_name.GetStringView());
129   const int64_t duration =
130       event.has_duration_ns() ? static_cast<int64_t>(event.duration_ns()) : 0;
131   uint32_t frame_number = event.has_frame_number() ? event.frame_number() : 0;
132 
133   tables::GpuTrackTable::Row track(track_name_id);
134   track.scope = graphics_event_scope_id_;
135   TrackId track_id = context_->track_tracker->LegacyInternGpuTrack(track);
136 
137   auto* graphics_frame_slice_table =
138       context_->storage->mutable_graphics_frame_slice_table();
139   {
140     tables::GraphicsFrameSliceTable::Row row;
141     row.ts = timestamp;
142     row.track_id = track_id;
143     row.name = event_name_id;
144     row.dur = duration;
145     row.frame_number = frame_number;
146     row.layer_name = layer_name_id;
147     if (event.type() == GraphicsFrameEvent::PRESENT_FENCE) {
148       auto acquire_ts =
149           graphics_frame_stats_map_[event_key]
150                                    [GraphicsFrameEvent::ACQUIRE_FENCE];
151       auto queue_ts =
152           graphics_frame_stats_map_[event_key][GraphicsFrameEvent::QUEUE];
153       auto latch_ts =
154           graphics_frame_stats_map_[event_key][GraphicsFrameEvent::LATCH];
155 
156       row.queue_to_acquire_time =
157           std::max(acquire_ts - queue_ts, static_cast<int64_t>(0));
158       row.acquire_to_latch_time = latch_ts - acquire_ts;
159       row.latch_to_present_time = timestamp - latch_ts;
160     }
161     std::optional<SliceId> opt_slice_id =
162         context_->slice_tracker->ScopedTyped(graphics_frame_slice_table, row);
163     if (event.type() == GraphicsFrameEvent::DEQUEUE) {
164       if (opt_slice_id) {
165         dequeue_slice_ids_[event_key] = *opt_slice_id;
166       }
167     } else if (event.type() == GraphicsFrameEvent::QUEUE) {
168       auto it = dequeue_slice_ids_.find(event_key);
169       if (it != dequeue_slice_ids_.end()) {
170         auto rr = graphics_frame_slice_table->FindById(it->second);
171         rr->set_frame_number(frame_number);
172       }
173     }
174   }
175   return true;
176 }
177 
InvalidatePhaseEvent(int64_t timestamp,TrackId track_id,bool reset_name)178 void GraphicsFrameEventParser::InvalidatePhaseEvent(int64_t timestamp,
179                                                     TrackId track_id,
180                                                     bool reset_name) {
181   const auto opt_slice_id = context_->slice_tracker->End(timestamp, track_id);
182 
183   if (opt_slice_id) {
184     auto* graphics_frame_slice_table =
185         context_->storage->mutable_graphics_frame_slice_table();
186     auto rr = *graphics_frame_slice_table->FindById(*opt_slice_id);
187     if (reset_name) {
188       // Set the name (frame_number) to be 0 since there is no frame number
189       // associated, example : dequeue event.
190       StringId frame_name_id = context_->storage->InternString("0");
191       rr.set_name(frame_name_id);
192       rr.set_frame_number(0);
193     }
194 
195     // Set the duration to -1 so that this slice will be ignored by the
196     // UI. Setting any other duration results in wrong data which we want
197     // to avoid at all costs.
198     rr.set_dur(-1);
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,GraphicsFrameEventDecoder & event)207 void GraphicsFrameEventParser::CreatePhaseEvent(
208     int64_t timestamp,
209     GraphicsFrameEventDecoder& event) {
210   // Use buffer id + layer name as key because sometimes the same buffer can be
211   // used by different layers.
212   char event_key_buffer[4096];
213   base::StringWriter event_key_str(event_key_buffer,
214                                    base::ArraySize(event_key_buffer));
215   const uint32_t buffer_id = event.buffer_id();
216   uint32_t frame_number = event.has_frame_number() ? event.frame_number() : 0;
217   event_key_str.AppendUnsignedInt(buffer_id);
218   StringId layer_name_id;
219   if (event.has_layer_name()) {
220     layer_name_id = context_->storage->InternString(event.layer_name());
221     event_key_str.AppendString(base::StringView(event.layer_name()));
222   } else {
223     layer_name_id = no_layer_name_name_id_;
224   }
225   StringId event_key =
226       context_->storage->InternString(event_key_str.GetStringView());
227 
228   char track_buffer[4096];
229   char slice_buffer[4096];
230   // We'll be using the name StringWriter and name_id for writing track names
231   // and slice names.
232   base::StringWriter track_name(track_buffer, base::ArraySize(track_buffer));
233   base::StringWriter slice_name(slice_buffer, base::ArraySize(slice_buffer));
234   StringId track_name_id;
235   TrackId track_id;
236   bool start_slice = true;
237 
238   // Close the previous phase before starting the new phase
239   switch (event.type()) {
240     case GraphicsFrameEvent::DEQUEUE: {
241       track_name.reset();
242       track_name.AppendLiteral("APP_");
243       track_name.AppendUnsignedInt(buffer_id);
244       track_name.AppendLiteral(" ");
245       track_name.AppendString(base::StringView(event.layer_name()));
246       track_name_id =
247           context_->storage->InternString(track_name.GetStringView());
248       tables::GpuTrackTable::Row app_track(track_name_id);
249       app_track.scope = graphics_event_scope_id_;
250       track_id = context_->track_tracker->LegacyInternGpuTrack(app_track);
251 
252       // Error handling
253       auto dequeue_time = dequeue_map_.find(event_key);
254       if (dequeue_time != dequeue_map_.end()) {
255         InvalidatePhaseEvent(timestamp, dequeue_time->second, true);
256         dequeue_map_.erase(dequeue_time);
257       }
258       auto queue_time = queue_map_.find(event_key);
259       if (queue_time != queue_map_.end()) {
260         InvalidatePhaseEvent(timestamp, queue_time->second);
261         queue_map_.erase(queue_time);
262       }
263 
264       dequeue_map_[event_key] = track_id;
265       last_dequeued_[event_key] = timestamp;
266       break;
267     }
268 
269     case GraphicsFrameEvent::QUEUE: {
270       auto dequeue_time = dequeue_map_.find(event_key);
271       if (dequeue_time != dequeue_map_.end()) {
272         const auto opt_slice_id =
273             context_->slice_tracker->End(timestamp, dequeue_time->second);
274         slice_name.reset();
275         slice_name.AppendUnsignedInt(frame_number);
276         if (opt_slice_id) {
277           auto* graphics_frame_slice_table =
278               context_->storage->mutable_graphics_frame_slice_table();
279           // Set the name of the slice to be the frame number since dequeue did
280           // not have a frame number at that time.
281           auto rr = *graphics_frame_slice_table->FindById(*opt_slice_id);
282           rr.set_name(
283               context_->storage->InternString(slice_name.GetStringView()));
284           rr.set_frame_number(frame_number);
285           dequeue_map_.erase(dequeue_time);
286         }
287       }
288       // The AcquireFence might be signaled before receiving a QUEUE event
289       // sometimes. In that case, we shouldn't start a slice.
290       if (last_acquired_[event_key] > last_dequeued_[event_key] &&
291           last_acquired_[event_key] < timestamp) {
292         start_slice = false;
293         break;
294       }
295       track_name.reset();
296       track_name.AppendLiteral("GPU_");
297       track_name.AppendUnsignedInt(buffer_id);
298       track_name.AppendLiteral(" ");
299       track_name.AppendString(base::StringView(event.layer_name()));
300       track_name_id =
301           context_->storage->InternString(track_name.GetStringView());
302       tables::GpuTrackTable::Row gpu_track(track_name_id);
303       gpu_track.scope = graphics_event_scope_id_;
304       track_id = context_->track_tracker->LegacyInternGpuTrack(gpu_track);
305       queue_map_[event_key] = track_id;
306       break;
307     }
308     case GraphicsFrameEvent::ACQUIRE_FENCE: {
309       auto queue_time = queue_map_.find(event_key);
310       if (queue_time != queue_map_.end()) {
311         context_->slice_tracker->End(timestamp, queue_time->second);
312         queue_map_.erase(queue_time);
313       }
314       last_acquired_[event_key] = timestamp;
315       start_slice = false;
316       break;
317     }
318     case GraphicsFrameEvent::LATCH: {
319       // b/157578286 - Sometimes Queue event goes missing. To prevent having a
320       // wrong slice info, we try to close any existing APP slice.
321       auto dequeue_time = dequeue_map_.find(event_key);
322       if (dequeue_time != dequeue_map_.end()) {
323         InvalidatePhaseEvent(timestamp, dequeue_time->second, true);
324         dequeue_map_.erase(dequeue_time);
325       }
326       track_name.reset();
327       track_name.AppendLiteral("SF_");
328       track_name.AppendUnsignedInt(buffer_id);
329       track_name.AppendLiteral(" ");
330       track_name.AppendString(base::StringView(event.layer_name()));
331       track_name_id =
332           context_->storage->InternString(track_name.GetStringView());
333       tables::GpuTrackTable::Row sf_track(track_name_id);
334       sf_track.scope = graphics_event_scope_id_;
335       track_id = context_->track_tracker->LegacyInternGpuTrack(sf_track);
336       latch_map_[event_key] = track_id;
337       break;
338     }
339 
340     case GraphicsFrameEvent::PRESENT_FENCE: {
341       auto latch_time = latch_map_.find(event_key);
342       if (latch_time != latch_map_.end()) {
343         context_->slice_tracker->End(timestamp, latch_time->second);
344         latch_map_.erase(latch_time);
345       }
346       auto display_time = display_map_.find(layer_name_id);
347       if (display_time != display_map_.end()) {
348         context_->slice_tracker->End(timestamp, display_time->second);
349         display_map_.erase(display_time);
350       }
351       base::StringView layerName(event.layer_name());
352       track_name.reset();
353       track_name.AppendLiteral("Display_");
354       track_name.AppendString(layerName.substr(0, 10));
355       track_name_id =
356           context_->storage->InternString(track_name.GetStringView());
357       tables::GpuTrackTable::Row display_track(track_name_id);
358       display_track.scope = graphics_event_scope_id_;
359       track_id = context_->track_tracker->LegacyInternGpuTrack(display_track);
360       display_map_[layer_name_id] = track_id;
361       break;
362     }
363 
364     default:
365       start_slice = false;
366   }
367 
368   // Start the new phase if needed.
369   if (start_slice) {
370     tables::GraphicsFrameSliceTable::Row slice;
371     slice.ts = timestamp;
372     slice.track_id = track_id;
373     slice.layer_name = layer_name_id;
374     slice_name.reset();
375     // If the frame_number is known, set it as the name of the slice.
376     // If not known (DEQUEUE), set the name as the timestamp.
377     // Timestamp is chosen here because the stack_id is hashed based on the name
378     // of the slice. To not have any conflicting stack_id with any of the
379     // existing slices, we use timestamp as the temporary name.
380     if (frame_number != 0) {
381       slice_name.AppendUnsignedInt(frame_number);
382     } else {
383       slice_name.AppendInt(timestamp);
384     }
385     slice.name = context_->storage->InternString(slice_name.GetStringView());
386     slice.frame_number = frame_number;
387     context_->slice_tracker->BeginTyped(
388         context_->storage->mutable_graphics_frame_slice_table(), slice);
389   }
390 }
391 
ParseGraphicsFrameEvent(int64_t timestamp,ConstBytes blob)392 void GraphicsFrameEventParser::ParseGraphicsFrameEvent(int64_t timestamp,
393                                                        ConstBytes blob) {
394   protos::pbzero::GraphicsFrameEvent::Decoder frame_event(blob);
395   if (!frame_event.has_buffer_event()) {
396     return;
397   }
398 
399   protos::pbzero::GraphicsFrameEvent::BufferEvent::Decoder event(
400       frame_event.buffer_event());
401   if (CreateBufferEvent(timestamp, event)) {
402     // Create a phase event only if the buffer event finishes successfully
403     CreatePhaseEvent(timestamp, event);
404   }
405 }
406 
407 }  // namespace perfetto::trace_processor
408