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