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