• 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,GameMode 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, GameMode 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 (mActuals.presentTime == Fence::SIGNAL_TIME_INVALID) {
496         // Cannot do any classification for invalid present time.
497         mJankType = JankType::Unknown;
498         deadlineDelta = -1;
499         return;
500     }
501 
502     if (mPredictionState == PredictionState::Expired) {
503         // We classify prediction expired as AppDeadlineMissed as the
504         // TokenManager::kMaxTokens we store is large enough to account for a
505         // reasonable app, so prediction expire would mean a huge scheduling delay.
506         mJankType = JankType::AppDeadlineMissed;
507         deadlineDelta = -1;
508         return;
509     }
510 
511     if (mPredictionState == PredictionState::None) {
512         // Cannot do jank classification on frames that don't have a token.
513         return;
514     }
515 
516     deadlineDelta = mActuals.endTime - mPredictions.endTime;
517     const nsecs_t presentDelta = mActuals.presentTime - mPredictions.presentTime;
518     const nsecs_t deltaToVsync = refreshRate.getPeriodNsecs() > 0
519             ? std::abs(presentDelta) % refreshRate.getPeriodNsecs()
520             : 0;
521 
522     if (deadlineDelta > mJankClassificationThresholds.deadlineThreshold) {
523         mFrameReadyMetadata = FrameReadyMetadata::LateFinish;
524     } else {
525         mFrameReadyMetadata = FrameReadyMetadata::OnTimeFinish;
526     }
527 
528     if (std::abs(presentDelta) > mJankClassificationThresholds.presentThreshold) {
529         mFramePresentMetadata = presentDelta > 0 ? FramePresentMetadata::LatePresent
530                                                  : FramePresentMetadata::EarlyPresent;
531     } else {
532         mFramePresentMetadata = FramePresentMetadata::OnTimePresent;
533     }
534 
535     if (mFramePresentMetadata == FramePresentMetadata::OnTimePresent) {
536         // Frames presented on time are not janky.
537         mJankType = JankType::None;
538     } else if (mFramePresentMetadata == FramePresentMetadata::EarlyPresent) {
539         if (mFrameReadyMetadata == FrameReadyMetadata::OnTimeFinish) {
540             // Finish on time, Present early
541             if (deltaToVsync < mJankClassificationThresholds.presentThreshold ||
542                 deltaToVsync >= refreshRate.getPeriodNsecs() -
543                                 mJankClassificationThresholds.presentThreshold) {
544                 // Delta factor of vsync
545                 mJankType = JankType::SurfaceFlingerScheduling;
546             } else {
547                 // Delta not a factor of vsync
548                 mJankType = JankType::PredictionError;
549             }
550         } else if (mFrameReadyMetadata == FrameReadyMetadata::LateFinish) {
551             // Finish late, Present early
552             mJankType = JankType::Unknown;
553         }
554     } else {
555         if (mLastLatchTime != 0 && mPredictions.endTime <= mLastLatchTime) {
556             // Buffer Stuffing.
557             mJankType |= JankType::BufferStuffing;
558             // In a stuffed state, the frame could be stuck on a dequeue wait for quite some time.
559             // Because of this dequeue wait, it can be hard to tell if a frame was genuinely late.
560             // We try to do this by moving the deadline. Since the queue could be stuffed by more
561             // than one buffer, we take the last latch time as reference and give one vsync
562             // worth of time for the frame to be ready.
563             nsecs_t adjustedDeadline = mLastLatchTime + refreshRate.getPeriodNsecs();
564             if (adjustedDeadline > mActuals.endTime) {
565                 mFrameReadyMetadata = FrameReadyMetadata::OnTimeFinish;
566             } else {
567                 mFrameReadyMetadata = FrameReadyMetadata::LateFinish;
568             }
569         }
570         if (mFrameReadyMetadata == FrameReadyMetadata::OnTimeFinish) {
571             // Finish on time, Present late
572             if (displayFrameJankType != JankType::None) {
573                 // Propagate displayFrame's jank if it exists
574                 mJankType |= displayFrameJankType;
575             } else {
576                 if (!(mJankType & JankType::BufferStuffing)) {
577                     // In a stuffed state, if the app finishes on time and there is no display frame
578                     // jank, only buffer stuffing is the root cause of the jank.
579                     if (deltaToVsync < mJankClassificationThresholds.presentThreshold ||
580                         deltaToVsync >= refreshRate.getPeriodNsecs() -
581                                         mJankClassificationThresholds.presentThreshold) {
582                         // Delta factor of vsync
583                         mJankType |= JankType::SurfaceFlingerScheduling;
584                     } else {
585                         // Delta not a factor of vsync
586                         mJankType |= JankType::PredictionError;
587                     }
588                 }
589             }
590         } else if (mFrameReadyMetadata == FrameReadyMetadata::LateFinish) {
591             // Finish late, Present late
592             mJankType |= JankType::AppDeadlineMissed;
593             // Propagate DisplayFrame's jankType if it is janky
594             mJankType |= displayFrameJankType;
595         }
596     }
597 }
598 
onPresent(nsecs_t presentTime,int32_t displayFrameJankType,Fps refreshRate,nsecs_t displayDeadlineDelta,nsecs_t displayPresentDelta)599 void SurfaceFrame::onPresent(nsecs_t presentTime, int32_t displayFrameJankType, Fps refreshRate,
600                              nsecs_t displayDeadlineDelta, nsecs_t displayPresentDelta) {
601     std::scoped_lock lock(mMutex);
602 
603     if (mPresentState != PresentState::Presented) {
604         // No need to update dropped buffers
605         return;
606     }
607 
608     mActuals.presentTime = presentTime;
609     nsecs_t deadlineDelta = 0;
610 
611     classifyJankLocked(displayFrameJankType, refreshRate, deadlineDelta);
612 
613     if (mPredictionState != PredictionState::None) {
614         // Only update janky frames if the app used vsync predictions
615         mTimeStats->incrementJankyFrames({refreshRate, mRenderRate, mOwnerUid, mLayerName,
616                                           mGameMode, mJankType, displayDeadlineDelta,
617                                           displayPresentDelta, deadlineDelta});
618     }
619 }
620 
tracePredictions(int64_t displayFrameToken,nsecs_t monoBootOffset) const621 void SurfaceFrame::tracePredictions(int64_t displayFrameToken, nsecs_t monoBootOffset) const {
622     int64_t expectedTimelineCookie = mTraceCookieCounter.getCookieForTracing();
623 
624     // Expected timeline start
625     FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
626         std::scoped_lock lock(mMutex);
627         auto packet = ctx.NewTracePacket();
628         packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_BOOTTIME);
629         packet->set_timestamp(static_cast<uint64_t>(mPredictions.startTime + monoBootOffset));
630 
631         auto* event = packet->set_frame_timeline_event();
632         auto* expectedSurfaceFrameStartEvent = event->set_expected_surface_frame_start();
633 
634         expectedSurfaceFrameStartEvent->set_cookie(expectedTimelineCookie);
635 
636         expectedSurfaceFrameStartEvent->set_token(mToken);
637         expectedSurfaceFrameStartEvent->set_display_frame_token(displayFrameToken);
638 
639         expectedSurfaceFrameStartEvent->set_pid(mOwnerPid);
640         expectedSurfaceFrameStartEvent->set_layer_name(mDebugName);
641     });
642 
643     // Expected timeline end
644     FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
645         std::scoped_lock lock(mMutex);
646         auto packet = ctx.NewTracePacket();
647         packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_BOOTTIME);
648         packet->set_timestamp(static_cast<uint64_t>(mPredictions.endTime + monoBootOffset));
649 
650         auto* event = packet->set_frame_timeline_event();
651         auto* expectedSurfaceFrameEndEvent = event->set_frame_end();
652 
653         expectedSurfaceFrameEndEvent->set_cookie(expectedTimelineCookie);
654     });
655 }
656 
traceActuals(int64_t displayFrameToken,nsecs_t monoBootOffset) const657 void SurfaceFrame::traceActuals(int64_t displayFrameToken, nsecs_t monoBootOffset) const {
658     int64_t actualTimelineCookie = mTraceCookieCounter.getCookieForTracing();
659 
660     // Actual timeline start
661     FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
662         std::scoped_lock lock(mMutex);
663         auto packet = ctx.NewTracePacket();
664         packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_BOOTTIME);
665         // Actual start time is not yet available, so use expected start instead
666         if (mPredictionState == PredictionState::Expired) {
667             // If prediction is expired, we can't use the predicted start time. Instead, just use a
668             // start time a little earlier than the end time so that we have some info about this
669             // frame in the trace.
670             nsecs_t endTime =
671                     (mPresentState == PresentState::Dropped ? mDropTime : mActuals.endTime);
672             const auto timestamp = endTime - kPredictionExpiredStartTimeDelta;
673             packet->set_timestamp(static_cast<uint64_t>(timestamp + monoBootOffset));
674         } else {
675             const auto timestamp =
676                     mActuals.startTime == 0 ? mPredictions.startTime : mActuals.startTime;
677             packet->set_timestamp(static_cast<uint64_t>(timestamp + monoBootOffset));
678         }
679 
680         auto* event = packet->set_frame_timeline_event();
681         auto* actualSurfaceFrameStartEvent = event->set_actual_surface_frame_start();
682 
683         actualSurfaceFrameStartEvent->set_cookie(actualTimelineCookie);
684 
685         actualSurfaceFrameStartEvent->set_token(mToken);
686         actualSurfaceFrameStartEvent->set_display_frame_token(displayFrameToken);
687 
688         actualSurfaceFrameStartEvent->set_pid(mOwnerPid);
689         actualSurfaceFrameStartEvent->set_layer_name(mDebugName);
690 
691         if (mPresentState == PresentState::Dropped) {
692             actualSurfaceFrameStartEvent->set_present_type(FrameTimelineEvent::PRESENT_DROPPED);
693         } else if (mPresentState == PresentState::Unknown) {
694             actualSurfaceFrameStartEvent->set_present_type(FrameTimelineEvent::PRESENT_UNSPECIFIED);
695         } else {
696             actualSurfaceFrameStartEvent->set_present_type(toProto(mFramePresentMetadata));
697         }
698         actualSurfaceFrameStartEvent->set_on_time_finish(mFrameReadyMetadata ==
699                                                          FrameReadyMetadata::OnTimeFinish);
700         actualSurfaceFrameStartEvent->set_gpu_composition(mGpuComposition);
701         actualSurfaceFrameStartEvent->set_jank_type(jankTypeBitmaskToProto(mJankType));
702         actualSurfaceFrameStartEvent->set_prediction_type(toProto(mPredictionState));
703         actualSurfaceFrameStartEvent->set_is_buffer(mIsBuffer);
704     });
705 
706     // Actual timeline end
707     FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
708         std::scoped_lock lock(mMutex);
709         auto packet = ctx.NewTracePacket();
710         packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_BOOTTIME);
711         if (mPresentState == PresentState::Dropped) {
712             packet->set_timestamp(static_cast<uint64_t>(mDropTime + monoBootOffset));
713         } else {
714             packet->set_timestamp(static_cast<uint64_t>(mActuals.endTime + monoBootOffset));
715         }
716 
717         auto* event = packet->set_frame_timeline_event();
718         auto* actualSurfaceFrameEndEvent = event->set_frame_end();
719 
720         actualSurfaceFrameEndEvent->set_cookie(actualTimelineCookie);
721     });
722 }
723 
724 /**
725  * TODO(b/178637512): add inputEventId to the perfetto trace.
726  */
trace(int64_t displayFrameToken,nsecs_t monoBootOffset) const727 void SurfaceFrame::trace(int64_t displayFrameToken, nsecs_t monoBootOffset) const {
728     if (mToken == FrameTimelineInfo::INVALID_VSYNC_ID ||
729         displayFrameToken == FrameTimelineInfo::INVALID_VSYNC_ID) {
730         // No packets can be traced with a missing token.
731         return;
732     }
733     if (getPredictionState() != PredictionState::Expired) {
734         // Expired predictions have zeroed timestamps. This cannot be used in any meaningful way in
735         // a trace.
736         tracePredictions(displayFrameToken, monoBootOffset);
737     }
738     traceActuals(displayFrameToken, monoBootOffset);
739 }
740 
741 namespace impl {
742 
generateTokenForPredictions(TimelineItem && predictions)743 int64_t TokenManager::generateTokenForPredictions(TimelineItem&& predictions) {
744     ATRACE_CALL();
745     std::scoped_lock lock(mMutex);
746     while (mPredictions.size() >= kMaxTokens) {
747         mPredictions.erase(mPredictions.begin());
748     }
749     const int64_t assignedToken = mCurrentToken++;
750     mPredictions[assignedToken] = predictions;
751     return assignedToken;
752 }
753 
getPredictionsForToken(int64_t token) const754 std::optional<TimelineItem> TokenManager::getPredictionsForToken(int64_t token) const {
755     std::scoped_lock lock(mMutex);
756     auto predictionsIterator = mPredictions.find(token);
757     if (predictionsIterator != mPredictions.end()) {
758         return predictionsIterator->second;
759     }
760     return {};
761 }
762 
FrameTimeline(std::shared_ptr<TimeStats> timeStats,pid_t surfaceFlingerPid,JankClassificationThresholds thresholds,bool useBootTimeClock)763 FrameTimeline::FrameTimeline(std::shared_ptr<TimeStats> timeStats, pid_t surfaceFlingerPid,
764                              JankClassificationThresholds thresholds, bool useBootTimeClock)
765       : mUseBootTimeClock(useBootTimeClock),
766         mMaxDisplayFrames(kDefaultMaxDisplayFrames),
767         mTimeStats(std::move(timeStats)),
768         mSurfaceFlingerPid(surfaceFlingerPid),
769         mJankClassificationThresholds(thresholds) {
770     mCurrentDisplayFrame =
771             std::make_shared<DisplayFrame>(mTimeStats, thresholds, &mTraceCookieCounter);
772 }
773 
onBootFinished()774 void FrameTimeline::onBootFinished() {
775     perfetto::TracingInitArgs args;
776     args.backends = perfetto::kSystemBackend;
777     perfetto::Tracing::Initialize(args);
778     registerDataSource();
779 }
780 
registerDataSource()781 void FrameTimeline::registerDataSource() {
782     perfetto::DataSourceDescriptor dsd;
783     dsd.set_name(kFrameTimelineDataSource);
784     FrameTimelineDataSource::Register(dsd);
785 }
786 
createSurfaceFrameForToken(const FrameTimelineInfo & frameTimelineInfo,pid_t ownerPid,uid_t ownerUid,int32_t layerId,std::string layerName,std::string debugName,bool isBuffer,GameMode gameMode)787 std::shared_ptr<SurfaceFrame> FrameTimeline::createSurfaceFrameForToken(
788         const FrameTimelineInfo& frameTimelineInfo, pid_t ownerPid, uid_t ownerUid, int32_t layerId,
789         std::string layerName, std::string debugName, bool isBuffer, GameMode gameMode) {
790     ATRACE_CALL();
791     if (frameTimelineInfo.vsyncId == FrameTimelineInfo::INVALID_VSYNC_ID) {
792         return std::make_shared<SurfaceFrame>(frameTimelineInfo, ownerPid, ownerUid, layerId,
793                                               std::move(layerName), std::move(debugName),
794                                               PredictionState::None, TimelineItem(), mTimeStats,
795                                               mJankClassificationThresholds, &mTraceCookieCounter,
796                                               isBuffer, gameMode);
797     }
798     std::optional<TimelineItem> predictions =
799             mTokenManager.getPredictionsForToken(frameTimelineInfo.vsyncId);
800     if (predictions) {
801         return std::make_shared<SurfaceFrame>(frameTimelineInfo, ownerPid, ownerUid, layerId,
802                                               std::move(layerName), std::move(debugName),
803                                               PredictionState::Valid, std::move(*predictions),
804                                               mTimeStats, mJankClassificationThresholds,
805                                               &mTraceCookieCounter, isBuffer, gameMode);
806     }
807     return std::make_shared<SurfaceFrame>(frameTimelineInfo, ownerPid, ownerUid, layerId,
808                                           std::move(layerName), std::move(debugName),
809                                           PredictionState::Expired, TimelineItem(), mTimeStats,
810                                           mJankClassificationThresholds, &mTraceCookieCounter,
811                                           isBuffer, gameMode);
812 }
813 
DisplayFrame(std::shared_ptr<TimeStats> timeStats,JankClassificationThresholds thresholds,TraceCookieCounter * traceCookieCounter)814 FrameTimeline::DisplayFrame::DisplayFrame(std::shared_ptr<TimeStats> timeStats,
815                                           JankClassificationThresholds thresholds,
816                                           TraceCookieCounter* traceCookieCounter)
817       : mSurfaceFlingerPredictions(TimelineItem()),
818         mSurfaceFlingerActuals(TimelineItem()),
819         mTimeStats(timeStats),
820         mJankClassificationThresholds(thresholds),
821         mTraceCookieCounter(*traceCookieCounter) {
822     mSurfaceFrames.reserve(kNumSurfaceFramesInitial);
823 }
824 
addSurfaceFrame(std::shared_ptr<SurfaceFrame> surfaceFrame)825 void FrameTimeline::addSurfaceFrame(std::shared_ptr<SurfaceFrame> surfaceFrame) {
826     ATRACE_CALL();
827     std::scoped_lock lock(mMutex);
828     mCurrentDisplayFrame->addSurfaceFrame(surfaceFrame);
829 }
830 
setSfWakeUp(int64_t token,nsecs_t wakeUpTime,Fps refreshRate)831 void FrameTimeline::setSfWakeUp(int64_t token, nsecs_t wakeUpTime, Fps refreshRate) {
832     ATRACE_CALL();
833     std::scoped_lock lock(mMutex);
834     mCurrentDisplayFrame->onSfWakeUp(token, refreshRate,
835                                      mTokenManager.getPredictionsForToken(token), wakeUpTime);
836 }
837 
setSfPresent(nsecs_t sfPresentTime,const std::shared_ptr<FenceTime> & presentFence,const std::shared_ptr<FenceTime> & gpuFence)838 void FrameTimeline::setSfPresent(nsecs_t sfPresentTime,
839                                  const std::shared_ptr<FenceTime>& presentFence,
840                                  const std::shared_ptr<FenceTime>& gpuFence) {
841     ATRACE_CALL();
842     std::scoped_lock lock(mMutex);
843     mCurrentDisplayFrame->setActualEndTime(sfPresentTime);
844     mCurrentDisplayFrame->setGpuFence(gpuFence);
845     mPendingPresentFences.emplace_back(std::make_pair(presentFence, mCurrentDisplayFrame));
846     flushPendingPresentFences();
847     finalizeCurrentDisplayFrame();
848 }
849 
addSurfaceFrame(std::shared_ptr<SurfaceFrame> surfaceFrame)850 void FrameTimeline::DisplayFrame::addSurfaceFrame(std::shared_ptr<SurfaceFrame> surfaceFrame) {
851     mSurfaceFrames.push_back(surfaceFrame);
852 }
853 
onSfWakeUp(int64_t token,Fps refreshRate,std::optional<TimelineItem> predictions,nsecs_t wakeUpTime)854 void FrameTimeline::DisplayFrame::onSfWakeUp(int64_t token, Fps refreshRate,
855                                              std::optional<TimelineItem> predictions,
856                                              nsecs_t wakeUpTime) {
857     mToken = token;
858     mRefreshRate = refreshRate;
859     if (!predictions) {
860         mPredictionState = PredictionState::Expired;
861     } else {
862         mPredictionState = PredictionState::Valid;
863         mSurfaceFlingerPredictions = *predictions;
864     }
865     mSurfaceFlingerActuals.startTime = wakeUpTime;
866 }
867 
setPredictions(PredictionState predictionState,TimelineItem predictions)868 void FrameTimeline::DisplayFrame::setPredictions(PredictionState predictionState,
869                                                  TimelineItem predictions) {
870     mPredictionState = predictionState;
871     mSurfaceFlingerPredictions = predictions;
872 }
873 
setActualStartTime(nsecs_t actualStartTime)874 void FrameTimeline::DisplayFrame::setActualStartTime(nsecs_t actualStartTime) {
875     mSurfaceFlingerActuals.startTime = actualStartTime;
876 }
877 
setActualEndTime(nsecs_t actualEndTime)878 void FrameTimeline::DisplayFrame::setActualEndTime(nsecs_t actualEndTime) {
879     mSurfaceFlingerActuals.endTime = actualEndTime;
880 }
881 
setGpuFence(const std::shared_ptr<FenceTime> & gpuFence)882 void FrameTimeline::DisplayFrame::setGpuFence(const std::shared_ptr<FenceTime>& gpuFence) {
883     mGpuFence = gpuFence;
884 }
885 
classifyJank(nsecs_t & deadlineDelta,nsecs_t & deltaToVsync,nsecs_t previousPresentTime)886 void FrameTimeline::DisplayFrame::classifyJank(nsecs_t& deadlineDelta, nsecs_t& deltaToVsync,
887                                                nsecs_t previousPresentTime) {
888     if (mPredictionState == PredictionState::Expired ||
889         mSurfaceFlingerActuals.presentTime == Fence::SIGNAL_TIME_INVALID) {
890         // Cannot do jank classification with expired predictions or invalid signal times. Set the
891         // deltas to 0 as both negative and positive deltas are used as real values.
892         mJankType = JankType::Unknown;
893         deadlineDelta = 0;
894         deltaToVsync = 0;
895         return;
896     }
897 
898     // Delta between the expected present and the actual present
899     const nsecs_t presentDelta =
900             mSurfaceFlingerActuals.presentTime - mSurfaceFlingerPredictions.presentTime;
901     // Sf actual end time represents the CPU end time. In case of HWC, SF's end time would have
902     // included the time for composition. However, for GPU composition, the final end time is max(sf
903     // end time, gpu fence time).
904     nsecs_t combinedEndTime = mSurfaceFlingerActuals.endTime;
905     if (mGpuFence != FenceTime::NO_FENCE) {
906         combinedEndTime = std::max(combinedEndTime, mGpuFence->getSignalTime());
907     }
908     deadlineDelta = combinedEndTime - mSurfaceFlingerPredictions.endTime;
909 
910     // How far off was the presentDelta when compared to the vsyncPeriod. Used in checking if there
911     // was a prediction error or not.
912     deltaToVsync = mRefreshRate.getPeriodNsecs() > 0
913             ? std::abs(presentDelta) % mRefreshRate.getPeriodNsecs()
914             : 0;
915 
916     if (std::abs(presentDelta) > mJankClassificationThresholds.presentThreshold) {
917         mFramePresentMetadata = presentDelta > 0 ? FramePresentMetadata::LatePresent
918                                                  : FramePresentMetadata::EarlyPresent;
919     } else {
920         mFramePresentMetadata = FramePresentMetadata::OnTimePresent;
921     }
922 
923     if (combinedEndTime > mSurfaceFlingerPredictions.endTime) {
924         mFrameReadyMetadata = FrameReadyMetadata::LateFinish;
925     } else {
926         mFrameReadyMetadata = FrameReadyMetadata::OnTimeFinish;
927     }
928 
929     if (std::abs(mSurfaceFlingerActuals.startTime - mSurfaceFlingerPredictions.startTime) >
930         mJankClassificationThresholds.startThreshold) {
931         mFrameStartMetadata =
932                 mSurfaceFlingerActuals.startTime > mSurfaceFlingerPredictions.startTime
933                 ? FrameStartMetadata::LateStart
934                 : FrameStartMetadata::EarlyStart;
935     }
936 
937     if (mFramePresentMetadata != FramePresentMetadata::OnTimePresent) {
938         // Do jank classification only if present is not on time
939         if (mFramePresentMetadata == FramePresentMetadata::EarlyPresent) {
940             if (mFrameReadyMetadata == FrameReadyMetadata::OnTimeFinish) {
941                 // Finish on time, Present early
942                 if (deltaToVsync < mJankClassificationThresholds.presentThreshold ||
943                     deltaToVsync >= (mRefreshRate.getPeriodNsecs() -
944                                      mJankClassificationThresholds.presentThreshold)) {
945                     // Delta is a factor of vsync if its within the presentTheshold on either side
946                     // of the vsyncPeriod. Example: 0-2ms and 9-11ms are both within the threshold
947                     // of the vsyncPeriod if the threshold was 2ms and the vsyncPeriod was 11ms.
948                     mJankType = JankType::SurfaceFlingerScheduling;
949                 } else {
950                     // Delta is not a factor of vsync,
951                     mJankType = JankType::PredictionError;
952                 }
953             } else if (mFrameReadyMetadata == FrameReadyMetadata::LateFinish) {
954                 // Finish late, Present early
955                 mJankType = JankType::SurfaceFlingerScheduling;
956             } else {
957                 // Finish time unknown
958                 mJankType = JankType::Unknown;
959             }
960         } else if (mFramePresentMetadata == FramePresentMetadata::LatePresent) {
961             if (std::abs(mSurfaceFlingerPredictions.presentTime - previousPresentTime) <=
962                         mJankClassificationThresholds.presentThreshold ||
963                 previousPresentTime > mSurfaceFlingerPredictions.presentTime) {
964                 // The previous frame was either presented in the current frame's expected vsync or
965                 // it was presented even later than the current frame's expected vsync.
966                 mJankType = JankType::SurfaceFlingerStuffing;
967             }
968             if (mFrameReadyMetadata == FrameReadyMetadata::OnTimeFinish &&
969                 !(mJankType & JankType::SurfaceFlingerStuffing)) {
970                 // Finish on time, Present late
971                 if (deltaToVsync < mJankClassificationThresholds.presentThreshold ||
972                     deltaToVsync >= (mRefreshRate.getPeriodNsecs() -
973                                      mJankClassificationThresholds.presentThreshold)) {
974                     // Delta is a factor of vsync if its within the presentTheshold on either side
975                     // of the vsyncPeriod. Example: 0-2ms and 9-11ms are both within the threshold
976                     // of the vsyncPeriod if the threshold was 2ms and the vsyncPeriod was 11ms.
977                     mJankType = JankType::DisplayHAL;
978                 } else {
979                     // Delta is not a factor of vsync
980                     mJankType = JankType::PredictionError;
981                 }
982             } else if (mFrameReadyMetadata == FrameReadyMetadata::LateFinish) {
983                 if (!(mJankType & JankType::SurfaceFlingerStuffing) ||
984                     mSurfaceFlingerActuals.presentTime - previousPresentTime >
985                             mRefreshRate.getPeriodNsecs() +
986                                     mJankClassificationThresholds.presentThreshold) {
987                     // Classify CPU vs GPU if SF wasn't stuffed or if SF was stuffed but this frame
988                     // was presented more than a vsync late.
989                     if (mGpuFence != FenceTime::NO_FENCE &&
990                         mSurfaceFlingerActuals.endTime - mSurfaceFlingerActuals.startTime <
991                                 mRefreshRate.getPeriodNsecs()) {
992                         // If SF was in GPU composition and the CPU work finished before the vsync
993                         // period, classify it as GPU deadline missed.
994                         mJankType = JankType::SurfaceFlingerGpuDeadlineMissed;
995                     } else {
996                         mJankType = JankType::SurfaceFlingerCpuDeadlineMissed;
997                     }
998                 }
999             } else {
1000                 // Finish time unknown
1001                 mJankType = JankType::Unknown;
1002             }
1003         } else {
1004             // Present unknown
1005             mJankType = JankType::Unknown;
1006         }
1007     }
1008 }
1009 
onPresent(nsecs_t signalTime,nsecs_t previousPresentTime)1010 void FrameTimeline::DisplayFrame::onPresent(nsecs_t signalTime, nsecs_t previousPresentTime) {
1011     mSurfaceFlingerActuals.presentTime = signalTime;
1012     nsecs_t deadlineDelta = 0;
1013     nsecs_t deltaToVsync = 0;
1014     classifyJank(deadlineDelta, deltaToVsync, previousPresentTime);
1015 
1016     for (auto& surfaceFrame : mSurfaceFrames) {
1017         surfaceFrame->onPresent(signalTime, mJankType, mRefreshRate, deadlineDelta, deltaToVsync);
1018     }
1019 }
1020 
tracePredictions(pid_t surfaceFlingerPid,nsecs_t monoBootOffset) const1021 void FrameTimeline::DisplayFrame::tracePredictions(pid_t surfaceFlingerPid,
1022                                                    nsecs_t monoBootOffset) const {
1023     int64_t expectedTimelineCookie = mTraceCookieCounter.getCookieForTracing();
1024 
1025     // Expected timeline start
1026     FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
1027         auto packet = ctx.NewTracePacket();
1028         packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_BOOTTIME);
1029         packet->set_timestamp(
1030                 static_cast<uint64_t>(mSurfaceFlingerPredictions.startTime + monoBootOffset));
1031 
1032         auto* event = packet->set_frame_timeline_event();
1033         auto* expectedDisplayFrameStartEvent = event->set_expected_display_frame_start();
1034 
1035         expectedDisplayFrameStartEvent->set_cookie(expectedTimelineCookie);
1036 
1037         expectedDisplayFrameStartEvent->set_token(mToken);
1038         expectedDisplayFrameStartEvent->set_pid(surfaceFlingerPid);
1039     });
1040 
1041     // Expected timeline end
1042     FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
1043         auto packet = ctx.NewTracePacket();
1044         packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_BOOTTIME);
1045         packet->set_timestamp(
1046                 static_cast<uint64_t>(mSurfaceFlingerPredictions.endTime + monoBootOffset));
1047 
1048         auto* event = packet->set_frame_timeline_event();
1049         auto* expectedDisplayFrameEndEvent = event->set_frame_end();
1050 
1051         expectedDisplayFrameEndEvent->set_cookie(expectedTimelineCookie);
1052     });
1053 }
1054 
traceActuals(pid_t surfaceFlingerPid,nsecs_t monoBootOffset) const1055 void FrameTimeline::DisplayFrame::traceActuals(pid_t surfaceFlingerPid,
1056                                                nsecs_t monoBootOffset) const {
1057     int64_t actualTimelineCookie = mTraceCookieCounter.getCookieForTracing();
1058 
1059     // Actual timeline start
1060     FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
1061         auto packet = ctx.NewTracePacket();
1062         packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_BOOTTIME);
1063         packet->set_timestamp(
1064                 static_cast<uint64_t>(mSurfaceFlingerActuals.startTime + monoBootOffset));
1065 
1066         auto* event = packet->set_frame_timeline_event();
1067         auto* actualDisplayFrameStartEvent = event->set_actual_display_frame_start();
1068 
1069         actualDisplayFrameStartEvent->set_cookie(actualTimelineCookie);
1070 
1071         actualDisplayFrameStartEvent->set_token(mToken);
1072         actualDisplayFrameStartEvent->set_pid(surfaceFlingerPid);
1073 
1074         actualDisplayFrameStartEvent->set_present_type(toProto(mFramePresentMetadata));
1075         actualDisplayFrameStartEvent->set_on_time_finish(mFrameReadyMetadata ==
1076                                                          FrameReadyMetadata::OnTimeFinish);
1077         actualDisplayFrameStartEvent->set_gpu_composition(mGpuFence != FenceTime::NO_FENCE);
1078         actualDisplayFrameStartEvent->set_jank_type(jankTypeBitmaskToProto(mJankType));
1079         actualDisplayFrameStartEvent->set_prediction_type(toProto(mPredictionState));
1080     });
1081 
1082     // Actual timeline end
1083     FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
1084         auto packet = ctx.NewTracePacket();
1085         packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_BOOTTIME);
1086         packet->set_timestamp(
1087                 static_cast<uint64_t>(mSurfaceFlingerActuals.presentTime + monoBootOffset));
1088 
1089         auto* event = packet->set_frame_timeline_event();
1090         auto* actualDisplayFrameEndEvent = event->set_frame_end();
1091 
1092         actualDisplayFrameEndEvent->set_cookie(actualTimelineCookie);
1093     });
1094 }
1095 
trace(pid_t surfaceFlingerPid,nsecs_t monoBootOffset) const1096 void FrameTimeline::DisplayFrame::trace(pid_t surfaceFlingerPid, nsecs_t monoBootOffset) const {
1097     if (mToken == FrameTimelineInfo::INVALID_VSYNC_ID) {
1098         // DisplayFrame should not have an invalid token.
1099         ALOGE("Cannot trace DisplayFrame with invalid token");
1100         return;
1101     }
1102 
1103     if (mPredictionState == PredictionState::Valid) {
1104         // Expired and unknown predictions have zeroed timestamps. This cannot be used in any
1105         // meaningful way in a trace.
1106         tracePredictions(surfaceFlingerPid, monoBootOffset);
1107     }
1108     traceActuals(surfaceFlingerPid, monoBootOffset);
1109 
1110     for (auto& surfaceFrame : mSurfaceFrames) {
1111         surfaceFrame->trace(mToken, monoBootOffset);
1112     }
1113 }
1114 
computeFps(const std::unordered_set<int32_t> & layerIds)1115 float FrameTimeline::computeFps(const std::unordered_set<int32_t>& layerIds) {
1116     if (layerIds.empty()) {
1117         return 0.0f;
1118     }
1119 
1120     std::vector<nsecs_t> presentTimes;
1121     {
1122         std::scoped_lock lock(mMutex);
1123         presentTimes.reserve(mDisplayFrames.size());
1124         for (size_t i = 0; i < mDisplayFrames.size(); i++) {
1125             const auto& displayFrame = mDisplayFrames[i];
1126             if (displayFrame->getActuals().presentTime <= 0) {
1127                 continue;
1128             }
1129             for (const auto& surfaceFrame : displayFrame->getSurfaceFrames()) {
1130                 if (surfaceFrame->getPresentState() == SurfaceFrame::PresentState::Presented &&
1131                     layerIds.count(surfaceFrame->getLayerId()) > 0) {
1132                     // We're looking for DisplayFrames that presents at least one layer from
1133                     // layerIds, so push the present time and skip looking through the rest of the
1134                     // SurfaceFrames.
1135                     presentTimes.push_back(displayFrame->getActuals().presentTime);
1136                     break;
1137                 }
1138             }
1139         }
1140     }
1141 
1142     // FPS can't be computed when there's fewer than 2 presented frames.
1143     if (presentTimes.size() <= 1) {
1144         return 0.0f;
1145     }
1146 
1147     nsecs_t priorPresentTime = -1;
1148     nsecs_t totalPresentToPresentWalls = 0;
1149 
1150     for (const nsecs_t presentTime : presentTimes) {
1151         if (priorPresentTime == -1) {
1152             priorPresentTime = presentTime;
1153             continue;
1154         }
1155 
1156         totalPresentToPresentWalls += (presentTime - priorPresentTime);
1157         priorPresentTime = presentTime;
1158     }
1159 
1160     if (CC_UNLIKELY(totalPresentToPresentWalls <= 0)) {
1161         ALOGW("Invalid total present-to-present duration when computing fps: %" PRId64,
1162               totalPresentToPresentWalls);
1163         return 0.0f;
1164     }
1165 
1166     const constexpr nsecs_t kOneSecond =
1167             std::chrono::duration_cast<std::chrono::nanoseconds>(1s).count();
1168     // (10^9 nanoseconds / second) * (N present deltas) / (total nanoseconds in N present deltas) =
1169     // M frames / second
1170     return kOneSecond * static_cast<nsecs_t>((presentTimes.size() - 1)) /
1171             static_cast<float>(totalPresentToPresentWalls);
1172 }
1173 
flushPendingPresentFences()1174 void FrameTimeline::flushPendingPresentFences() {
1175     // Perfetto is using boottime clock to void drifts when the device goes
1176     // to suspend.
1177     const auto monoBootOffset = mUseBootTimeClock
1178             ? (systemTime(SYSTEM_TIME_BOOTTIME) - systemTime(SYSTEM_TIME_MONOTONIC))
1179             : 0;
1180 
1181     for (size_t i = 0; i < mPendingPresentFences.size(); i++) {
1182         const auto& pendingPresentFence = mPendingPresentFences[i];
1183         nsecs_t signalTime = Fence::SIGNAL_TIME_INVALID;
1184         if (pendingPresentFence.first && pendingPresentFence.first->isValid()) {
1185             signalTime = pendingPresentFence.first->getSignalTime();
1186             if (signalTime == Fence::SIGNAL_TIME_PENDING) {
1187                 continue;
1188             }
1189         }
1190         auto& displayFrame = pendingPresentFence.second;
1191         displayFrame->onPresent(signalTime, mPreviousPresentTime);
1192         displayFrame->trace(mSurfaceFlingerPid, monoBootOffset);
1193         mPreviousPresentTime = signalTime;
1194 
1195         mPendingPresentFences.erase(mPendingPresentFences.begin() + static_cast<int>(i));
1196         --i;
1197     }
1198 }
1199 
finalizeCurrentDisplayFrame()1200 void FrameTimeline::finalizeCurrentDisplayFrame() {
1201     while (mDisplayFrames.size() >= mMaxDisplayFrames) {
1202         // We maintain only a fixed number of frames' data. Pop older frames
1203         mDisplayFrames.pop_front();
1204     }
1205     mDisplayFrames.push_back(mCurrentDisplayFrame);
1206     mCurrentDisplayFrame.reset();
1207     mCurrentDisplayFrame = std::make_shared<DisplayFrame>(mTimeStats, mJankClassificationThresholds,
1208                                                           &mTraceCookieCounter);
1209 }
1210 
getBaseTime() const1211 nsecs_t FrameTimeline::DisplayFrame::getBaseTime() const {
1212     nsecs_t baseTime =
1213             getMinTime(mPredictionState, mSurfaceFlingerPredictions, mSurfaceFlingerActuals);
1214     for (const auto& surfaceFrame : mSurfaceFrames) {
1215         nsecs_t surfaceFrameBaseTime = surfaceFrame->getBaseTime();
1216         if (surfaceFrameBaseTime != 0) {
1217             baseTime = std::min(baseTime, surfaceFrameBaseTime);
1218         }
1219     }
1220     return baseTime;
1221 }
1222 
dumpJank(std::string & result,nsecs_t baseTime,int displayFrameCount) const1223 void FrameTimeline::DisplayFrame::dumpJank(std::string& result, nsecs_t baseTime,
1224                                            int displayFrameCount) const {
1225     if (mJankType == JankType::None) {
1226         // Check if any Surface Frame has been janky
1227         bool isJanky = false;
1228         for (const auto& surfaceFrame : mSurfaceFrames) {
1229             if (surfaceFrame->getJankType() != JankType::None) {
1230                 isJanky = true;
1231                 break;
1232             }
1233         }
1234         if (!isJanky) {
1235             return;
1236         }
1237     }
1238     StringAppendF(&result, "Display Frame %d", displayFrameCount);
1239     dump(result, baseTime);
1240 }
1241 
dumpAll(std::string & result,nsecs_t baseTime) const1242 void FrameTimeline::DisplayFrame::dumpAll(std::string& result, nsecs_t baseTime) const {
1243     dump(result, baseTime);
1244 }
1245 
dump(std::string & result,nsecs_t baseTime) const1246 void FrameTimeline::DisplayFrame::dump(std::string& result, nsecs_t baseTime) const {
1247     if (mJankType != JankType::None) {
1248         // Easily identify a janky Display Frame in the dump
1249         StringAppendF(&result, " [*] ");
1250     }
1251     StringAppendF(&result, "\n");
1252     StringAppendF(&result, "Prediction State : %s\n", toString(mPredictionState).c_str());
1253     StringAppendF(&result, "Jank Type : %s\n", jankTypeBitmaskToString(mJankType).c_str());
1254     StringAppendF(&result, "Present Metadata : %s\n", toString(mFramePresentMetadata).c_str());
1255     StringAppendF(&result, "Finish Metadata: %s\n", toString(mFrameReadyMetadata).c_str());
1256     StringAppendF(&result, "Start Metadata: %s\n", toString(mFrameStartMetadata).c_str());
1257     std::chrono::nanoseconds vsyncPeriod(mRefreshRate.getPeriodNsecs());
1258     StringAppendF(&result, "Vsync Period: %10f\n",
1259                   std::chrono::duration<double, std::milli>(vsyncPeriod).count());
1260     nsecs_t presentDelta =
1261             mSurfaceFlingerActuals.presentTime - mSurfaceFlingerPredictions.presentTime;
1262     std::chrono::nanoseconds presentDeltaNs(std::abs(presentDelta));
1263     StringAppendF(&result, "Present delta: %10f\n",
1264                   std::chrono::duration<double, std::milli>(presentDeltaNs).count());
1265     std::chrono::nanoseconds deltaToVsync(std::abs(presentDelta) % mRefreshRate.getPeriodNsecs());
1266     StringAppendF(&result, "Present delta %% refreshrate: %10f\n",
1267                   std::chrono::duration<double, std::milli>(deltaToVsync).count());
1268     dumpTable(result, mSurfaceFlingerPredictions, mSurfaceFlingerActuals, "", mPredictionState,
1269               baseTime);
1270     StringAppendF(&result, "\n");
1271     std::string indent = "    "; // 4 spaces
1272     for (const auto& surfaceFrame : mSurfaceFrames) {
1273         surfaceFrame->dump(result, indent, baseTime);
1274     }
1275     StringAppendF(&result, "\n");
1276 }
1277 
dumpAll(std::string & result)1278 void FrameTimeline::dumpAll(std::string& result) {
1279     std::scoped_lock lock(mMutex);
1280     StringAppendF(&result, "Number of display frames : %d\n", (int)mDisplayFrames.size());
1281     nsecs_t baseTime = (mDisplayFrames.empty()) ? 0 : mDisplayFrames[0]->getBaseTime();
1282     for (size_t i = 0; i < mDisplayFrames.size(); i++) {
1283         StringAppendF(&result, "Display Frame %d", static_cast<int>(i));
1284         mDisplayFrames[i]->dumpAll(result, baseTime);
1285     }
1286 }
1287 
dumpJank(std::string & result)1288 void FrameTimeline::dumpJank(std::string& result) {
1289     std::scoped_lock lock(mMutex);
1290     nsecs_t baseTime = (mDisplayFrames.empty()) ? 0 : mDisplayFrames[0]->getBaseTime();
1291     for (size_t i = 0; i < mDisplayFrames.size(); i++) {
1292         mDisplayFrames[i]->dumpJank(result, baseTime, static_cast<int>(i));
1293     }
1294 }
1295 
parseArgs(const Vector<String16> & args,std::string & result)1296 void FrameTimeline::parseArgs(const Vector<String16>& args, std::string& result) {
1297     ATRACE_CALL();
1298     std::unordered_map<std::string, bool> argsMap;
1299     for (size_t i = 0; i < args.size(); i++) {
1300         argsMap[std::string(String8(args[i]).c_str())] = true;
1301     }
1302     if (argsMap.count("-jank")) {
1303         dumpJank(result);
1304     }
1305     if (argsMap.count("-all")) {
1306         dumpAll(result);
1307     }
1308 }
1309 
setMaxDisplayFrames(uint32_t size)1310 void FrameTimeline::setMaxDisplayFrames(uint32_t size) {
1311     std::scoped_lock lock(mMutex);
1312 
1313     // The size can either increase or decrease, clear everything, to be consistent
1314     mDisplayFrames.clear();
1315     mPendingPresentFences.clear();
1316     mMaxDisplayFrames = size;
1317 }
1318 
reset()1319 void FrameTimeline::reset() {
1320     setMaxDisplayFrames(kDefaultMaxDisplayFrames);
1321 }
1322 
1323 } // namespace impl
1324 } // namespace android::frametimeline
1325