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