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