blob: eb0c7244b368e67e7405930407515200ee5c88c7 [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"
22#include <android-base/stringprintf.h>
Ady Abraham7f8a1e62020-09-28 16:09:35 -070023#include <utils/Log.h>
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -070024#include <utils/Trace.h>
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -070025#include <chrono>
Adithya Srinivasanf279e042020-08-17 14:56:27 -070026#include <cinttypes>
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -070027#include <numeric>
Adithya Srinivasanf279e042020-08-17 14:56:27 -070028
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -080029namespace android::frametimeline {
Adithya Srinivasanf279e042020-08-17 14:56:27 -070030
31using base::StringAppendF;
Adithya Srinivasan01189672020-10-20 14:23:05 -070032using FrameTimelineEvent = perfetto::protos::pbzero::FrameTimelineEvent;
Adithya Srinivasanf279e042020-08-17 14:56:27 -070033
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -070034void dumpTable(std::string& result, TimelineItem predictions, TimelineItem actuals,
35 const std::string& indent, PredictionState predictionState, nsecs_t baseTime) {
36 StringAppendF(&result, "%s", indent.c_str());
37 StringAppendF(&result, "\t\t");
38 StringAppendF(&result, " Start time\t\t|");
39 StringAppendF(&result, " End time\t\t|");
40 StringAppendF(&result, " Present time\n");
41 if (predictionState == PredictionState::Valid) {
42 // Dump the Predictions only if they are valid
43 StringAppendF(&result, "%s", indent.c_str());
44 StringAppendF(&result, "Expected\t|");
45 std::chrono::nanoseconds startTime(predictions.startTime - baseTime);
46 std::chrono::nanoseconds endTime(predictions.endTime - baseTime);
47 std::chrono::nanoseconds presentTime(predictions.presentTime - baseTime);
48 StringAppendF(&result, "\t%10.2f\t|\t%10.2f\t|\t%10.2f\n",
49 std::chrono::duration<double, std::milli>(startTime).count(),
50 std::chrono::duration<double, std::milli>(endTime).count(),
51 std::chrono::duration<double, std::milli>(presentTime).count());
52 }
53 StringAppendF(&result, "%s", indent.c_str());
54 StringAppendF(&result, "Actual \t|");
55
56 if (actuals.startTime == 0) {
57 StringAppendF(&result, "\t\tN/A\t|");
58 } else {
59 std::chrono::nanoseconds startTime(std::max<nsecs_t>(0, actuals.startTime - baseTime));
60 StringAppendF(&result, "\t%10.2f\t|",
61 std::chrono::duration<double, std::milli>(startTime).count());
62 }
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -080063 if (actuals.endTime <= 0) {
64 // Animation leashes can send the endTime as -1
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -070065 StringAppendF(&result, "\t\tN/A\t|");
66 } else {
67 std::chrono::nanoseconds endTime(actuals.endTime - baseTime);
68 StringAppendF(&result, "\t%10.2f\t|",
69 std::chrono::duration<double, std::milli>(endTime).count());
70 }
71 if (actuals.presentTime == 0) {
72 StringAppendF(&result, "\t\tN/A\n");
73 } else {
74 std::chrono::nanoseconds presentTime(std::max<nsecs_t>(0, actuals.presentTime - baseTime));
75 StringAppendF(&result, "\t%10.2f\n",
76 std::chrono::duration<double, std::milli>(presentTime).count());
77 }
78
79 StringAppendF(&result, "%s", indent.c_str());
80 StringAppendF(&result, "----------------------");
81 StringAppendF(&result, "----------------------");
82 StringAppendF(&result, "----------------------");
83 StringAppendF(&result, "----------------------\n");
84}
85
86std::string toString(PredictionState predictionState) {
87 switch (predictionState) {
88 case PredictionState::Valid:
89 return "Valid";
90 case PredictionState::Expired:
91 return "Expired";
92 case PredictionState::None:
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -070093 return "None";
94 }
95}
96
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -080097std::string jankTypeBitmaskToString(int32_t jankType) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -080098 if (jankType == JankType::None) {
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -070099 return "None";
100 }
Adithya Srinivasan552e2a72021-01-15 03:21:53 +0000101
102 std::vector<std::string> janks;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800103 if (jankType & JankType::DisplayHAL) {
104 janks.emplace_back("Display HAL");
Adithya Srinivasan552e2a72021-01-15 03:21:53 +0000105 jankType &= ~JankType::DisplayHAL;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800106 }
107 if (jankType & JankType::SurfaceFlingerCpuDeadlineMissed) {
108 janks.emplace_back("SurfaceFlinger CPU Deadline Missed");
Adithya Srinivasan552e2a72021-01-15 03:21:53 +0000109 jankType &= ~JankType::SurfaceFlingerCpuDeadlineMissed;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800110 }
111 if (jankType & JankType::SurfaceFlingerGpuDeadlineMissed) {
112 janks.emplace_back("SurfaceFlinger GPU Deadline Missed");
Adithya Srinivasan552e2a72021-01-15 03:21:53 +0000113 jankType &= ~JankType::SurfaceFlingerGpuDeadlineMissed;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800114 }
115 if (jankType & JankType::AppDeadlineMissed) {
116 janks.emplace_back("App Deadline Missed");
Adithya Srinivasan552e2a72021-01-15 03:21:53 +0000117 jankType &= ~JankType::AppDeadlineMissed;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800118 }
119 if (jankType & JankType::PredictionError) {
120 janks.emplace_back("Prediction Error");
Adithya Srinivasan552e2a72021-01-15 03:21:53 +0000121 jankType &= ~JankType::PredictionError;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800122 }
123 if (jankType & JankType::SurfaceFlingerScheduling) {
124 janks.emplace_back("SurfaceFlinger Scheduling");
Adithya Srinivasan552e2a72021-01-15 03:21:53 +0000125 jankType &= ~JankType::SurfaceFlingerScheduling;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800126 }
127 if (jankType & JankType::BufferStuffing) {
128 janks.emplace_back("Buffer Stuffing");
Adithya Srinivasan552e2a72021-01-15 03:21:53 +0000129 jankType &= ~JankType::BufferStuffing;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800130 }
131 if (jankType & JankType::Unknown) {
132 janks.emplace_back("Unknown jank");
Adithya Srinivasan552e2a72021-01-15 03:21:53 +0000133 jankType &= ~JankType::Unknown;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800134 }
Adithya Srinivasan552e2a72021-01-15 03:21:53 +0000135
136 // jankType should be 0 if all types of jank were checked for.
137 LOG_ALWAYS_FATAL_IF(jankType != 0, "Unrecognized jank type value 0x%x", jankType);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800138 return std::accumulate(janks.begin(), janks.end(), std::string(),
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700139 [](const std::string& l, const std::string& r) {
140 return l.empty() ? r : l + ", " + r;
141 });
142}
143
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800144std::string toString(FramePresentMetadata presentMetadata) {
145 switch (presentMetadata) {
146 case FramePresentMetadata::OnTimePresent:
147 return "On Time Present";
148 case FramePresentMetadata::LatePresent:
149 return "Late Present";
150 case FramePresentMetadata::EarlyPresent:
151 return "Early Present";
152 case FramePresentMetadata::UnknownPresent:
153 return "Unknown Present";
Adithya Srinivasan01189672020-10-20 14:23:05 -0700154 }
Adithya Srinivasan01189672020-10-20 14:23:05 -0700155}
156
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800157std::string toString(FrameReadyMetadata finishMetadata) {
158 switch (finishMetadata) {
159 case FrameReadyMetadata::OnTimeFinish:
160 return "On Time Finish";
161 case FrameReadyMetadata::LateFinish:
162 return "Late Finish";
163 case FrameReadyMetadata::UnknownFinish:
164 return "Unknown Finish";
165 }
166}
167
168std::string toString(FrameStartMetadata startMetadata) {
169 switch (startMetadata) {
170 case FrameStartMetadata::OnTimeStart:
171 return "On Time Start";
172 case FrameStartMetadata::LateStart:
173 return "Late Start";
174 case FrameStartMetadata::EarlyStart:
175 return "Early Start";
176 case FrameStartMetadata::UnknownStart:
177 return "Unknown Start";
178 }
179}
180
181std::string toString(SurfaceFrame::PresentState presentState) {
182 using PresentState = SurfaceFrame::PresentState;
183 switch (presentState) {
184 case PresentState::Presented:
185 return "Presented";
186 case PresentState::Dropped:
187 return "Dropped";
188 case PresentState::Unknown:
189 return "Unknown";
190 }
191}
192
193FrameTimelineEvent::PresentType toProto(FramePresentMetadata presentMetadata) {
194 switch (presentMetadata) {
195 case FramePresentMetadata::EarlyPresent:
196 return FrameTimelineEvent::PRESENT_EARLY;
197 case FramePresentMetadata::LatePresent:
198 return FrameTimelineEvent::PRESENT_LATE;
199 case FramePresentMetadata::OnTimePresent:
200 return FrameTimelineEvent::PRESENT_ON_TIME;
201 case FramePresentMetadata::UnknownPresent:
202 return FrameTimelineEvent::PRESENT_UNSPECIFIED;
203 }
204}
205
Adithya Srinivasan552e2a72021-01-15 03:21:53 +0000206int32_t jankTypeBitmaskToProto(int32_t jankType) {
207 if (jankType == JankType::None) {
208 return FrameTimelineEvent::JANK_NONE;
Adithya Srinivasan01189672020-10-20 14:23:05 -0700209 }
Adithya Srinivasan552e2a72021-01-15 03:21:53 +0000210
211 int32_t protoJank = 0;
212 if (jankType & JankType::DisplayHAL) {
213 protoJank |= FrameTimelineEvent::JANK_DISPLAY_HAL;
214 jankType &= ~JankType::DisplayHAL;
215 }
216 if (jankType & JankType::SurfaceFlingerCpuDeadlineMissed) {
217 protoJank |= FrameTimelineEvent::JANK_SF_CPU_DEADLINE_MISSED;
218 jankType &= ~JankType::SurfaceFlingerCpuDeadlineMissed;
219 }
220 if (jankType & JankType::SurfaceFlingerGpuDeadlineMissed) {
221 protoJank |= FrameTimelineEvent::JANK_SF_GPU_DEADLINE_MISSED;
222 jankType &= ~JankType::SurfaceFlingerGpuDeadlineMissed;
223 }
224 if (jankType & JankType::AppDeadlineMissed) {
225 protoJank |= FrameTimelineEvent::JANK_APP_DEADLINE_MISSED;
226 jankType &= ~JankType::AppDeadlineMissed;
227 }
228 if (jankType & JankType::PredictionError) {
229 protoJank |= FrameTimelineEvent::JANK_PREDICTION_ERROR;
230 jankType &= ~JankType::PredictionError;
231 }
232 if (jankType & JankType::SurfaceFlingerScheduling) {
233 protoJank |= FrameTimelineEvent::JANK_SF_SCHEDULING;
234 jankType &= ~JankType::SurfaceFlingerScheduling;
235 }
236 if (jankType & JankType::BufferStuffing) {
237 protoJank |= FrameTimelineEvent::JANK_BUFFER_STUFFING;
238 jankType &= ~JankType::BufferStuffing;
239 }
240 if (jankType & JankType::Unknown) {
241 protoJank |= FrameTimelineEvent::JANK_UNKNOWN;
242 jankType &= ~JankType::Unknown;
243 }
244
245 // jankType should be 0 if all types of jank were checked for.
246 LOG_ALWAYS_FATAL_IF(jankType != 0, "Unrecognized jank type value 0x%x", jankType);
247 return protoJank;
Adithya Srinivasan01189672020-10-20 14:23:05 -0700248}
249
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800250// Returns the smallest timestamp from the set of predictions and actuals.
251nsecs_t getMinTime(PredictionState predictionState, TimelineItem predictions,
252 TimelineItem actuals) {
253 nsecs_t minTime = std::numeric_limits<nsecs_t>::max();
254 if (predictionState == PredictionState::Valid) {
255 // Checking start time for predictions is enough because start time is always lesser than
256 // endTime and presentTime.
257 minTime = std::min(minTime, predictions.startTime);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700258 }
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700259
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800260 // Need to check startTime, endTime and presentTime for actuals because some frames might not
261 // have them set.
262 if (actuals.startTime != 0) {
263 minTime = std::min(minTime, actuals.startTime);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700264 }
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800265 if (actuals.endTime != 0) {
266 minTime = std::min(minTime, actuals.endTime);
267 }
268 if (actuals.presentTime != 0) {
269 minTime = std::min(minTime, actuals.endTime);
270 }
271 return minTime;
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700272}
273
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000274int64_t TraceCookieCounter::getCookieForTracing() {
275 return ++mTraceCookie;
276}
277
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000278SurfaceFrame::SurfaceFrame(const FrameTimelineInfo& frameTimelineInfo, pid_t ownerPid,
279 uid_t ownerUid, std::string layerName, std::string debugName,
280 PredictionState predictionState,
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800281 frametimeline::TimelineItem&& predictions,
282 std::shared_ptr<TimeStats> timeStats,
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000283 JankClassificationThresholds thresholds,
284 TraceCookieCounter* traceCookieCounter)
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000285 : mToken(frameTimelineInfo.vsyncId),
286 mInputEventId(frameTimelineInfo.inputEventId),
Adithya Srinivasan01189672020-10-20 14:23:05 -0700287 mOwnerPid(ownerPid),
Adithya Srinivasan9febda82020-10-19 10:49:41 -0700288 mOwnerUid(ownerUid),
Alec Mouri9a29e672020-09-14 12:39:14 -0700289 mLayerName(std::move(layerName)),
290 mDebugName(std::move(debugName)),
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700291 mPresentState(PresentState::Unknown),
292 mPredictionState(predictionState),
293 mPredictions(predictions),
294 mActuals({0, 0, 0}),
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800295 mTimeStats(timeStats),
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000296 mJankClassificationThresholds(thresholds),
297 mTraceCookieCounter(*traceCookieCounter) {}
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700298
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -0700299void SurfaceFrame::setActualStartTime(nsecs_t actualStartTime) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000300 std::scoped_lock lock(mMutex);
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -0700301 mActuals.startTime = actualStartTime;
302}
303
304void SurfaceFrame::setActualQueueTime(nsecs_t actualQueueTime) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000305 std::scoped_lock lock(mMutex);
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -0700306 mActualQueueTime = actualQueueTime;
307}
Ady Abraham7f8a1e62020-09-28 16:09:35 -0700308void SurfaceFrame::setAcquireFenceTime(nsecs_t acquireFenceTime) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000309 std::scoped_lock lock(mMutex);
Ady Abraham7f8a1e62020-09-28 16:09:35 -0700310 mActuals.endTime = std::max(acquireFenceTime, mActualQueueTime);
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -0700311}
312
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800313void SurfaceFrame::setPresentState(PresentState presentState, nsecs_t lastLatchTime) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000314 std::scoped_lock lock(mMutex);
Adithya Srinivasanb9a7dab2021-01-14 23:49:46 +0000315 LOG_ALWAYS_FATAL_IF(mPresentState != PresentState::Unknown,
316 "setPresentState called on a SurfaceFrame from Layer - %s, that has a "
317 "PresentState - %s set already.",
318 mDebugName.c_str(), toString(mPresentState).c_str());
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800319 mPresentState = presentState;
320 mLastLatchTime = lastLatchTime;
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700321}
322
Alec Mouri7d436ec2021-01-27 20:40:50 -0800323void SurfaceFrame::setRenderRate(Fps renderRate) {
324 std::lock_guard<std::mutex> lock(mMutex);
325 mRenderRate = renderRate;
326}
327
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800328std::optional<int32_t> SurfaceFrame::getJankType() const {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000329 std::scoped_lock lock(mMutex);
Jorim Jaggi9c03b502020-11-24 23:51:31 +0100330 if (mActuals.presentTime == 0) {
331 return std::nullopt;
332 }
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700333 return mJankType;
334}
335
336nsecs_t SurfaceFrame::getBaseTime() const {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000337 std::scoped_lock lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800338 return getMinTime(mPredictionState, mPredictions, mActuals);
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700339}
340
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800341TimelineItem SurfaceFrame::getActuals() const {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000342 std::scoped_lock lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800343 return mActuals;
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700344}
345
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800346SurfaceFrame::PresentState SurfaceFrame::getPresentState() const {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000347 std::scoped_lock lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800348 return mPresentState;
349}
350
351FramePresentMetadata SurfaceFrame::getFramePresentMetadata() const {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000352 std::scoped_lock lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800353 return mFramePresentMetadata;
354}
355
356FrameReadyMetadata SurfaceFrame::getFrameReadyMetadata() const {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000357 std::scoped_lock lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800358 return mFrameReadyMetadata;
359}
360
361void SurfaceFrame::dump(std::string& result, const std::string& indent, nsecs_t baseTime) const {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000362 std::scoped_lock lock(mMutex);
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700363 StringAppendF(&result, "%s", indent.c_str());
Alec Mouri9a29e672020-09-14 12:39:14 -0700364 StringAppendF(&result, "Layer - %s", mDebugName.c_str());
Jorim Jaggi5814ab82020-12-03 20:45:58 +0100365 if (mJankType != JankType::None) {
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700366 // Easily identify a janky Surface Frame in the dump
367 StringAppendF(&result, " [*] ");
368 }
369 StringAppendF(&result, "\n");
370 StringAppendF(&result, "%s", indent.c_str());
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800371 StringAppendF(&result, "Token: %" PRId64 "\n", mToken);
372 StringAppendF(&result, "%s", indent.c_str());
Adithya Srinivasan9febda82020-10-19 10:49:41 -0700373 StringAppendF(&result, "Owner Pid : %d\n", mOwnerPid);
374 StringAppendF(&result, "%s", indent.c_str());
Alec Mouri7d436ec2021-01-27 20:40:50 -0800375 StringAppendF(&result, "Scheduled rendering rate: %d fps\n",
376 mRenderRate ? mRenderRate->getIntValue() : 0);
377 StringAppendF(&result, "%s", indent.c_str());
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800378 StringAppendF(&result, "Present State : %s\n", toString(mPresentState).c_str());
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700379 StringAppendF(&result, "%s", indent.c_str());
380 StringAppendF(&result, "Prediction State : %s\n", toString(mPredictionState).c_str());
381 StringAppendF(&result, "%s", indent.c_str());
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800382 StringAppendF(&result, "Jank Type : %s\n", jankTypeBitmaskToString(mJankType).c_str());
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700383 StringAppendF(&result, "%s", indent.c_str());
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800384 StringAppendF(&result, "Present Metadata : %s\n", toString(mFramePresentMetadata).c_str());
385 StringAppendF(&result, "%s", indent.c_str());
386 StringAppendF(&result, "Finish Metadata: %s\n", toString(mFrameReadyMetadata).c_str());
387 std::chrono::nanoseconds latchTime(
388 std::max(static_cast<int64_t>(0), mLastLatchTime - baseTime));
389 StringAppendF(&result, "%s", indent.c_str());
390 StringAppendF(&result, "Last latch time: %10f\n",
391 std::chrono::duration<double, std::milli>(latchTime).count());
392 if (mPredictionState == PredictionState::Valid) {
393 nsecs_t presentDelta = mActuals.presentTime - mPredictions.presentTime;
394 std::chrono::nanoseconds presentDeltaNs(std::abs(presentDelta));
395 StringAppendF(&result, "%s", indent.c_str());
396 StringAppendF(&result, "Present delta: %10f\n",
397 std::chrono::duration<double, std::milli>(presentDeltaNs).count());
398 }
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700399 dumpTable(result, mPredictions, mActuals, indent, mPredictionState, baseTime);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700400}
401
Alec Mouri363faf02021-01-29 16:34:55 -0800402void SurfaceFrame::onPresent(nsecs_t presentTime, int32_t displayFrameJankType, Fps refreshRate,
403 nsecs_t displayDeadlineDelta, nsecs_t displayPresentDelta) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000404 std::scoped_lock lock(mMutex);
Alec Mouri7d436ec2021-01-27 20:40:50 -0800405
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800406 if (mPresentState != PresentState::Presented) {
407 // No need to update dropped buffers
408 return;
409 }
410
411 mActuals.presentTime = presentTime;
412 // Jank Analysis for SurfaceFrame
413 if (mPredictionState == PredictionState::None) {
414 // Cannot do jank classification on frames that don't have a token.
415 return;
416 }
417 if (mPredictionState == PredictionState::Expired) {
418 // We do not know what happened here to classify this correctly. This could
419 // potentially be AppDeadlineMissed but that's assuming no app will request frames
420 // 120ms apart.
421 mJankType = JankType::Unknown;
422 mFramePresentMetadata = FramePresentMetadata::UnknownPresent;
423 mFrameReadyMetadata = FrameReadyMetadata::UnknownFinish;
Alec Mouri363faf02021-01-29 16:34:55 -0800424 const constexpr nsecs_t kAppDeadlineDelta = -1;
425 mTimeStats->incrementJankyFrames({refreshRate, mRenderRate, mOwnerUid, mLayerName,
426 mJankType, displayDeadlineDelta, displayPresentDelta,
427 kAppDeadlineDelta});
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800428 return;
429 }
430
431 const nsecs_t presentDelta = mActuals.presentTime - mPredictions.presentTime;
432 const nsecs_t deadlineDelta = mActuals.endTime - mPredictions.endTime;
Alec Mouri7d436ec2021-01-27 20:40:50 -0800433 const nsecs_t deltaToVsync = std::abs(presentDelta) % refreshRate.getPeriodNsecs();
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800434
435 if (deadlineDelta > mJankClassificationThresholds.deadlineThreshold) {
436 mFrameReadyMetadata = FrameReadyMetadata::LateFinish;
437 } else {
438 mFrameReadyMetadata = FrameReadyMetadata::OnTimeFinish;
439 }
440
441 if (std::abs(presentDelta) > mJankClassificationThresholds.presentThreshold) {
442 mFramePresentMetadata = presentDelta > 0 ? FramePresentMetadata::LatePresent
443 : FramePresentMetadata::EarlyPresent;
444 } else {
445 mFramePresentMetadata = FramePresentMetadata::OnTimePresent;
446 }
447
448 if (mFramePresentMetadata == FramePresentMetadata::OnTimePresent) {
449 // Frames presented on time are not janky.
450 mJankType = JankType::None;
451 } else if (mFramePresentMetadata == FramePresentMetadata::EarlyPresent) {
452 if (mFrameReadyMetadata == FrameReadyMetadata::OnTimeFinish) {
453 // Finish on time, Present early
454 if (deltaToVsync < mJankClassificationThresholds.presentThreshold ||
Alec Mouri7d436ec2021-01-27 20:40:50 -0800455 deltaToVsync >= refreshRate.getPeriodNsecs() -
456 mJankClassificationThresholds.presentThreshold) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800457 // Delta factor of vsync
458 mJankType = JankType::SurfaceFlingerScheduling;
459 } else {
460 // Delta not a factor of vsync
461 mJankType = JankType::PredictionError;
462 }
463 } else if (mFrameReadyMetadata == FrameReadyMetadata::LateFinish) {
464 // Finish late, Present early
465 mJankType = JankType::Unknown;
466 }
467 } else {
468 if (mLastLatchTime != 0 && mPredictions.endTime <= mLastLatchTime) {
469 // Buffer Stuffing.
470 mJankType |= JankType::BufferStuffing;
471 }
472 if (mFrameReadyMetadata == FrameReadyMetadata::OnTimeFinish) {
473 // Finish on time, Present late
474 if (displayFrameJankType != JankType::None) {
475 // Propagate displayFrame's jank if it exists
476 mJankType |= displayFrameJankType;
477 } else {
478 if (deltaToVsync < mJankClassificationThresholds.presentThreshold ||
Alec Mouri7d436ec2021-01-27 20:40:50 -0800479 deltaToVsync >= refreshRate.getPeriodNsecs() -
480 mJankClassificationThresholds.presentThreshold) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800481 // Delta factor of vsync
482 mJankType |= JankType::SurfaceFlingerScheduling;
483 } else {
484 // Delta not a factor of vsync
485 mJankType |= JankType::PredictionError;
486 }
487 }
488 } else if (mFrameReadyMetadata == FrameReadyMetadata::LateFinish) {
489 // Finish late, Present late
490 if (displayFrameJankType == JankType::None) {
491 // Display frame is not janky, so purely app's fault
492 mJankType |= JankType::AppDeadlineMissed;
493 } else {
494 // Propagate DisplayFrame's jankType if it is janky
495 mJankType |= displayFrameJankType;
496 }
497 }
498 }
Alec Mouri363faf02021-01-29 16:34:55 -0800499 mTimeStats->incrementJankyFrames({refreshRate, mRenderRate, mOwnerUid, mLayerName, mJankType,
500 displayDeadlineDelta, displayPresentDelta, deadlineDelta});
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800501}
502
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000503/**
504 * TODO(b/178637512): add inputEventId to the perfetto trace.
505 */
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800506void SurfaceFrame::trace(int64_t displayFrameToken) {
507 using FrameTimelineDataSource = impl::FrameTimeline::FrameTimelineDataSource;
Adithya Srinivasan86678502021-01-19 21:50:38 +0000508
509 int64_t expectedTimelineCookie = mTraceCookieCounter.getCookieForTracing();
510 bool missingToken = false;
511 // Expected timeline start
512 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000513 std::scoped_lock lock(mMutex);
514 if (mToken == FrameTimelineInfo::INVALID_VSYNC_ID) {
Adithya Srinivasan01189672020-10-20 14:23:05 -0700515 ALOGD("Cannot trace SurfaceFrame - %s with invalid token", mLayerName.c_str());
Adithya Srinivasan86678502021-01-19 21:50:38 +0000516 missingToken = true;
Adithya Srinivasan01189672020-10-20 14:23:05 -0700517 return;
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000518 } else if (displayFrameToken == FrameTimelineInfo::INVALID_VSYNC_ID) {
Adithya Srinivasan01189672020-10-20 14:23:05 -0700519 ALOGD("Cannot trace SurfaceFrame - %s with invalid displayFrameToken",
520 mLayerName.c_str());
Adithya Srinivasan86678502021-01-19 21:50:38 +0000521 missingToken = true;
Adithya Srinivasan01189672020-10-20 14:23:05 -0700522 return;
523 }
524 auto packet = ctx.NewTracePacket();
525 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000526 packet->set_timestamp(static_cast<uint64_t>(mPredictions.startTime));
Adithya Srinivasan01189672020-10-20 14:23:05 -0700527
528 auto* event = packet->set_frame_timeline_event();
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000529 auto* expectedSurfaceFrameStartEvent = event->set_expected_surface_frame_start();
Adithya Srinivasan01189672020-10-20 14:23:05 -0700530
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000531 expectedSurfaceFrameStartEvent->set_cookie(expectedTimelineCookie);
532
533 expectedSurfaceFrameStartEvent->set_token(mToken);
534 expectedSurfaceFrameStartEvent->set_display_frame_token(displayFrameToken);
535
536 expectedSurfaceFrameStartEvent->set_pid(mOwnerPid);
537 expectedSurfaceFrameStartEvent->set_layer_name(mDebugName);
538 });
Adithya Srinivasan86678502021-01-19 21:50:38 +0000539
540 if (missingToken) {
541 // If one packet can't be traced because of missing token, then no packets can be traced.
542 // Exit early in this case.
543 return;
544 }
545
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000546 // Expected timeline end
547 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000548 std::scoped_lock lock(mMutex);
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000549 auto packet = ctx.NewTracePacket();
550 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
551 packet->set_timestamp(static_cast<uint64_t>(mPredictions.endTime));
552
553 auto* event = packet->set_frame_timeline_event();
554 auto* expectedSurfaceFrameEndEvent = event->set_frame_end();
555
556 expectedSurfaceFrameEndEvent->set_cookie(expectedTimelineCookie);
557 });
558
559 int64_t actualTimelineCookie = mTraceCookieCounter.getCookieForTracing();
560 // Actual timeline start
561 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000562 std::scoped_lock lock(mMutex);
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000563 auto packet = ctx.NewTracePacket();
564 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
565 // Actual start time is not yet available, so use expected start instead
566 packet->set_timestamp(static_cast<uint64_t>(mPredictions.startTime));
567
568 auto* event = packet->set_frame_timeline_event();
569 auto* actualSurfaceFrameStartEvent = event->set_actual_surface_frame_start();
570
571 actualSurfaceFrameStartEvent->set_cookie(actualTimelineCookie);
572
573 actualSurfaceFrameStartEvent->set_token(mToken);
574 actualSurfaceFrameStartEvent->set_display_frame_token(displayFrameToken);
575
576 actualSurfaceFrameStartEvent->set_pid(mOwnerPid);
577 actualSurfaceFrameStartEvent->set_layer_name(mDebugName);
Adithya Srinivasan01189672020-10-20 14:23:05 -0700578
579 if (mPresentState == PresentState::Dropped) {
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000580 actualSurfaceFrameStartEvent->set_present_type(FrameTimelineEvent::PRESENT_DROPPED);
Adithya Srinivasan01189672020-10-20 14:23:05 -0700581 } else if (mPresentState == PresentState::Unknown) {
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000582 actualSurfaceFrameStartEvent->set_present_type(FrameTimelineEvent::PRESENT_UNSPECIFIED);
Adithya Srinivasan01189672020-10-20 14:23:05 -0700583 } else {
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000584 actualSurfaceFrameStartEvent->set_present_type(toProto(mFramePresentMetadata));
Adithya Srinivasan01189672020-10-20 14:23:05 -0700585 }
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000586 actualSurfaceFrameStartEvent->set_on_time_finish(mFrameReadyMetadata ==
587 FrameReadyMetadata::OnTimeFinish);
588 actualSurfaceFrameStartEvent->set_gpu_composition(mGpuComposition);
589 actualSurfaceFrameStartEvent->set_jank_type(jankTypeBitmaskToProto(mJankType));
590 });
591 // Actual timeline end
592 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000593 std::scoped_lock lock(mMutex);
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000594 auto packet = ctx.NewTracePacket();
595 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
596 packet->set_timestamp(static_cast<uint64_t>(mActuals.endTime));
Adithya Srinivasan01189672020-10-20 14:23:05 -0700597
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000598 auto* event = packet->set_frame_timeline_event();
599 auto* actualSurfaceFrameEndEvent = event->set_frame_end();
Adithya Srinivasan01189672020-10-20 14:23:05 -0700600
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000601 actualSurfaceFrameEndEvent->set_cookie(actualTimelineCookie);
Adithya Srinivasan01189672020-10-20 14:23:05 -0700602 });
603}
604
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800605namespace impl {
606
607int64_t TokenManager::generateTokenForPredictions(TimelineItem&& predictions) {
608 ATRACE_CALL();
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000609 std::scoped_lock lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800610 const int64_t assignedToken = mCurrentToken++;
611 mPredictions[assignedToken] = {systemTime(), predictions};
612 flushTokens(systemTime());
613 return assignedToken;
614}
615
616std::optional<TimelineItem> TokenManager::getPredictionsForToken(int64_t token) const {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000617 std::scoped_lock lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800618 auto predictionsIterator = mPredictions.find(token);
619 if (predictionsIterator != mPredictions.end()) {
620 return predictionsIterator->second.predictions;
621 }
622 return {};
623}
624
625void TokenManager::flushTokens(nsecs_t flushTime) {
626 for (auto it = mPredictions.begin(); it != mPredictions.end();) {
627 if (flushTime - it->second.timestamp >= kMaxRetentionTime) {
628 it = mPredictions.erase(it);
629 } else {
630 // Tokens are ordered by time. If i'th token is within the retention time, then the
631 // i+1'th token will also be within retention time.
632 break;
633 }
634 }
635}
636
637FrameTimeline::FrameTimeline(std::shared_ptr<TimeStats> timeStats, pid_t surfaceFlingerPid,
638 JankClassificationThresholds thresholds)
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000639 : mMaxDisplayFrames(kDefaultMaxDisplayFrames),
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800640 mTimeStats(std::move(timeStats)),
641 mSurfaceFlingerPid(surfaceFlingerPid),
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000642 mJankClassificationThresholds(thresholds) {
643 mCurrentDisplayFrame =
644 std::make_shared<DisplayFrame>(mTimeStats, thresholds, &mTraceCookieCounter);
645}
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700646
Adithya Srinivasan01189672020-10-20 14:23:05 -0700647void FrameTimeline::onBootFinished() {
648 perfetto::TracingInitArgs args;
649 args.backends = perfetto::kSystemBackend;
650 perfetto::Tracing::Initialize(args);
651 registerDataSource();
652}
653
654void FrameTimeline::registerDataSource() {
655 perfetto::DataSourceDescriptor dsd;
656 dsd.set_name(kFrameTimelineDataSource);
657 FrameTimelineDataSource::Register(dsd);
658}
659
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800660std::shared_ptr<SurfaceFrame> FrameTimeline::createSurfaceFrameForToken(
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000661 const FrameTimelineInfo& frameTimelineInfo, pid_t ownerPid, uid_t ownerUid,
662 std::string layerName, std::string debugName) {
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -0700663 ATRACE_CALL();
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000664 if (frameTimelineInfo.vsyncId == FrameTimelineInfo::INVALID_VSYNC_ID) {
665 return std::make_shared<SurfaceFrame>(frameTimelineInfo, ownerPid, ownerUid,
666 std::move(layerName), std::move(debugName),
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800667 PredictionState::None, TimelineItem(), mTimeStats,
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000668 mJankClassificationThresholds, &mTraceCookieCounter);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700669 }
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000670 std::optional<TimelineItem> predictions =
671 mTokenManager.getPredictionsForToken(frameTimelineInfo.vsyncId);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700672 if (predictions) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000673 return std::make_shared<SurfaceFrame>(frameTimelineInfo, ownerPid, ownerUid,
674 std::move(layerName), std::move(debugName),
675 PredictionState::Valid, std::move(*predictions),
676 mTimeStats, mJankClassificationThresholds,
677 &mTraceCookieCounter);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700678 }
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000679 return std::make_shared<SurfaceFrame>(frameTimelineInfo, ownerPid, ownerUid,
680 std::move(layerName), std::move(debugName),
681 PredictionState::Expired, TimelineItem(), mTimeStats,
682 mJankClassificationThresholds, &mTraceCookieCounter);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700683}
684
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800685FrameTimeline::DisplayFrame::DisplayFrame(std::shared_ptr<TimeStats> timeStats,
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000686 JankClassificationThresholds thresholds,
687 TraceCookieCounter* traceCookieCounter)
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800688 : mSurfaceFlingerPredictions(TimelineItem()),
689 mSurfaceFlingerActuals(TimelineItem()),
690 mTimeStats(timeStats),
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000691 mJankClassificationThresholds(thresholds),
692 mTraceCookieCounter(*traceCookieCounter) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800693 mSurfaceFrames.reserve(kNumSurfaceFramesInitial);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700694}
695
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800696void FrameTimeline::addSurfaceFrame(std::shared_ptr<SurfaceFrame> surfaceFrame) {
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -0700697 ATRACE_CALL();
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000698 std::scoped_lock lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800699 mCurrentDisplayFrame->addSurfaceFrame(surfaceFrame);
700}
701
Alec Mouri7d436ec2021-01-27 20:40:50 -0800702void FrameTimeline::setSfWakeUp(int64_t token, nsecs_t wakeUpTime, Fps refreshRate) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800703 ATRACE_CALL();
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000704 std::scoped_lock lock(mMutex);
Alec Mouri7d436ec2021-01-27 20:40:50 -0800705 mCurrentDisplayFrame->onSfWakeUp(token, refreshRate,
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800706 mTokenManager.getPredictionsForToken(token), wakeUpTime);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700707}
708
709void FrameTimeline::setSfPresent(nsecs_t sfPresentTime,
710 const std::shared_ptr<FenceTime>& presentFence) {
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -0700711 ATRACE_CALL();
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000712 std::scoped_lock lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800713 mCurrentDisplayFrame->setActualEndTime(sfPresentTime);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700714 mPendingPresentFences.emplace_back(std::make_pair(presentFence, mCurrentDisplayFrame));
715 flushPendingPresentFences();
716 finalizeCurrentDisplayFrame();
717}
718
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800719void FrameTimeline::DisplayFrame::addSurfaceFrame(std::shared_ptr<SurfaceFrame> surfaceFrame) {
720 mSurfaceFrames.push_back(surfaceFrame);
721}
722
Alec Mouri7d436ec2021-01-27 20:40:50 -0800723void FrameTimeline::DisplayFrame::onSfWakeUp(int64_t token, Fps refreshRate,
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800724 std::optional<TimelineItem> predictions,
725 nsecs_t wakeUpTime) {
726 mToken = token;
Alec Mouri7d436ec2021-01-27 20:40:50 -0800727 mRefreshRate = refreshRate;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800728 if (!predictions) {
729 mPredictionState = PredictionState::Expired;
730 } else {
731 mPredictionState = PredictionState::Valid;
732 mSurfaceFlingerPredictions = *predictions;
733 }
734 mSurfaceFlingerActuals.startTime = wakeUpTime;
735}
736
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800737void FrameTimeline::DisplayFrame::setPredictions(PredictionState predictionState,
738 TimelineItem predictions) {
739 mPredictionState = predictionState;
740 mSurfaceFlingerPredictions = predictions;
741}
742
743void FrameTimeline::DisplayFrame::setActualStartTime(nsecs_t actualStartTime) {
744 mSurfaceFlingerActuals.startTime = actualStartTime;
745}
746
747void FrameTimeline::DisplayFrame::setActualEndTime(nsecs_t actualEndTime) {
748 mSurfaceFlingerActuals.endTime = actualEndTime;
749}
750
751void FrameTimeline::DisplayFrame::onPresent(nsecs_t signalTime) {
752 mSurfaceFlingerActuals.presentTime = signalTime;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800753
754 // Delta between the expected present and the actual present
755 const nsecs_t presentDelta =
756 mSurfaceFlingerActuals.presentTime - mSurfaceFlingerPredictions.presentTime;
Alec Mouri363faf02021-01-29 16:34:55 -0800757 const nsecs_t deadlineDelta =
758 mSurfaceFlingerActuals.endTime - mSurfaceFlingerPredictions.endTime;
759
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800760 // How far off was the presentDelta when compared to the vsyncPeriod. Used in checking if there
761 // was a prediction error or not.
Alec Mouri7d436ec2021-01-27 20:40:50 -0800762 nsecs_t deltaToVsync = std::abs(presentDelta) % mRefreshRate.getPeriodNsecs();
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800763 if (std::abs(presentDelta) > mJankClassificationThresholds.presentThreshold) {
764 mFramePresentMetadata = presentDelta > 0 ? FramePresentMetadata::LatePresent
765 : FramePresentMetadata::EarlyPresent;
766 } else {
767 mFramePresentMetadata = FramePresentMetadata::OnTimePresent;
768 }
769
770 if (mSurfaceFlingerActuals.endTime - mSurfaceFlingerPredictions.endTime >
771 mJankClassificationThresholds.deadlineThreshold) {
772 mFrameReadyMetadata = FrameReadyMetadata::LateFinish;
773 } else {
774 mFrameReadyMetadata = FrameReadyMetadata::OnTimeFinish;
775 }
776
777 if (std::abs(mSurfaceFlingerActuals.startTime - mSurfaceFlingerPredictions.startTime) >
778 mJankClassificationThresholds.startThreshold) {
779 mFrameStartMetadata =
780 mSurfaceFlingerActuals.startTime > mSurfaceFlingerPredictions.startTime
781 ? FrameStartMetadata::LateStart
782 : FrameStartMetadata::EarlyStart;
783 }
784
785 if (mFramePresentMetadata != FramePresentMetadata::OnTimePresent) {
786 // Do jank classification only if present is not on time
787 if (mFramePresentMetadata == FramePresentMetadata::EarlyPresent) {
788 if (mFrameReadyMetadata == FrameReadyMetadata::OnTimeFinish) {
789 // Finish on time, Present early
790 if (deltaToVsync < mJankClassificationThresholds.presentThreshold ||
Alec Mouri7d436ec2021-01-27 20:40:50 -0800791 deltaToVsync >= (mRefreshRate.getPeriodNsecs() -
792 mJankClassificationThresholds.presentThreshold)) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800793 // Delta is a factor of vsync if its within the presentTheshold on either side
794 // of the vsyncPeriod. Example: 0-2ms and 9-11ms are both within the threshold
795 // of the vsyncPeriod if the threshold was 2ms and the vsyncPeriod was 11ms.
796 mJankType = JankType::SurfaceFlingerScheduling;
797 } else {
798 // Delta is not a factor of vsync,
799 mJankType = JankType::PredictionError;
800 }
801 } else if (mFrameReadyMetadata == FrameReadyMetadata::LateFinish) {
802 // Finish late, Present early
803 mJankType = JankType::SurfaceFlingerScheduling;
804 } else {
805 // Finish time unknown
806 mJankType = JankType::Unknown;
807 }
808 } else if (mFramePresentMetadata == FramePresentMetadata::LatePresent) {
809 if (mFrameReadyMetadata == FrameReadyMetadata::OnTimeFinish) {
810 // Finish on time, Present late
811 if (deltaToVsync < mJankClassificationThresholds.presentThreshold ||
Alec Mouri7d436ec2021-01-27 20:40:50 -0800812 deltaToVsync >= (mRefreshRate.getPeriodNsecs() -
813 mJankClassificationThresholds.presentThreshold)) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800814 // Delta is a factor of vsync if its within the presentTheshold on either side
815 // of the vsyncPeriod. Example: 0-2ms and 9-11ms are both within the threshold
816 // of the vsyncPeriod if the threshold was 2ms and the vsyncPeriod was 11ms.
817 mJankType = JankType::DisplayHAL;
818 } else {
819 // Delta is not a factor of vsync
820 mJankType = JankType::PredictionError;
821 }
822 } else if (mFrameReadyMetadata == FrameReadyMetadata::LateFinish) {
823 // Finish late, Present late
824 mJankType = JankType::SurfaceFlingerCpuDeadlineMissed;
825 } else {
826 // Finish time unknown
827 mJankType = JankType::Unknown;
828 }
829 } else {
830 // Present unknown
831 mJankType = JankType::Unknown;
832 }
833 }
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800834 for (auto& surfaceFrame : mSurfaceFrames) {
Alec Mouri363faf02021-01-29 16:34:55 -0800835 surfaceFrame->onPresent(signalTime, mJankType, mRefreshRate, deadlineDelta, deltaToVsync);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800836 }
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800837}
838
839void FrameTimeline::DisplayFrame::trace(pid_t surfaceFlingerPid) const {
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000840 int64_t expectedTimelineCookie = mTraceCookieCounter.getCookieForTracing();
Adithya Srinivasan86678502021-01-19 21:50:38 +0000841 bool missingToken = false;
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000842 // Expected timeline start
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800843 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800844 auto packet = ctx.NewTracePacket();
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -1000845 if (mToken == FrameTimelineInfo::INVALID_VSYNC_ID) {
Adithya Srinivasan86678502021-01-19 21:50:38 +0000846 ALOGD("Cannot trace DisplayFrame with invalid token");
847 missingToken = true;
848 return;
849 }
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800850 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000851 packet->set_timestamp(static_cast<uint64_t>(mSurfaceFlingerPredictions.startTime));
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800852
853 auto* event = packet->set_frame_timeline_event();
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000854 auto* expectedDisplayFrameStartEvent = event->set_expected_display_frame_start();
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800855
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000856 expectedDisplayFrameStartEvent->set_cookie(expectedTimelineCookie);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800857
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000858 expectedDisplayFrameStartEvent->set_token(mToken);
859 expectedDisplayFrameStartEvent->set_pid(surfaceFlingerPid);
860 });
Adithya Srinivasan86678502021-01-19 21:50:38 +0000861
862 if (missingToken) {
863 // If one packet can't be traced because of missing token, then no packets can be traced.
864 // Exit early in this case.
865 return;
866 }
867
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000868 // Expected timeline end
869 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
870 auto packet = ctx.NewTracePacket();
871 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
872 packet->set_timestamp(static_cast<uint64_t>(mSurfaceFlingerPredictions.endTime));
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800873
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000874 auto* event = packet->set_frame_timeline_event();
875 auto* expectedDisplayFrameEndEvent = event->set_frame_end();
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800876
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000877 expectedDisplayFrameEndEvent->set_cookie(expectedTimelineCookie);
878 });
879
880 int64_t actualTimelineCookie = mTraceCookieCounter.getCookieForTracing();
881 // Expected timeline start
882 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
883 auto packet = ctx.NewTracePacket();
884 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
885 packet->set_timestamp(static_cast<uint64_t>(mSurfaceFlingerActuals.startTime));
886
887 auto* event = packet->set_frame_timeline_event();
888 auto* actualDisplayFrameStartEvent = event->set_actual_display_frame_start();
889
890 actualDisplayFrameStartEvent->set_cookie(actualTimelineCookie);
891
892 actualDisplayFrameStartEvent->set_token(mToken);
893 actualDisplayFrameStartEvent->set_pid(surfaceFlingerPid);
894
895 actualDisplayFrameStartEvent->set_present_type(toProto(mFramePresentMetadata));
896 actualDisplayFrameStartEvent->set_on_time_finish(mFrameReadyMetadata ==
897 FrameReadyMetadata::OnTimeFinish);
898 actualDisplayFrameStartEvent->set_gpu_composition(mGpuComposition);
899 actualDisplayFrameStartEvent->set_jank_type(jankTypeBitmaskToProto(mJankType));
900 });
901 // Expected timeline end
902 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
903 auto packet = ctx.NewTracePacket();
904 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
905 packet->set_timestamp(static_cast<uint64_t>(mSurfaceFlingerActuals.endTime));
906
907 auto* event = packet->set_frame_timeline_event();
908 auto* actualDisplayFrameEndEvent = event->set_frame_end();
909
910 actualDisplayFrameEndEvent->set_cookie(actualTimelineCookie);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800911 });
912
913 for (auto& surfaceFrame : mSurfaceFrames) {
914 surfaceFrame->trace(mToken);
915 }
916}
917
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700918void FrameTimeline::flushPendingPresentFences() {
919 for (size_t i = 0; i < mPendingPresentFences.size(); i++) {
920 const auto& pendingPresentFence = mPendingPresentFences[i];
921 nsecs_t signalTime = Fence::SIGNAL_TIME_INVALID;
922 if (pendingPresentFence.first && pendingPresentFence.first->isValid()) {
923 signalTime = pendingPresentFence.first->getSignalTime();
924 if (signalTime == Fence::SIGNAL_TIME_PENDING) {
925 continue;
926 }
927 }
928 if (signalTime != Fence::SIGNAL_TIME_INVALID) {
929 auto& displayFrame = pendingPresentFence.second;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800930 displayFrame->onPresent(signalTime);
931 displayFrame->trace(mSurfaceFlingerPid);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700932 }
933
934 mPendingPresentFences.erase(mPendingPresentFences.begin() + static_cast<int>(i));
935 --i;
936 }
937}
938
939void FrameTimeline::finalizeCurrentDisplayFrame() {
Adithya Srinivasan2d736322020-10-01 16:53:48 -0700940 while (mDisplayFrames.size() >= mMaxDisplayFrames) {
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700941 // We maintain only a fixed number of frames' data. Pop older frames
942 mDisplayFrames.pop_front();
943 }
944 mDisplayFrames.push_back(mCurrentDisplayFrame);
945 mCurrentDisplayFrame.reset();
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000946 mCurrentDisplayFrame = std::make_shared<DisplayFrame>(mTimeStats, mJankClassificationThresholds,
947 &mTraceCookieCounter);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700948}
949
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800950nsecs_t FrameTimeline::DisplayFrame::getBaseTime() const {
951 nsecs_t baseTime =
952 getMinTime(mPredictionState, mSurfaceFlingerPredictions, mSurfaceFlingerActuals);
953 for (const auto& surfaceFrame : mSurfaceFrames) {
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700954 nsecs_t surfaceFrameBaseTime = surfaceFrame->getBaseTime();
955 if (surfaceFrameBaseTime != 0) {
956 baseTime = std::min(baseTime, surfaceFrameBaseTime);
957 }
958 }
959 return baseTime;
960}
961
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800962void FrameTimeline::DisplayFrame::dumpJank(std::string& result, nsecs_t baseTime,
963 int displayFrameCount) const {
964 if (mJankType == JankType::None) {
965 // Check if any Surface Frame has been janky
966 bool isJanky = false;
967 for (const auto& surfaceFrame : mSurfaceFrames) {
968 if (surfaceFrame->getJankType() != JankType::None) {
969 isJanky = true;
970 break;
971 }
972 }
973 if (!isJanky) {
974 return;
975 }
976 }
977 StringAppendF(&result, "Display Frame %d", displayFrameCount);
978 dump(result, baseTime);
979}
980
981void FrameTimeline::DisplayFrame::dumpAll(std::string& result, nsecs_t baseTime) const {
982 dump(result, baseTime);
983}
984
985void FrameTimeline::DisplayFrame::dump(std::string& result, nsecs_t baseTime) const {
986 if (mJankType != JankType::None) {
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700987 // Easily identify a janky Display Frame in the dump
988 StringAppendF(&result, " [*] ");
989 }
990 StringAppendF(&result, "\n");
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800991 StringAppendF(&result, "Prediction State : %s\n", toString(mPredictionState).c_str());
992 StringAppendF(&result, "Jank Type : %s\n", jankTypeBitmaskToString(mJankType).c_str());
993 StringAppendF(&result, "Present Metadata : %s\n", toString(mFramePresentMetadata).c_str());
994 StringAppendF(&result, "Finish Metadata: %s\n", toString(mFrameReadyMetadata).c_str());
995 StringAppendF(&result, "Start Metadata: %s\n", toString(mFrameStartMetadata).c_str());
Alec Mouri7d436ec2021-01-27 20:40:50 -0800996 std::chrono::nanoseconds vsyncPeriod(mRefreshRate.getPeriodNsecs());
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800997 StringAppendF(&result, "Vsync Period: %10f\n",
998 std::chrono::duration<double, std::milli>(vsyncPeriod).count());
999 nsecs_t presentDelta =
1000 mSurfaceFlingerActuals.presentTime - mSurfaceFlingerPredictions.presentTime;
1001 std::chrono::nanoseconds presentDeltaNs(std::abs(presentDelta));
1002 StringAppendF(&result, "Present delta: %10f\n",
1003 std::chrono::duration<double, std::milli>(presentDeltaNs).count());
Alec Mouri7d436ec2021-01-27 20:40:50 -08001004 std::chrono::nanoseconds deltaToVsync(std::abs(presentDelta) % mRefreshRate.getPeriodNsecs());
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001005 StringAppendF(&result, "Present delta %% refreshrate: %10f\n",
1006 std::chrono::duration<double, std::milli>(deltaToVsync).count());
1007 dumpTable(result, mSurfaceFlingerPredictions, mSurfaceFlingerActuals, "", mPredictionState,
1008 baseTime);
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -07001009 StringAppendF(&result, "\n");
1010 std::string indent = " "; // 4 spaces
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001011 for (const auto& surfaceFrame : mSurfaceFrames) {
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -07001012 surfaceFrame->dump(result, indent, baseTime);
1013 }
1014 StringAppendF(&result, "\n");
1015}
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001016
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -07001017void FrameTimeline::dumpAll(std::string& result) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -10001018 std::scoped_lock lock(mMutex);
Adithya Srinivasanf279e042020-08-17 14:56:27 -07001019 StringAppendF(&result, "Number of display frames : %d\n", (int)mDisplayFrames.size());
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001020 nsecs_t baseTime = (mDisplayFrames.empty()) ? 0 : mDisplayFrames[0]->getBaseTime();
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -07001021 for (size_t i = 0; i < mDisplayFrames.size(); i++) {
1022 StringAppendF(&result, "Display Frame %d", static_cast<int>(i));
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001023 mDisplayFrames[i]->dumpAll(result, baseTime);
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -07001024 }
1025}
1026
1027void FrameTimeline::dumpJank(std::string& result) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -10001028 std::scoped_lock lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001029 nsecs_t baseTime = (mDisplayFrames.empty()) ? 0 : mDisplayFrames[0]->getBaseTime();
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -07001030 for (size_t i = 0; i < mDisplayFrames.size(); i++) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001031 mDisplayFrames[i]->dumpJank(result, baseTime, static_cast<int>(i));
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -07001032 }
1033}
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001034
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -07001035void FrameTimeline::parseArgs(const Vector<String16>& args, std::string& result) {
1036 ATRACE_CALL();
1037 std::unordered_map<std::string, bool> argsMap;
1038 for (size_t i = 0; i < args.size(); i++) {
1039 argsMap[std::string(String8(args[i]).c_str())] = true;
1040 }
1041 if (argsMap.count("-jank")) {
1042 dumpJank(result);
1043 }
1044 if (argsMap.count("-all")) {
1045 dumpAll(result);
Adithya Srinivasanf279e042020-08-17 14:56:27 -07001046 }
1047}
1048
Adithya Srinivasan2d736322020-10-01 16:53:48 -07001049void FrameTimeline::setMaxDisplayFrames(uint32_t size) {
Siarhei Vishniakoufc434ac2021-01-13 10:28:00 -10001050 std::scoped_lock lock(mMutex);
Adithya Srinivasan2d736322020-10-01 16:53:48 -07001051
1052 // The size can either increase or decrease, clear everything, to be consistent
1053 mDisplayFrames.clear();
1054 mPendingPresentFences.clear();
1055 mMaxDisplayFrames = size;
1056}
1057
1058void FrameTimeline::reset() {
1059 setMaxDisplayFrames(kDefaultMaxDisplayFrames);
1060}
1061
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001062} // namespace impl
1063} // namespace android::frametimeline