blob: f19e2a786301b7f38bd28639f27f4a2ea5d7ddae [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 Srinivasan552e2a72021-01-15 03:21:53 +0000139
140 // jankType should be 0 if all types of jank were checked for.
141 LOG_ALWAYS_FATAL_IF(jankType != 0, "Unrecognized jank type value 0x%x", jankType);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800142 return std::accumulate(janks.begin(), janks.end(), std::string(),
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700143 [](const std::string& l, const std::string& r) {
144 return l.empty() ? r : l + ", " + r;
145 });
146}
147
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800148std::string toString(FramePresentMetadata presentMetadata) {
149 switch (presentMetadata) {
150 case FramePresentMetadata::OnTimePresent:
151 return "On Time Present";
152 case FramePresentMetadata::LatePresent:
153 return "Late Present";
154 case FramePresentMetadata::EarlyPresent:
155 return "Early Present";
156 case FramePresentMetadata::UnknownPresent:
157 return "Unknown Present";
Adithya Srinivasan01189672020-10-20 14:23:05 -0700158 }
Adithya Srinivasan01189672020-10-20 14:23:05 -0700159}
160
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800161std::string toString(FrameReadyMetadata finishMetadata) {
162 switch (finishMetadata) {
163 case FrameReadyMetadata::OnTimeFinish:
164 return "On Time Finish";
165 case FrameReadyMetadata::LateFinish:
166 return "Late Finish";
167 case FrameReadyMetadata::UnknownFinish:
168 return "Unknown Finish";
169 }
170}
171
172std::string toString(FrameStartMetadata startMetadata) {
173 switch (startMetadata) {
174 case FrameStartMetadata::OnTimeStart:
175 return "On Time Start";
176 case FrameStartMetadata::LateStart:
177 return "Late Start";
178 case FrameStartMetadata::EarlyStart:
179 return "Early Start";
180 case FrameStartMetadata::UnknownStart:
181 return "Unknown Start";
182 }
183}
184
185std::string toString(SurfaceFrame::PresentState presentState) {
186 using PresentState = SurfaceFrame::PresentState;
187 switch (presentState) {
188 case PresentState::Presented:
189 return "Presented";
190 case PresentState::Dropped:
191 return "Dropped";
192 case PresentState::Unknown:
193 return "Unknown";
194 }
195}
196
197FrameTimelineEvent::PresentType toProto(FramePresentMetadata presentMetadata) {
198 switch (presentMetadata) {
199 case FramePresentMetadata::EarlyPresent:
200 return FrameTimelineEvent::PRESENT_EARLY;
201 case FramePresentMetadata::LatePresent:
202 return FrameTimelineEvent::PRESENT_LATE;
203 case FramePresentMetadata::OnTimePresent:
204 return FrameTimelineEvent::PRESENT_ON_TIME;
205 case FramePresentMetadata::UnknownPresent:
206 return FrameTimelineEvent::PRESENT_UNSPECIFIED;
207 }
208}
209
Adithya Srinivasan78e58af2021-02-25 00:08:08 +0000210FrameTimelineEvent::PredictionType toProto(PredictionState predictionState) {
211 switch (predictionState) {
212 case PredictionState::Valid:
213 return FrameTimelineEvent::PREDICTION_VALID;
214 case PredictionState::Expired:
215 return FrameTimelineEvent::PREDICTION_EXPIRED;
216 case PredictionState::None:
217 return FrameTimelineEvent::PREDICTION_UNKNOWN;
218 }
219}
220
Adithya Srinivasan552e2a72021-01-15 03:21:53 +0000221int32_t jankTypeBitmaskToProto(int32_t jankType) {
222 if (jankType == JankType::None) {
223 return FrameTimelineEvent::JANK_NONE;
Adithya Srinivasan01189672020-10-20 14:23:05 -0700224 }
Adithya Srinivasan552e2a72021-01-15 03:21:53 +0000225
226 int32_t protoJank = 0;
227 if (jankType & JankType::DisplayHAL) {
228 protoJank |= FrameTimelineEvent::JANK_DISPLAY_HAL;
229 jankType &= ~JankType::DisplayHAL;
230 }
231 if (jankType & JankType::SurfaceFlingerCpuDeadlineMissed) {
232 protoJank |= FrameTimelineEvent::JANK_SF_CPU_DEADLINE_MISSED;
233 jankType &= ~JankType::SurfaceFlingerCpuDeadlineMissed;
234 }
235 if (jankType & JankType::SurfaceFlingerGpuDeadlineMissed) {
236 protoJank |= FrameTimelineEvent::JANK_SF_GPU_DEADLINE_MISSED;
237 jankType &= ~JankType::SurfaceFlingerGpuDeadlineMissed;
238 }
239 if (jankType & JankType::AppDeadlineMissed) {
240 protoJank |= FrameTimelineEvent::JANK_APP_DEADLINE_MISSED;
241 jankType &= ~JankType::AppDeadlineMissed;
242 }
243 if (jankType & JankType::PredictionError) {
244 protoJank |= FrameTimelineEvent::JANK_PREDICTION_ERROR;
245 jankType &= ~JankType::PredictionError;
246 }
247 if (jankType & JankType::SurfaceFlingerScheduling) {
248 protoJank |= FrameTimelineEvent::JANK_SF_SCHEDULING;
249 jankType &= ~JankType::SurfaceFlingerScheduling;
250 }
251 if (jankType & JankType::BufferStuffing) {
252 protoJank |= FrameTimelineEvent::JANK_BUFFER_STUFFING;
253 jankType &= ~JankType::BufferStuffing;
254 }
255 if (jankType & JankType::Unknown) {
256 protoJank |= FrameTimelineEvent::JANK_UNKNOWN;
257 jankType &= ~JankType::Unknown;
258 }
Adithya Srinivasan57dc81d2021-04-14 17:31:41 +0000259 if (jankType & JankType::SurfaceFlingerStuffing) {
260 protoJank |= FrameTimelineEvent::JANK_SF_STUFFING;
261 jankType &= ~JankType::SurfaceFlingerStuffing;
262 }
Adithya Srinivasan552e2a72021-01-15 03:21:53 +0000263
264 // jankType should be 0 if all types of jank were checked for.
265 LOG_ALWAYS_FATAL_IF(jankType != 0, "Unrecognized jank type value 0x%x", jankType);
266 return protoJank;
Adithya Srinivasan01189672020-10-20 14:23:05 -0700267}
268
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800269// Returns the smallest timestamp from the set of predictions and actuals.
270nsecs_t getMinTime(PredictionState predictionState, TimelineItem predictions,
271 TimelineItem actuals) {
272 nsecs_t minTime = std::numeric_limits<nsecs_t>::max();
273 if (predictionState == PredictionState::Valid) {
274 // Checking start time for predictions is enough because start time is always lesser than
275 // endTime and presentTime.
276 minTime = std::min(minTime, predictions.startTime);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700277 }
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700278
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800279 // Need to check startTime, endTime and presentTime for actuals because some frames might not
280 // have them set.
281 if (actuals.startTime != 0) {
282 minTime = std::min(minTime, actuals.startTime);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700283 }
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800284 if (actuals.endTime != 0) {
285 minTime = std::min(minTime, actuals.endTime);
286 }
287 if (actuals.presentTime != 0) {
288 minTime = std::min(minTime, actuals.endTime);
289 }
290 return minTime;
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700291}
292
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000293int64_t TraceCookieCounter::getCookieForTracing() {
294 return ++mTraceCookie;
295}
296
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000297SurfaceFrame::SurfaceFrame(const FrameTimelineInfo& frameTimelineInfo, pid_t ownerPid,
Alec Mouriadebf5c2021-01-05 12:57:36 -0800298 uid_t ownerUid, int32_t layerId, std::string layerName,
299 std::string debugName, PredictionState predictionState,
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800300 frametimeline::TimelineItem&& predictions,
301 std::shared_ptr<TimeStats> timeStats,
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000302 JankClassificationThresholds thresholds,
Adithya Srinivasan785addd2021-03-09 00:38:00 +0000303 TraceCookieCounter* traceCookieCounter, bool isBuffer)
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000304 : mToken(frameTimelineInfo.vsyncId),
305 mInputEventId(frameTimelineInfo.inputEventId),
Adithya Srinivasan01189672020-10-20 14:23:05 -0700306 mOwnerPid(ownerPid),
Adithya Srinivasan9febda82020-10-19 10:49:41 -0700307 mOwnerUid(ownerUid),
Alec Mouri9a29e672020-09-14 12:39:14 -0700308 mLayerName(std::move(layerName)),
309 mDebugName(std::move(debugName)),
Alec Mouriadebf5c2021-01-05 12:57:36 -0800310 mLayerId(layerId),
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700311 mPresentState(PresentState::Unknown),
312 mPredictionState(predictionState),
313 mPredictions(predictions),
314 mActuals({0, 0, 0}),
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800315 mTimeStats(timeStats),
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000316 mJankClassificationThresholds(thresholds),
Adithya Srinivasan785addd2021-03-09 00:38:00 +0000317 mTraceCookieCounter(*traceCookieCounter),
318 mIsBuffer(isBuffer) {}
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700319
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -0700320void SurfaceFrame::setActualStartTime(nsecs_t actualStartTime) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000321 std::scoped_lock lock(mMutex);
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -0700322 mActuals.startTime = actualStartTime;
323}
324
325void SurfaceFrame::setActualQueueTime(nsecs_t actualQueueTime) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000326 std::scoped_lock lock(mMutex);
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -0700327 mActualQueueTime = actualQueueTime;
328}
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000329
Ady Abraham7f8a1e62020-09-28 16:09:35 -0700330void SurfaceFrame::setAcquireFenceTime(nsecs_t acquireFenceTime) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000331 std::scoped_lock lock(mMutex);
Ady Abraham7f8a1e62020-09-28 16:09:35 -0700332 mActuals.endTime = std::max(acquireFenceTime, mActualQueueTime);
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -0700333}
334
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000335void SurfaceFrame::setDropTime(nsecs_t dropTime) {
336 std::scoped_lock lock(mMutex);
337 mDropTime = dropTime;
338}
339
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800340void SurfaceFrame::setPresentState(PresentState presentState, nsecs_t lastLatchTime) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000341 std::scoped_lock lock(mMutex);
Adithya Srinivasanb9a7dab2021-01-14 23:49:46 +0000342 LOG_ALWAYS_FATAL_IF(mPresentState != PresentState::Unknown,
343 "setPresentState called on a SurfaceFrame from Layer - %s, that has a "
344 "PresentState - %s set already.",
345 mDebugName.c_str(), toString(mPresentState).c_str());
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800346 mPresentState = presentState;
347 mLastLatchTime = lastLatchTime;
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700348}
349
Alec Mouri7d436ec2021-01-27 20:40:50 -0800350void SurfaceFrame::setRenderRate(Fps renderRate) {
351 std::lock_guard<std::mutex> lock(mMutex);
352 mRenderRate = renderRate;
353}
354
Adithya Srinivasanb6a2fa12021-03-13 00:23:09 +0000355void SurfaceFrame::setGpuComposition() {
356 std::scoped_lock lock(mMutex);
357 mGpuComposition = true;
358}
359
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800360std::optional<int32_t> SurfaceFrame::getJankType() const {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000361 std::scoped_lock lock(mMutex);
Adithya Srinivasan95619432021-02-08 21:52:51 +0000362 if (mPresentState == PresentState::Dropped) {
363 // Return no jank if it's a dropped frame since we cannot attribute a jank to a it.
364 return JankType::None;
365 }
Jorim Jaggi9c03b502020-11-24 23:51:31 +0100366 if (mActuals.presentTime == 0) {
Adithya Srinivasan95619432021-02-08 21:52:51 +0000367 // Frame hasn't been presented yet.
Jorim Jaggi9c03b502020-11-24 23:51:31 +0100368 return std::nullopt;
369 }
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700370 return mJankType;
371}
372
373nsecs_t SurfaceFrame::getBaseTime() const {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000374 std::scoped_lock lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800375 return getMinTime(mPredictionState, mPredictions, mActuals);
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700376}
377
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800378TimelineItem SurfaceFrame::getActuals() const {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000379 std::scoped_lock lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800380 return mActuals;
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700381}
382
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000383PredictionState SurfaceFrame::getPredictionState() const {
384 std::scoped_lock lock(mMutex);
385 return mPredictionState;
386}
387
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800388SurfaceFrame::PresentState SurfaceFrame::getPresentState() const {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000389 std::scoped_lock lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800390 return mPresentState;
391}
392
393FramePresentMetadata SurfaceFrame::getFramePresentMetadata() const {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000394 std::scoped_lock lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800395 return mFramePresentMetadata;
396}
397
398FrameReadyMetadata SurfaceFrame::getFrameReadyMetadata() const {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000399 std::scoped_lock lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800400 return mFrameReadyMetadata;
401}
402
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000403nsecs_t SurfaceFrame::getDropTime() const {
404 std::scoped_lock lock(mMutex);
405 return mDropTime;
406}
407
Adithya Srinivasan785addd2021-03-09 00:38:00 +0000408void SurfaceFrame::promoteToBuffer() {
409 std::scoped_lock lock(mMutex);
410 LOG_ALWAYS_FATAL_IF(mIsBuffer == true,
411 "Trying to promote an already promoted BufferSurfaceFrame from layer %s "
412 "with token %" PRId64 "",
413 mDebugName.c_str(), mToken);
414 mIsBuffer = true;
415}
416
417bool SurfaceFrame::getIsBuffer() const {
418 std::scoped_lock lock(mMutex);
419 return mIsBuffer;
420}
421
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800422void SurfaceFrame::dump(std::string& result, const std::string& indent, nsecs_t baseTime) const {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000423 std::scoped_lock lock(mMutex);
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700424 StringAppendF(&result, "%s", indent.c_str());
Alec Mouri9a29e672020-09-14 12:39:14 -0700425 StringAppendF(&result, "Layer - %s", mDebugName.c_str());
Jorim Jaggi5814ab82020-12-03 20:45:58 +0100426 if (mJankType != JankType::None) {
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700427 // Easily identify a janky Surface Frame in the dump
428 StringAppendF(&result, " [*] ");
429 }
430 StringAppendF(&result, "\n");
431 StringAppendF(&result, "%s", indent.c_str());
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800432 StringAppendF(&result, "Token: %" PRId64 "\n", mToken);
433 StringAppendF(&result, "%s", indent.c_str());
Adithya Srinivasan785addd2021-03-09 00:38:00 +0000434 StringAppendF(&result, "Is Buffer?: %d\n", mIsBuffer);
435 StringAppendF(&result, "%s", indent.c_str());
Adithya Srinivasan9febda82020-10-19 10:49:41 -0700436 StringAppendF(&result, "Owner Pid : %d\n", mOwnerPid);
437 StringAppendF(&result, "%s", indent.c_str());
Alec Mouri7d436ec2021-01-27 20:40:50 -0800438 StringAppendF(&result, "Scheduled rendering rate: %d fps\n",
439 mRenderRate ? mRenderRate->getIntValue() : 0);
440 StringAppendF(&result, "%s", indent.c_str());
Alec Mouriadebf5c2021-01-05 12:57:36 -0800441 StringAppendF(&result, "Layer ID : %d\n", mLayerId);
442 StringAppendF(&result, "%s", indent.c_str());
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800443 StringAppendF(&result, "Present State : %s\n", toString(mPresentState).c_str());
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700444 StringAppendF(&result, "%s", indent.c_str());
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000445 if (mPresentState == PresentState::Dropped) {
446 std::chrono::nanoseconds dropTime(mDropTime - baseTime);
447 StringAppendF(&result, "Drop time : %10f\n",
448 std::chrono::duration<double, std::milli>(dropTime).count());
449 StringAppendF(&result, "%s", indent.c_str());
450 }
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700451 StringAppendF(&result, "Prediction State : %s\n", toString(mPredictionState).c_str());
452 StringAppendF(&result, "%s", indent.c_str());
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800453 StringAppendF(&result, "Jank Type : %s\n", jankTypeBitmaskToString(mJankType).c_str());
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700454 StringAppendF(&result, "%s", indent.c_str());
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800455 StringAppendF(&result, "Present Metadata : %s\n", toString(mFramePresentMetadata).c_str());
456 StringAppendF(&result, "%s", indent.c_str());
457 StringAppendF(&result, "Finish Metadata: %s\n", toString(mFrameReadyMetadata).c_str());
458 std::chrono::nanoseconds latchTime(
459 std::max(static_cast<int64_t>(0), mLastLatchTime - baseTime));
460 StringAppendF(&result, "%s", indent.c_str());
461 StringAppendF(&result, "Last latch time: %10f\n",
462 std::chrono::duration<double, std::milli>(latchTime).count());
463 if (mPredictionState == PredictionState::Valid) {
464 nsecs_t presentDelta = mActuals.presentTime - mPredictions.presentTime;
465 std::chrono::nanoseconds presentDeltaNs(std::abs(presentDelta));
466 StringAppendF(&result, "%s", indent.c_str());
467 StringAppendF(&result, "Present delta: %10f\n",
468 std::chrono::duration<double, std::milli>(presentDeltaNs).count());
469 }
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700470 dumpTable(result, mPredictions, mActuals, indent, mPredictionState, baseTime);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700471}
472
Adithya Srinivasan785addd2021-03-09 00:38:00 +0000473std::string SurfaceFrame::miniDump() const {
474 std::scoped_lock lock(mMutex);
475 std::string result;
476 StringAppendF(&result, "Layer - %s\n", mDebugName.c_str());
477 StringAppendF(&result, "Token: %" PRId64 "\n", mToken);
478 StringAppendF(&result, "Is Buffer?: %d\n", mIsBuffer);
479 StringAppendF(&result, "Present State : %s\n", toString(mPresentState).c_str());
480 StringAppendF(&result, "Prediction State : %s\n", toString(mPredictionState).c_str());
481 StringAppendF(&result, "Jank Type : %s\n", jankTypeBitmaskToString(mJankType).c_str());
482 StringAppendF(&result, "Present Metadata : %s\n", toString(mFramePresentMetadata).c_str());
483 StringAppendF(&result, "Finish Metadata: %s\n", toString(mFrameReadyMetadata).c_str());
484 StringAppendF(&result, "Present time: %" PRId64 "", mActuals.presentTime);
485 return result;
486}
487
Adithya Srinivasan7c4ac7a2021-03-08 23:48:03 +0000488void SurfaceFrame::classifyJankLocked(int32_t displayFrameJankType, const Fps& refreshRate,
489 nsecs_t& deadlineDelta) {
490 if (mPredictionState == PredictionState::Expired ||
491 mActuals.presentTime == Fence::SIGNAL_TIME_INVALID) {
492 // Cannot do any classification for invalid present time.
493 // For prediction expired case, we do not know what happened here to classify this
494 // correctly. This could potentially be AppDeadlineMissed but that's assuming no app will
495 // request frames 120ms apart.
496 mJankType = JankType::Unknown;
497 deadlineDelta = -1;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800498 return;
499 }
500
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800501 if (mPredictionState == PredictionState::None) {
502 // Cannot do jank classification on frames that don't have a token.
503 return;
504 }
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800505
Adithya Srinivasan7c4ac7a2021-03-08 23:48:03 +0000506 deadlineDelta = mActuals.endTime - mPredictions.endTime;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800507 const nsecs_t presentDelta = mActuals.presentTime - mPredictions.presentTime;
Alec Mouriadebf5c2021-01-05 12:57:36 -0800508 const nsecs_t deltaToVsync = refreshRate.getPeriodNsecs() > 0
509 ? std::abs(presentDelta) % refreshRate.getPeriodNsecs()
510 : 0;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800511
512 if (deadlineDelta > mJankClassificationThresholds.deadlineThreshold) {
513 mFrameReadyMetadata = FrameReadyMetadata::LateFinish;
514 } else {
515 mFrameReadyMetadata = FrameReadyMetadata::OnTimeFinish;
516 }
517
518 if (std::abs(presentDelta) > mJankClassificationThresholds.presentThreshold) {
519 mFramePresentMetadata = presentDelta > 0 ? FramePresentMetadata::LatePresent
520 : FramePresentMetadata::EarlyPresent;
521 } else {
522 mFramePresentMetadata = FramePresentMetadata::OnTimePresent;
523 }
524
525 if (mFramePresentMetadata == FramePresentMetadata::OnTimePresent) {
526 // Frames presented on time are not janky.
527 mJankType = JankType::None;
528 } else if (mFramePresentMetadata == FramePresentMetadata::EarlyPresent) {
529 if (mFrameReadyMetadata == FrameReadyMetadata::OnTimeFinish) {
530 // Finish on time, Present early
531 if (deltaToVsync < mJankClassificationThresholds.presentThreshold ||
Alec Mouri7d436ec2021-01-27 20:40:50 -0800532 deltaToVsync >= refreshRate.getPeriodNsecs() -
533 mJankClassificationThresholds.presentThreshold) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800534 // Delta factor of vsync
535 mJankType = JankType::SurfaceFlingerScheduling;
536 } else {
537 // Delta not a factor of vsync
538 mJankType = JankType::PredictionError;
539 }
540 } else if (mFrameReadyMetadata == FrameReadyMetadata::LateFinish) {
541 // Finish late, Present early
542 mJankType = JankType::Unknown;
543 }
544 } else {
545 if (mLastLatchTime != 0 && mPredictions.endTime <= mLastLatchTime) {
546 // Buffer Stuffing.
547 mJankType |= JankType::BufferStuffing;
Adithya Srinivasan939cd4d2021-02-23 06:18:13 +0000548 // In a stuffed state, the frame could be stuck on a dequeue wait for quite some time.
549 // Because of this dequeue wait, it can be hard to tell if a frame was genuinely late.
550 // We try to do this by moving the deadline. Since the queue could be stuffed by more
551 // than one buffer, we take the last latch time as reference and give one vsync
552 // worth of time for the frame to be ready.
553 nsecs_t adjustedDeadline = mLastLatchTime + refreshRate.getPeriodNsecs();
554 if (adjustedDeadline > mActuals.endTime) {
555 mFrameReadyMetadata = FrameReadyMetadata::OnTimeFinish;
556 } else {
557 mFrameReadyMetadata = FrameReadyMetadata::LateFinish;
558 }
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800559 }
560 if (mFrameReadyMetadata == FrameReadyMetadata::OnTimeFinish) {
561 // Finish on time, Present late
562 if (displayFrameJankType != JankType::None) {
563 // Propagate displayFrame's jank if it exists
564 mJankType |= displayFrameJankType;
565 } else {
Adithya Srinivasan939cd4d2021-02-23 06:18:13 +0000566 if (!(mJankType & JankType::BufferStuffing)) {
567 // In a stuffed state, if the app finishes on time and there is no display frame
568 // jank, only buffer stuffing is the root cause of the jank.
569 if (deltaToVsync < mJankClassificationThresholds.presentThreshold ||
570 deltaToVsync >= refreshRate.getPeriodNsecs() -
571 mJankClassificationThresholds.presentThreshold) {
572 // Delta factor of vsync
573 mJankType |= JankType::SurfaceFlingerScheduling;
574 } else {
575 // Delta not a factor of vsync
576 mJankType |= JankType::PredictionError;
577 }
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800578 }
579 }
580 } else if (mFrameReadyMetadata == FrameReadyMetadata::LateFinish) {
581 // Finish late, Present late
Adithya Srinivasan8a945502021-03-19 19:12:32 +0000582 mJankType |= JankType::AppDeadlineMissed;
583 // Propagate DisplayFrame's jankType if it is janky
584 mJankType |= displayFrameJankType;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800585 }
586 }
Adithya Srinivasan7c4ac7a2021-03-08 23:48:03 +0000587}
588
589void SurfaceFrame::onPresent(nsecs_t presentTime, int32_t displayFrameJankType, Fps refreshRate,
590 nsecs_t displayDeadlineDelta, nsecs_t displayPresentDelta) {
591 std::scoped_lock lock(mMutex);
592
593 if (mPresentState != PresentState::Presented) {
594 // No need to update dropped buffers
595 return;
596 }
597
598 mActuals.presentTime = presentTime;
599 nsecs_t deadlineDelta = 0;
600
601 classifyJankLocked(displayFrameJankType, refreshRate, deadlineDelta);
602
603 if (mPredictionState != PredictionState::None) {
604 // Only update janky frames if the app used vsync predictions
605 mTimeStats->incrementJankyFrames({refreshRate, mRenderRate, mOwnerUid, mLayerName,
606 mJankType, displayDeadlineDelta, displayPresentDelta,
607 deadlineDelta});
608 }
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800609}
610
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000611void SurfaceFrame::tracePredictions(int64_t displayFrameToken) const {
Adithya Srinivasan86678502021-01-19 21:50:38 +0000612 int64_t expectedTimelineCookie = mTraceCookieCounter.getCookieForTracing();
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000613
Adithya Srinivasan86678502021-01-19 21:50:38 +0000614 // Expected timeline start
615 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000616 std::scoped_lock lock(mMutex);
Adithya Srinivasan01189672020-10-20 14:23:05 -0700617 auto packet = ctx.NewTracePacket();
618 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000619 packet->set_timestamp(static_cast<uint64_t>(mPredictions.startTime));
Adithya Srinivasan01189672020-10-20 14:23:05 -0700620
621 auto* event = packet->set_frame_timeline_event();
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000622 auto* expectedSurfaceFrameStartEvent = event->set_expected_surface_frame_start();
Adithya Srinivasan01189672020-10-20 14:23:05 -0700623
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000624 expectedSurfaceFrameStartEvent->set_cookie(expectedTimelineCookie);
625
626 expectedSurfaceFrameStartEvent->set_token(mToken);
627 expectedSurfaceFrameStartEvent->set_display_frame_token(displayFrameToken);
628
629 expectedSurfaceFrameStartEvent->set_pid(mOwnerPid);
630 expectedSurfaceFrameStartEvent->set_layer_name(mDebugName);
631 });
Adithya Srinivasan86678502021-01-19 21:50:38 +0000632
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000633 // Expected timeline end
634 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000635 std::scoped_lock lock(mMutex);
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000636 auto packet = ctx.NewTracePacket();
637 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
638 packet->set_timestamp(static_cast<uint64_t>(mPredictions.endTime));
639
640 auto* event = packet->set_frame_timeline_event();
641 auto* expectedSurfaceFrameEndEvent = event->set_frame_end();
642
643 expectedSurfaceFrameEndEvent->set_cookie(expectedTimelineCookie);
644 });
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000645}
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000646
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000647void SurfaceFrame::traceActuals(int64_t displayFrameToken) const {
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000648 int64_t actualTimelineCookie = mTraceCookieCounter.getCookieForTracing();
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000649
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000650 // Actual timeline start
651 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000652 std::scoped_lock lock(mMutex);
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000653 auto packet = ctx.NewTracePacket();
654 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
655 // Actual start time is not yet available, so use expected start instead
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000656 if (mPredictionState == PredictionState::Expired) {
657 // If prediction is expired, we can't use the predicted start time. Instead, just use a
658 // start time a little earlier than the end time so that we have some info about this
659 // frame in the trace.
Adithya Srinivasanb2283c32021-04-21 21:31:56 +0000660 nsecs_t endTime =
661 (mPresentState == PresentState::Dropped ? mDropTime : mActuals.endTime);
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000662 packet->set_timestamp(
Adithya Srinivasanb2283c32021-04-21 21:31:56 +0000663 static_cast<uint64_t>(endTime - kPredictionExpiredStartTimeDelta));
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000664 } else {
665 packet->set_timestamp(static_cast<uint64_t>(mPredictions.startTime));
666 }
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000667
668 auto* event = packet->set_frame_timeline_event();
669 auto* actualSurfaceFrameStartEvent = event->set_actual_surface_frame_start();
670
671 actualSurfaceFrameStartEvent->set_cookie(actualTimelineCookie);
672
673 actualSurfaceFrameStartEvent->set_token(mToken);
674 actualSurfaceFrameStartEvent->set_display_frame_token(displayFrameToken);
675
676 actualSurfaceFrameStartEvent->set_pid(mOwnerPid);
677 actualSurfaceFrameStartEvent->set_layer_name(mDebugName);
Adithya Srinivasan01189672020-10-20 14:23:05 -0700678
679 if (mPresentState == PresentState::Dropped) {
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000680 actualSurfaceFrameStartEvent->set_present_type(FrameTimelineEvent::PRESENT_DROPPED);
Adithya Srinivasan01189672020-10-20 14:23:05 -0700681 } else if (mPresentState == PresentState::Unknown) {
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000682 actualSurfaceFrameStartEvent->set_present_type(FrameTimelineEvent::PRESENT_UNSPECIFIED);
Adithya Srinivasan01189672020-10-20 14:23:05 -0700683 } else {
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000684 actualSurfaceFrameStartEvent->set_present_type(toProto(mFramePresentMetadata));
Adithya Srinivasan01189672020-10-20 14:23:05 -0700685 }
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000686 actualSurfaceFrameStartEvent->set_on_time_finish(mFrameReadyMetadata ==
687 FrameReadyMetadata::OnTimeFinish);
688 actualSurfaceFrameStartEvent->set_gpu_composition(mGpuComposition);
689 actualSurfaceFrameStartEvent->set_jank_type(jankTypeBitmaskToProto(mJankType));
Adithya Srinivasan78e58af2021-02-25 00:08:08 +0000690 actualSurfaceFrameStartEvent->set_prediction_type(toProto(mPredictionState));
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000691 });
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000692
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000693 // Actual timeline end
694 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000695 std::scoped_lock lock(mMutex);
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000696 auto packet = ctx.NewTracePacket();
697 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000698 if (mPresentState == PresentState::Dropped) {
699 packet->set_timestamp(static_cast<uint64_t>(mDropTime));
700 } else {
701 packet->set_timestamp(static_cast<uint64_t>(mActuals.endTime));
702 }
Adithya Srinivasan01189672020-10-20 14:23:05 -0700703
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000704 auto* event = packet->set_frame_timeline_event();
705 auto* actualSurfaceFrameEndEvent = event->set_frame_end();
Adithya Srinivasan01189672020-10-20 14:23:05 -0700706
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000707 actualSurfaceFrameEndEvent->set_cookie(actualTimelineCookie);
Adithya Srinivasan01189672020-10-20 14:23:05 -0700708 });
709}
710
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000711/**
712 * TODO(b/178637512): add inputEventId to the perfetto trace.
713 */
714void SurfaceFrame::trace(int64_t displayFrameToken) const {
715 if (mToken == FrameTimelineInfo::INVALID_VSYNC_ID ||
716 displayFrameToken == FrameTimelineInfo::INVALID_VSYNC_ID) {
717 // No packets can be traced with a missing token.
718 return;
719 }
720 if (getPredictionState() != PredictionState::Expired) {
721 // Expired predictions have zeroed timestamps. This cannot be used in any meaningful way in
722 // a trace.
723 tracePredictions(displayFrameToken);
724 }
725 traceActuals(displayFrameToken);
726}
727
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800728namespace impl {
729
730int64_t TokenManager::generateTokenForPredictions(TimelineItem&& predictions) {
731 ATRACE_CALL();
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000732 std::scoped_lock lock(mMutex);
Adithya Srinivasanbed4c4f2021-05-03 20:24:46 +0000733 while (mPredictions.size() >= kMaxTokens) {
734 mPredictions.erase(mPredictions.begin());
735 }
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800736 const int64_t assignedToken = mCurrentToken++;
Adithya Srinivasanbed4c4f2021-05-03 20:24:46 +0000737 mPredictions[assignedToken] = predictions;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800738 return assignedToken;
739}
740
741std::optional<TimelineItem> TokenManager::getPredictionsForToken(int64_t token) const {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000742 std::scoped_lock lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800743 auto predictionsIterator = mPredictions.find(token);
744 if (predictionsIterator != mPredictions.end()) {
Adithya Srinivasanbed4c4f2021-05-03 20:24:46 +0000745 return predictionsIterator->second;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800746 }
747 return {};
748}
749
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800750FrameTimeline::FrameTimeline(std::shared_ptr<TimeStats> timeStats, pid_t surfaceFlingerPid,
Adithya Srinivasan82eef322021-04-10 00:06:04 +0000751 JankClassificationThresholds thresholds)
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000752 : mMaxDisplayFrames(kDefaultMaxDisplayFrames),
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800753 mTimeStats(std::move(timeStats)),
754 mSurfaceFlingerPid(surfaceFlingerPid),
Adithya Srinivasan82eef322021-04-10 00:06:04 +0000755 mJankClassificationThresholds(thresholds) {
756 mCurrentDisplayFrame =
757 std::make_shared<DisplayFrame>(mTimeStats, thresholds, &mTraceCookieCounter);
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000758}
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700759
Adithya Srinivasan01189672020-10-20 14:23:05 -0700760void FrameTimeline::onBootFinished() {
761 perfetto::TracingInitArgs args;
762 args.backends = perfetto::kSystemBackend;
763 perfetto::Tracing::Initialize(args);
764 registerDataSource();
765}
766
767void FrameTimeline::registerDataSource() {
768 perfetto::DataSourceDescriptor dsd;
769 dsd.set_name(kFrameTimelineDataSource);
770 FrameTimelineDataSource::Register(dsd);
771}
772
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800773std::shared_ptr<SurfaceFrame> FrameTimeline::createSurfaceFrameForToken(
Alec Mouriadebf5c2021-01-05 12:57:36 -0800774 const FrameTimelineInfo& frameTimelineInfo, pid_t ownerPid, uid_t ownerUid, int32_t layerId,
Adithya Srinivasan785addd2021-03-09 00:38:00 +0000775 std::string layerName, std::string debugName, bool isBuffer) {
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -0700776 ATRACE_CALL();
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000777 if (frameTimelineInfo.vsyncId == FrameTimelineInfo::INVALID_VSYNC_ID) {
Alec Mouriadebf5c2021-01-05 12:57:36 -0800778 return std::make_shared<SurfaceFrame>(frameTimelineInfo, ownerPid, ownerUid, layerId,
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000779 std::move(layerName), std::move(debugName),
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800780 PredictionState::None, TimelineItem(), mTimeStats,
Adithya Srinivasan785addd2021-03-09 00:38:00 +0000781 mJankClassificationThresholds, &mTraceCookieCounter,
782 isBuffer);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700783 }
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000784 std::optional<TimelineItem> predictions =
785 mTokenManager.getPredictionsForToken(frameTimelineInfo.vsyncId);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700786 if (predictions) {
Alec Mouriadebf5c2021-01-05 12:57:36 -0800787 return std::make_shared<SurfaceFrame>(frameTimelineInfo, ownerPid, ownerUid, layerId,
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000788 std::move(layerName), std::move(debugName),
789 PredictionState::Valid, std::move(*predictions),
790 mTimeStats, mJankClassificationThresholds,
Adithya Srinivasan785addd2021-03-09 00:38:00 +0000791 &mTraceCookieCounter, isBuffer);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700792 }
Alec Mouriadebf5c2021-01-05 12:57:36 -0800793 return std::make_shared<SurfaceFrame>(frameTimelineInfo, ownerPid, ownerUid, layerId,
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000794 std::move(layerName), std::move(debugName),
795 PredictionState::Expired, TimelineItem(), mTimeStats,
Adithya Srinivasan785addd2021-03-09 00:38:00 +0000796 mJankClassificationThresholds, &mTraceCookieCounter,
797 isBuffer);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700798}
799
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800800FrameTimeline::DisplayFrame::DisplayFrame(std::shared_ptr<TimeStats> timeStats,
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000801 JankClassificationThresholds thresholds,
802 TraceCookieCounter* traceCookieCounter)
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800803 : mSurfaceFlingerPredictions(TimelineItem()),
804 mSurfaceFlingerActuals(TimelineItem()),
805 mTimeStats(timeStats),
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000806 mJankClassificationThresholds(thresholds),
807 mTraceCookieCounter(*traceCookieCounter) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800808 mSurfaceFrames.reserve(kNumSurfaceFramesInitial);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700809}
810
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800811void FrameTimeline::addSurfaceFrame(std::shared_ptr<SurfaceFrame> surfaceFrame) {
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -0700812 ATRACE_CALL();
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000813 std::scoped_lock lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800814 mCurrentDisplayFrame->addSurfaceFrame(surfaceFrame);
815}
816
Alec Mouri7d436ec2021-01-27 20:40:50 -0800817void FrameTimeline::setSfWakeUp(int64_t token, nsecs_t wakeUpTime, Fps refreshRate) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800818 ATRACE_CALL();
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000819 std::scoped_lock lock(mMutex);
Alec Mouri7d436ec2021-01-27 20:40:50 -0800820 mCurrentDisplayFrame->onSfWakeUp(token, refreshRate,
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800821 mTokenManager.getPredictionsForToken(token), wakeUpTime);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700822}
823
824void FrameTimeline::setSfPresent(nsecs_t sfPresentTime,
Adithya Srinivasanb6a2fa12021-03-13 00:23:09 +0000825 const std::shared_ptr<FenceTime>& presentFence,
Adithya Srinivasan36b01af2021-04-07 22:29:47 +0000826 const std::shared_ptr<FenceTime>& gpuFence) {
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -0700827 ATRACE_CALL();
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000828 std::scoped_lock lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800829 mCurrentDisplayFrame->setActualEndTime(sfPresentTime);
Adithya Srinivasan36b01af2021-04-07 22:29:47 +0000830 mCurrentDisplayFrame->setGpuFence(gpuFence);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700831 mPendingPresentFences.emplace_back(std::make_pair(presentFence, mCurrentDisplayFrame));
832 flushPendingPresentFences();
833 finalizeCurrentDisplayFrame();
834}
835
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800836void FrameTimeline::DisplayFrame::addSurfaceFrame(std::shared_ptr<SurfaceFrame> surfaceFrame) {
837 mSurfaceFrames.push_back(surfaceFrame);
838}
839
Alec Mouri7d436ec2021-01-27 20:40:50 -0800840void FrameTimeline::DisplayFrame::onSfWakeUp(int64_t token, Fps refreshRate,
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800841 std::optional<TimelineItem> predictions,
842 nsecs_t wakeUpTime) {
843 mToken = token;
Alec Mouri7d436ec2021-01-27 20:40:50 -0800844 mRefreshRate = refreshRate;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800845 if (!predictions) {
846 mPredictionState = PredictionState::Expired;
847 } else {
848 mPredictionState = PredictionState::Valid;
849 mSurfaceFlingerPredictions = *predictions;
850 }
851 mSurfaceFlingerActuals.startTime = wakeUpTime;
852}
853
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800854void FrameTimeline::DisplayFrame::setPredictions(PredictionState predictionState,
855 TimelineItem predictions) {
856 mPredictionState = predictionState;
857 mSurfaceFlingerPredictions = predictions;
858}
859
860void FrameTimeline::DisplayFrame::setActualStartTime(nsecs_t actualStartTime) {
861 mSurfaceFlingerActuals.startTime = actualStartTime;
862}
863
864void FrameTimeline::DisplayFrame::setActualEndTime(nsecs_t actualEndTime) {
865 mSurfaceFlingerActuals.endTime = actualEndTime;
866}
867
Adithya Srinivasan36b01af2021-04-07 22:29:47 +0000868void FrameTimeline::DisplayFrame::setGpuFence(const std::shared_ptr<FenceTime>& gpuFence) {
869 mGpuFence = gpuFence;
Adithya Srinivasanb6a2fa12021-03-13 00:23:09 +0000870}
871
Adithya Srinivasan57dc81d2021-04-14 17:31:41 +0000872void FrameTimeline::DisplayFrame::classifyJank(nsecs_t& deadlineDelta, nsecs_t& deltaToVsync,
873 nsecs_t previousPresentTime) {
Adithya Srinivasan7c4ac7a2021-03-08 23:48:03 +0000874 if (mPredictionState == PredictionState::Expired ||
875 mSurfaceFlingerActuals.presentTime == Fence::SIGNAL_TIME_INVALID) {
Adithya Srinivasande272452021-04-10 00:21:00 +0000876 // Cannot do jank classification with expired predictions or invalid signal times. Set the
877 // deltas to 0 as both negative and positive deltas are used as real values.
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000878 mJankType = JankType::Unknown;
Adithya Srinivasande272452021-04-10 00:21:00 +0000879 deadlineDelta = 0;
880 deltaToVsync = 0;
Adithya Srinivasan061c14c2021-02-11 01:19:47 +0000881 return;
882 }
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800883
884 // Delta between the expected present and the actual present
885 const nsecs_t presentDelta =
886 mSurfaceFlingerActuals.presentTime - mSurfaceFlingerPredictions.presentTime;
Adithya Srinivasan36b01af2021-04-07 22:29:47 +0000887 // Sf actual end time represents the CPU end time. In case of HWC, SF's end time would have
888 // included the time for composition. However, for GPU composition, the final end time is max(sf
889 // end time, gpu fence time).
890 nsecs_t combinedEndTime = mSurfaceFlingerActuals.endTime;
891 if (mGpuFence != FenceTime::NO_FENCE) {
892 combinedEndTime = std::max(combinedEndTime, mGpuFence->getSignalTime());
893 }
894 deadlineDelta = combinedEndTime - mSurfaceFlingerPredictions.endTime;
Alec Mouri363faf02021-01-29 16:34:55 -0800895
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800896 // How far off was the presentDelta when compared to the vsyncPeriod. Used in checking if there
897 // was a prediction error or not.
Adithya Srinivasan115ac692021-03-06 01:21:30 +0000898 deltaToVsync = mRefreshRate.getPeriodNsecs() > 0
Alec Mouriadebf5c2021-01-05 12:57:36 -0800899 ? std::abs(presentDelta) % mRefreshRate.getPeriodNsecs()
900 : 0;
Adithya Srinivasan115ac692021-03-06 01:21:30 +0000901
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800902 if (std::abs(presentDelta) > mJankClassificationThresholds.presentThreshold) {
903 mFramePresentMetadata = presentDelta > 0 ? FramePresentMetadata::LatePresent
904 : FramePresentMetadata::EarlyPresent;
905 } else {
906 mFramePresentMetadata = FramePresentMetadata::OnTimePresent;
907 }
908
Adithya Srinivasan36b01af2021-04-07 22:29:47 +0000909 if (combinedEndTime > mSurfaceFlingerPredictions.endTime) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800910 mFrameReadyMetadata = FrameReadyMetadata::LateFinish;
911 } else {
912 mFrameReadyMetadata = FrameReadyMetadata::OnTimeFinish;
913 }
914
915 if (std::abs(mSurfaceFlingerActuals.startTime - mSurfaceFlingerPredictions.startTime) >
916 mJankClassificationThresholds.startThreshold) {
917 mFrameStartMetadata =
918 mSurfaceFlingerActuals.startTime > mSurfaceFlingerPredictions.startTime
919 ? FrameStartMetadata::LateStart
920 : FrameStartMetadata::EarlyStart;
921 }
922
923 if (mFramePresentMetadata != FramePresentMetadata::OnTimePresent) {
924 // Do jank classification only if present is not on time
925 if (mFramePresentMetadata == FramePresentMetadata::EarlyPresent) {
926 if (mFrameReadyMetadata == FrameReadyMetadata::OnTimeFinish) {
927 // Finish on time, Present early
928 if (deltaToVsync < mJankClassificationThresholds.presentThreshold ||
Alec Mouri7d436ec2021-01-27 20:40:50 -0800929 deltaToVsync >= (mRefreshRate.getPeriodNsecs() -
930 mJankClassificationThresholds.presentThreshold)) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800931 // Delta is a factor of vsync if its within the presentTheshold on either side
932 // of the vsyncPeriod. Example: 0-2ms and 9-11ms are both within the threshold
933 // of the vsyncPeriod if the threshold was 2ms and the vsyncPeriod was 11ms.
934 mJankType = JankType::SurfaceFlingerScheduling;
935 } else {
936 // Delta is not a factor of vsync,
937 mJankType = JankType::PredictionError;
938 }
939 } else if (mFrameReadyMetadata == FrameReadyMetadata::LateFinish) {
940 // Finish late, Present early
941 mJankType = JankType::SurfaceFlingerScheduling;
942 } else {
943 // Finish time unknown
944 mJankType = JankType::Unknown;
945 }
946 } else if (mFramePresentMetadata == FramePresentMetadata::LatePresent) {
Adithya Srinivasan57dc81d2021-04-14 17:31:41 +0000947 if (std::abs(mSurfaceFlingerPredictions.presentTime - previousPresentTime) <=
948 mJankClassificationThresholds.presentThreshold ||
949 previousPresentTime > mSurfaceFlingerPredictions.presentTime) {
950 // The previous frame was either presented in the current frame's expected vsync or
951 // it was presented even later than the current frame's expected vsync.
952 mJankType = JankType::SurfaceFlingerStuffing;
953 }
954 if (mFrameReadyMetadata == FrameReadyMetadata::OnTimeFinish &&
955 !(mJankType & JankType::SurfaceFlingerStuffing)) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800956 // Finish on time, Present late
957 if (deltaToVsync < mJankClassificationThresholds.presentThreshold ||
Alec Mouri7d436ec2021-01-27 20:40:50 -0800958 deltaToVsync >= (mRefreshRate.getPeriodNsecs() -
959 mJankClassificationThresholds.presentThreshold)) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800960 // Delta is a factor of vsync if its within the presentTheshold on either side
961 // of the vsyncPeriod. Example: 0-2ms and 9-11ms are both within the threshold
962 // of the vsyncPeriod if the threshold was 2ms and the vsyncPeriod was 11ms.
963 mJankType = JankType::DisplayHAL;
964 } else {
965 // Delta is not a factor of vsync
966 mJankType = JankType::PredictionError;
967 }
968 } else if (mFrameReadyMetadata == FrameReadyMetadata::LateFinish) {
Adithya Srinivasan57dc81d2021-04-14 17:31:41 +0000969 if (!(mJankType & JankType::SurfaceFlingerStuffing) ||
970 mSurfaceFlingerActuals.presentTime - previousPresentTime >
971 mRefreshRate.getPeriodNsecs() +
972 mJankClassificationThresholds.presentThreshold) {
973 // Classify CPU vs GPU if SF wasn't stuffed or if SF was stuffed but this frame
974 // was presented more than a vsync late.
Adithya Srinivasan36b01af2021-04-07 22:29:47 +0000975 if (mGpuFence != FenceTime::NO_FENCE &&
976 mSurfaceFlingerActuals.endTime - mSurfaceFlingerActuals.startTime <
977 mRefreshRate.getPeriodNsecs()) {
978 // If SF was in GPU composition and the CPU work finished before the vsync
979 // period, classify it as GPU deadline missed.
980 mJankType = JankType::SurfaceFlingerGpuDeadlineMissed;
981 } else {
982 mJankType = JankType::SurfaceFlingerCpuDeadlineMissed;
983 }
Adithya Srinivasan939cd4d2021-02-23 06:18:13 +0000984 }
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800985 } else {
986 // Finish time unknown
987 mJankType = JankType::Unknown;
988 }
989 } else {
990 // Present unknown
991 mJankType = JankType::Unknown;
992 }
993 }
Adithya Srinivasan115ac692021-03-06 01:21:30 +0000994}
995
Adithya Srinivasan57dc81d2021-04-14 17:31:41 +0000996void FrameTimeline::DisplayFrame::onPresent(nsecs_t signalTime, nsecs_t previousPresentTime) {
Adithya Srinivasan115ac692021-03-06 01:21:30 +0000997 mSurfaceFlingerActuals.presentTime = signalTime;
998 nsecs_t deadlineDelta = 0;
999 nsecs_t deltaToVsync = 0;
Adithya Srinivasan57dc81d2021-04-14 17:31:41 +00001000 classifyJank(deadlineDelta, deltaToVsync, previousPresentTime);
Adithya Srinivasan115ac692021-03-06 01:21:30 +00001001
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001002 for (auto& surfaceFrame : mSurfaceFrames) {
Alec Mouri363faf02021-01-29 16:34:55 -08001003 surfaceFrame->onPresent(signalTime, mJankType, mRefreshRate, deadlineDelta, deltaToVsync);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001004 }
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001005}
1006
Adithya Srinivasan061c14c2021-02-11 01:19:47 +00001007void FrameTimeline::DisplayFrame::tracePredictions(pid_t surfaceFlingerPid) const {
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +00001008 int64_t expectedTimelineCookie = mTraceCookieCounter.getCookieForTracing();
Adithya Srinivasan061c14c2021-02-11 01:19:47 +00001009
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +00001010 // Expected timeline start
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001011 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001012 auto packet = ctx.NewTracePacket();
1013 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +00001014 packet->set_timestamp(static_cast<uint64_t>(mSurfaceFlingerPredictions.startTime));
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001015
1016 auto* event = packet->set_frame_timeline_event();
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +00001017 auto* expectedDisplayFrameStartEvent = event->set_expected_display_frame_start();
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001018
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +00001019 expectedDisplayFrameStartEvent->set_cookie(expectedTimelineCookie);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001020
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +00001021 expectedDisplayFrameStartEvent->set_token(mToken);
1022 expectedDisplayFrameStartEvent->set_pid(surfaceFlingerPid);
1023 });
Adithya Srinivasan86678502021-01-19 21:50:38 +00001024
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +00001025 // Expected timeline end
1026 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
1027 auto packet = ctx.NewTracePacket();
1028 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
1029 packet->set_timestamp(static_cast<uint64_t>(mSurfaceFlingerPredictions.endTime));
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001030
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +00001031 auto* event = packet->set_frame_timeline_event();
1032 auto* expectedDisplayFrameEndEvent = event->set_frame_end();
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001033
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +00001034 expectedDisplayFrameEndEvent->set_cookie(expectedTimelineCookie);
1035 });
Adithya Srinivasan061c14c2021-02-11 01:19:47 +00001036}
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +00001037
Adithya Srinivasan061c14c2021-02-11 01:19:47 +00001038void FrameTimeline::DisplayFrame::traceActuals(pid_t surfaceFlingerPid) const {
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +00001039 int64_t actualTimelineCookie = mTraceCookieCounter.getCookieForTracing();
Adithya Srinivasan061c14c2021-02-11 01:19:47 +00001040
1041 // Actual timeline start
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +00001042 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
1043 auto packet = ctx.NewTracePacket();
1044 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
1045 packet->set_timestamp(static_cast<uint64_t>(mSurfaceFlingerActuals.startTime));
1046
1047 auto* event = packet->set_frame_timeline_event();
1048 auto* actualDisplayFrameStartEvent = event->set_actual_display_frame_start();
1049
1050 actualDisplayFrameStartEvent->set_cookie(actualTimelineCookie);
1051
1052 actualDisplayFrameStartEvent->set_token(mToken);
1053 actualDisplayFrameStartEvent->set_pid(surfaceFlingerPid);
1054
1055 actualDisplayFrameStartEvent->set_present_type(toProto(mFramePresentMetadata));
1056 actualDisplayFrameStartEvent->set_on_time_finish(mFrameReadyMetadata ==
1057 FrameReadyMetadata::OnTimeFinish);
Adithya Srinivasan36b01af2021-04-07 22:29:47 +00001058 actualDisplayFrameStartEvent->set_gpu_composition(mGpuFence != FenceTime::NO_FENCE);
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +00001059 actualDisplayFrameStartEvent->set_jank_type(jankTypeBitmaskToProto(mJankType));
Adithya Srinivasan78e58af2021-02-25 00:08:08 +00001060 actualDisplayFrameStartEvent->set_prediction_type(toProto(mPredictionState));
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +00001061 });
Adithya Srinivasan061c14c2021-02-11 01:19:47 +00001062
1063 // Actual timeline end
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +00001064 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
1065 auto packet = ctx.NewTracePacket();
1066 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
Adithya Srinivasan1a971632021-02-26 23:10:29 +00001067 packet->set_timestamp(static_cast<uint64_t>(mSurfaceFlingerActuals.presentTime));
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +00001068
1069 auto* event = packet->set_frame_timeline_event();
1070 auto* actualDisplayFrameEndEvent = event->set_frame_end();
1071
1072 actualDisplayFrameEndEvent->set_cookie(actualTimelineCookie);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001073 });
Adithya Srinivasan061c14c2021-02-11 01:19:47 +00001074}
1075
1076void FrameTimeline::DisplayFrame::trace(pid_t surfaceFlingerPid) const {
1077 if (mToken == FrameTimelineInfo::INVALID_VSYNC_ID) {
1078 // DisplayFrame should not have an invalid token.
1079 ALOGE("Cannot trace DisplayFrame with invalid token");
1080 return;
1081 }
1082
1083 if (mPredictionState == PredictionState::Valid) {
1084 // Expired and unknown predictions have zeroed timestamps. This cannot be used in any
1085 // meaningful way in a trace.
1086 tracePredictions(surfaceFlingerPid);
1087 }
1088 traceActuals(surfaceFlingerPid);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001089
1090 for (auto& surfaceFrame : mSurfaceFrames) {
1091 surfaceFrame->trace(mToken);
1092 }
1093}
1094
Alec Mouriadebf5c2021-01-05 12:57:36 -08001095float FrameTimeline::computeFps(const std::unordered_set<int32_t>& layerIds) {
1096 if (layerIds.empty()) {
1097 return 0.0f;
1098 }
1099
1100 std::vector<nsecs_t> presentTimes;
1101 {
1102 std::scoped_lock lock(mMutex);
1103 presentTimes.reserve(mDisplayFrames.size());
1104 for (size_t i = 0; i < mDisplayFrames.size(); i++) {
1105 const auto& displayFrame = mDisplayFrames[i];
1106 if (displayFrame->getActuals().presentTime <= 0) {
1107 continue;
1108 }
1109 for (const auto& surfaceFrame : displayFrame->getSurfaceFrames()) {
1110 if (surfaceFrame->getPresentState() == SurfaceFrame::PresentState::Presented &&
1111 layerIds.count(surfaceFrame->getLayerId()) > 0) {
1112 // We're looking for DisplayFrames that presents at least one layer from
1113 // layerIds, so push the present time and skip looking through the rest of the
1114 // SurfaceFrames.
1115 presentTimes.push_back(displayFrame->getActuals().presentTime);
1116 break;
1117 }
1118 }
1119 }
1120 }
1121
1122 // FPS can't be computed when there's fewer than 2 presented frames.
1123 if (presentTimes.size() <= 1) {
1124 return 0.0f;
1125 }
1126
1127 nsecs_t priorPresentTime = -1;
1128 nsecs_t totalPresentToPresentWalls = 0;
1129
1130 for (const nsecs_t presentTime : presentTimes) {
1131 if (priorPresentTime == -1) {
1132 priorPresentTime = presentTime;
1133 continue;
1134 }
1135
1136 totalPresentToPresentWalls += (presentTime - priorPresentTime);
1137 priorPresentTime = presentTime;
1138 }
1139
1140 if (CC_UNLIKELY(totalPresentToPresentWalls <= 0)) {
1141 ALOGW("Invalid total present-to-present duration when computing fps: %" PRId64,
1142 totalPresentToPresentWalls);
1143 return 0.0f;
1144 }
1145
1146 const constexpr nsecs_t kOneSecond =
1147 std::chrono::duration_cast<std::chrono::nanoseconds>(1s).count();
1148 // (10^9 nanoseconds / second) * (N present deltas) / (total nanoseconds in N present deltas) =
1149 // M frames / second
1150 return kOneSecond * static_cast<nsecs_t>((presentTimes.size() - 1)) /
1151 static_cast<float>(totalPresentToPresentWalls);
1152}
1153
Adithya Srinivasanf279e042020-08-17 14:56:27 -07001154void FrameTimeline::flushPendingPresentFences() {
1155 for (size_t i = 0; i < mPendingPresentFences.size(); i++) {
1156 const auto& pendingPresentFence = mPendingPresentFences[i];
1157 nsecs_t signalTime = Fence::SIGNAL_TIME_INVALID;
1158 if (pendingPresentFence.first && pendingPresentFence.first->isValid()) {
1159 signalTime = pendingPresentFence.first->getSignalTime();
1160 if (signalTime == Fence::SIGNAL_TIME_PENDING) {
1161 continue;
1162 }
1163 }
Adithya Srinivasan7c4ac7a2021-03-08 23:48:03 +00001164 auto& displayFrame = pendingPresentFence.second;
Adithya Srinivasan57dc81d2021-04-14 17:31:41 +00001165 displayFrame->onPresent(signalTime, mPreviousPresentTime);
Adithya Srinivasan7c4ac7a2021-03-08 23:48:03 +00001166 displayFrame->trace(mSurfaceFlingerPid);
Adithya Srinivasan57dc81d2021-04-14 17:31:41 +00001167 mPreviousPresentTime = signalTime;
Adithya Srinivasanf279e042020-08-17 14:56:27 -07001168
1169 mPendingPresentFences.erase(mPendingPresentFences.begin() + static_cast<int>(i));
1170 --i;
1171 }
1172}
1173
1174void FrameTimeline::finalizeCurrentDisplayFrame() {
Adithya Srinivasan2d736322020-10-01 16:53:48 -07001175 while (mDisplayFrames.size() >= mMaxDisplayFrames) {
Adithya Srinivasanf279e042020-08-17 14:56:27 -07001176 // We maintain only a fixed number of frames' data. Pop older frames
1177 mDisplayFrames.pop_front();
1178 }
1179 mDisplayFrames.push_back(mCurrentDisplayFrame);
1180 mCurrentDisplayFrame.reset();
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +00001181 mCurrentDisplayFrame = std::make_shared<DisplayFrame>(mTimeStats, mJankClassificationThresholds,
Adithya Srinivasan82eef322021-04-10 00:06:04 +00001182 &mTraceCookieCounter);
Adithya Srinivasanf279e042020-08-17 14:56:27 -07001183}
1184
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001185nsecs_t FrameTimeline::DisplayFrame::getBaseTime() const {
1186 nsecs_t baseTime =
1187 getMinTime(mPredictionState, mSurfaceFlingerPredictions, mSurfaceFlingerActuals);
1188 for (const auto& surfaceFrame : mSurfaceFrames) {
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -07001189 nsecs_t surfaceFrameBaseTime = surfaceFrame->getBaseTime();
1190 if (surfaceFrameBaseTime != 0) {
1191 baseTime = std::min(baseTime, surfaceFrameBaseTime);
1192 }
1193 }
1194 return baseTime;
1195}
1196
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001197void FrameTimeline::DisplayFrame::dumpJank(std::string& result, nsecs_t baseTime,
1198 int displayFrameCount) const {
1199 if (mJankType == JankType::None) {
1200 // Check if any Surface Frame has been janky
1201 bool isJanky = false;
1202 for (const auto& surfaceFrame : mSurfaceFrames) {
1203 if (surfaceFrame->getJankType() != JankType::None) {
1204 isJanky = true;
1205 break;
1206 }
1207 }
1208 if (!isJanky) {
1209 return;
1210 }
1211 }
1212 StringAppendF(&result, "Display Frame %d", displayFrameCount);
1213 dump(result, baseTime);
1214}
1215
1216void FrameTimeline::DisplayFrame::dumpAll(std::string& result, nsecs_t baseTime) const {
1217 dump(result, baseTime);
1218}
1219
1220void FrameTimeline::DisplayFrame::dump(std::string& result, nsecs_t baseTime) const {
1221 if (mJankType != JankType::None) {
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -07001222 // Easily identify a janky Display Frame in the dump
1223 StringAppendF(&result, " [*] ");
1224 }
1225 StringAppendF(&result, "\n");
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001226 StringAppendF(&result, "Prediction State : %s\n", toString(mPredictionState).c_str());
1227 StringAppendF(&result, "Jank Type : %s\n", jankTypeBitmaskToString(mJankType).c_str());
1228 StringAppendF(&result, "Present Metadata : %s\n", toString(mFramePresentMetadata).c_str());
1229 StringAppendF(&result, "Finish Metadata: %s\n", toString(mFrameReadyMetadata).c_str());
1230 StringAppendF(&result, "Start Metadata: %s\n", toString(mFrameStartMetadata).c_str());
Alec Mouri7d436ec2021-01-27 20:40:50 -08001231 std::chrono::nanoseconds vsyncPeriod(mRefreshRate.getPeriodNsecs());
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001232 StringAppendF(&result, "Vsync Period: %10f\n",
1233 std::chrono::duration<double, std::milli>(vsyncPeriod).count());
1234 nsecs_t presentDelta =
1235 mSurfaceFlingerActuals.presentTime - mSurfaceFlingerPredictions.presentTime;
1236 std::chrono::nanoseconds presentDeltaNs(std::abs(presentDelta));
1237 StringAppendF(&result, "Present delta: %10f\n",
1238 std::chrono::duration<double, std::milli>(presentDeltaNs).count());
Alec Mouri7d436ec2021-01-27 20:40:50 -08001239 std::chrono::nanoseconds deltaToVsync(std::abs(presentDelta) % mRefreshRate.getPeriodNsecs());
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001240 StringAppendF(&result, "Present delta %% refreshrate: %10f\n",
1241 std::chrono::duration<double, std::milli>(deltaToVsync).count());
1242 dumpTable(result, mSurfaceFlingerPredictions, mSurfaceFlingerActuals, "", mPredictionState,
1243 baseTime);
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -07001244 StringAppendF(&result, "\n");
1245 std::string indent = " "; // 4 spaces
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001246 for (const auto& surfaceFrame : mSurfaceFrames) {
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -07001247 surfaceFrame->dump(result, indent, baseTime);
1248 }
1249 StringAppendF(&result, "\n");
1250}
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001251
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -07001252void FrameTimeline::dumpAll(std::string& result) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -10001253 std::scoped_lock lock(mMutex);
Adithya Srinivasanf279e042020-08-17 14:56:27 -07001254 StringAppendF(&result, "Number of display frames : %d\n", (int)mDisplayFrames.size());
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001255 nsecs_t baseTime = (mDisplayFrames.empty()) ? 0 : mDisplayFrames[0]->getBaseTime();
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -07001256 for (size_t i = 0; i < mDisplayFrames.size(); i++) {
1257 StringAppendF(&result, "Display Frame %d", static_cast<int>(i));
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001258 mDisplayFrames[i]->dumpAll(result, baseTime);
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -07001259 }
1260}
1261
1262void FrameTimeline::dumpJank(std::string& result) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -10001263 std::scoped_lock lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001264 nsecs_t baseTime = (mDisplayFrames.empty()) ? 0 : mDisplayFrames[0]->getBaseTime();
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -07001265 for (size_t i = 0; i < mDisplayFrames.size(); i++) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001266 mDisplayFrames[i]->dumpJank(result, baseTime, static_cast<int>(i));
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -07001267 }
1268}
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001269
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -07001270void FrameTimeline::parseArgs(const Vector<String16>& args, std::string& result) {
1271 ATRACE_CALL();
1272 std::unordered_map<std::string, bool> argsMap;
1273 for (size_t i = 0; i < args.size(); i++) {
1274 argsMap[std::string(String8(args[i]).c_str())] = true;
1275 }
1276 if (argsMap.count("-jank")) {
1277 dumpJank(result);
1278 }
1279 if (argsMap.count("-all")) {
1280 dumpAll(result);
Adithya Srinivasanf279e042020-08-17 14:56:27 -07001281 }
1282}
1283
Adithya Srinivasan2d736322020-10-01 16:53:48 -07001284void FrameTimeline::setMaxDisplayFrames(uint32_t size) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -10001285 std::scoped_lock lock(mMutex);
Adithya Srinivasan2d736322020-10-01 16:53:48 -07001286
1287 // The size can either increase or decrease, clear everything, to be consistent
1288 mDisplayFrames.clear();
1289 mPendingPresentFences.clear();
1290 mMaxDisplayFrames = size;
1291}
1292
1293void FrameTimeline::reset() {
1294 setMaxDisplayFrames(kDefaultMaxDisplayFrames);
1295}
1296
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001297} // namespace impl
1298} // namespace android::frametimeline