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