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