blob: 81747d596a1697005b25a491ab337cb499dca569 [file] [log] [blame]
Adithya Srinivasanf279e042020-08-17 14:56:27 -07001/*
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"
Alec Mouriadebf5c2021-01-05 12:57:36 -080022
Adithya Srinivasanf279e042020-08-17 14:56:27 -070023#include <android-base/stringprintf.h>
Ady Abraham7f8a1e62020-09-28 16:09:35 -070024#include <utils/Log.h>
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -070025#include <utils/Trace.h>
Alec Mouriadebf5c2021-01-05 12:57:36 -080026
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -070027#include <chrono>
Adithya Srinivasanf279e042020-08-17 14:56:27 -070028#include <cinttypes>
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -070029#include <numeric>
Alec Mouriadebf5c2021-01-05 12:57:36 -080030#include <unordered_set>
Adithya Srinivasanf279e042020-08-17 14:56:27 -070031
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -080032namespace android::frametimeline {
Adithya Srinivasanf279e042020-08-17 14:56:27 -070033
34using base::StringAppendF;
Adithya Srinivasan01189672020-10-20 14:23:05 -070035using FrameTimelineEvent = perfetto::protos::pbzero::FrameTimelineEvent;
Adithya Srinivasan061c14c2021-02-11 01:19:47 +000036using FrameTimelineDataSource = impl::FrameTimeline::FrameTimelineDataSource;
Adithya Srinivasanf279e042020-08-17 14:56:27 -070037
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -070038void dumpTable(std::string& result, TimelineItem predictions, TimelineItem actuals,
39 const std::string& indent, PredictionState predictionState, nsecs_t baseTime) {
40 StringAppendF(&result, "%s", indent.c_str());
41 StringAppendF(&result, "\t\t");
42 StringAppendF(&result, " Start time\t\t|");
43 StringAppendF(&result, " End time\t\t|");
44 StringAppendF(&result, " Present time\n");
45 if (predictionState == PredictionState::Valid) {
46 // Dump the Predictions only if they are valid
47 StringAppendF(&result, "%s", indent.c_str());
48 StringAppendF(&result, "Expected\t|");
49 std::chrono::nanoseconds startTime(predictions.startTime - baseTime);
50 std::chrono::nanoseconds endTime(predictions.endTime - baseTime);
51 std::chrono::nanoseconds presentTime(predictions.presentTime - baseTime);
52 StringAppendF(&result, "\t%10.2f\t|\t%10.2f\t|\t%10.2f\n",
53 std::chrono::duration<double, std::milli>(startTime).count(),
54 std::chrono::duration<double, std::milli>(endTime).count(),
55 std::chrono::duration<double, std::milli>(presentTime).count());
56 }
57 StringAppendF(&result, "%s", indent.c_str());
58 StringAppendF(&result, "Actual \t|");
59
60 if (actuals.startTime == 0) {
61 StringAppendF(&result, "\t\tN/A\t|");
62 } else {
63 std::chrono::nanoseconds startTime(std::max<nsecs_t>(0, actuals.startTime - baseTime));
64 StringAppendF(&result, "\t%10.2f\t|",
65 std::chrono::duration<double, std::milli>(startTime).count());
66 }
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -080067 if (actuals.endTime <= 0) {
68 // Animation leashes can send the endTime as -1
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -070069 StringAppendF(&result, "\t\tN/A\t|");
70 } else {
71 std::chrono::nanoseconds endTime(actuals.endTime - baseTime);
72 StringAppendF(&result, "\t%10.2f\t|",
73 std::chrono::duration<double, std::milli>(endTime).count());
74 }
75 if (actuals.presentTime == 0) {
76 StringAppendF(&result, "\t\tN/A\n");
77 } else {
78 std::chrono::nanoseconds presentTime(std::max<nsecs_t>(0, actuals.presentTime - baseTime));
79 StringAppendF(&result, "\t%10.2f\n",
80 std::chrono::duration<double, std::milli>(presentTime).count());
81 }
82
83 StringAppendF(&result, "%s", indent.c_str());
84 StringAppendF(&result, "----------------------");
85 StringAppendF(&result, "----------------------");
86 StringAppendF(&result, "----------------------");
87 StringAppendF(&result, "----------------------\n");
88}
89
90std::string toString(PredictionState predictionState) {
91 switch (predictionState) {
92 case PredictionState::Valid:
93 return "Valid";
94 case PredictionState::Expired:
95 return "Expired";
96 case PredictionState::None:
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -070097 return "None";
98 }
99}
100
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800101std::string jankTypeBitmaskToString(int32_t jankType) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800102 if (jankType == JankType::None) {
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700103 return "None";
104 }
Adithya Srinivasan552e2a72021-01-15 03:21:53 +0000105
106 std::vector<std::string> janks;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800107 if (jankType & JankType::DisplayHAL) {
108 janks.emplace_back("Display HAL");
Adithya Srinivasan552e2a72021-01-15 03:21:53 +0000109 jankType &= ~JankType::DisplayHAL;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800110 }
111 if (jankType & JankType::SurfaceFlingerCpuDeadlineMissed) {
112 janks.emplace_back("SurfaceFlinger CPU Deadline Missed");
Adithya Srinivasan552e2a72021-01-15 03:21:53 +0000113 jankType &= ~JankType::SurfaceFlingerCpuDeadlineMissed;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800114 }
115 if (jankType & JankType::SurfaceFlingerGpuDeadlineMissed) {
116 janks.emplace_back("SurfaceFlinger GPU Deadline Missed");
Adithya Srinivasan552e2a72021-01-15 03:21:53 +0000117 jankType &= ~JankType::SurfaceFlingerGpuDeadlineMissed;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800118 }
119 if (jankType & JankType::AppDeadlineMissed) {
120 janks.emplace_back("App Deadline Missed");
Adithya Srinivasan552e2a72021-01-15 03:21:53 +0000121 jankType &= ~JankType::AppDeadlineMissed;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800122 }
123 if (jankType & JankType::PredictionError) {
124 janks.emplace_back("Prediction Error");
Adithya Srinivasan552e2a72021-01-15 03:21:53 +0000125 jankType &= ~JankType::PredictionError;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800126 }
127 if (jankType & JankType::SurfaceFlingerScheduling) {
128 janks.emplace_back("SurfaceFlinger Scheduling");
Adithya Srinivasan552e2a72021-01-15 03:21:53 +0000129 jankType &= ~JankType::SurfaceFlingerScheduling;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800130 }
131 if (jankType & JankType::BufferStuffing) {
132 janks.emplace_back("Buffer Stuffing");
Adithya Srinivasan552e2a72021-01-15 03:21:53 +0000133 jankType &= ~JankType::BufferStuffing;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800134 }
135 if (jankType & JankType::Unknown) {
136 janks.emplace_back("Unknown jank");
Adithya Srinivasan552e2a72021-01-15 03:21:53 +0000137 jankType &= ~JankType::Unknown;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800138 }
Adithya Srinivasan2045ddf2021-05-27 17:38:10 +0000139 if (jankType & JankType::SurfaceFlingerStuffing) {
140 janks.emplace_back("SurfaceFlinger Stuffing");
141 jankType &= ~JankType::SurfaceFlingerStuffing;
142 }
Adithya Srinivasan552e2a72021-01-15 03:21:53 +0000143
144 // jankType should be 0 if all types of jank were checked for.
145 LOG_ALWAYS_FATAL_IF(jankType != 0, "Unrecognized jank type value 0x%x", jankType);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800146 return std::accumulate(janks.begin(), janks.end(), std::string(),
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700147 [](const std::string& l, const std::string& r) {
148 return l.empty() ? r : l + ", " + r;
149 });
150}
151
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800152std::string toString(FramePresentMetadata presentMetadata) {
153 switch (presentMetadata) {
154 case FramePresentMetadata::OnTimePresent:
155 return "On Time Present";
156 case FramePresentMetadata::LatePresent:
157 return "Late Present";
158 case FramePresentMetadata::EarlyPresent:
159 return "Early Present";
160 case FramePresentMetadata::UnknownPresent:
161 return "Unknown Present";
Adithya Srinivasan01189672020-10-20 14:23:05 -0700162 }
Adithya Srinivasan01189672020-10-20 14:23:05 -0700163}
164
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800165std::string toString(FrameReadyMetadata finishMetadata) {
166 switch (finishMetadata) {
167 case FrameReadyMetadata::OnTimeFinish:
168 return "On Time Finish";
169 case FrameReadyMetadata::LateFinish:
170 return "Late Finish";
171 case FrameReadyMetadata::UnknownFinish:
172 return "Unknown Finish";
173 }
174}
175
176std::string toString(FrameStartMetadata startMetadata) {
177 switch (startMetadata) {
178 case FrameStartMetadata::OnTimeStart:
179 return "On Time Start";
180 case FrameStartMetadata::LateStart:
181 return "Late Start";
182 case FrameStartMetadata::EarlyStart:
183 return "Early Start";
184 case FrameStartMetadata::UnknownStart:
185 return "Unknown Start";
186 }
187}
188
189std::string toString(SurfaceFrame::PresentState presentState) {
190 using PresentState = SurfaceFrame::PresentState;
191 switch (presentState) {
192 case PresentState::Presented:
193 return "Presented";
194 case PresentState::Dropped:
195 return "Dropped";
196 case PresentState::Unknown:
197 return "Unknown";
198 }
199}
200
201FrameTimelineEvent::PresentType toProto(FramePresentMetadata presentMetadata) {
202 switch (presentMetadata) {
203 case FramePresentMetadata::EarlyPresent:
204 return FrameTimelineEvent::PRESENT_EARLY;
205 case FramePresentMetadata::LatePresent:
206 return FrameTimelineEvent::PRESENT_LATE;
207 case FramePresentMetadata::OnTimePresent:
208 return FrameTimelineEvent::PRESENT_ON_TIME;
209 case FramePresentMetadata::UnknownPresent:
210 return FrameTimelineEvent::PRESENT_UNSPECIFIED;
211 }
212}
213
Adithya Srinivasan78e58af2021-02-25 00:08:08 +0000214FrameTimelineEvent::PredictionType toProto(PredictionState predictionState) {
215 switch (predictionState) {
216 case PredictionState::Valid:
217 return FrameTimelineEvent::PREDICTION_VALID;
218 case PredictionState::Expired:
219 return FrameTimelineEvent::PREDICTION_EXPIRED;
220 case PredictionState::None:
221 return FrameTimelineEvent::PREDICTION_UNKNOWN;
222 }
223}
224
Adithya Srinivasan552e2a72021-01-15 03:21:53 +0000225int32_t jankTypeBitmaskToProto(int32_t jankType) {
226 if (jankType == JankType::None) {
227 return FrameTimelineEvent::JANK_NONE;
Adithya Srinivasan01189672020-10-20 14:23:05 -0700228 }
Adithya Srinivasan552e2a72021-01-15 03:21:53 +0000229
230 int32_t protoJank = 0;
231 if (jankType & JankType::DisplayHAL) {
232 protoJank |= FrameTimelineEvent::JANK_DISPLAY_HAL;
233 jankType &= ~JankType::DisplayHAL;
234 }
235 if (jankType & JankType::SurfaceFlingerCpuDeadlineMissed) {
236 protoJank |= FrameTimelineEvent::JANK_SF_CPU_DEADLINE_MISSED;
237 jankType &= ~JankType::SurfaceFlingerCpuDeadlineMissed;
238 }
239 if (jankType & JankType::SurfaceFlingerGpuDeadlineMissed) {
240 protoJank |= FrameTimelineEvent::JANK_SF_GPU_DEADLINE_MISSED;
241 jankType &= ~JankType::SurfaceFlingerGpuDeadlineMissed;
242 }
243 if (jankType & JankType::AppDeadlineMissed) {
244 protoJank |= FrameTimelineEvent::JANK_APP_DEADLINE_MISSED;
245 jankType &= ~JankType::AppDeadlineMissed;
246 }
247 if (jankType & JankType::PredictionError) {
248 protoJank |= FrameTimelineEvent::JANK_PREDICTION_ERROR;
249 jankType &= ~JankType::PredictionError;
250 }
251 if (jankType & JankType::SurfaceFlingerScheduling) {
252 protoJank |= FrameTimelineEvent::JANK_SF_SCHEDULING;
253 jankType &= ~JankType::SurfaceFlingerScheduling;
254 }
255 if (jankType & JankType::BufferStuffing) {
256 protoJank |= FrameTimelineEvent::JANK_BUFFER_STUFFING;
257 jankType &= ~JankType::BufferStuffing;
258 }
259 if (jankType & JankType::Unknown) {
260 protoJank |= FrameTimelineEvent::JANK_UNKNOWN;
261 jankType &= ~JankType::Unknown;
262 }
Adithya Srinivasan57dc81d2021-04-14 17:31:41 +0000263 if (jankType & JankType::SurfaceFlingerStuffing) {
264 protoJank |= FrameTimelineEvent::JANK_SF_STUFFING;
265 jankType &= ~JankType::SurfaceFlingerStuffing;
266 }
Adithya Srinivasan552e2a72021-01-15 03:21:53 +0000267
268 // jankType should be 0 if all types of jank were checked for.
269 LOG_ALWAYS_FATAL_IF(jankType != 0, "Unrecognized jank type value 0x%x", jankType);
270 return protoJank;
Adithya Srinivasan01189672020-10-20 14:23:05 -0700271}
272
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800273// Returns the smallest timestamp from the set of predictions and actuals.
274nsecs_t getMinTime(PredictionState predictionState, TimelineItem predictions,
275 TimelineItem actuals) {
276 nsecs_t minTime = std::numeric_limits<nsecs_t>::max();
277 if (predictionState == PredictionState::Valid) {
278 // Checking start time for predictions is enough because start time is always lesser than
279 // endTime and presentTime.
280 minTime = std::min(minTime, predictions.startTime);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700281 }
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700282
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800283 // Need to check startTime, endTime and presentTime for actuals because some frames might not
284 // have them set.
285 if (actuals.startTime != 0) {
286 minTime = std::min(minTime, actuals.startTime);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700287 }
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800288 if (actuals.endTime != 0) {
289 minTime = std::min(minTime, actuals.endTime);
290 }
291 if (actuals.presentTime != 0) {
292 minTime = std::min(minTime, actuals.endTime);
293 }
294 return minTime;
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700295}
296
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000297int64_t TraceCookieCounter::getCookieForTracing() {
298 return ++mTraceCookie;
299}
300
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000301SurfaceFrame::SurfaceFrame(const FrameTimelineInfo& frameTimelineInfo, pid_t ownerPid,
Alec Mouriadebf5c2021-01-05 12:57:36 -0800302 uid_t ownerUid, int32_t layerId, std::string layerName,
303 std::string debugName, PredictionState predictionState,
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800304 frametimeline::TimelineItem&& predictions,
305 std::shared_ptr<TimeStats> timeStats,
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000306 JankClassificationThresholds thresholds,
Dominik Laskowskif5d0ea52021-09-26 17:27:01 -0700307 TraceCookieCounter* traceCookieCounter, bool isBuffer, GameMode gameMode)
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000308 : mToken(frameTimelineInfo.vsyncId),
309 mInputEventId(frameTimelineInfo.inputEventId),
Adithya Srinivasan01189672020-10-20 14:23:05 -0700310 mOwnerPid(ownerPid),
Adithya Srinivasan9febda82020-10-19 10:49:41 -0700311 mOwnerUid(ownerUid),
Alec Mouri9a29e672020-09-14 12:39:14 -0700312 mLayerName(std::move(layerName)),
313 mDebugName(std::move(debugName)),
Alec Mouriadebf5c2021-01-05 12:57:36 -0800314 mLayerId(layerId),
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700315 mPresentState(PresentState::Unknown),
316 mPredictionState(predictionState),
317 mPredictions(predictions),
318 mActuals({0, 0, 0}),
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800319 mTimeStats(timeStats),
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000320 mJankClassificationThresholds(thresholds),
Adithya Srinivasan785addd2021-03-09 00:38:00 +0000321 mTraceCookieCounter(*traceCookieCounter),
Adithya Srinivasan58069dc2021-06-04 20:37:02 +0000322 mIsBuffer(isBuffer),
323 mGameMode(gameMode) {}
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700324
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -0700325void SurfaceFrame::setActualStartTime(nsecs_t actualStartTime) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000326 std::scoped_lock lock(mMutex);
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -0700327 mActuals.startTime = actualStartTime;
328}
329
330void SurfaceFrame::setActualQueueTime(nsecs_t actualQueueTime) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000331 std::scoped_lock lock(mMutex);
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -0700332 mActualQueueTime = actualQueueTime;
333}
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000334
Ady Abraham7f8a1e62020-09-28 16:09:35 -0700335void SurfaceFrame::setAcquireFenceTime(nsecs_t acquireFenceTime) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000336 std::scoped_lock lock(mMutex);
Ady Abraham7f8a1e62020-09-28 16:09:35 -0700337 mActuals.endTime = std::max(acquireFenceTime, mActualQueueTime);
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -0700338}
339
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000340void SurfaceFrame::setDropTime(nsecs_t dropTime) {
341 std::scoped_lock lock(mMutex);
342 mDropTime = dropTime;
343}
344
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800345void SurfaceFrame::setPresentState(PresentState presentState, nsecs_t lastLatchTime) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000346 std::scoped_lock lock(mMutex);
Adithya Srinivasanb9a7dab2021-01-14 23:49:46 +0000347 LOG_ALWAYS_FATAL_IF(mPresentState != PresentState::Unknown,
348 "setPresentState called on a SurfaceFrame from Layer - %s, that has a "
349 "PresentState - %s set already.",
350 mDebugName.c_str(), toString(mPresentState).c_str());
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800351 mPresentState = presentState;
352 mLastLatchTime = lastLatchTime;
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700353}
354
Alec Mouri7d436ec2021-01-27 20:40:50 -0800355void SurfaceFrame::setRenderRate(Fps renderRate) {
356 std::lock_guard<std::mutex> lock(mMutex);
357 mRenderRate = renderRate;
358}
359
Adithya Srinivasanb6a2fa12021-03-13 00:23:09 +0000360void SurfaceFrame::setGpuComposition() {
361 std::scoped_lock lock(mMutex);
362 mGpuComposition = true;
363}
364
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800365std::optional<int32_t> SurfaceFrame::getJankType() const {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000366 std::scoped_lock lock(mMutex);
Adithya Srinivasan95619432021-02-08 21:52:51 +0000367 if (mPresentState == PresentState::Dropped) {
368 // Return no jank if it's a dropped frame since we cannot attribute a jank to a it.
369 return JankType::None;
370 }
Jorim Jaggi9c03b502020-11-24 23:51:31 +0100371 if (mActuals.presentTime == 0) {
Adithya Srinivasan95619432021-02-08 21:52:51 +0000372 // Frame hasn't been presented yet.
Jorim Jaggi9c03b502020-11-24 23:51:31 +0100373 return std::nullopt;
374 }
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700375 return mJankType;
376}
377
378nsecs_t SurfaceFrame::getBaseTime() const {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000379 std::scoped_lock lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800380 return getMinTime(mPredictionState, mPredictions, mActuals);
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700381}
382
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800383TimelineItem SurfaceFrame::getActuals() const {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000384 std::scoped_lock lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800385 return mActuals;
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700386}
387
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000388PredictionState SurfaceFrame::getPredictionState() const {
389 std::scoped_lock lock(mMutex);
390 return mPredictionState;
391}
392
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800393SurfaceFrame::PresentState SurfaceFrame::getPresentState() const {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000394 std::scoped_lock lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800395 return mPresentState;
396}
397
398FramePresentMetadata SurfaceFrame::getFramePresentMetadata() const {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000399 std::scoped_lock lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800400 return mFramePresentMetadata;
401}
402
403FrameReadyMetadata SurfaceFrame::getFrameReadyMetadata() const {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000404 std::scoped_lock lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800405 return mFrameReadyMetadata;
406}
407
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000408nsecs_t SurfaceFrame::getDropTime() const {
409 std::scoped_lock lock(mMutex);
410 return mDropTime;
411}
412
Adithya Srinivasan785addd2021-03-09 00:38:00 +0000413void SurfaceFrame::promoteToBuffer() {
414 std::scoped_lock lock(mMutex);
415 LOG_ALWAYS_FATAL_IF(mIsBuffer == true,
416 "Trying to promote an already promoted BufferSurfaceFrame from layer %s "
417 "with token %" PRId64 "",
418 mDebugName.c_str(), mToken);
419 mIsBuffer = true;
420}
421
422bool SurfaceFrame::getIsBuffer() const {
423 std::scoped_lock lock(mMutex);
424 return mIsBuffer;
425}
426
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800427void SurfaceFrame::dump(std::string& result, const std::string& indent, nsecs_t baseTime) const {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000428 std::scoped_lock lock(mMutex);
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700429 StringAppendF(&result, "%s", indent.c_str());
Alec Mouri9a29e672020-09-14 12:39:14 -0700430 StringAppendF(&result, "Layer - %s", mDebugName.c_str());
Jorim Jaggi5814ab82020-12-03 20:45:58 +0100431 if (mJankType != JankType::None) {
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700432 // Easily identify a janky Surface Frame in the dump
433 StringAppendF(&result, " [*] ");
434 }
435 StringAppendF(&result, "\n");
436 StringAppendF(&result, "%s", indent.c_str());
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800437 StringAppendF(&result, "Token: %" PRId64 "\n", mToken);
438 StringAppendF(&result, "%s", indent.c_str());
Adithya Srinivasan785addd2021-03-09 00:38:00 +0000439 StringAppendF(&result, "Is Buffer?: %d\n", mIsBuffer);
440 StringAppendF(&result, "%s", indent.c_str());
Adithya Srinivasan9febda82020-10-19 10:49:41 -0700441 StringAppendF(&result, "Owner Pid : %d\n", mOwnerPid);
442 StringAppendF(&result, "%s", indent.c_str());
Alec Mouri7d436ec2021-01-27 20:40:50 -0800443 StringAppendF(&result, "Scheduled rendering rate: %d fps\n",
444 mRenderRate ? mRenderRate->getIntValue() : 0);
445 StringAppendF(&result, "%s", indent.c_str());
Alec Mouriadebf5c2021-01-05 12:57:36 -0800446 StringAppendF(&result, "Layer ID : %d\n", mLayerId);
447 StringAppendF(&result, "%s", indent.c_str());
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800448 StringAppendF(&result, "Present State : %s\n", toString(mPresentState).c_str());
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700449 StringAppendF(&result, "%s", indent.c_str());
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000450 if (mPresentState == PresentState::Dropped) {
451 std::chrono::nanoseconds dropTime(mDropTime - baseTime);
452 StringAppendF(&result, "Drop time : %10f\n",
453 std::chrono::duration<double, std::milli>(dropTime).count());
454 StringAppendF(&result, "%s", indent.c_str());
455 }
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700456 StringAppendF(&result, "Prediction State : %s\n", toString(mPredictionState).c_str());
457 StringAppendF(&result, "%s", indent.c_str());
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800458 StringAppendF(&result, "Jank Type : %s\n", jankTypeBitmaskToString(mJankType).c_str());
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700459 StringAppendF(&result, "%s", indent.c_str());
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800460 StringAppendF(&result, "Present Metadata : %s\n", toString(mFramePresentMetadata).c_str());
461 StringAppendF(&result, "%s", indent.c_str());
462 StringAppendF(&result, "Finish Metadata: %s\n", toString(mFrameReadyMetadata).c_str());
463 std::chrono::nanoseconds latchTime(
464 std::max(static_cast<int64_t>(0), mLastLatchTime - baseTime));
465 StringAppendF(&result, "%s", indent.c_str());
466 StringAppendF(&result, "Last latch time: %10f\n",
467 std::chrono::duration<double, std::milli>(latchTime).count());
468 if (mPredictionState == PredictionState::Valid) {
469 nsecs_t presentDelta = mActuals.presentTime - mPredictions.presentTime;
470 std::chrono::nanoseconds presentDeltaNs(std::abs(presentDelta));
471 StringAppendF(&result, "%s", indent.c_str());
472 StringAppendF(&result, "Present delta: %10f\n",
473 std::chrono::duration<double, std::milli>(presentDeltaNs).count());
474 }
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700475 dumpTable(result, mPredictions, mActuals, indent, mPredictionState, baseTime);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700476}
477
Adithya Srinivasan785addd2021-03-09 00:38:00 +0000478std::string SurfaceFrame::miniDump() const {
479 std::scoped_lock lock(mMutex);
480 std::string result;
481 StringAppendF(&result, "Layer - %s\n", mDebugName.c_str());
482 StringAppendF(&result, "Token: %" PRId64 "\n", mToken);
483 StringAppendF(&result, "Is Buffer?: %d\n", mIsBuffer);
484 StringAppendF(&result, "Present State : %s\n", toString(mPresentState).c_str());
485 StringAppendF(&result, "Prediction State : %s\n", toString(mPredictionState).c_str());
486 StringAppendF(&result, "Jank Type : %s\n", jankTypeBitmaskToString(mJankType).c_str());
487 StringAppendF(&result, "Present Metadata : %s\n", toString(mFramePresentMetadata).c_str());
488 StringAppendF(&result, "Finish Metadata: %s\n", toString(mFrameReadyMetadata).c_str());
489 StringAppendF(&result, "Present time: %" PRId64 "", mActuals.presentTime);
490 return result;
491}
492
Adithya Srinivasan7c4ac7a2021-03-08 23:48:03 +0000493void SurfaceFrame::classifyJankLocked(int32_t displayFrameJankType, const Fps& refreshRate,
494 nsecs_t& deadlineDelta) {
Ady Abrahame43ff722022-02-15 14:44:25 -0800495 if (mActuals.presentTime == Fence::SIGNAL_TIME_INVALID) {
Adithya Srinivasan7c4ac7a2021-03-08 23:48:03 +0000496 // Cannot do any classification for invalid present time.
Adithya Srinivasan7c4ac7a2021-03-08 23:48:03 +0000497 mJankType = JankType::Unknown;
498 deadlineDelta = -1;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800499 return;
500 }
501
Ady Abrahame43ff722022-02-15 14:44:25 -0800502 if (mPredictionState == PredictionState::Expired) {
503 // We classify prediction expired as AppDeadlineMissed as the
504 // TokenManager::kMaxTokens we store is large enough to account for a
505 // reasonable app, so prediction expire would mean a huge scheduling delay.
506 mJankType = JankType::AppDeadlineMissed;
507 deadlineDelta = -1;
508 return;
509 }
510
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800511 if (mPredictionState == PredictionState::None) {
512 // Cannot do jank classification on frames that don't have a token.
513 return;
514 }
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800515
Adithya Srinivasan7c4ac7a2021-03-08 23:48:03 +0000516 deadlineDelta = mActuals.endTime - mPredictions.endTime;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800517 const nsecs_t presentDelta = mActuals.presentTime - mPredictions.presentTime;
Alec Mouriadebf5c2021-01-05 12:57:36 -0800518 const nsecs_t deltaToVsync = refreshRate.getPeriodNsecs() > 0
519 ? std::abs(presentDelta) % refreshRate.getPeriodNsecs()
520 : 0;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800521
522 if (deadlineDelta > mJankClassificationThresholds.deadlineThreshold) {
523 mFrameReadyMetadata = FrameReadyMetadata::LateFinish;
524 } else {
525 mFrameReadyMetadata = FrameReadyMetadata::OnTimeFinish;
526 }
527
528 if (std::abs(presentDelta) > mJankClassificationThresholds.presentThreshold) {
529 mFramePresentMetadata = presentDelta > 0 ? FramePresentMetadata::LatePresent
530 : FramePresentMetadata::EarlyPresent;
531 } else {
532 mFramePresentMetadata = FramePresentMetadata::OnTimePresent;
533 }
534
535 if (mFramePresentMetadata == FramePresentMetadata::OnTimePresent) {
536 // Frames presented on time are not janky.
537 mJankType = JankType::None;
538 } else if (mFramePresentMetadata == FramePresentMetadata::EarlyPresent) {
539 if (mFrameReadyMetadata == FrameReadyMetadata::OnTimeFinish) {
540 // Finish on time, Present early
541 if (deltaToVsync < mJankClassificationThresholds.presentThreshold ||
Alec Mouri7d436ec2021-01-27 20:40:50 -0800542 deltaToVsync >= refreshRate.getPeriodNsecs() -
543 mJankClassificationThresholds.presentThreshold) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800544 // Delta factor of vsync
545 mJankType = JankType::SurfaceFlingerScheduling;
546 } else {
547 // Delta not a factor of vsync
548 mJankType = JankType::PredictionError;
549 }
550 } else if (mFrameReadyMetadata == FrameReadyMetadata::LateFinish) {
551 // Finish late, Present early
552 mJankType = JankType::Unknown;
553 }
554 } else {
555 if (mLastLatchTime != 0 && mPredictions.endTime <= mLastLatchTime) {
556 // Buffer Stuffing.
557 mJankType |= JankType::BufferStuffing;
Adithya Srinivasan939cd4d2021-02-23 06:18:13 +0000558 // In a stuffed state, the frame could be stuck on a dequeue wait for quite some time.
559 // Because of this dequeue wait, it can be hard to tell if a frame was genuinely late.
560 // We try to do this by moving the deadline. Since the queue could be stuffed by more
561 // than one buffer, we take the last latch time as reference and give one vsync
562 // worth of time for the frame to be ready.
563 nsecs_t adjustedDeadline = mLastLatchTime + refreshRate.getPeriodNsecs();
564 if (adjustedDeadline > mActuals.endTime) {
565 mFrameReadyMetadata = FrameReadyMetadata::OnTimeFinish;
566 } else {
567 mFrameReadyMetadata = FrameReadyMetadata::LateFinish;
568 }
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800569 }
570 if (mFrameReadyMetadata == FrameReadyMetadata::OnTimeFinish) {
571 // Finish on time, Present late
572 if (displayFrameJankType != JankType::None) {
573 // Propagate displayFrame's jank if it exists
574 mJankType |= displayFrameJankType;
575 } else {
Adithya Srinivasan939cd4d2021-02-23 06:18:13 +0000576 if (!(mJankType & JankType::BufferStuffing)) {
577 // In a stuffed state, if the app finishes on time and there is no display frame
578 // jank, only buffer stuffing is the root cause of the jank.
579 if (deltaToVsync < mJankClassificationThresholds.presentThreshold ||
580 deltaToVsync >= refreshRate.getPeriodNsecs() -
581 mJankClassificationThresholds.presentThreshold) {
582 // Delta factor of vsync
583 mJankType |= JankType::SurfaceFlingerScheduling;
584 } else {
585 // Delta not a factor of vsync
586 mJankType |= JankType::PredictionError;
587 }
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800588 }
589 }
590 } else if (mFrameReadyMetadata == FrameReadyMetadata::LateFinish) {
591 // Finish late, Present late
Adithya Srinivasan8a945502021-03-19 19:12:32 +0000592 mJankType |= JankType::AppDeadlineMissed;
593 // Propagate DisplayFrame's jankType if it is janky
594 mJankType |= displayFrameJankType;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800595 }
596 }
Adithya Srinivasan7c4ac7a2021-03-08 23:48:03 +0000597}
598
599void SurfaceFrame::onPresent(nsecs_t presentTime, int32_t displayFrameJankType, Fps refreshRate,
600 nsecs_t displayDeadlineDelta, nsecs_t displayPresentDelta) {
601 std::scoped_lock lock(mMutex);
602
603 if (mPresentState != PresentState::Presented) {
604 // No need to update dropped buffers
605 return;
606 }
607
608 mActuals.presentTime = presentTime;
609 nsecs_t deadlineDelta = 0;
610
611 classifyJankLocked(displayFrameJankType, refreshRate, deadlineDelta);
612
613 if (mPredictionState != PredictionState::None) {
614 // Only update janky frames if the app used vsync predictions
615 mTimeStats->incrementJankyFrames({refreshRate, mRenderRate, mOwnerUid, mLayerName,
Adithya Srinivasan58069dc2021-06-04 20:37:02 +0000616 mGameMode, mJankType, displayDeadlineDelta,
617 displayPresentDelta, deadlineDelta});
Adithya Srinivasan7c4ac7a2021-03-08 23:48:03 +0000618 }
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800619}
620
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000621void SurfaceFrame::tracePredictions(int64_t displayFrameToken) const {
Adithya Srinivasan86678502021-01-19 21:50:38 +0000622 int64_t expectedTimelineCookie = mTraceCookieCounter.getCookieForTracing();
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000623
Adithya Srinivasan86678502021-01-19 21:50:38 +0000624 // Expected timeline start
625 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000626 std::scoped_lock lock(mMutex);
Adithya Srinivasan01189672020-10-20 14:23:05 -0700627 auto packet = ctx.NewTracePacket();
628 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000629 packet->set_timestamp(static_cast<uint64_t>(mPredictions.startTime));
Adithya Srinivasan01189672020-10-20 14:23:05 -0700630
631 auto* event = packet->set_frame_timeline_event();
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000632 auto* expectedSurfaceFrameStartEvent = event->set_expected_surface_frame_start();
Adithya Srinivasan01189672020-10-20 14:23:05 -0700633
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000634 expectedSurfaceFrameStartEvent->set_cookie(expectedTimelineCookie);
635
636 expectedSurfaceFrameStartEvent->set_token(mToken);
637 expectedSurfaceFrameStartEvent->set_display_frame_token(displayFrameToken);
638
639 expectedSurfaceFrameStartEvent->set_pid(mOwnerPid);
640 expectedSurfaceFrameStartEvent->set_layer_name(mDebugName);
641 });
Adithya Srinivasan86678502021-01-19 21:50:38 +0000642
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000643 // Expected timeline end
644 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000645 std::scoped_lock lock(mMutex);
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000646 auto packet = ctx.NewTracePacket();
647 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
648 packet->set_timestamp(static_cast<uint64_t>(mPredictions.endTime));
649
650 auto* event = packet->set_frame_timeline_event();
651 auto* expectedSurfaceFrameEndEvent = event->set_frame_end();
652
653 expectedSurfaceFrameEndEvent->set_cookie(expectedTimelineCookie);
654 });
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000655}
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000656
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000657void SurfaceFrame::traceActuals(int64_t displayFrameToken) const {
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000658 int64_t actualTimelineCookie = mTraceCookieCounter.getCookieForTracing();
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000659
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000660 // Actual timeline start
661 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000662 std::scoped_lock lock(mMutex);
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000663 auto packet = ctx.NewTracePacket();
664 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
665 // Actual start time is not yet available, so use expected start instead
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000666 if (mPredictionState == PredictionState::Expired) {
667 // If prediction is expired, we can't use the predicted start time. Instead, just use a
668 // start time a little earlier than the end time so that we have some info about this
669 // frame in the trace.
Adithya Srinivasanb2283c32021-04-21 21:31:56 +0000670 nsecs_t endTime =
671 (mPresentState == PresentState::Dropped ? mDropTime : mActuals.endTime);
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000672 packet->set_timestamp(
Adithya Srinivasanb2283c32021-04-21 21:31:56 +0000673 static_cast<uint64_t>(endTime - kPredictionExpiredStartTimeDelta));
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000674 } else {
Rachel Leeed511ef2021-10-11 15:09:51 -0700675 packet->set_timestamp(static_cast<uint64_t>(
676 mActuals.startTime == 0 ? mPredictions.startTime : mActuals.startTime));
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000677 }
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000678
679 auto* event = packet->set_frame_timeline_event();
680 auto* actualSurfaceFrameStartEvent = event->set_actual_surface_frame_start();
681
682 actualSurfaceFrameStartEvent->set_cookie(actualTimelineCookie);
683
684 actualSurfaceFrameStartEvent->set_token(mToken);
685 actualSurfaceFrameStartEvent->set_display_frame_token(displayFrameToken);
686
687 actualSurfaceFrameStartEvent->set_pid(mOwnerPid);
688 actualSurfaceFrameStartEvent->set_layer_name(mDebugName);
Adithya Srinivasan01189672020-10-20 14:23:05 -0700689
690 if (mPresentState == PresentState::Dropped) {
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000691 actualSurfaceFrameStartEvent->set_present_type(FrameTimelineEvent::PRESENT_DROPPED);
Adithya Srinivasan01189672020-10-20 14:23:05 -0700692 } else if (mPresentState == PresentState::Unknown) {
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000693 actualSurfaceFrameStartEvent->set_present_type(FrameTimelineEvent::PRESENT_UNSPECIFIED);
Adithya Srinivasan01189672020-10-20 14:23:05 -0700694 } else {
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000695 actualSurfaceFrameStartEvent->set_present_type(toProto(mFramePresentMetadata));
Adithya Srinivasan01189672020-10-20 14:23:05 -0700696 }
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000697 actualSurfaceFrameStartEvent->set_on_time_finish(mFrameReadyMetadata ==
698 FrameReadyMetadata::OnTimeFinish);
699 actualSurfaceFrameStartEvent->set_gpu_composition(mGpuComposition);
700 actualSurfaceFrameStartEvent->set_jank_type(jankTypeBitmaskToProto(mJankType));
Adithya Srinivasan78e58af2021-02-25 00:08:08 +0000701 actualSurfaceFrameStartEvent->set_prediction_type(toProto(mPredictionState));
Adithya Srinivasan1f9450c2021-06-10 22:39:19 +0000702 actualSurfaceFrameStartEvent->set_is_buffer(mIsBuffer);
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000703 });
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000704
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000705 // Actual timeline end
706 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000707 std::scoped_lock lock(mMutex);
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000708 auto packet = ctx.NewTracePacket();
709 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000710 if (mPresentState == PresentState::Dropped) {
711 packet->set_timestamp(static_cast<uint64_t>(mDropTime));
712 } else {
713 packet->set_timestamp(static_cast<uint64_t>(mActuals.endTime));
714 }
Adithya Srinivasan01189672020-10-20 14:23:05 -0700715
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000716 auto* event = packet->set_frame_timeline_event();
717 auto* actualSurfaceFrameEndEvent = event->set_frame_end();
Adithya Srinivasan01189672020-10-20 14:23:05 -0700718
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000719 actualSurfaceFrameEndEvent->set_cookie(actualTimelineCookie);
Adithya Srinivasan01189672020-10-20 14:23:05 -0700720 });
721}
722
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000723/**
724 * TODO(b/178637512): add inputEventId to the perfetto trace.
725 */
726void SurfaceFrame::trace(int64_t displayFrameToken) const {
727 if (mToken == FrameTimelineInfo::INVALID_VSYNC_ID ||
728 displayFrameToken == FrameTimelineInfo::INVALID_VSYNC_ID) {
729 // No packets can be traced with a missing token.
730 return;
731 }
732 if (getPredictionState() != PredictionState::Expired) {
733 // Expired predictions have zeroed timestamps. This cannot be used in any meaningful way in
734 // a trace.
735 tracePredictions(displayFrameToken);
736 }
737 traceActuals(displayFrameToken);
738}
739
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800740namespace impl {
741
742int64_t TokenManager::generateTokenForPredictions(TimelineItem&& predictions) {
743 ATRACE_CALL();
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000744 std::scoped_lock lock(mMutex);
Adithya Srinivasanbed4c4f2021-05-03 20:24:46 +0000745 while (mPredictions.size() >= kMaxTokens) {
746 mPredictions.erase(mPredictions.begin());
747 }
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800748 const int64_t assignedToken = mCurrentToken++;
Adithya Srinivasanbed4c4f2021-05-03 20:24:46 +0000749 mPredictions[assignedToken] = predictions;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800750 return assignedToken;
751}
752
753std::optional<TimelineItem> TokenManager::getPredictionsForToken(int64_t token) const {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000754 std::scoped_lock lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800755 auto predictionsIterator = mPredictions.find(token);
756 if (predictionsIterator != mPredictions.end()) {
Adithya Srinivasanbed4c4f2021-05-03 20:24:46 +0000757 return predictionsIterator->second;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800758 }
759 return {};
760}
761
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800762FrameTimeline::FrameTimeline(std::shared_ptr<TimeStats> timeStats, pid_t surfaceFlingerPid,
Adithya Srinivasan82eef322021-04-10 00:06:04 +0000763 JankClassificationThresholds thresholds)
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000764 : mMaxDisplayFrames(kDefaultMaxDisplayFrames),
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800765 mTimeStats(std::move(timeStats)),
766 mSurfaceFlingerPid(surfaceFlingerPid),
Adithya Srinivasan82eef322021-04-10 00:06:04 +0000767 mJankClassificationThresholds(thresholds) {
768 mCurrentDisplayFrame =
769 std::make_shared<DisplayFrame>(mTimeStats, thresholds, &mTraceCookieCounter);
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000770}
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700771
Adithya Srinivasan01189672020-10-20 14:23:05 -0700772void FrameTimeline::onBootFinished() {
773 perfetto::TracingInitArgs args;
774 args.backends = perfetto::kSystemBackend;
775 perfetto::Tracing::Initialize(args);
776 registerDataSource();
777}
778
779void FrameTimeline::registerDataSource() {
780 perfetto::DataSourceDescriptor dsd;
781 dsd.set_name(kFrameTimelineDataSource);
782 FrameTimelineDataSource::Register(dsd);
783}
784
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800785std::shared_ptr<SurfaceFrame> FrameTimeline::createSurfaceFrameForToken(
Alec Mouriadebf5c2021-01-05 12:57:36 -0800786 const FrameTimelineInfo& frameTimelineInfo, pid_t ownerPid, uid_t ownerUid, int32_t layerId,
Dominik Laskowskif5d0ea52021-09-26 17:27:01 -0700787 std::string layerName, std::string debugName, bool isBuffer, GameMode gameMode) {
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -0700788 ATRACE_CALL();
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000789 if (frameTimelineInfo.vsyncId == FrameTimelineInfo::INVALID_VSYNC_ID) {
Alec Mouriadebf5c2021-01-05 12:57:36 -0800790 return std::make_shared<SurfaceFrame>(frameTimelineInfo, ownerPid, ownerUid, layerId,
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000791 std::move(layerName), std::move(debugName),
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800792 PredictionState::None, TimelineItem(), mTimeStats,
Adithya Srinivasan785addd2021-03-09 00:38:00 +0000793 mJankClassificationThresholds, &mTraceCookieCounter,
Adithya Srinivasan58069dc2021-06-04 20:37:02 +0000794 isBuffer, gameMode);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700795 }
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000796 std::optional<TimelineItem> predictions =
797 mTokenManager.getPredictionsForToken(frameTimelineInfo.vsyncId);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700798 if (predictions) {
Alec Mouriadebf5c2021-01-05 12:57:36 -0800799 return std::make_shared<SurfaceFrame>(frameTimelineInfo, ownerPid, ownerUid, layerId,
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000800 std::move(layerName), std::move(debugName),
801 PredictionState::Valid, std::move(*predictions),
802 mTimeStats, mJankClassificationThresholds,
Adithya Srinivasan58069dc2021-06-04 20:37:02 +0000803 &mTraceCookieCounter, isBuffer, gameMode);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700804 }
Alec Mouriadebf5c2021-01-05 12:57:36 -0800805 return std::make_shared<SurfaceFrame>(frameTimelineInfo, ownerPid, ownerUid, layerId,
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000806 std::move(layerName), std::move(debugName),
807 PredictionState::Expired, TimelineItem(), mTimeStats,
Adithya Srinivasan785addd2021-03-09 00:38:00 +0000808 mJankClassificationThresholds, &mTraceCookieCounter,
Adithya Srinivasan58069dc2021-06-04 20:37:02 +0000809 isBuffer, gameMode);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700810}
811
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800812FrameTimeline::DisplayFrame::DisplayFrame(std::shared_ptr<TimeStats> timeStats,
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000813 JankClassificationThresholds thresholds,
814 TraceCookieCounter* traceCookieCounter)
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800815 : mSurfaceFlingerPredictions(TimelineItem()),
816 mSurfaceFlingerActuals(TimelineItem()),
817 mTimeStats(timeStats),
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000818 mJankClassificationThresholds(thresholds),
819 mTraceCookieCounter(*traceCookieCounter) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800820 mSurfaceFrames.reserve(kNumSurfaceFramesInitial);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700821}
822
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800823void FrameTimeline::addSurfaceFrame(std::shared_ptr<SurfaceFrame> surfaceFrame) {
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -0700824 ATRACE_CALL();
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000825 std::scoped_lock lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800826 mCurrentDisplayFrame->addSurfaceFrame(surfaceFrame);
827}
828
Alec Mouri7d436ec2021-01-27 20:40:50 -0800829void FrameTimeline::setSfWakeUp(int64_t token, nsecs_t wakeUpTime, Fps refreshRate) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800830 ATRACE_CALL();
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000831 std::scoped_lock lock(mMutex);
Alec Mouri7d436ec2021-01-27 20:40:50 -0800832 mCurrentDisplayFrame->onSfWakeUp(token, refreshRate,
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800833 mTokenManager.getPredictionsForToken(token), wakeUpTime);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700834}
835
836void FrameTimeline::setSfPresent(nsecs_t sfPresentTime,
Adithya Srinivasanb6a2fa12021-03-13 00:23:09 +0000837 const std::shared_ptr<FenceTime>& presentFence,
Adithya Srinivasan36b01af2021-04-07 22:29:47 +0000838 const std::shared_ptr<FenceTime>& gpuFence) {
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -0700839 ATRACE_CALL();
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000840 std::scoped_lock lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800841 mCurrentDisplayFrame->setActualEndTime(sfPresentTime);
Adithya Srinivasan36b01af2021-04-07 22:29:47 +0000842 mCurrentDisplayFrame->setGpuFence(gpuFence);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700843 mPendingPresentFences.emplace_back(std::make_pair(presentFence, mCurrentDisplayFrame));
844 flushPendingPresentFences();
845 finalizeCurrentDisplayFrame();
846}
847
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800848void FrameTimeline::DisplayFrame::addSurfaceFrame(std::shared_ptr<SurfaceFrame> surfaceFrame) {
849 mSurfaceFrames.push_back(surfaceFrame);
850}
851
Alec Mouri7d436ec2021-01-27 20:40:50 -0800852void FrameTimeline::DisplayFrame::onSfWakeUp(int64_t token, Fps refreshRate,
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800853 std::optional<TimelineItem> predictions,
854 nsecs_t wakeUpTime) {
855 mToken = token;
Alec Mouri7d436ec2021-01-27 20:40:50 -0800856 mRefreshRate = refreshRate;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800857 if (!predictions) {
858 mPredictionState = PredictionState::Expired;
859 } else {
860 mPredictionState = PredictionState::Valid;
861 mSurfaceFlingerPredictions = *predictions;
862 }
863 mSurfaceFlingerActuals.startTime = wakeUpTime;
864}
865
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800866void FrameTimeline::DisplayFrame::setPredictions(PredictionState predictionState,
867 TimelineItem predictions) {
868 mPredictionState = predictionState;
869 mSurfaceFlingerPredictions = predictions;
870}
871
872void FrameTimeline::DisplayFrame::setActualStartTime(nsecs_t actualStartTime) {
873 mSurfaceFlingerActuals.startTime = actualStartTime;
874}
875
876void FrameTimeline::DisplayFrame::setActualEndTime(nsecs_t actualEndTime) {
877 mSurfaceFlingerActuals.endTime = actualEndTime;
878}
879
Adithya Srinivasan36b01af2021-04-07 22:29:47 +0000880void FrameTimeline::DisplayFrame::setGpuFence(const std::shared_ptr<FenceTime>& gpuFence) {
881 mGpuFence = gpuFence;
Adithya Srinivasanb6a2fa12021-03-13 00:23:09 +0000882}
883
Adithya Srinivasan57dc81d2021-04-14 17:31:41 +0000884void FrameTimeline::DisplayFrame::classifyJank(nsecs_t& deadlineDelta, nsecs_t& deltaToVsync,
885 nsecs_t previousPresentTime) {
Adithya Srinivasan7c4ac7a2021-03-08 23:48:03 +0000886 if (mPredictionState == PredictionState::Expired ||
887 mSurfaceFlingerActuals.presentTime == Fence::SIGNAL_TIME_INVALID) {
Adithya Srinivasande272452021-04-10 00:21:00 +0000888 // Cannot do jank classification with expired predictions or invalid signal times. Set the
889 // deltas to 0 as both negative and positive deltas are used as real values.
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000890 mJankType = JankType::Unknown;
Adithya Srinivasande272452021-04-10 00:21:00 +0000891 deadlineDelta = 0;
892 deltaToVsync = 0;
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000893 return;
894 }
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800895
896 // Delta between the expected present and the actual present
897 const nsecs_t presentDelta =
898 mSurfaceFlingerActuals.presentTime - mSurfaceFlingerPredictions.presentTime;
Adithya Srinivasan36b01af2021-04-07 22:29:47 +0000899 // Sf actual end time represents the CPU end time. In case of HWC, SF's end time would have
900 // included the time for composition. However, for GPU composition, the final end time is max(sf
901 // end time, gpu fence time).
902 nsecs_t combinedEndTime = mSurfaceFlingerActuals.endTime;
903 if (mGpuFence != FenceTime::NO_FENCE) {
904 combinedEndTime = std::max(combinedEndTime, mGpuFence->getSignalTime());
905 }
906 deadlineDelta = combinedEndTime - mSurfaceFlingerPredictions.endTime;
Alec Mouri363faf02021-01-29 16:34:55 -0800907
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800908 // How far off was the presentDelta when compared to the vsyncPeriod. Used in checking if there
909 // was a prediction error or not.
Adithya Srinivasan115ac692021-03-06 01:21:30 +0000910 deltaToVsync = mRefreshRate.getPeriodNsecs() > 0
Alec Mouriadebf5c2021-01-05 12:57:36 -0800911 ? std::abs(presentDelta) % mRefreshRate.getPeriodNsecs()
912 : 0;
Adithya Srinivasan115ac692021-03-06 01:21:30 +0000913
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800914 if (std::abs(presentDelta) > mJankClassificationThresholds.presentThreshold) {
915 mFramePresentMetadata = presentDelta > 0 ? FramePresentMetadata::LatePresent
916 : FramePresentMetadata::EarlyPresent;
917 } else {
918 mFramePresentMetadata = FramePresentMetadata::OnTimePresent;
919 }
920
Adithya Srinivasan36b01af2021-04-07 22:29:47 +0000921 if (combinedEndTime > mSurfaceFlingerPredictions.endTime) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800922 mFrameReadyMetadata = FrameReadyMetadata::LateFinish;
923 } else {
924 mFrameReadyMetadata = FrameReadyMetadata::OnTimeFinish;
925 }
926
927 if (std::abs(mSurfaceFlingerActuals.startTime - mSurfaceFlingerPredictions.startTime) >
928 mJankClassificationThresholds.startThreshold) {
929 mFrameStartMetadata =
930 mSurfaceFlingerActuals.startTime > mSurfaceFlingerPredictions.startTime
931 ? FrameStartMetadata::LateStart
932 : FrameStartMetadata::EarlyStart;
933 }
934
935 if (mFramePresentMetadata != FramePresentMetadata::OnTimePresent) {
936 // Do jank classification only if present is not on time
937 if (mFramePresentMetadata == FramePresentMetadata::EarlyPresent) {
938 if (mFrameReadyMetadata == FrameReadyMetadata::OnTimeFinish) {
939 // Finish on time, Present early
940 if (deltaToVsync < mJankClassificationThresholds.presentThreshold ||
Alec Mouri7d436ec2021-01-27 20:40:50 -0800941 deltaToVsync >= (mRefreshRate.getPeriodNsecs() -
942 mJankClassificationThresholds.presentThreshold)) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800943 // Delta is a factor of vsync if its within the presentTheshold on either side
944 // of the vsyncPeriod. Example: 0-2ms and 9-11ms are both within the threshold
945 // of the vsyncPeriod if the threshold was 2ms and the vsyncPeriod was 11ms.
946 mJankType = JankType::SurfaceFlingerScheduling;
947 } else {
948 // Delta is not a factor of vsync,
949 mJankType = JankType::PredictionError;
950 }
951 } else if (mFrameReadyMetadata == FrameReadyMetadata::LateFinish) {
952 // Finish late, Present early
953 mJankType = JankType::SurfaceFlingerScheduling;
954 } else {
955 // Finish time unknown
956 mJankType = JankType::Unknown;
957 }
958 } else if (mFramePresentMetadata == FramePresentMetadata::LatePresent) {
Adithya Srinivasan57dc81d2021-04-14 17:31:41 +0000959 if (std::abs(mSurfaceFlingerPredictions.presentTime - previousPresentTime) <=
960 mJankClassificationThresholds.presentThreshold ||
961 previousPresentTime > mSurfaceFlingerPredictions.presentTime) {
962 // The previous frame was either presented in the current frame's expected vsync or
963 // it was presented even later than the current frame's expected vsync.
964 mJankType = JankType::SurfaceFlingerStuffing;
965 }
966 if (mFrameReadyMetadata == FrameReadyMetadata::OnTimeFinish &&
967 !(mJankType & JankType::SurfaceFlingerStuffing)) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800968 // Finish on time, Present late
969 if (deltaToVsync < mJankClassificationThresholds.presentThreshold ||
Alec Mouri7d436ec2021-01-27 20:40:50 -0800970 deltaToVsync >= (mRefreshRate.getPeriodNsecs() -
971 mJankClassificationThresholds.presentThreshold)) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800972 // Delta is a factor of vsync if its within the presentTheshold on either side
973 // of the vsyncPeriod. Example: 0-2ms and 9-11ms are both within the threshold
974 // of the vsyncPeriod if the threshold was 2ms and the vsyncPeriod was 11ms.
975 mJankType = JankType::DisplayHAL;
976 } else {
977 // Delta is not a factor of vsync
978 mJankType = JankType::PredictionError;
979 }
980 } else if (mFrameReadyMetadata == FrameReadyMetadata::LateFinish) {
Adithya Srinivasan57dc81d2021-04-14 17:31:41 +0000981 if (!(mJankType & JankType::SurfaceFlingerStuffing) ||
982 mSurfaceFlingerActuals.presentTime - previousPresentTime >
983 mRefreshRate.getPeriodNsecs() +
984 mJankClassificationThresholds.presentThreshold) {
985 // Classify CPU vs GPU if SF wasn't stuffed or if SF was stuffed but this frame
986 // was presented more than a vsync late.
Adithya Srinivasan36b01af2021-04-07 22:29:47 +0000987 if (mGpuFence != FenceTime::NO_FENCE &&
988 mSurfaceFlingerActuals.endTime - mSurfaceFlingerActuals.startTime <
989 mRefreshRate.getPeriodNsecs()) {
990 // If SF was in GPU composition and the CPU work finished before the vsync
991 // period, classify it as GPU deadline missed.
992 mJankType = JankType::SurfaceFlingerGpuDeadlineMissed;
993 } else {
994 mJankType = JankType::SurfaceFlingerCpuDeadlineMissed;
995 }
Adithya Srinivasan939cd4d2021-02-23 06:18:13 +0000996 }
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800997 } else {
998 // Finish time unknown
999 mJankType = JankType::Unknown;
1000 }
1001 } else {
1002 // Present unknown
1003 mJankType = JankType::Unknown;
1004 }
1005 }
Adithya Srinivasan115ac692021-03-06 01:21:30 +00001006}
1007
Adithya Srinivasan57dc81d2021-04-14 17:31:41 +00001008void FrameTimeline::DisplayFrame::onPresent(nsecs_t signalTime, nsecs_t previousPresentTime) {
Adithya Srinivasan115ac692021-03-06 01:21:30 +00001009 mSurfaceFlingerActuals.presentTime = signalTime;
1010 nsecs_t deadlineDelta = 0;
1011 nsecs_t deltaToVsync = 0;
Adithya Srinivasan57dc81d2021-04-14 17:31:41 +00001012 classifyJank(deadlineDelta, deltaToVsync, previousPresentTime);
Adithya Srinivasan115ac692021-03-06 01:21:30 +00001013
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001014 for (auto& surfaceFrame : mSurfaceFrames) {
Alec Mouri363faf02021-01-29 16:34:55 -08001015 surfaceFrame->onPresent(signalTime, mJankType, mRefreshRate, deadlineDelta, deltaToVsync);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001016 }
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001017}
1018
Adithya Srinivasan061c14c2021-02-11 01:19:47 +00001019void FrameTimeline::DisplayFrame::tracePredictions(pid_t surfaceFlingerPid) const {
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +00001020 int64_t expectedTimelineCookie = mTraceCookieCounter.getCookieForTracing();
Adithya Srinivasan061c14c2021-02-11 01:19:47 +00001021
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +00001022 // Expected timeline start
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001023 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001024 auto packet = ctx.NewTracePacket();
1025 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +00001026 packet->set_timestamp(static_cast<uint64_t>(mSurfaceFlingerPredictions.startTime));
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001027
1028 auto* event = packet->set_frame_timeline_event();
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +00001029 auto* expectedDisplayFrameStartEvent = event->set_expected_display_frame_start();
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001030
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +00001031 expectedDisplayFrameStartEvent->set_cookie(expectedTimelineCookie);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001032
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +00001033 expectedDisplayFrameStartEvent->set_token(mToken);
1034 expectedDisplayFrameStartEvent->set_pid(surfaceFlingerPid);
1035 });
Adithya Srinivasan86678502021-01-19 21:50:38 +00001036
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +00001037 // Expected timeline end
1038 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
1039 auto packet = ctx.NewTracePacket();
1040 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
1041 packet->set_timestamp(static_cast<uint64_t>(mSurfaceFlingerPredictions.endTime));
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001042
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +00001043 auto* event = packet->set_frame_timeline_event();
1044 auto* expectedDisplayFrameEndEvent = event->set_frame_end();
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001045
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +00001046 expectedDisplayFrameEndEvent->set_cookie(expectedTimelineCookie);
1047 });
Adithya Srinivasan061c14c2021-02-11 01:19:47 +00001048}
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +00001049
Adithya Srinivasan061c14c2021-02-11 01:19:47 +00001050void FrameTimeline::DisplayFrame::traceActuals(pid_t surfaceFlingerPid) const {
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +00001051 int64_t actualTimelineCookie = mTraceCookieCounter.getCookieForTracing();
Adithya Srinivasan061c14c2021-02-11 01:19:47 +00001052
1053 // Actual timeline start
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +00001054 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
1055 auto packet = ctx.NewTracePacket();
1056 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
1057 packet->set_timestamp(static_cast<uint64_t>(mSurfaceFlingerActuals.startTime));
1058
1059 auto* event = packet->set_frame_timeline_event();
1060 auto* actualDisplayFrameStartEvent = event->set_actual_display_frame_start();
1061
1062 actualDisplayFrameStartEvent->set_cookie(actualTimelineCookie);
1063
1064 actualDisplayFrameStartEvent->set_token(mToken);
1065 actualDisplayFrameStartEvent->set_pid(surfaceFlingerPid);
1066
1067 actualDisplayFrameStartEvent->set_present_type(toProto(mFramePresentMetadata));
1068 actualDisplayFrameStartEvent->set_on_time_finish(mFrameReadyMetadata ==
1069 FrameReadyMetadata::OnTimeFinish);
Adithya Srinivasan36b01af2021-04-07 22:29:47 +00001070 actualDisplayFrameStartEvent->set_gpu_composition(mGpuFence != FenceTime::NO_FENCE);
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +00001071 actualDisplayFrameStartEvent->set_jank_type(jankTypeBitmaskToProto(mJankType));
Adithya Srinivasan78e58af2021-02-25 00:08:08 +00001072 actualDisplayFrameStartEvent->set_prediction_type(toProto(mPredictionState));
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +00001073 });
Adithya Srinivasan061c14c2021-02-11 01:19:47 +00001074
1075 // Actual timeline end
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +00001076 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
1077 auto packet = ctx.NewTracePacket();
1078 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
Adithya Srinivasan1a971632021-02-26 23:10:29 +00001079 packet->set_timestamp(static_cast<uint64_t>(mSurfaceFlingerActuals.presentTime));
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +00001080
1081 auto* event = packet->set_frame_timeline_event();
1082 auto* actualDisplayFrameEndEvent = event->set_frame_end();
1083
1084 actualDisplayFrameEndEvent->set_cookie(actualTimelineCookie);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001085 });
Adithya Srinivasan061c14c2021-02-11 01:19:47 +00001086}
1087
1088void FrameTimeline::DisplayFrame::trace(pid_t surfaceFlingerPid) const {
1089 if (mToken == FrameTimelineInfo::INVALID_VSYNC_ID) {
1090 // DisplayFrame should not have an invalid token.
1091 ALOGE("Cannot trace DisplayFrame with invalid token");
1092 return;
1093 }
1094
1095 if (mPredictionState == PredictionState::Valid) {
1096 // Expired and unknown predictions have zeroed timestamps. This cannot be used in any
1097 // meaningful way in a trace.
1098 tracePredictions(surfaceFlingerPid);
1099 }
1100 traceActuals(surfaceFlingerPid);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001101
1102 for (auto& surfaceFrame : mSurfaceFrames) {
1103 surfaceFrame->trace(mToken);
1104 }
1105}
1106
Alec Mouriadebf5c2021-01-05 12:57:36 -08001107float FrameTimeline::computeFps(const std::unordered_set<int32_t>& layerIds) {
1108 if (layerIds.empty()) {
1109 return 0.0f;
1110 }
1111
1112 std::vector<nsecs_t> presentTimes;
1113 {
1114 std::scoped_lock lock(mMutex);
1115 presentTimes.reserve(mDisplayFrames.size());
1116 for (size_t i = 0; i < mDisplayFrames.size(); i++) {
1117 const auto& displayFrame = mDisplayFrames[i];
1118 if (displayFrame->getActuals().presentTime <= 0) {
1119 continue;
1120 }
1121 for (const auto& surfaceFrame : displayFrame->getSurfaceFrames()) {
1122 if (surfaceFrame->getPresentState() == SurfaceFrame::PresentState::Presented &&
1123 layerIds.count(surfaceFrame->getLayerId()) > 0) {
1124 // We're looking for DisplayFrames that presents at least one layer from
1125 // layerIds, so push the present time and skip looking through the rest of the
1126 // SurfaceFrames.
1127 presentTimes.push_back(displayFrame->getActuals().presentTime);
1128 break;
1129 }
1130 }
1131 }
1132 }
1133
1134 // FPS can't be computed when there's fewer than 2 presented frames.
1135 if (presentTimes.size() <= 1) {
1136 return 0.0f;
1137 }
1138
1139 nsecs_t priorPresentTime = -1;
1140 nsecs_t totalPresentToPresentWalls = 0;
1141
1142 for (const nsecs_t presentTime : presentTimes) {
1143 if (priorPresentTime == -1) {
1144 priorPresentTime = presentTime;
1145 continue;
1146 }
1147
1148 totalPresentToPresentWalls += (presentTime - priorPresentTime);
1149 priorPresentTime = presentTime;
1150 }
1151
1152 if (CC_UNLIKELY(totalPresentToPresentWalls <= 0)) {
1153 ALOGW("Invalid total present-to-present duration when computing fps: %" PRId64,
1154 totalPresentToPresentWalls);
1155 return 0.0f;
1156 }
1157
1158 const constexpr nsecs_t kOneSecond =
1159 std::chrono::duration_cast<std::chrono::nanoseconds>(1s).count();
1160 // (10^9 nanoseconds / second) * (N present deltas) / (total nanoseconds in N present deltas) =
1161 // M frames / second
1162 return kOneSecond * static_cast<nsecs_t>((presentTimes.size() - 1)) /
1163 static_cast<float>(totalPresentToPresentWalls);
1164}
1165
Adithya Srinivasanf279e042020-08-17 14:56:27 -07001166void FrameTimeline::flushPendingPresentFences() {
1167 for (size_t i = 0; i < mPendingPresentFences.size(); i++) {
1168 const auto& pendingPresentFence = mPendingPresentFences[i];
1169 nsecs_t signalTime = Fence::SIGNAL_TIME_INVALID;
1170 if (pendingPresentFence.first && pendingPresentFence.first->isValid()) {
1171 signalTime = pendingPresentFence.first->getSignalTime();
1172 if (signalTime == Fence::SIGNAL_TIME_PENDING) {
1173 continue;
1174 }
1175 }
Adithya Srinivasan7c4ac7a2021-03-08 23:48:03 +00001176 auto& displayFrame = pendingPresentFence.second;
Adithya Srinivasan57dc81d2021-04-14 17:31:41 +00001177 displayFrame->onPresent(signalTime, mPreviousPresentTime);
Adithya Srinivasan7c4ac7a2021-03-08 23:48:03 +00001178 displayFrame->trace(mSurfaceFlingerPid);
Adithya Srinivasan57dc81d2021-04-14 17:31:41 +00001179 mPreviousPresentTime = signalTime;
Adithya Srinivasanf279e042020-08-17 14:56:27 -07001180
1181 mPendingPresentFences.erase(mPendingPresentFences.begin() + static_cast<int>(i));
1182 --i;
1183 }
1184}
1185
1186void FrameTimeline::finalizeCurrentDisplayFrame() {
Adithya Srinivasan2d736322020-10-01 16:53:48 -07001187 while (mDisplayFrames.size() >= mMaxDisplayFrames) {
Adithya Srinivasanf279e042020-08-17 14:56:27 -07001188 // We maintain only a fixed number of frames' data. Pop older frames
1189 mDisplayFrames.pop_front();
1190 }
1191 mDisplayFrames.push_back(mCurrentDisplayFrame);
1192 mCurrentDisplayFrame.reset();
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +00001193 mCurrentDisplayFrame = std::make_shared<DisplayFrame>(mTimeStats, mJankClassificationThresholds,
Adithya Srinivasan82eef322021-04-10 00:06:04 +00001194 &mTraceCookieCounter);
Adithya Srinivasanf279e042020-08-17 14:56:27 -07001195}
1196
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001197nsecs_t FrameTimeline::DisplayFrame::getBaseTime() const {
1198 nsecs_t baseTime =
1199 getMinTime(mPredictionState, mSurfaceFlingerPredictions, mSurfaceFlingerActuals);
1200 for (const auto& surfaceFrame : mSurfaceFrames) {
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -07001201 nsecs_t surfaceFrameBaseTime = surfaceFrame->getBaseTime();
1202 if (surfaceFrameBaseTime != 0) {
1203 baseTime = std::min(baseTime, surfaceFrameBaseTime);
1204 }
1205 }
1206 return baseTime;
1207}
1208
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001209void FrameTimeline::DisplayFrame::dumpJank(std::string& result, nsecs_t baseTime,
1210 int displayFrameCount) const {
1211 if (mJankType == JankType::None) {
1212 // Check if any Surface Frame has been janky
1213 bool isJanky = false;
1214 for (const auto& surfaceFrame : mSurfaceFrames) {
1215 if (surfaceFrame->getJankType() != JankType::None) {
1216 isJanky = true;
1217 break;
1218 }
1219 }
1220 if (!isJanky) {
1221 return;
1222 }
1223 }
1224 StringAppendF(&result, "Display Frame %d", displayFrameCount);
1225 dump(result, baseTime);
1226}
1227
1228void FrameTimeline::DisplayFrame::dumpAll(std::string& result, nsecs_t baseTime) const {
1229 dump(result, baseTime);
1230}
1231
1232void FrameTimeline::DisplayFrame::dump(std::string& result, nsecs_t baseTime) const {
1233 if (mJankType != JankType::None) {
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -07001234 // Easily identify a janky Display Frame in the dump
1235 StringAppendF(&result, " [*] ");
1236 }
1237 StringAppendF(&result, "\n");
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001238 StringAppendF(&result, "Prediction State : %s\n", toString(mPredictionState).c_str());
1239 StringAppendF(&result, "Jank Type : %s\n", jankTypeBitmaskToString(mJankType).c_str());
1240 StringAppendF(&result, "Present Metadata : %s\n", toString(mFramePresentMetadata).c_str());
1241 StringAppendF(&result, "Finish Metadata: %s\n", toString(mFrameReadyMetadata).c_str());
1242 StringAppendF(&result, "Start Metadata: %s\n", toString(mFrameStartMetadata).c_str());
Alec Mouri7d436ec2021-01-27 20:40:50 -08001243 std::chrono::nanoseconds vsyncPeriod(mRefreshRate.getPeriodNsecs());
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001244 StringAppendF(&result, "Vsync Period: %10f\n",
1245 std::chrono::duration<double, std::milli>(vsyncPeriod).count());
1246 nsecs_t presentDelta =
1247 mSurfaceFlingerActuals.presentTime - mSurfaceFlingerPredictions.presentTime;
1248 std::chrono::nanoseconds presentDeltaNs(std::abs(presentDelta));
1249 StringAppendF(&result, "Present delta: %10f\n",
1250 std::chrono::duration<double, std::milli>(presentDeltaNs).count());
Alec Mouri7d436ec2021-01-27 20:40:50 -08001251 std::chrono::nanoseconds deltaToVsync(std::abs(presentDelta) % mRefreshRate.getPeriodNsecs());
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001252 StringAppendF(&result, "Present delta %% refreshrate: %10f\n",
1253 std::chrono::duration<double, std::milli>(deltaToVsync).count());
1254 dumpTable(result, mSurfaceFlingerPredictions, mSurfaceFlingerActuals, "", mPredictionState,
1255 baseTime);
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -07001256 StringAppendF(&result, "\n");
1257 std::string indent = " "; // 4 spaces
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001258 for (const auto& surfaceFrame : mSurfaceFrames) {
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -07001259 surfaceFrame->dump(result, indent, baseTime);
1260 }
1261 StringAppendF(&result, "\n");
1262}
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001263
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -07001264void FrameTimeline::dumpAll(std::string& result) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -10001265 std::scoped_lock lock(mMutex);
Adithya Srinivasanf279e042020-08-17 14:56:27 -07001266 StringAppendF(&result, "Number of display frames : %d\n", (int)mDisplayFrames.size());
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001267 nsecs_t baseTime = (mDisplayFrames.empty()) ? 0 : mDisplayFrames[0]->getBaseTime();
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -07001268 for (size_t i = 0; i < mDisplayFrames.size(); i++) {
1269 StringAppendF(&result, "Display Frame %d", static_cast<int>(i));
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001270 mDisplayFrames[i]->dumpAll(result, baseTime);
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -07001271 }
1272}
1273
1274void FrameTimeline::dumpJank(std::string& result) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -10001275 std::scoped_lock lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001276 nsecs_t baseTime = (mDisplayFrames.empty()) ? 0 : mDisplayFrames[0]->getBaseTime();
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -07001277 for (size_t i = 0; i < mDisplayFrames.size(); i++) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001278 mDisplayFrames[i]->dumpJank(result, baseTime, static_cast<int>(i));
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -07001279 }
1280}
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001281
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -07001282void FrameTimeline::parseArgs(const Vector<String16>& args, std::string& result) {
1283 ATRACE_CALL();
1284 std::unordered_map<std::string, bool> argsMap;
1285 for (size_t i = 0; i < args.size(); i++) {
1286 argsMap[std::string(String8(args[i]).c_str())] = true;
1287 }
1288 if (argsMap.count("-jank")) {
1289 dumpJank(result);
1290 }
1291 if (argsMap.count("-all")) {
1292 dumpAll(result);
Adithya Srinivasanf279e042020-08-17 14:56:27 -07001293 }
1294}
1295
Adithya Srinivasan2d736322020-10-01 16:53:48 -07001296void FrameTimeline::setMaxDisplayFrames(uint32_t size) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -10001297 std::scoped_lock lock(mMutex);
Adithya Srinivasan2d736322020-10-01 16:53:48 -07001298
1299 // The size can either increase or decrease, clear everything, to be consistent
1300 mDisplayFrames.clear();
1301 mPendingPresentFences.clear();
1302 mMaxDisplayFrames = size;
1303}
1304
1305void FrameTimeline::reset() {
1306 setMaxDisplayFrames(kDefaultMaxDisplayFrames);
1307}
1308
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001309} // namespace impl
1310} // namespace android::frametimeline