• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
1 /*
2  * Copyright 2020 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 #undef LOG_TAG
18 #define LOG_TAG "FrameTimeline"
19 #define ATRACE_TAG ATRACE_TAG_GRAPHICS
20 
21 #include "FrameTimeline.h"
22 
23 #include <android-base/stringprintf.h>
24 #include <utils/Log.h>
25 #include <utils/Trace.h>
26 
27 #include <chrono>
28 #include <cinttypes>
29 #include <numeric>
30 #include <unordered_set>
31 
32 namespace android::frametimeline {
33 
34 using base::StringAppendF;
35 using FrameTimelineEvent = perfetto::protos::pbzero::FrameTimelineEvent;
36 using FrameTimelineDataSource = impl::FrameTimeline::FrameTimelineDataSource;
37 
dumpTable(std::string & result,TimelineItem predictions,TimelineItem actuals,const std::string & indent,PredictionState predictionState,nsecs_t baseTime)38 void dumpTable(std::string& result, TimelineItem predictions, TimelineItem actuals,
39                const std::string& indent, PredictionState predictionState, nsecs_t baseTime) {
40     StringAppendF(&result, "%s", indent.c_str());
41     StringAppendF(&result, "\t\t");
42     StringAppendF(&result, "    Start time\t\t|");
43     StringAppendF(&result, "    End time\t\t|");
44     StringAppendF(&result, "    Present time\n");
45     if (predictionState == PredictionState::Valid) {
46         // Dump the Predictions only if they are valid
47         StringAppendF(&result, "%s", indent.c_str());
48         StringAppendF(&result, "Expected\t|");
49         std::chrono::nanoseconds startTime(predictions.startTime - baseTime);
50         std::chrono::nanoseconds endTime(predictions.endTime - baseTime);
51         std::chrono::nanoseconds presentTime(predictions.presentTime - baseTime);
52         StringAppendF(&result, "\t%10.2f\t|\t%10.2f\t|\t%10.2f\n",
53                       std::chrono::duration<double, std::milli>(startTime).count(),
54                       std::chrono::duration<double, std::milli>(endTime).count(),
55                       std::chrono::duration<double, std::milli>(presentTime).count());
56     }
57     StringAppendF(&result, "%s", indent.c_str());
58     StringAppendF(&result, "Actual  \t|");
59 
60     if (actuals.startTime == 0) {
61         StringAppendF(&result, "\t\tN/A\t|");
62     } else {
63         std::chrono::nanoseconds startTime(std::max<nsecs_t>(0, actuals.startTime - baseTime));
64         StringAppendF(&result, "\t%10.2f\t|",
65                       std::chrono::duration<double, std::milli>(startTime).count());
66     }
67     if (actuals.endTime <= 0) {
68         // Animation leashes can send the endTime as -1
69         StringAppendF(&result, "\t\tN/A\t|");
70     } else {
71         std::chrono::nanoseconds endTime(actuals.endTime - baseTime);
72         StringAppendF(&result, "\t%10.2f\t|",
73                       std::chrono::duration<double, std::milli>(endTime).count());
74     }
75     if (actuals.presentTime == 0) {
76         StringAppendF(&result, "\t\tN/A\n");
77     } else {
78         std::chrono::nanoseconds presentTime(std::max<nsecs_t>(0, actuals.presentTime - baseTime));
79         StringAppendF(&result, "\t%10.2f\n",
80                       std::chrono::duration<double, std::milli>(presentTime).count());
81     }
82 
83     StringAppendF(&result, "%s", indent.c_str());
84     StringAppendF(&result, "----------------------");
85     StringAppendF(&result, "----------------------");
86     StringAppendF(&result, "----------------------");
87     StringAppendF(&result, "----------------------\n");
88 }
89 
toString(PredictionState predictionState)90 std::string toString(PredictionState predictionState) {
91     switch (predictionState) {
92         case PredictionState::Valid:
93             return "Valid";
94         case PredictionState::Expired:
95             return "Expired";
96         case PredictionState::None:
97             return "None";
98     }
99 }
100 
jankTypeBitmaskToString(int32_t jankType)101 std::string jankTypeBitmaskToString(int32_t jankType) {
102     if (jankType == JankType::None) {
103         return "None";
104     }
105 
106     std::vector<std::string> janks;
107     if (jankType & JankType::DisplayHAL) {
108         janks.emplace_back("Display HAL");
109         jankType &= ~JankType::DisplayHAL;
110     }
111     if (jankType & JankType::SurfaceFlingerCpuDeadlineMissed) {
112         janks.emplace_back("SurfaceFlinger CPU Deadline Missed");
113         jankType &= ~JankType::SurfaceFlingerCpuDeadlineMissed;
114     }
115     if (jankType & JankType::SurfaceFlingerGpuDeadlineMissed) {
116         janks.emplace_back("SurfaceFlinger GPU Deadline Missed");
117         jankType &= ~JankType::SurfaceFlingerGpuDeadlineMissed;
118     }
119     if (jankType & JankType::AppDeadlineMissed) {
120         janks.emplace_back("App Deadline Missed");
121         jankType &= ~JankType::AppDeadlineMissed;
122     }
123     if (jankType & JankType::PredictionError) {
124         janks.emplace_back("Prediction Error");
125         jankType &= ~JankType::PredictionError;
126     }
127     if (jankType & JankType::SurfaceFlingerScheduling) {
128         janks.emplace_back("SurfaceFlinger Scheduling");
129         jankType &= ~JankType::SurfaceFlingerScheduling;
130     }
131     if (jankType & JankType::BufferStuffing) {
132         janks.emplace_back("Buffer Stuffing");
133         jankType &= ~JankType::BufferStuffing;
134     }
135     if (jankType & JankType::Unknown) {
136         janks.emplace_back("Unknown jank");
137         jankType &= ~JankType::Unknown;
138     }
139     if (jankType & JankType::SurfaceFlingerStuffing) {
140         janks.emplace_back("SurfaceFlinger Stuffing");
141         jankType &= ~JankType::SurfaceFlingerStuffing;
142     }
143 
144     // jankType should be 0 if all types of jank were checked for.
145     LOG_ALWAYS_FATAL_IF(jankType != 0, "Unrecognized jank type value 0x%x", jankType);
146     return std::accumulate(janks.begin(), janks.end(), std::string(),
147                            [](const std::string& l, const std::string& r) {
148                                return l.empty() ? r : l + ", " + r;
149                            });
150 }
151 
toString(FramePresentMetadata presentMetadata)152 std::string toString(FramePresentMetadata presentMetadata) {
153     switch (presentMetadata) {
154         case FramePresentMetadata::OnTimePresent:
155             return "On Time Present";
156         case FramePresentMetadata::LatePresent:
157             return "Late Present";
158         case FramePresentMetadata::EarlyPresent:
159             return "Early Present";
160         case FramePresentMetadata::UnknownPresent:
161             return "Unknown Present";
162     }
163 }
164 
toString(FrameReadyMetadata finishMetadata)165 std::string toString(FrameReadyMetadata finishMetadata) {
166     switch (finishMetadata) {
167         case FrameReadyMetadata::OnTimeFinish:
168             return "On Time Finish";
169         case FrameReadyMetadata::LateFinish:
170             return "Late Finish";
171         case FrameReadyMetadata::UnknownFinish:
172             return "Unknown Finish";
173     }
174 }
175 
toString(FrameStartMetadata startMetadata)176 std::string toString(FrameStartMetadata startMetadata) {
177     switch (startMetadata) {
178         case FrameStartMetadata::OnTimeStart:
179             return "On Time Start";
180         case FrameStartMetadata::LateStart:
181             return "Late Start";
182         case FrameStartMetadata::EarlyStart:
183             return "Early Start";
184         case FrameStartMetadata::UnknownStart:
185             return "Unknown Start";
186     }
187 }
188 
toString(SurfaceFrame::PresentState presentState)189 std::string toString(SurfaceFrame::PresentState presentState) {
190     using PresentState = SurfaceFrame::PresentState;
191     switch (presentState) {
192         case PresentState::Presented:
193             return "Presented";
194         case PresentState::Dropped:
195             return "Dropped";
196         case PresentState::Unknown:
197             return "Unknown";
198     }
199 }
200 
toProto(FramePresentMetadata presentMetadata)201 FrameTimelineEvent::PresentType toProto(FramePresentMetadata presentMetadata) {
202     switch (presentMetadata) {
203         case FramePresentMetadata::EarlyPresent:
204             return FrameTimelineEvent::PRESENT_EARLY;
205         case FramePresentMetadata::LatePresent:
206             return FrameTimelineEvent::PRESENT_LATE;
207         case FramePresentMetadata::OnTimePresent:
208             return FrameTimelineEvent::PRESENT_ON_TIME;
209         case FramePresentMetadata::UnknownPresent:
210             return FrameTimelineEvent::PRESENT_UNSPECIFIED;
211     }
212 }
213 
toProto(PredictionState predictionState)214 FrameTimelineEvent::PredictionType toProto(PredictionState predictionState) {
215     switch (predictionState) {
216         case PredictionState::Valid:
217             return FrameTimelineEvent::PREDICTION_VALID;
218         case PredictionState::Expired:
219             return FrameTimelineEvent::PREDICTION_EXPIRED;
220         case PredictionState::None:
221             return FrameTimelineEvent::PREDICTION_UNKNOWN;
222     }
223 }
224 
jankTypeBitmaskToProto(int32_t jankType)225 int32_t jankTypeBitmaskToProto(int32_t jankType) {
226     if (jankType == JankType::None) {
227         return FrameTimelineEvent::JANK_NONE;
228     }
229 
230     int32_t protoJank = 0;
231     if (jankType & JankType::DisplayHAL) {
232         protoJank |= FrameTimelineEvent::JANK_DISPLAY_HAL;
233         jankType &= ~JankType::DisplayHAL;
234     }
235     if (jankType & JankType::SurfaceFlingerCpuDeadlineMissed) {
236         protoJank |= FrameTimelineEvent::JANK_SF_CPU_DEADLINE_MISSED;
237         jankType &= ~JankType::SurfaceFlingerCpuDeadlineMissed;
238     }
239     if (jankType & JankType::SurfaceFlingerGpuDeadlineMissed) {
240         protoJank |= FrameTimelineEvent::JANK_SF_GPU_DEADLINE_MISSED;
241         jankType &= ~JankType::SurfaceFlingerGpuDeadlineMissed;
242     }
243     if (jankType & JankType::AppDeadlineMissed) {
244         protoJank |= FrameTimelineEvent::JANK_APP_DEADLINE_MISSED;
245         jankType &= ~JankType::AppDeadlineMissed;
246     }
247     if (jankType & JankType::PredictionError) {
248         protoJank |= FrameTimelineEvent::JANK_PREDICTION_ERROR;
249         jankType &= ~JankType::PredictionError;
250     }
251     if (jankType & JankType::SurfaceFlingerScheduling) {
252         protoJank |= FrameTimelineEvent::JANK_SF_SCHEDULING;
253         jankType &= ~JankType::SurfaceFlingerScheduling;
254     }
255     if (jankType & JankType::BufferStuffing) {
256         protoJank |= FrameTimelineEvent::JANK_BUFFER_STUFFING;
257         jankType &= ~JankType::BufferStuffing;
258     }
259     if (jankType & JankType::Unknown) {
260         protoJank |= FrameTimelineEvent::JANK_UNKNOWN;
261         jankType &= ~JankType::Unknown;
262     }
263     if (jankType & JankType::SurfaceFlingerStuffing) {
264         protoJank |= FrameTimelineEvent::JANK_SF_STUFFING;
265         jankType &= ~JankType::SurfaceFlingerStuffing;
266     }
267 
268     // jankType should be 0 if all types of jank were checked for.
269     LOG_ALWAYS_FATAL_IF(jankType != 0, "Unrecognized jank type value 0x%x", jankType);
270     return protoJank;
271 }
272 
273 // Returns the smallest timestamp from the set of predictions and actuals.
getMinTime(PredictionState predictionState,TimelineItem predictions,TimelineItem actuals)274 nsecs_t getMinTime(PredictionState predictionState, TimelineItem predictions,
275                    TimelineItem actuals) {
276     nsecs_t minTime = std::numeric_limits<nsecs_t>::max();
277     if (predictionState == PredictionState::Valid) {
278         // Checking start time for predictions is enough because start time is always lesser than
279         // endTime and presentTime.
280         minTime = std::min(minTime, predictions.startTime);
281     }
282 
283     // Need to check startTime, endTime and presentTime for actuals because some frames might not
284     // have them set.
285     if (actuals.startTime != 0) {
286         minTime = std::min(minTime, actuals.startTime);
287     }
288     if (actuals.endTime != 0) {
289         minTime = std::min(minTime, actuals.endTime);
290     }
291     if (actuals.presentTime != 0) {
292         minTime = std::min(minTime, actuals.endTime);
293     }
294     return minTime;
295 }
296 
getCookieForTracing()297 int64_t TraceCookieCounter::getCookieForTracing() {
298     return ++mTraceCookie;
299 }
300 
SurfaceFrame(const FrameTimelineInfo & frameTimelineInfo,pid_t ownerPid,uid_t ownerUid,int32_t layerId,std::string layerName,std::string debugName,PredictionState predictionState,frametimeline::TimelineItem && predictions,std::shared_ptr<TimeStats> timeStats,JankClassificationThresholds thresholds,TraceCookieCounter * traceCookieCounter,bool isBuffer,int32_t gameMode)301 SurfaceFrame::SurfaceFrame(const FrameTimelineInfo& frameTimelineInfo, pid_t ownerPid,
302                            uid_t ownerUid, int32_t layerId, std::string layerName,
303                            std::string debugName, PredictionState predictionState,
304                            frametimeline::TimelineItem&& predictions,
305                            std::shared_ptr<TimeStats> timeStats,
306                            JankClassificationThresholds thresholds,
307                            TraceCookieCounter* traceCookieCounter, bool isBuffer, int32_t gameMode)
308       : mToken(frameTimelineInfo.vsyncId),
309         mInputEventId(frameTimelineInfo.inputEventId),
310         mOwnerPid(ownerPid),
311         mOwnerUid(ownerUid),
312         mLayerName(std::move(layerName)),
313         mDebugName(std::move(debugName)),
314         mLayerId(layerId),
315         mPresentState(PresentState::Unknown),
316         mPredictionState(predictionState),
317         mPredictions(predictions),
318         mActuals({0, 0, 0}),
319         mTimeStats(timeStats),
320         mJankClassificationThresholds(thresholds),
321         mTraceCookieCounter(*traceCookieCounter),
322         mIsBuffer(isBuffer),
323         mGameMode(gameMode) {}
324 
setActualStartTime(nsecs_t actualStartTime)325 void SurfaceFrame::setActualStartTime(nsecs_t actualStartTime) {
326     std::scoped_lock lock(mMutex);
327     mActuals.startTime = actualStartTime;
328 }
329 
setActualQueueTime(nsecs_t actualQueueTime)330 void SurfaceFrame::setActualQueueTime(nsecs_t actualQueueTime) {
331     std::scoped_lock lock(mMutex);
332     mActualQueueTime = actualQueueTime;
333 }
334 
setAcquireFenceTime(nsecs_t acquireFenceTime)335 void SurfaceFrame::setAcquireFenceTime(nsecs_t acquireFenceTime) {
336     std::scoped_lock lock(mMutex);
337     mActuals.endTime = std::max(acquireFenceTime, mActualQueueTime);
338 }
339 
setDropTime(nsecs_t dropTime)340 void SurfaceFrame::setDropTime(nsecs_t dropTime) {
341     std::scoped_lock lock(mMutex);
342     mDropTime = dropTime;
343 }
344 
setPresentState(PresentState presentState,nsecs_t lastLatchTime)345 void SurfaceFrame::setPresentState(PresentState presentState, nsecs_t lastLatchTime) {
346     std::scoped_lock lock(mMutex);
347     LOG_ALWAYS_FATAL_IF(mPresentState != PresentState::Unknown,
348                         "setPresentState called on a SurfaceFrame from Layer - %s, that has a "
349                         "PresentState - %s set already.",
350                         mDebugName.c_str(), toString(mPresentState).c_str());
351     mPresentState = presentState;
352     mLastLatchTime = lastLatchTime;
353 }
354 
setRenderRate(Fps renderRate)355 void SurfaceFrame::setRenderRate(Fps renderRate) {
356     std::lock_guard<std::mutex> lock(mMutex);
357     mRenderRate = renderRate;
358 }
359 
setGpuComposition()360 void SurfaceFrame::setGpuComposition() {
361     std::scoped_lock lock(mMutex);
362     mGpuComposition = true;
363 }
364 
getJankType() const365 std::optional<int32_t> SurfaceFrame::getJankType() const {
366     std::scoped_lock lock(mMutex);
367     if (mPresentState == PresentState::Dropped) {
368         // Return no jank if it's a dropped frame since we cannot attribute a jank to a it.
369         return JankType::None;
370     }
371     if (mActuals.presentTime == 0) {
372         // Frame hasn't been presented yet.
373         return std::nullopt;
374     }
375     return mJankType;
376 }
377 
getBaseTime() const378 nsecs_t SurfaceFrame::getBaseTime() const {
379     std::scoped_lock lock(mMutex);
380     return getMinTime(mPredictionState, mPredictions, mActuals);
381 }
382 
getActuals() const383 TimelineItem SurfaceFrame::getActuals() const {
384     std::scoped_lock lock(mMutex);
385     return mActuals;
386 }
387 
getPredictionState() const388 PredictionState SurfaceFrame::getPredictionState() const {
389     std::scoped_lock lock(mMutex);
390     return mPredictionState;
391 }
392 
getPresentState() const393 SurfaceFrame::PresentState SurfaceFrame::getPresentState() const {
394     std::scoped_lock lock(mMutex);
395     return mPresentState;
396 }
397 
getFramePresentMetadata() const398 FramePresentMetadata SurfaceFrame::getFramePresentMetadata() const {
399     std::scoped_lock lock(mMutex);
400     return mFramePresentMetadata;
401 }
402 
getFrameReadyMetadata() const403 FrameReadyMetadata SurfaceFrame::getFrameReadyMetadata() const {
404     std::scoped_lock lock(mMutex);
405     return mFrameReadyMetadata;
406 }
407 
getDropTime() const408 nsecs_t SurfaceFrame::getDropTime() const {
409     std::scoped_lock lock(mMutex);
410     return mDropTime;
411 }
412 
promoteToBuffer()413 void SurfaceFrame::promoteToBuffer() {
414     std::scoped_lock lock(mMutex);
415     LOG_ALWAYS_FATAL_IF(mIsBuffer == true,
416                         "Trying to promote an already promoted BufferSurfaceFrame from layer %s "
417                         "with token %" PRId64 "",
418                         mDebugName.c_str(), mToken);
419     mIsBuffer = true;
420 }
421 
getIsBuffer() const422 bool SurfaceFrame::getIsBuffer() const {
423     std::scoped_lock lock(mMutex);
424     return mIsBuffer;
425 }
426 
dump(std::string & result,const std::string & indent,nsecs_t baseTime) const427 void SurfaceFrame::dump(std::string& result, const std::string& indent, nsecs_t baseTime) const {
428     std::scoped_lock lock(mMutex);
429     StringAppendF(&result, "%s", indent.c_str());
430     StringAppendF(&result, "Layer - %s", mDebugName.c_str());
431     if (mJankType != JankType::None) {
432         // Easily identify a janky Surface Frame in the dump
433         StringAppendF(&result, " [*] ");
434     }
435     StringAppendF(&result, "\n");
436     StringAppendF(&result, "%s", indent.c_str());
437     StringAppendF(&result, "Token: %" PRId64 "\n", mToken);
438     StringAppendF(&result, "%s", indent.c_str());
439     StringAppendF(&result, "Is Buffer?: %d\n", mIsBuffer);
440     StringAppendF(&result, "%s", indent.c_str());
441     StringAppendF(&result, "Owner Pid : %d\n", mOwnerPid);
442     StringAppendF(&result, "%s", indent.c_str());
443     StringAppendF(&result, "Scheduled rendering rate: %d fps\n",
444                   mRenderRate ? mRenderRate->getIntValue() : 0);
445     StringAppendF(&result, "%s", indent.c_str());
446     StringAppendF(&result, "Layer ID : %d\n", mLayerId);
447     StringAppendF(&result, "%s", indent.c_str());
448     StringAppendF(&result, "Present State : %s\n", toString(mPresentState).c_str());
449     StringAppendF(&result, "%s", indent.c_str());
450     if (mPresentState == PresentState::Dropped) {
451         std::chrono::nanoseconds dropTime(mDropTime - baseTime);
452         StringAppendF(&result, "Drop time : %10f\n",
453                       std::chrono::duration<double, std::milli>(dropTime).count());
454         StringAppendF(&result, "%s", indent.c_str());
455     }
456     StringAppendF(&result, "Prediction State : %s\n", toString(mPredictionState).c_str());
457     StringAppendF(&result, "%s", indent.c_str());
458     StringAppendF(&result, "Jank Type : %s\n", jankTypeBitmaskToString(mJankType).c_str());
459     StringAppendF(&result, "%s", indent.c_str());
460     StringAppendF(&result, "Present Metadata : %s\n", toString(mFramePresentMetadata).c_str());
461     StringAppendF(&result, "%s", indent.c_str());
462     StringAppendF(&result, "Finish Metadata: %s\n", toString(mFrameReadyMetadata).c_str());
463     std::chrono::nanoseconds latchTime(
464             std::max(static_cast<int64_t>(0), mLastLatchTime - baseTime));
465     StringAppendF(&result, "%s", indent.c_str());
466     StringAppendF(&result, "Last latch time: %10f\n",
467                   std::chrono::duration<double, std::milli>(latchTime).count());
468     if (mPredictionState == PredictionState::Valid) {
469         nsecs_t presentDelta = mActuals.presentTime - mPredictions.presentTime;
470         std::chrono::nanoseconds presentDeltaNs(std::abs(presentDelta));
471         StringAppendF(&result, "%s", indent.c_str());
472         StringAppendF(&result, "Present delta: %10f\n",
473                       std::chrono::duration<double, std::milli>(presentDeltaNs).count());
474     }
475     dumpTable(result, mPredictions, mActuals, indent, mPredictionState, baseTime);
476 }
477 
miniDump() const478 std::string SurfaceFrame::miniDump() const {
479     std::scoped_lock lock(mMutex);
480     std::string result;
481     StringAppendF(&result, "Layer - %s\n", mDebugName.c_str());
482     StringAppendF(&result, "Token: %" PRId64 "\n", mToken);
483     StringAppendF(&result, "Is Buffer?: %d\n", mIsBuffer);
484     StringAppendF(&result, "Present State : %s\n", toString(mPresentState).c_str());
485     StringAppendF(&result, "Prediction State : %s\n", toString(mPredictionState).c_str());
486     StringAppendF(&result, "Jank Type : %s\n", jankTypeBitmaskToString(mJankType).c_str());
487     StringAppendF(&result, "Present Metadata : %s\n", toString(mFramePresentMetadata).c_str());
488     StringAppendF(&result, "Finish Metadata: %s\n", toString(mFrameReadyMetadata).c_str());
489     StringAppendF(&result, "Present time: %" PRId64 "", mActuals.presentTime);
490     return result;
491 }
492 
classifyJankLocked(int32_t displayFrameJankType,const Fps & refreshRate,nsecs_t & deadlineDelta)493 void SurfaceFrame::classifyJankLocked(int32_t displayFrameJankType, const Fps& refreshRate,
494                                       nsecs_t& deadlineDelta) {
495     if (mPredictionState == PredictionState::Expired ||
496         mActuals.presentTime == Fence::SIGNAL_TIME_INVALID) {
497         // Cannot do any classification for invalid present time.
498         // For prediction expired case, we do not know what happened here to classify this
499         // correctly. This could potentially be AppDeadlineMissed but that's assuming no app will
500         // request frames 120ms apart.
501         mJankType = JankType::Unknown;
502         deadlineDelta = -1;
503         return;
504     }
505 
506     if (mPredictionState == PredictionState::None) {
507         // Cannot do jank classification on frames that don't have a token.
508         return;
509     }
510 
511     deadlineDelta = mActuals.endTime - mPredictions.endTime;
512     const nsecs_t presentDelta = mActuals.presentTime - mPredictions.presentTime;
513     const nsecs_t deltaToVsync = refreshRate.getPeriodNsecs() > 0
514             ? std::abs(presentDelta) % refreshRate.getPeriodNsecs()
515             : 0;
516 
517     if (deadlineDelta > mJankClassificationThresholds.deadlineThreshold) {
518         mFrameReadyMetadata = FrameReadyMetadata::LateFinish;
519     } else {
520         mFrameReadyMetadata = FrameReadyMetadata::OnTimeFinish;
521     }
522 
523     if (std::abs(presentDelta) > mJankClassificationThresholds.presentThreshold) {
524         mFramePresentMetadata = presentDelta > 0 ? FramePresentMetadata::LatePresent
525                                                  : FramePresentMetadata::EarlyPresent;
526     } else {
527         mFramePresentMetadata = FramePresentMetadata::OnTimePresent;
528     }
529 
530     if (mFramePresentMetadata == FramePresentMetadata::OnTimePresent) {
531         // Frames presented on time are not janky.
532         mJankType = JankType::None;
533     } else if (mFramePresentMetadata == FramePresentMetadata::EarlyPresent) {
534         if (mFrameReadyMetadata == FrameReadyMetadata::OnTimeFinish) {
535             // Finish on time, Present early
536             if (deltaToVsync < mJankClassificationThresholds.presentThreshold ||
537                 deltaToVsync >= refreshRate.getPeriodNsecs() -
538                                 mJankClassificationThresholds.presentThreshold) {
539                 // Delta factor of vsync
540                 mJankType = JankType::SurfaceFlingerScheduling;
541             } else {
542                 // Delta not a factor of vsync
543                 mJankType = JankType::PredictionError;
544             }
545         } else if (mFrameReadyMetadata == FrameReadyMetadata::LateFinish) {
546             // Finish late, Present early
547             mJankType = JankType::Unknown;
548         }
549     } else {
550         if (mLastLatchTime != 0 && mPredictions.endTime <= mLastLatchTime) {
551             // Buffer Stuffing.
552             mJankType |= JankType::BufferStuffing;
553             // In a stuffed state, the frame could be stuck on a dequeue wait for quite some time.
554             // Because of this dequeue wait, it can be hard to tell if a frame was genuinely late.
555             // We try to do this by moving the deadline. Since the queue could be stuffed by more
556             // than one buffer, we take the last latch time as reference and give one vsync
557             // worth of time for the frame to be ready.
558             nsecs_t adjustedDeadline = mLastLatchTime + refreshRate.getPeriodNsecs();
559             if (adjustedDeadline > mActuals.endTime) {
560                 mFrameReadyMetadata = FrameReadyMetadata::OnTimeFinish;
561             } else {
562                 mFrameReadyMetadata = FrameReadyMetadata::LateFinish;
563             }
564         }
565         if (mFrameReadyMetadata == FrameReadyMetadata::OnTimeFinish) {
566             // Finish on time, Present late
567             if (displayFrameJankType != JankType::None) {
568                 // Propagate displayFrame's jank if it exists
569                 mJankType |= displayFrameJankType;
570             } else {
571                 if (!(mJankType & JankType::BufferStuffing)) {
572                     // In a stuffed state, if the app finishes on time and there is no display frame
573                     // jank, only buffer stuffing is the root cause of the jank.
574                     if (deltaToVsync < mJankClassificationThresholds.presentThreshold ||
575                         deltaToVsync >= refreshRate.getPeriodNsecs() -
576                                         mJankClassificationThresholds.presentThreshold) {
577                         // Delta factor of vsync
578                         mJankType |= JankType::SurfaceFlingerScheduling;
579                     } else {
580                         // Delta not a factor of vsync
581                         mJankType |= JankType::PredictionError;
582                     }
583                 }
584             }
585         } else if (mFrameReadyMetadata == FrameReadyMetadata::LateFinish) {
586             // Finish late, Present late
587             mJankType |= JankType::AppDeadlineMissed;
588             // Propagate DisplayFrame's jankType if it is janky
589             mJankType |= displayFrameJankType;
590         }
591     }
592 }
593 
onPresent(nsecs_t presentTime,int32_t displayFrameJankType,Fps refreshRate,nsecs_t displayDeadlineDelta,nsecs_t displayPresentDelta)594 void SurfaceFrame::onPresent(nsecs_t presentTime, int32_t displayFrameJankType, Fps refreshRate,
595                              nsecs_t displayDeadlineDelta, nsecs_t displayPresentDelta) {
596     std::scoped_lock lock(mMutex);
597 
598     if (mPresentState != PresentState::Presented) {
599         // No need to update dropped buffers
600         return;
601     }
602 
603     mActuals.presentTime = presentTime;
604     nsecs_t deadlineDelta = 0;
605 
606     classifyJankLocked(displayFrameJankType, refreshRate, deadlineDelta);
607 
608     if (mPredictionState != PredictionState::None) {
609         // Only update janky frames if the app used vsync predictions
610         mTimeStats->incrementJankyFrames({refreshRate, mRenderRate, mOwnerUid, mLayerName,
611                                           mGameMode, mJankType, displayDeadlineDelta,
612                                           displayPresentDelta, deadlineDelta});
613     }
614 }
615 
tracePredictions(int64_t displayFrameToken) const616 void SurfaceFrame::tracePredictions(int64_t displayFrameToken) const {
617     int64_t expectedTimelineCookie = mTraceCookieCounter.getCookieForTracing();
618 
619     // Expected timeline start
620     FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
621         std::scoped_lock lock(mMutex);
622         auto packet = ctx.NewTracePacket();
623         packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
624         packet->set_timestamp(static_cast<uint64_t>(mPredictions.startTime));
625 
626         auto* event = packet->set_frame_timeline_event();
627         auto* expectedSurfaceFrameStartEvent = event->set_expected_surface_frame_start();
628 
629         expectedSurfaceFrameStartEvent->set_cookie(expectedTimelineCookie);
630 
631         expectedSurfaceFrameStartEvent->set_token(mToken);
632         expectedSurfaceFrameStartEvent->set_display_frame_token(displayFrameToken);
633 
634         expectedSurfaceFrameStartEvent->set_pid(mOwnerPid);
635         expectedSurfaceFrameStartEvent->set_layer_name(mDebugName);
636     });
637 
638     // Expected timeline end
639     FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
640         std::scoped_lock lock(mMutex);
641         auto packet = ctx.NewTracePacket();
642         packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
643         packet->set_timestamp(static_cast<uint64_t>(mPredictions.endTime));
644 
645         auto* event = packet->set_frame_timeline_event();
646         auto* expectedSurfaceFrameEndEvent = event->set_frame_end();
647 
648         expectedSurfaceFrameEndEvent->set_cookie(expectedTimelineCookie);
649     });
650 }
651 
traceActuals(int64_t displayFrameToken) const652 void SurfaceFrame::traceActuals(int64_t displayFrameToken) const {
653     int64_t actualTimelineCookie = mTraceCookieCounter.getCookieForTracing();
654 
655     // Actual timeline start
656     FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
657         std::scoped_lock lock(mMutex);
658         auto packet = ctx.NewTracePacket();
659         packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
660         // Actual start time is not yet available, so use expected start instead
661         if (mPredictionState == PredictionState::Expired) {
662             // If prediction is expired, we can't use the predicted start time. Instead, just use a
663             // start time a little earlier than the end time so that we have some info about this
664             // frame in the trace.
665             nsecs_t endTime =
666                     (mPresentState == PresentState::Dropped ? mDropTime : mActuals.endTime);
667             packet->set_timestamp(
668                     static_cast<uint64_t>(endTime - kPredictionExpiredStartTimeDelta));
669         } else {
670             packet->set_timestamp(static_cast<uint64_t>(mPredictions.startTime));
671         }
672 
673         auto* event = packet->set_frame_timeline_event();
674         auto* actualSurfaceFrameStartEvent = event->set_actual_surface_frame_start();
675 
676         actualSurfaceFrameStartEvent->set_cookie(actualTimelineCookie);
677 
678         actualSurfaceFrameStartEvent->set_token(mToken);
679         actualSurfaceFrameStartEvent->set_display_frame_token(displayFrameToken);
680 
681         actualSurfaceFrameStartEvent->set_pid(mOwnerPid);
682         actualSurfaceFrameStartEvent->set_layer_name(mDebugName);
683 
684         if (mPresentState == PresentState::Dropped) {
685             actualSurfaceFrameStartEvent->set_present_type(FrameTimelineEvent::PRESENT_DROPPED);
686         } else if (mPresentState == PresentState::Unknown) {
687             actualSurfaceFrameStartEvent->set_present_type(FrameTimelineEvent::PRESENT_UNSPECIFIED);
688         } else {
689             actualSurfaceFrameStartEvent->set_present_type(toProto(mFramePresentMetadata));
690         }
691         actualSurfaceFrameStartEvent->set_on_time_finish(mFrameReadyMetadata ==
692                                                          FrameReadyMetadata::OnTimeFinish);
693         actualSurfaceFrameStartEvent->set_gpu_composition(mGpuComposition);
694         actualSurfaceFrameStartEvent->set_jank_type(jankTypeBitmaskToProto(mJankType));
695         actualSurfaceFrameStartEvent->set_prediction_type(toProto(mPredictionState));
696         actualSurfaceFrameStartEvent->set_is_buffer(mIsBuffer);
697     });
698 
699     // Actual timeline end
700     FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
701         std::scoped_lock lock(mMutex);
702         auto packet = ctx.NewTracePacket();
703         packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
704         if (mPresentState == PresentState::Dropped) {
705             packet->set_timestamp(static_cast<uint64_t>(mDropTime));
706         } else {
707             packet->set_timestamp(static_cast<uint64_t>(mActuals.endTime));
708         }
709 
710         auto* event = packet->set_frame_timeline_event();
711         auto* actualSurfaceFrameEndEvent = event->set_frame_end();
712 
713         actualSurfaceFrameEndEvent->set_cookie(actualTimelineCookie);
714     });
715 }
716 
717 /**
718  * TODO(b/178637512): add inputEventId to the perfetto trace.
719  */
trace(int64_t displayFrameToken) const720 void SurfaceFrame::trace(int64_t displayFrameToken) const {
721     if (mToken == FrameTimelineInfo::INVALID_VSYNC_ID ||
722         displayFrameToken == FrameTimelineInfo::INVALID_VSYNC_ID) {
723         // No packets can be traced with a missing token.
724         return;
725     }
726     if (getPredictionState() != PredictionState::Expired) {
727         // Expired predictions have zeroed timestamps. This cannot be used in any meaningful way in
728         // a trace.
729         tracePredictions(displayFrameToken);
730     }
731     traceActuals(displayFrameToken);
732 }
733 
734 namespace impl {
735 
generateTokenForPredictions(TimelineItem && predictions)736 int64_t TokenManager::generateTokenForPredictions(TimelineItem&& predictions) {
737     ATRACE_CALL();
738     std::scoped_lock lock(mMutex);
739     while (mPredictions.size() >= kMaxTokens) {
740         mPredictions.erase(mPredictions.begin());
741     }
742     const int64_t assignedToken = mCurrentToken++;
743     mPredictions[assignedToken] = predictions;
744     return assignedToken;
745 }
746 
getPredictionsForToken(int64_t token) const747 std::optional<TimelineItem> TokenManager::getPredictionsForToken(int64_t token) const {
748     std::scoped_lock lock(mMutex);
749     auto predictionsIterator = mPredictions.find(token);
750     if (predictionsIterator != mPredictions.end()) {
751         return predictionsIterator->second;
752     }
753     return {};
754 }
755 
FrameTimeline(std::shared_ptr<TimeStats> timeStats,pid_t surfaceFlingerPid,JankClassificationThresholds thresholds)756 FrameTimeline::FrameTimeline(std::shared_ptr<TimeStats> timeStats, pid_t surfaceFlingerPid,
757                              JankClassificationThresholds thresholds)
758       : mMaxDisplayFrames(kDefaultMaxDisplayFrames),
759         mTimeStats(std::move(timeStats)),
760         mSurfaceFlingerPid(surfaceFlingerPid),
761         mJankClassificationThresholds(thresholds) {
762     mCurrentDisplayFrame =
763             std::make_shared<DisplayFrame>(mTimeStats, thresholds, &mTraceCookieCounter);
764 }
765 
onBootFinished()766 void FrameTimeline::onBootFinished() {
767     perfetto::TracingInitArgs args;
768     args.backends = perfetto::kSystemBackend;
769     perfetto::Tracing::Initialize(args);
770     registerDataSource();
771 }
772 
registerDataSource()773 void FrameTimeline::registerDataSource() {
774     perfetto::DataSourceDescriptor dsd;
775     dsd.set_name(kFrameTimelineDataSource);
776     FrameTimelineDataSource::Register(dsd);
777 }
778 
createSurfaceFrameForToken(const FrameTimelineInfo & frameTimelineInfo,pid_t ownerPid,uid_t ownerUid,int32_t layerId,std::string layerName,std::string debugName,bool isBuffer,int32_t gameMode)779 std::shared_ptr<SurfaceFrame> FrameTimeline::createSurfaceFrameForToken(
780         const FrameTimelineInfo& frameTimelineInfo, pid_t ownerPid, uid_t ownerUid, int32_t layerId,
781         std::string layerName, std::string debugName, bool isBuffer, int32_t gameMode) {
782     ATRACE_CALL();
783     if (frameTimelineInfo.vsyncId == FrameTimelineInfo::INVALID_VSYNC_ID) {
784         return std::make_shared<SurfaceFrame>(frameTimelineInfo, ownerPid, ownerUid, layerId,
785                                               std::move(layerName), std::move(debugName),
786                                               PredictionState::None, TimelineItem(), mTimeStats,
787                                               mJankClassificationThresholds, &mTraceCookieCounter,
788                                               isBuffer, gameMode);
789     }
790     std::optional<TimelineItem> predictions =
791             mTokenManager.getPredictionsForToken(frameTimelineInfo.vsyncId);
792     if (predictions) {
793         return std::make_shared<SurfaceFrame>(frameTimelineInfo, ownerPid, ownerUid, layerId,
794                                               std::move(layerName), std::move(debugName),
795                                               PredictionState::Valid, std::move(*predictions),
796                                               mTimeStats, mJankClassificationThresholds,
797                                               &mTraceCookieCounter, isBuffer, gameMode);
798     }
799     return std::make_shared<SurfaceFrame>(frameTimelineInfo, ownerPid, ownerUid, layerId,
800                                           std::move(layerName), std::move(debugName),
801                                           PredictionState::Expired, TimelineItem(), mTimeStats,
802                                           mJankClassificationThresholds, &mTraceCookieCounter,
803                                           isBuffer, gameMode);
804 }
805 
DisplayFrame(std::shared_ptr<TimeStats> timeStats,JankClassificationThresholds thresholds,TraceCookieCounter * traceCookieCounter)806 FrameTimeline::DisplayFrame::DisplayFrame(std::shared_ptr<TimeStats> timeStats,
807                                           JankClassificationThresholds thresholds,
808                                           TraceCookieCounter* traceCookieCounter)
809       : mSurfaceFlingerPredictions(TimelineItem()),
810         mSurfaceFlingerActuals(TimelineItem()),
811         mTimeStats(timeStats),
812         mJankClassificationThresholds(thresholds),
813         mTraceCookieCounter(*traceCookieCounter) {
814     mSurfaceFrames.reserve(kNumSurfaceFramesInitial);
815 }
816 
addSurfaceFrame(std::shared_ptr<SurfaceFrame> surfaceFrame)817 void FrameTimeline::addSurfaceFrame(std::shared_ptr<SurfaceFrame> surfaceFrame) {
818     ATRACE_CALL();
819     std::scoped_lock lock(mMutex);
820     mCurrentDisplayFrame->addSurfaceFrame(surfaceFrame);
821 }
822 
setSfWakeUp(int64_t token,nsecs_t wakeUpTime,Fps refreshRate)823 void FrameTimeline::setSfWakeUp(int64_t token, nsecs_t wakeUpTime, Fps refreshRate) {
824     ATRACE_CALL();
825     std::scoped_lock lock(mMutex);
826     mCurrentDisplayFrame->onSfWakeUp(token, refreshRate,
827                                      mTokenManager.getPredictionsForToken(token), wakeUpTime);
828 }
829 
setSfPresent(nsecs_t sfPresentTime,const std::shared_ptr<FenceTime> & presentFence,const std::shared_ptr<FenceTime> & gpuFence)830 void FrameTimeline::setSfPresent(nsecs_t sfPresentTime,
831                                  const std::shared_ptr<FenceTime>& presentFence,
832                                  const std::shared_ptr<FenceTime>& gpuFence) {
833     ATRACE_CALL();
834     std::scoped_lock lock(mMutex);
835     mCurrentDisplayFrame->setActualEndTime(sfPresentTime);
836     mCurrentDisplayFrame->setGpuFence(gpuFence);
837     mPendingPresentFences.emplace_back(std::make_pair(presentFence, mCurrentDisplayFrame));
838     flushPendingPresentFences();
839     finalizeCurrentDisplayFrame();
840 }
841 
addSurfaceFrame(std::shared_ptr<SurfaceFrame> surfaceFrame)842 void FrameTimeline::DisplayFrame::addSurfaceFrame(std::shared_ptr<SurfaceFrame> surfaceFrame) {
843     mSurfaceFrames.push_back(surfaceFrame);
844 }
845 
onSfWakeUp(int64_t token,Fps refreshRate,std::optional<TimelineItem> predictions,nsecs_t wakeUpTime)846 void FrameTimeline::DisplayFrame::onSfWakeUp(int64_t token, Fps refreshRate,
847                                              std::optional<TimelineItem> predictions,
848                                              nsecs_t wakeUpTime) {
849     mToken = token;
850     mRefreshRate = refreshRate;
851     if (!predictions) {
852         mPredictionState = PredictionState::Expired;
853     } else {
854         mPredictionState = PredictionState::Valid;
855         mSurfaceFlingerPredictions = *predictions;
856     }
857     mSurfaceFlingerActuals.startTime = wakeUpTime;
858 }
859 
setPredictions(PredictionState predictionState,TimelineItem predictions)860 void FrameTimeline::DisplayFrame::setPredictions(PredictionState predictionState,
861                                                  TimelineItem predictions) {
862     mPredictionState = predictionState;
863     mSurfaceFlingerPredictions = predictions;
864 }
865 
setActualStartTime(nsecs_t actualStartTime)866 void FrameTimeline::DisplayFrame::setActualStartTime(nsecs_t actualStartTime) {
867     mSurfaceFlingerActuals.startTime = actualStartTime;
868 }
869 
setActualEndTime(nsecs_t actualEndTime)870 void FrameTimeline::DisplayFrame::setActualEndTime(nsecs_t actualEndTime) {
871     mSurfaceFlingerActuals.endTime = actualEndTime;
872 }
873 
setGpuFence(const std::shared_ptr<FenceTime> & gpuFence)874 void FrameTimeline::DisplayFrame::setGpuFence(const std::shared_ptr<FenceTime>& gpuFence) {
875     mGpuFence = gpuFence;
876 }
877 
classifyJank(nsecs_t & deadlineDelta,nsecs_t & deltaToVsync,nsecs_t previousPresentTime)878 void FrameTimeline::DisplayFrame::classifyJank(nsecs_t& deadlineDelta, nsecs_t& deltaToVsync,
879                                                nsecs_t previousPresentTime) {
880     if (mPredictionState == PredictionState::Expired ||
881         mSurfaceFlingerActuals.presentTime == Fence::SIGNAL_TIME_INVALID) {
882         // Cannot do jank classification with expired predictions or invalid signal times. Set the
883         // deltas to 0 as both negative and positive deltas are used as real values.
884         mJankType = JankType::Unknown;
885         deadlineDelta = 0;
886         deltaToVsync = 0;
887         return;
888     }
889 
890     // Delta between the expected present and the actual present
891     const nsecs_t presentDelta =
892             mSurfaceFlingerActuals.presentTime - mSurfaceFlingerPredictions.presentTime;
893     // Sf actual end time represents the CPU end time. In case of HWC, SF's end time would have
894     // included the time for composition. However, for GPU composition, the final end time is max(sf
895     // end time, gpu fence time).
896     nsecs_t combinedEndTime = mSurfaceFlingerActuals.endTime;
897     if (mGpuFence != FenceTime::NO_FENCE) {
898         combinedEndTime = std::max(combinedEndTime, mGpuFence->getSignalTime());
899     }
900     deadlineDelta = combinedEndTime - mSurfaceFlingerPredictions.endTime;
901 
902     // How far off was the presentDelta when compared to the vsyncPeriod. Used in checking if there
903     // was a prediction error or not.
904     deltaToVsync = mRefreshRate.getPeriodNsecs() > 0
905             ? std::abs(presentDelta) % mRefreshRate.getPeriodNsecs()
906             : 0;
907 
908     if (std::abs(presentDelta) > mJankClassificationThresholds.presentThreshold) {
909         mFramePresentMetadata = presentDelta > 0 ? FramePresentMetadata::LatePresent
910                                                  : FramePresentMetadata::EarlyPresent;
911     } else {
912         mFramePresentMetadata = FramePresentMetadata::OnTimePresent;
913     }
914 
915     if (combinedEndTime > mSurfaceFlingerPredictions.endTime) {
916         mFrameReadyMetadata = FrameReadyMetadata::LateFinish;
917     } else {
918         mFrameReadyMetadata = FrameReadyMetadata::OnTimeFinish;
919     }
920 
921     if (std::abs(mSurfaceFlingerActuals.startTime - mSurfaceFlingerPredictions.startTime) >
922         mJankClassificationThresholds.startThreshold) {
923         mFrameStartMetadata =
924                 mSurfaceFlingerActuals.startTime > mSurfaceFlingerPredictions.startTime
925                 ? FrameStartMetadata::LateStart
926                 : FrameStartMetadata::EarlyStart;
927     }
928 
929     if (mFramePresentMetadata != FramePresentMetadata::OnTimePresent) {
930         // Do jank classification only if present is not on time
931         if (mFramePresentMetadata == FramePresentMetadata::EarlyPresent) {
932             if (mFrameReadyMetadata == FrameReadyMetadata::OnTimeFinish) {
933                 // Finish on time, Present early
934                 if (deltaToVsync < mJankClassificationThresholds.presentThreshold ||
935                     deltaToVsync >= (mRefreshRate.getPeriodNsecs() -
936                                      mJankClassificationThresholds.presentThreshold)) {
937                     // Delta is a factor of vsync if its within the presentTheshold on either side
938                     // of the vsyncPeriod. Example: 0-2ms and 9-11ms are both within the threshold
939                     // of the vsyncPeriod if the threshold was 2ms and the vsyncPeriod was 11ms.
940                     mJankType = JankType::SurfaceFlingerScheduling;
941                 } else {
942                     // Delta is not a factor of vsync,
943                     mJankType = JankType::PredictionError;
944                 }
945             } else if (mFrameReadyMetadata == FrameReadyMetadata::LateFinish) {
946                 // Finish late, Present early
947                 mJankType = JankType::SurfaceFlingerScheduling;
948             } else {
949                 // Finish time unknown
950                 mJankType = JankType::Unknown;
951             }
952         } else if (mFramePresentMetadata == FramePresentMetadata::LatePresent) {
953             if (std::abs(mSurfaceFlingerPredictions.presentTime - previousPresentTime) <=
954                         mJankClassificationThresholds.presentThreshold ||
955                 previousPresentTime > mSurfaceFlingerPredictions.presentTime) {
956                 // The previous frame was either presented in the current frame's expected vsync or
957                 // it was presented even later than the current frame's expected vsync.
958                 mJankType = JankType::SurfaceFlingerStuffing;
959             }
960             if (mFrameReadyMetadata == FrameReadyMetadata::OnTimeFinish &&
961                 !(mJankType & JankType::SurfaceFlingerStuffing)) {
962                 // Finish on time, Present late
963                 if (deltaToVsync < mJankClassificationThresholds.presentThreshold ||
964                     deltaToVsync >= (mRefreshRate.getPeriodNsecs() -
965                                      mJankClassificationThresholds.presentThreshold)) {
966                     // Delta is a factor of vsync if its within the presentTheshold on either side
967                     // of the vsyncPeriod. Example: 0-2ms and 9-11ms are both within the threshold
968                     // of the vsyncPeriod if the threshold was 2ms and the vsyncPeriod was 11ms.
969                     mJankType = JankType::DisplayHAL;
970                 } else {
971                     // Delta is not a factor of vsync
972                     mJankType = JankType::PredictionError;
973                 }
974             } else if (mFrameReadyMetadata == FrameReadyMetadata::LateFinish) {
975                 if (!(mJankType & JankType::SurfaceFlingerStuffing) ||
976                     mSurfaceFlingerActuals.presentTime - previousPresentTime >
977                             mRefreshRate.getPeriodNsecs() +
978                                     mJankClassificationThresholds.presentThreshold) {
979                     // Classify CPU vs GPU if SF wasn't stuffed or if SF was stuffed but this frame
980                     // was presented more than a vsync late.
981                     if (mGpuFence != FenceTime::NO_FENCE &&
982                         mSurfaceFlingerActuals.endTime - mSurfaceFlingerActuals.startTime <
983                                 mRefreshRate.getPeriodNsecs()) {
984                         // If SF was in GPU composition and the CPU work finished before the vsync
985                         // period, classify it as GPU deadline missed.
986                         mJankType = JankType::SurfaceFlingerGpuDeadlineMissed;
987                     } else {
988                         mJankType = JankType::SurfaceFlingerCpuDeadlineMissed;
989                     }
990                 }
991             } else {
992                 // Finish time unknown
993                 mJankType = JankType::Unknown;
994             }
995         } else {
996             // Present unknown
997             mJankType = JankType::Unknown;
998         }
999     }
1000 }
1001 
onPresent(nsecs_t signalTime,nsecs_t previousPresentTime)1002 void FrameTimeline::DisplayFrame::onPresent(nsecs_t signalTime, nsecs_t previousPresentTime) {
1003     mSurfaceFlingerActuals.presentTime = signalTime;
1004     nsecs_t deadlineDelta = 0;
1005     nsecs_t deltaToVsync = 0;
1006     classifyJank(deadlineDelta, deltaToVsync, previousPresentTime);
1007 
1008     for (auto& surfaceFrame : mSurfaceFrames) {
1009         surfaceFrame->onPresent(signalTime, mJankType, mRefreshRate, deadlineDelta, deltaToVsync);
1010     }
1011 }
1012 
tracePredictions(pid_t surfaceFlingerPid) const1013 void FrameTimeline::DisplayFrame::tracePredictions(pid_t surfaceFlingerPid) const {
1014     int64_t expectedTimelineCookie = mTraceCookieCounter.getCookieForTracing();
1015 
1016     // Expected timeline start
1017     FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
1018         auto packet = ctx.NewTracePacket();
1019         packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
1020         packet->set_timestamp(static_cast<uint64_t>(mSurfaceFlingerPredictions.startTime));
1021 
1022         auto* event = packet->set_frame_timeline_event();
1023         auto* expectedDisplayFrameStartEvent = event->set_expected_display_frame_start();
1024 
1025         expectedDisplayFrameStartEvent->set_cookie(expectedTimelineCookie);
1026 
1027         expectedDisplayFrameStartEvent->set_token(mToken);
1028         expectedDisplayFrameStartEvent->set_pid(surfaceFlingerPid);
1029     });
1030 
1031     // Expected timeline end
1032     FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
1033         auto packet = ctx.NewTracePacket();
1034         packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
1035         packet->set_timestamp(static_cast<uint64_t>(mSurfaceFlingerPredictions.endTime));
1036 
1037         auto* event = packet->set_frame_timeline_event();
1038         auto* expectedDisplayFrameEndEvent = event->set_frame_end();
1039 
1040         expectedDisplayFrameEndEvent->set_cookie(expectedTimelineCookie);
1041     });
1042 }
1043 
traceActuals(pid_t surfaceFlingerPid) const1044 void FrameTimeline::DisplayFrame::traceActuals(pid_t surfaceFlingerPid) const {
1045     int64_t actualTimelineCookie = mTraceCookieCounter.getCookieForTracing();
1046 
1047     // Actual timeline start
1048     FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
1049         auto packet = ctx.NewTracePacket();
1050         packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
1051         packet->set_timestamp(static_cast<uint64_t>(mSurfaceFlingerActuals.startTime));
1052 
1053         auto* event = packet->set_frame_timeline_event();
1054         auto* actualDisplayFrameStartEvent = event->set_actual_display_frame_start();
1055 
1056         actualDisplayFrameStartEvent->set_cookie(actualTimelineCookie);
1057 
1058         actualDisplayFrameStartEvent->set_token(mToken);
1059         actualDisplayFrameStartEvent->set_pid(surfaceFlingerPid);
1060 
1061         actualDisplayFrameStartEvent->set_present_type(toProto(mFramePresentMetadata));
1062         actualDisplayFrameStartEvent->set_on_time_finish(mFrameReadyMetadata ==
1063                                                          FrameReadyMetadata::OnTimeFinish);
1064         actualDisplayFrameStartEvent->set_gpu_composition(mGpuFence != FenceTime::NO_FENCE);
1065         actualDisplayFrameStartEvent->set_jank_type(jankTypeBitmaskToProto(mJankType));
1066         actualDisplayFrameStartEvent->set_prediction_type(toProto(mPredictionState));
1067     });
1068 
1069     // Actual timeline end
1070     FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
1071         auto packet = ctx.NewTracePacket();
1072         packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
1073         packet->set_timestamp(static_cast<uint64_t>(mSurfaceFlingerActuals.presentTime));
1074 
1075         auto* event = packet->set_frame_timeline_event();
1076         auto* actualDisplayFrameEndEvent = event->set_frame_end();
1077 
1078         actualDisplayFrameEndEvent->set_cookie(actualTimelineCookie);
1079     });
1080 }
1081 
trace(pid_t surfaceFlingerPid) const1082 void FrameTimeline::DisplayFrame::trace(pid_t surfaceFlingerPid) const {
1083     if (mToken == FrameTimelineInfo::INVALID_VSYNC_ID) {
1084         // DisplayFrame should not have an invalid token.
1085         ALOGE("Cannot trace DisplayFrame with invalid token");
1086         return;
1087     }
1088 
1089     if (mPredictionState == PredictionState::Valid) {
1090         // Expired and unknown predictions have zeroed timestamps. This cannot be used in any
1091         // meaningful way in a trace.
1092         tracePredictions(surfaceFlingerPid);
1093     }
1094     traceActuals(surfaceFlingerPid);
1095 
1096     for (auto& surfaceFrame : mSurfaceFrames) {
1097         surfaceFrame->trace(mToken);
1098     }
1099 }
1100 
computeFps(const std::unordered_set<int32_t> & layerIds)1101 float FrameTimeline::computeFps(const std::unordered_set<int32_t>& layerIds) {
1102     if (layerIds.empty()) {
1103         return 0.0f;
1104     }
1105 
1106     std::vector<nsecs_t> presentTimes;
1107     {
1108         std::scoped_lock lock(mMutex);
1109         presentTimes.reserve(mDisplayFrames.size());
1110         for (size_t i = 0; i < mDisplayFrames.size(); i++) {
1111             const auto& displayFrame = mDisplayFrames[i];
1112             if (displayFrame->getActuals().presentTime <= 0) {
1113                 continue;
1114             }
1115             for (const auto& surfaceFrame : displayFrame->getSurfaceFrames()) {
1116                 if (surfaceFrame->getPresentState() == SurfaceFrame::PresentState::Presented &&
1117                     layerIds.count(surfaceFrame->getLayerId()) > 0) {
1118                     // We're looking for DisplayFrames that presents at least one layer from
1119                     // layerIds, so push the present time and skip looking through the rest of the
1120                     // SurfaceFrames.
1121                     presentTimes.push_back(displayFrame->getActuals().presentTime);
1122                     break;
1123                 }
1124             }
1125         }
1126     }
1127 
1128     // FPS can't be computed when there's fewer than 2 presented frames.
1129     if (presentTimes.size() <= 1) {
1130         return 0.0f;
1131     }
1132 
1133     nsecs_t priorPresentTime = -1;
1134     nsecs_t totalPresentToPresentWalls = 0;
1135 
1136     for (const nsecs_t presentTime : presentTimes) {
1137         if (priorPresentTime == -1) {
1138             priorPresentTime = presentTime;
1139             continue;
1140         }
1141 
1142         totalPresentToPresentWalls += (presentTime - priorPresentTime);
1143         priorPresentTime = presentTime;
1144     }
1145 
1146     if (CC_UNLIKELY(totalPresentToPresentWalls <= 0)) {
1147         ALOGW("Invalid total present-to-present duration when computing fps: %" PRId64,
1148               totalPresentToPresentWalls);
1149         return 0.0f;
1150     }
1151 
1152     const constexpr nsecs_t kOneSecond =
1153             std::chrono::duration_cast<std::chrono::nanoseconds>(1s).count();
1154     // (10^9 nanoseconds / second) * (N present deltas) / (total nanoseconds in N present deltas) =
1155     // M frames / second
1156     return kOneSecond * static_cast<nsecs_t>((presentTimes.size() - 1)) /
1157             static_cast<float>(totalPresentToPresentWalls);
1158 }
1159 
flushPendingPresentFences()1160 void FrameTimeline::flushPendingPresentFences() {
1161     for (size_t i = 0; i < mPendingPresentFences.size(); i++) {
1162         const auto& pendingPresentFence = mPendingPresentFences[i];
1163         nsecs_t signalTime = Fence::SIGNAL_TIME_INVALID;
1164         if (pendingPresentFence.first && pendingPresentFence.first->isValid()) {
1165             signalTime = pendingPresentFence.first->getSignalTime();
1166             if (signalTime == Fence::SIGNAL_TIME_PENDING) {
1167                 continue;
1168             }
1169         }
1170         auto& displayFrame = pendingPresentFence.second;
1171         displayFrame->onPresent(signalTime, mPreviousPresentTime);
1172         displayFrame->trace(mSurfaceFlingerPid);
1173         mPreviousPresentTime = signalTime;
1174 
1175         mPendingPresentFences.erase(mPendingPresentFences.begin() + static_cast<int>(i));
1176         --i;
1177     }
1178 }
1179 
finalizeCurrentDisplayFrame()1180 void FrameTimeline::finalizeCurrentDisplayFrame() {
1181     while (mDisplayFrames.size() >= mMaxDisplayFrames) {
1182         // We maintain only a fixed number of frames' data. Pop older frames
1183         mDisplayFrames.pop_front();
1184     }
1185     mDisplayFrames.push_back(mCurrentDisplayFrame);
1186     mCurrentDisplayFrame.reset();
1187     mCurrentDisplayFrame = std::make_shared<DisplayFrame>(mTimeStats, mJankClassificationThresholds,
1188                                                           &mTraceCookieCounter);
1189 }
1190 
getBaseTime() const1191 nsecs_t FrameTimeline::DisplayFrame::getBaseTime() const {
1192     nsecs_t baseTime =
1193             getMinTime(mPredictionState, mSurfaceFlingerPredictions, mSurfaceFlingerActuals);
1194     for (const auto& surfaceFrame : mSurfaceFrames) {
1195         nsecs_t surfaceFrameBaseTime = surfaceFrame->getBaseTime();
1196         if (surfaceFrameBaseTime != 0) {
1197             baseTime = std::min(baseTime, surfaceFrameBaseTime);
1198         }
1199     }
1200     return baseTime;
1201 }
1202 
dumpJank(std::string & result,nsecs_t baseTime,int displayFrameCount) const1203 void FrameTimeline::DisplayFrame::dumpJank(std::string& result, nsecs_t baseTime,
1204                                            int displayFrameCount) const {
1205     if (mJankType == JankType::None) {
1206         // Check if any Surface Frame has been janky
1207         bool isJanky = false;
1208         for (const auto& surfaceFrame : mSurfaceFrames) {
1209             if (surfaceFrame->getJankType() != JankType::None) {
1210                 isJanky = true;
1211                 break;
1212             }
1213         }
1214         if (!isJanky) {
1215             return;
1216         }
1217     }
1218     StringAppendF(&result, "Display Frame %d", displayFrameCount);
1219     dump(result, baseTime);
1220 }
1221 
dumpAll(std::string & result,nsecs_t baseTime) const1222 void FrameTimeline::DisplayFrame::dumpAll(std::string& result, nsecs_t baseTime) const {
1223     dump(result, baseTime);
1224 }
1225 
dump(std::string & result,nsecs_t baseTime) const1226 void FrameTimeline::DisplayFrame::dump(std::string& result, nsecs_t baseTime) const {
1227     if (mJankType != JankType::None) {
1228         // Easily identify a janky Display Frame in the dump
1229         StringAppendF(&result, " [*] ");
1230     }
1231     StringAppendF(&result, "\n");
1232     StringAppendF(&result, "Prediction State : %s\n", toString(mPredictionState).c_str());
1233     StringAppendF(&result, "Jank Type : %s\n", jankTypeBitmaskToString(mJankType).c_str());
1234     StringAppendF(&result, "Present Metadata : %s\n", toString(mFramePresentMetadata).c_str());
1235     StringAppendF(&result, "Finish Metadata: %s\n", toString(mFrameReadyMetadata).c_str());
1236     StringAppendF(&result, "Start Metadata: %s\n", toString(mFrameStartMetadata).c_str());
1237     std::chrono::nanoseconds vsyncPeriod(mRefreshRate.getPeriodNsecs());
1238     StringAppendF(&result, "Vsync Period: %10f\n",
1239                   std::chrono::duration<double, std::milli>(vsyncPeriod).count());
1240     nsecs_t presentDelta =
1241             mSurfaceFlingerActuals.presentTime - mSurfaceFlingerPredictions.presentTime;
1242     std::chrono::nanoseconds presentDeltaNs(std::abs(presentDelta));
1243     StringAppendF(&result, "Present delta: %10f\n",
1244                   std::chrono::duration<double, std::milli>(presentDeltaNs).count());
1245     std::chrono::nanoseconds deltaToVsync(std::abs(presentDelta) % mRefreshRate.getPeriodNsecs());
1246     StringAppendF(&result, "Present delta %% refreshrate: %10f\n",
1247                   std::chrono::duration<double, std::milli>(deltaToVsync).count());
1248     dumpTable(result, mSurfaceFlingerPredictions, mSurfaceFlingerActuals, "", mPredictionState,
1249               baseTime);
1250     StringAppendF(&result, "\n");
1251     std::string indent = "    "; // 4 spaces
1252     for (const auto& surfaceFrame : mSurfaceFrames) {
1253         surfaceFrame->dump(result, indent, baseTime);
1254     }
1255     StringAppendF(&result, "\n");
1256 }
1257 
dumpAll(std::string & result)1258 void FrameTimeline::dumpAll(std::string& result) {
1259     std::scoped_lock lock(mMutex);
1260     StringAppendF(&result, "Number of display frames : %d\n", (int)mDisplayFrames.size());
1261     nsecs_t baseTime = (mDisplayFrames.empty()) ? 0 : mDisplayFrames[0]->getBaseTime();
1262     for (size_t i = 0; i < mDisplayFrames.size(); i++) {
1263         StringAppendF(&result, "Display Frame %d", static_cast<int>(i));
1264         mDisplayFrames[i]->dumpAll(result, baseTime);
1265     }
1266 }
1267 
dumpJank(std::string & result)1268 void FrameTimeline::dumpJank(std::string& result) {
1269     std::scoped_lock lock(mMutex);
1270     nsecs_t baseTime = (mDisplayFrames.empty()) ? 0 : mDisplayFrames[0]->getBaseTime();
1271     for (size_t i = 0; i < mDisplayFrames.size(); i++) {
1272         mDisplayFrames[i]->dumpJank(result, baseTime, static_cast<int>(i));
1273     }
1274 }
1275 
parseArgs(const Vector<String16> & args,std::string & result)1276 void FrameTimeline::parseArgs(const Vector<String16>& args, std::string& result) {
1277     ATRACE_CALL();
1278     std::unordered_map<std::string, bool> argsMap;
1279     for (size_t i = 0; i < args.size(); i++) {
1280         argsMap[std::string(String8(args[i]).c_str())] = true;
1281     }
1282     if (argsMap.count("-jank")) {
1283         dumpJank(result);
1284     }
1285     if (argsMap.count("-all")) {
1286         dumpAll(result);
1287     }
1288 }
1289 
setMaxDisplayFrames(uint32_t size)1290 void FrameTimeline::setMaxDisplayFrames(uint32_t size) {
1291     std::scoped_lock lock(mMutex);
1292 
1293     // The size can either increase or decrease, clear everything, to be consistent
1294     mDisplayFrames.clear();
1295     mPendingPresentFences.clear();
1296     mMaxDisplayFrames = size;
1297 }
1298 
reset()1299 void FrameTimeline::reset() {
1300     setMaxDisplayFrames(kDefaultMaxDisplayFrames);
1301 }
1302 
1303 } // namespace impl
1304 } // namespace android::frametimeline
1305