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