blob: 17d1f3bff7ab50e171a3bda81f2505d4bf7adefc [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
Adithya Srinivasan01189672020-10-20 14:23:05 -0700278SurfaceFrame::SurfaceFrame(int64_t token, pid_t ownerPid, uid_t ownerUid, std::string layerName,
Adithya Srinivasan9febda82020-10-19 10:49:41 -0700279 std::string debugName, PredictionState predictionState,
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800280 frametimeline::TimelineItem&& predictions,
281 std::shared_ptr<TimeStats> timeStats,
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000282 JankClassificationThresholds thresholds,
283 TraceCookieCounter* traceCookieCounter)
Adithya Srinivasan01189672020-10-20 14:23:05 -0700284 : mToken(token),
285 mOwnerPid(ownerPid),
Adithya Srinivasan9febda82020-10-19 10:49:41 -0700286 mOwnerUid(ownerUid),
Alec Mouri9a29e672020-09-14 12:39:14 -0700287 mLayerName(std::move(layerName)),
288 mDebugName(std::move(debugName)),
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700289 mPresentState(PresentState::Unknown),
290 mPredictionState(predictionState),
291 mPredictions(predictions),
292 mActuals({0, 0, 0}),
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800293 mTimeStats(timeStats),
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000294 mJankClassificationThresholds(thresholds),
295 mTraceCookieCounter(*traceCookieCounter) {}
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700296
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -0700297void SurfaceFrame::setActualStartTime(nsecs_t actualStartTime) {
298 std::lock_guard<std::mutex> lock(mMutex);
299 mActuals.startTime = actualStartTime;
300}
301
302void SurfaceFrame::setActualQueueTime(nsecs_t actualQueueTime) {
303 std::lock_guard<std::mutex> lock(mMutex);
304 mActualQueueTime = actualQueueTime;
305}
Ady Abraham7f8a1e62020-09-28 16:09:35 -0700306void SurfaceFrame::setAcquireFenceTime(nsecs_t acquireFenceTime) {
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -0700307 std::lock_guard<std::mutex> lock(mMutex);
Ady Abraham7f8a1e62020-09-28 16:09:35 -0700308 mActuals.endTime = std::max(acquireFenceTime, mActualQueueTime);
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -0700309}
310
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800311void SurfaceFrame::setPresentState(PresentState presentState, nsecs_t lastLatchTime) {
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700312 std::lock_guard<std::mutex> lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800313 mPresentState = presentState;
314 mLastLatchTime = lastLatchTime;
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700315}
316
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800317std::optional<int32_t> SurfaceFrame::getJankType() const {
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700318 std::lock_guard<std::mutex> lock(mMutex);
Jorim Jaggi9c03b502020-11-24 23:51:31 +0100319 if (mActuals.presentTime == 0) {
320 return std::nullopt;
321 }
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700322 return mJankType;
323}
324
325nsecs_t SurfaceFrame::getBaseTime() const {
326 std::lock_guard<std::mutex> lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800327 return getMinTime(mPredictionState, mPredictions, mActuals);
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700328}
329
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800330TimelineItem SurfaceFrame::getActuals() const {
331 std::lock_guard<std::mutex> lock(mMutex);
332 return mActuals;
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700333}
334
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800335SurfaceFrame::PresentState SurfaceFrame::getPresentState() const {
336 std::lock_guard<std::mutex> lock(mMutex);
337 return mPresentState;
338}
339
340FramePresentMetadata SurfaceFrame::getFramePresentMetadata() const {
341 std::lock_guard<std::mutex> lock(mMutex);
342 return mFramePresentMetadata;
343}
344
345FrameReadyMetadata SurfaceFrame::getFrameReadyMetadata() const {
346 std::lock_guard<std::mutex> lock(mMutex);
347 return mFrameReadyMetadata;
348}
349
350void SurfaceFrame::dump(std::string& result, const std::string& indent, nsecs_t baseTime) const {
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700351 std::lock_guard<std::mutex> lock(mMutex);
352 StringAppendF(&result, "%s", indent.c_str());
Alec Mouri9a29e672020-09-14 12:39:14 -0700353 StringAppendF(&result, "Layer - %s", mDebugName.c_str());
Jorim Jaggi5814ab82020-12-03 20:45:58 +0100354 if (mJankType != JankType::None) {
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700355 // Easily identify a janky Surface Frame in the dump
356 StringAppendF(&result, " [*] ");
357 }
358 StringAppendF(&result, "\n");
359 StringAppendF(&result, "%s", indent.c_str());
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800360 StringAppendF(&result, "Token: %" PRId64 "\n", mToken);
361 StringAppendF(&result, "%s", indent.c_str());
Adithya Srinivasan9febda82020-10-19 10:49:41 -0700362 StringAppendF(&result, "Owner Pid : %d\n", mOwnerPid);
363 StringAppendF(&result, "%s", indent.c_str());
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800364 StringAppendF(&result, "Present State : %s\n", toString(mPresentState).c_str());
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700365 StringAppendF(&result, "%s", indent.c_str());
366 StringAppendF(&result, "Prediction State : %s\n", toString(mPredictionState).c_str());
367 StringAppendF(&result, "%s", indent.c_str());
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800368 StringAppendF(&result, "Jank Type : %s\n", jankTypeBitmaskToString(mJankType).c_str());
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700369 StringAppendF(&result, "%s", indent.c_str());
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800370 StringAppendF(&result, "Present Metadata : %s\n", toString(mFramePresentMetadata).c_str());
371 StringAppendF(&result, "%s", indent.c_str());
372 StringAppendF(&result, "Finish Metadata: %s\n", toString(mFrameReadyMetadata).c_str());
373 std::chrono::nanoseconds latchTime(
374 std::max(static_cast<int64_t>(0), mLastLatchTime - baseTime));
375 StringAppendF(&result, "%s", indent.c_str());
376 StringAppendF(&result, "Last latch time: %10f\n",
377 std::chrono::duration<double, std::milli>(latchTime).count());
378 if (mPredictionState == PredictionState::Valid) {
379 nsecs_t presentDelta = mActuals.presentTime - mPredictions.presentTime;
380 std::chrono::nanoseconds presentDeltaNs(std::abs(presentDelta));
381 StringAppendF(&result, "%s", indent.c_str());
382 StringAppendF(&result, "Present delta: %10f\n",
383 std::chrono::duration<double, std::milli>(presentDeltaNs).count());
384 }
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700385 dumpTable(result, mPredictions, mActuals, indent, mPredictionState, baseTime);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700386}
387
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800388void SurfaceFrame::onPresent(nsecs_t presentTime, int32_t displayFrameJankType,
389 nsecs_t vsyncPeriod) {
390 std::lock_guard<std::mutex> lock(mMutex);
391 if (mPresentState != PresentState::Presented) {
392 // No need to update dropped buffers
393 return;
394 }
395
396 mActuals.presentTime = presentTime;
397 // Jank Analysis for SurfaceFrame
398 if (mPredictionState == PredictionState::None) {
399 // Cannot do jank classification on frames that don't have a token.
400 return;
401 }
402 if (mPredictionState == PredictionState::Expired) {
403 // We do not know what happened here to classify this correctly. This could
404 // potentially be AppDeadlineMissed but that's assuming no app will request frames
405 // 120ms apart.
406 mJankType = JankType::Unknown;
407 mFramePresentMetadata = FramePresentMetadata::UnknownPresent;
408 mFrameReadyMetadata = FrameReadyMetadata::UnknownFinish;
409 mTimeStats->incrementJankyFrames(mOwnerUid, mLayerName, mJankType);
410 return;
411 }
412
413 const nsecs_t presentDelta = mActuals.presentTime - mPredictions.presentTime;
414 const nsecs_t deadlineDelta = mActuals.endTime - mPredictions.endTime;
415 const nsecs_t deltaToVsync = std::abs(presentDelta) % vsyncPeriod;
416
417 if (deadlineDelta > mJankClassificationThresholds.deadlineThreshold) {
418 mFrameReadyMetadata = FrameReadyMetadata::LateFinish;
419 } else {
420 mFrameReadyMetadata = FrameReadyMetadata::OnTimeFinish;
421 }
422
423 if (std::abs(presentDelta) > mJankClassificationThresholds.presentThreshold) {
424 mFramePresentMetadata = presentDelta > 0 ? FramePresentMetadata::LatePresent
425 : FramePresentMetadata::EarlyPresent;
426 } else {
427 mFramePresentMetadata = FramePresentMetadata::OnTimePresent;
428 }
429
430 if (mFramePresentMetadata == FramePresentMetadata::OnTimePresent) {
431 // Frames presented on time are not janky.
432 mJankType = JankType::None;
433 } else if (mFramePresentMetadata == FramePresentMetadata::EarlyPresent) {
434 if (mFrameReadyMetadata == FrameReadyMetadata::OnTimeFinish) {
435 // Finish on time, Present early
436 if (deltaToVsync < mJankClassificationThresholds.presentThreshold ||
437 deltaToVsync >= vsyncPeriod - mJankClassificationThresholds.presentThreshold) {
438 // Delta factor of vsync
439 mJankType = JankType::SurfaceFlingerScheduling;
440 } else {
441 // Delta not a factor of vsync
442 mJankType = JankType::PredictionError;
443 }
444 } else if (mFrameReadyMetadata == FrameReadyMetadata::LateFinish) {
445 // Finish late, Present early
446 mJankType = JankType::Unknown;
447 }
448 } else {
449 if (mLastLatchTime != 0 && mPredictions.endTime <= mLastLatchTime) {
450 // Buffer Stuffing.
451 mJankType |= JankType::BufferStuffing;
452 }
453 if (mFrameReadyMetadata == FrameReadyMetadata::OnTimeFinish) {
454 // Finish on time, Present late
455 if (displayFrameJankType != JankType::None) {
456 // Propagate displayFrame's jank if it exists
457 mJankType |= displayFrameJankType;
458 } else {
459 if (deltaToVsync < mJankClassificationThresholds.presentThreshold ||
460 deltaToVsync >= vsyncPeriod - mJankClassificationThresholds.presentThreshold) {
461 // Delta factor of vsync
462 mJankType |= JankType::SurfaceFlingerScheduling;
463 } else {
464 // Delta not a factor of vsync
465 mJankType |= JankType::PredictionError;
466 }
467 }
468 } else if (mFrameReadyMetadata == FrameReadyMetadata::LateFinish) {
469 // Finish late, Present late
470 if (displayFrameJankType == JankType::None) {
471 // Display frame is not janky, so purely app's fault
472 mJankType |= JankType::AppDeadlineMissed;
473 } else {
474 // Propagate DisplayFrame's jankType if it is janky
475 mJankType |= displayFrameJankType;
476 }
477 }
478 }
479 mTimeStats->incrementJankyFrames(mOwnerUid, mLayerName, mJankType);
480}
481
482void SurfaceFrame::trace(int64_t displayFrameToken) {
483 using FrameTimelineDataSource = impl::FrameTimeline::FrameTimelineDataSource;
Adithya Srinivasan86678502021-01-19 21:50:38 +0000484
485 int64_t expectedTimelineCookie = mTraceCookieCounter.getCookieForTracing();
486 bool missingToken = false;
487 // Expected timeline start
488 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
Adithya Srinivasan01189672020-10-20 14:23:05 -0700489 std::lock_guard<std::mutex> lock(mMutex);
490 if (mToken == ISurfaceComposer::INVALID_VSYNC_ID) {
491 ALOGD("Cannot trace SurfaceFrame - %s with invalid token", mLayerName.c_str());
Adithya Srinivasan86678502021-01-19 21:50:38 +0000492 missingToken = true;
Adithya Srinivasan01189672020-10-20 14:23:05 -0700493 return;
494 } else if (displayFrameToken == ISurfaceComposer::INVALID_VSYNC_ID) {
495 ALOGD("Cannot trace SurfaceFrame - %s with invalid displayFrameToken",
496 mLayerName.c_str());
Adithya Srinivasan86678502021-01-19 21:50:38 +0000497 missingToken = true;
Adithya Srinivasan01189672020-10-20 14:23:05 -0700498 return;
499 }
500 auto packet = ctx.NewTracePacket();
501 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000502 packet->set_timestamp(static_cast<uint64_t>(mPredictions.startTime));
Adithya Srinivasan01189672020-10-20 14:23:05 -0700503
504 auto* event = packet->set_frame_timeline_event();
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000505 auto* expectedSurfaceFrameStartEvent = event->set_expected_surface_frame_start();
Adithya Srinivasan01189672020-10-20 14:23:05 -0700506
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000507 expectedSurfaceFrameStartEvent->set_cookie(expectedTimelineCookie);
508
509 expectedSurfaceFrameStartEvent->set_token(mToken);
510 expectedSurfaceFrameStartEvent->set_display_frame_token(displayFrameToken);
511
512 expectedSurfaceFrameStartEvent->set_pid(mOwnerPid);
513 expectedSurfaceFrameStartEvent->set_layer_name(mDebugName);
514 });
Adithya Srinivasan86678502021-01-19 21:50:38 +0000515
516 if (missingToken) {
517 // If one packet can't be traced because of missing token, then no packets can be traced.
518 // Exit early in this case.
519 return;
520 }
521
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000522 // Expected timeline end
523 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
524 std::lock_guard<std::mutex> lock(mMutex);
525 auto packet = ctx.NewTracePacket();
526 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
527 packet->set_timestamp(static_cast<uint64_t>(mPredictions.endTime));
528
529 auto* event = packet->set_frame_timeline_event();
530 auto* expectedSurfaceFrameEndEvent = event->set_frame_end();
531
532 expectedSurfaceFrameEndEvent->set_cookie(expectedTimelineCookie);
533 });
534
535 int64_t actualTimelineCookie = mTraceCookieCounter.getCookieForTracing();
536 // Actual timeline start
537 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
538 std::lock_guard<std::mutex> lock(mMutex);
539 auto packet = ctx.NewTracePacket();
540 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
541 // Actual start time is not yet available, so use expected start instead
542 packet->set_timestamp(static_cast<uint64_t>(mPredictions.startTime));
543
544 auto* event = packet->set_frame_timeline_event();
545 auto* actualSurfaceFrameStartEvent = event->set_actual_surface_frame_start();
546
547 actualSurfaceFrameStartEvent->set_cookie(actualTimelineCookie);
548
549 actualSurfaceFrameStartEvent->set_token(mToken);
550 actualSurfaceFrameStartEvent->set_display_frame_token(displayFrameToken);
551
552 actualSurfaceFrameStartEvent->set_pid(mOwnerPid);
553 actualSurfaceFrameStartEvent->set_layer_name(mDebugName);
Adithya Srinivasan01189672020-10-20 14:23:05 -0700554
555 if (mPresentState == PresentState::Dropped) {
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000556 actualSurfaceFrameStartEvent->set_present_type(FrameTimelineEvent::PRESENT_DROPPED);
Adithya Srinivasan01189672020-10-20 14:23:05 -0700557 } else if (mPresentState == PresentState::Unknown) {
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000558 actualSurfaceFrameStartEvent->set_present_type(FrameTimelineEvent::PRESENT_UNSPECIFIED);
Adithya Srinivasan01189672020-10-20 14:23:05 -0700559 } else {
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000560 actualSurfaceFrameStartEvent->set_present_type(toProto(mFramePresentMetadata));
Adithya Srinivasan01189672020-10-20 14:23:05 -0700561 }
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000562 actualSurfaceFrameStartEvent->set_on_time_finish(mFrameReadyMetadata ==
563 FrameReadyMetadata::OnTimeFinish);
564 actualSurfaceFrameStartEvent->set_gpu_composition(mGpuComposition);
565 actualSurfaceFrameStartEvent->set_jank_type(jankTypeBitmaskToProto(mJankType));
566 });
567 // Actual timeline end
568 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
569 std::lock_guard<std::mutex> lock(mMutex);
570 auto packet = ctx.NewTracePacket();
571 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
572 packet->set_timestamp(static_cast<uint64_t>(mActuals.endTime));
Adithya Srinivasan01189672020-10-20 14:23:05 -0700573
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000574 auto* event = packet->set_frame_timeline_event();
575 auto* actualSurfaceFrameEndEvent = event->set_frame_end();
Adithya Srinivasan01189672020-10-20 14:23:05 -0700576
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000577 actualSurfaceFrameEndEvent->set_cookie(actualTimelineCookie);
Adithya Srinivasan01189672020-10-20 14:23:05 -0700578 });
579}
580
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800581namespace impl {
582
583int64_t TokenManager::generateTokenForPredictions(TimelineItem&& predictions) {
584 ATRACE_CALL();
585 std::lock_guard<std::mutex> lock(mMutex);
586 const int64_t assignedToken = mCurrentToken++;
587 mPredictions[assignedToken] = {systemTime(), predictions};
588 flushTokens(systemTime());
589 return assignedToken;
590}
591
592std::optional<TimelineItem> TokenManager::getPredictionsForToken(int64_t token) const {
593 std::lock_guard<std::mutex> lock(mMutex);
594 auto predictionsIterator = mPredictions.find(token);
595 if (predictionsIterator != mPredictions.end()) {
596 return predictionsIterator->second.predictions;
597 }
598 return {};
599}
600
601void TokenManager::flushTokens(nsecs_t flushTime) {
602 for (auto it = mPredictions.begin(); it != mPredictions.end();) {
603 if (flushTime - it->second.timestamp >= kMaxRetentionTime) {
604 it = mPredictions.erase(it);
605 } else {
606 // Tokens are ordered by time. If i'th token is within the retention time, then the
607 // i+1'th token will also be within retention time.
608 break;
609 }
610 }
611}
612
613FrameTimeline::FrameTimeline(std::shared_ptr<TimeStats> timeStats, pid_t surfaceFlingerPid,
614 JankClassificationThresholds thresholds)
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000615 : mMaxDisplayFrames(kDefaultMaxDisplayFrames),
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800616 mTimeStats(std::move(timeStats)),
617 mSurfaceFlingerPid(surfaceFlingerPid),
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000618 mJankClassificationThresholds(thresholds) {
619 mCurrentDisplayFrame =
620 std::make_shared<DisplayFrame>(mTimeStats, thresholds, &mTraceCookieCounter);
621}
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700622
Adithya Srinivasan01189672020-10-20 14:23:05 -0700623void FrameTimeline::onBootFinished() {
624 perfetto::TracingInitArgs args;
625 args.backends = perfetto::kSystemBackend;
626 perfetto::Tracing::Initialize(args);
627 registerDataSource();
628}
629
630void FrameTimeline::registerDataSource() {
631 perfetto::DataSourceDescriptor dsd;
632 dsd.set_name(kFrameTimelineDataSource);
633 FrameTimelineDataSource::Register(dsd);
634}
635
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800636std::shared_ptr<SurfaceFrame> FrameTimeline::createSurfaceFrameForToken(
637 std::optional<int64_t> token, pid_t ownerPid, uid_t ownerUid, std::string layerName,
638 std::string debugName) {
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -0700639 ATRACE_CALL();
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700640 if (!token) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800641 return std::make_shared<SurfaceFrame>(ISurfaceComposer::INVALID_VSYNC_ID, ownerPid,
642 ownerUid, std::move(layerName), std::move(debugName),
643 PredictionState::None, TimelineItem(), mTimeStats,
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000644 mJankClassificationThresholds, &mTraceCookieCounter);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700645 }
646 std::optional<TimelineItem> predictions = mTokenManager.getPredictionsForToken(*token);
647 if (predictions) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800648 return std::make_shared<SurfaceFrame>(*token, ownerPid, ownerUid, std::move(layerName),
649 std::move(debugName), PredictionState::Valid,
650 std::move(*predictions), mTimeStats,
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000651 mJankClassificationThresholds, &mTraceCookieCounter);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700652 }
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800653 return std::make_shared<SurfaceFrame>(*token, ownerPid, ownerUid, std::move(layerName),
654 std::move(debugName), PredictionState::Expired,
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000655 TimelineItem(), mTimeStats, mJankClassificationThresholds,
656 &mTraceCookieCounter);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700657}
658
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800659FrameTimeline::DisplayFrame::DisplayFrame(std::shared_ptr<TimeStats> timeStats,
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000660 JankClassificationThresholds thresholds,
661 TraceCookieCounter* traceCookieCounter)
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800662 : mSurfaceFlingerPredictions(TimelineItem()),
663 mSurfaceFlingerActuals(TimelineItem()),
664 mTimeStats(timeStats),
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000665 mJankClassificationThresholds(thresholds),
666 mTraceCookieCounter(*traceCookieCounter) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800667 mSurfaceFrames.reserve(kNumSurfaceFramesInitial);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700668}
669
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800670void FrameTimeline::addSurfaceFrame(std::shared_ptr<SurfaceFrame> surfaceFrame) {
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -0700671 ATRACE_CALL();
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700672 std::lock_guard<std::mutex> lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800673 mCurrentDisplayFrame->addSurfaceFrame(surfaceFrame);
674}
675
676void FrameTimeline::setSfWakeUp(int64_t token, nsecs_t wakeUpTime, nsecs_t vsyncPeriod) {
677 ATRACE_CALL();
678 std::lock_guard<std::mutex> lock(mMutex);
679 mCurrentDisplayFrame->onSfWakeUp(token, vsyncPeriod,
680 mTokenManager.getPredictionsForToken(token), wakeUpTime);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700681}
682
683void FrameTimeline::setSfPresent(nsecs_t sfPresentTime,
684 const std::shared_ptr<FenceTime>& presentFence) {
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -0700685 ATRACE_CALL();
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700686 std::lock_guard<std::mutex> lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800687 mCurrentDisplayFrame->setActualEndTime(sfPresentTime);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700688 mPendingPresentFences.emplace_back(std::make_pair(presentFence, mCurrentDisplayFrame));
689 flushPendingPresentFences();
690 finalizeCurrentDisplayFrame();
691}
692
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800693void FrameTimeline::DisplayFrame::addSurfaceFrame(std::shared_ptr<SurfaceFrame> surfaceFrame) {
694 mSurfaceFrames.push_back(surfaceFrame);
695}
696
697void FrameTimeline::DisplayFrame::onSfWakeUp(int64_t token, nsecs_t vsyncPeriod,
698 std::optional<TimelineItem> predictions,
699 nsecs_t wakeUpTime) {
700 mToken = token;
701 mVsyncPeriod = vsyncPeriod;
702 if (!predictions) {
703 mPredictionState = PredictionState::Expired;
704 } else {
705 mPredictionState = PredictionState::Valid;
706 mSurfaceFlingerPredictions = *predictions;
707 }
708 mSurfaceFlingerActuals.startTime = wakeUpTime;
709}
710
711void FrameTimeline::DisplayFrame::setTokenAndVsyncPeriod(int64_t token, nsecs_t vsyncPeriod) {
712 mToken = token;
713 mVsyncPeriod = vsyncPeriod;
714}
715
716void FrameTimeline::DisplayFrame::setPredictions(PredictionState predictionState,
717 TimelineItem predictions) {
718 mPredictionState = predictionState;
719 mSurfaceFlingerPredictions = predictions;
720}
721
722void FrameTimeline::DisplayFrame::setActualStartTime(nsecs_t actualStartTime) {
723 mSurfaceFlingerActuals.startTime = actualStartTime;
724}
725
726void FrameTimeline::DisplayFrame::setActualEndTime(nsecs_t actualEndTime) {
727 mSurfaceFlingerActuals.endTime = actualEndTime;
728}
729
730void FrameTimeline::DisplayFrame::onPresent(nsecs_t signalTime) {
731 mSurfaceFlingerActuals.presentTime = signalTime;
732 int32_t totalJankReasons = JankType::None;
733
734 // Delta between the expected present and the actual present
735 const nsecs_t presentDelta =
736 mSurfaceFlingerActuals.presentTime - mSurfaceFlingerPredictions.presentTime;
737 // How far off was the presentDelta when compared to the vsyncPeriod. Used in checking if there
738 // was a prediction error or not.
739 nsecs_t deltaToVsync = std::abs(presentDelta) % mVsyncPeriod;
740 if (std::abs(presentDelta) > mJankClassificationThresholds.presentThreshold) {
741 mFramePresentMetadata = presentDelta > 0 ? FramePresentMetadata::LatePresent
742 : FramePresentMetadata::EarlyPresent;
743 } else {
744 mFramePresentMetadata = FramePresentMetadata::OnTimePresent;
745 }
746
747 if (mSurfaceFlingerActuals.endTime - mSurfaceFlingerPredictions.endTime >
748 mJankClassificationThresholds.deadlineThreshold) {
749 mFrameReadyMetadata = FrameReadyMetadata::LateFinish;
750 } else {
751 mFrameReadyMetadata = FrameReadyMetadata::OnTimeFinish;
752 }
753
754 if (std::abs(mSurfaceFlingerActuals.startTime - mSurfaceFlingerPredictions.startTime) >
755 mJankClassificationThresholds.startThreshold) {
756 mFrameStartMetadata =
757 mSurfaceFlingerActuals.startTime > mSurfaceFlingerPredictions.startTime
758 ? FrameStartMetadata::LateStart
759 : FrameStartMetadata::EarlyStart;
760 }
761
762 if (mFramePresentMetadata != FramePresentMetadata::OnTimePresent) {
763 // Do jank classification only if present is not on time
764 if (mFramePresentMetadata == FramePresentMetadata::EarlyPresent) {
765 if (mFrameReadyMetadata == FrameReadyMetadata::OnTimeFinish) {
766 // Finish on time, Present early
767 if (deltaToVsync < mJankClassificationThresholds.presentThreshold ||
768 deltaToVsync >=
769 (mVsyncPeriod - mJankClassificationThresholds.presentThreshold)) {
770 // Delta is a factor of vsync if its within the presentTheshold on either side
771 // of the vsyncPeriod. Example: 0-2ms and 9-11ms are both within the threshold
772 // of the vsyncPeriod if the threshold was 2ms and the vsyncPeriod was 11ms.
773 mJankType = JankType::SurfaceFlingerScheduling;
774 } else {
775 // Delta is not a factor of vsync,
776 mJankType = JankType::PredictionError;
777 }
778 } else if (mFrameReadyMetadata == FrameReadyMetadata::LateFinish) {
779 // Finish late, Present early
780 mJankType = JankType::SurfaceFlingerScheduling;
781 } else {
782 // Finish time unknown
783 mJankType = JankType::Unknown;
784 }
785 } else if (mFramePresentMetadata == FramePresentMetadata::LatePresent) {
786 if (mFrameReadyMetadata == FrameReadyMetadata::OnTimeFinish) {
787 // Finish on time, Present late
788 if (deltaToVsync < mJankClassificationThresholds.presentThreshold ||
789 deltaToVsync >=
790 (mVsyncPeriod - mJankClassificationThresholds.presentThreshold)) {
791 // Delta is a factor of vsync if its within the presentTheshold on either side
792 // of the vsyncPeriod. Example: 0-2ms and 9-11ms are both within the threshold
793 // of the vsyncPeriod if the threshold was 2ms and the vsyncPeriod was 11ms.
794 mJankType = JankType::DisplayHAL;
795 } else {
796 // Delta is not a factor of vsync
797 mJankType = JankType::PredictionError;
798 }
799 } else if (mFrameReadyMetadata == FrameReadyMetadata::LateFinish) {
800 // Finish late, Present late
801 mJankType = JankType::SurfaceFlingerCpuDeadlineMissed;
802 } else {
803 // Finish time unknown
804 mJankType = JankType::Unknown;
805 }
806 } else {
807 // Present unknown
808 mJankType = JankType::Unknown;
809 }
810 }
811 totalJankReasons |= mJankType;
812
813 for (auto& surfaceFrame : mSurfaceFrames) {
814 surfaceFrame->onPresent(signalTime, mJankType, mVsyncPeriod);
815 auto surfaceFrameJankType = surfaceFrame->getJankType();
816 if (surfaceFrameJankType != std::nullopt) {
817 totalJankReasons |= *surfaceFrameJankType;
818 }
819 }
820 mTimeStats->incrementJankyFrames(totalJankReasons);
821}
822
823void FrameTimeline::DisplayFrame::trace(pid_t surfaceFlingerPid) const {
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000824 int64_t expectedTimelineCookie = mTraceCookieCounter.getCookieForTracing();
Adithya Srinivasan86678502021-01-19 21:50:38 +0000825 bool missingToken = false;
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000826 // Expected timeline start
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800827 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800828 auto packet = ctx.NewTracePacket();
Adithya Srinivasan86678502021-01-19 21:50:38 +0000829 if (mToken == ISurfaceComposer::INVALID_VSYNC_ID) {
830 ALOGD("Cannot trace DisplayFrame with invalid token");
831 missingToken = true;
832 return;
833 }
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800834 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000835 packet->set_timestamp(static_cast<uint64_t>(mSurfaceFlingerPredictions.startTime));
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800836
837 auto* event = packet->set_frame_timeline_event();
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000838 auto* expectedDisplayFrameStartEvent = event->set_expected_display_frame_start();
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800839
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000840 expectedDisplayFrameStartEvent->set_cookie(expectedTimelineCookie);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800841
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000842 expectedDisplayFrameStartEvent->set_token(mToken);
843 expectedDisplayFrameStartEvent->set_pid(surfaceFlingerPid);
844 });
Adithya Srinivasan86678502021-01-19 21:50:38 +0000845
846 if (missingToken) {
847 // If one packet can't be traced because of missing token, then no packets can be traced.
848 // Exit early in this case.
849 return;
850 }
851
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000852 // Expected timeline end
853 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
854 auto packet = ctx.NewTracePacket();
855 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
856 packet->set_timestamp(static_cast<uint64_t>(mSurfaceFlingerPredictions.endTime));
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800857
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000858 auto* event = packet->set_frame_timeline_event();
859 auto* expectedDisplayFrameEndEvent = event->set_frame_end();
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800860
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000861 expectedDisplayFrameEndEvent->set_cookie(expectedTimelineCookie);
862 });
863
864 int64_t actualTimelineCookie = mTraceCookieCounter.getCookieForTracing();
865 // Expected timeline start
866 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
867 auto packet = ctx.NewTracePacket();
868 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
869 packet->set_timestamp(static_cast<uint64_t>(mSurfaceFlingerActuals.startTime));
870
871 auto* event = packet->set_frame_timeline_event();
872 auto* actualDisplayFrameStartEvent = event->set_actual_display_frame_start();
873
874 actualDisplayFrameStartEvent->set_cookie(actualTimelineCookie);
875
876 actualDisplayFrameStartEvent->set_token(mToken);
877 actualDisplayFrameStartEvent->set_pid(surfaceFlingerPid);
878
879 actualDisplayFrameStartEvent->set_present_type(toProto(mFramePresentMetadata));
880 actualDisplayFrameStartEvent->set_on_time_finish(mFrameReadyMetadata ==
881 FrameReadyMetadata::OnTimeFinish);
882 actualDisplayFrameStartEvent->set_gpu_composition(mGpuComposition);
883 actualDisplayFrameStartEvent->set_jank_type(jankTypeBitmaskToProto(mJankType));
884 });
885 // Expected timeline end
886 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
887 auto packet = ctx.NewTracePacket();
888 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
889 packet->set_timestamp(static_cast<uint64_t>(mSurfaceFlingerActuals.endTime));
890
891 auto* event = packet->set_frame_timeline_event();
892 auto* actualDisplayFrameEndEvent = event->set_frame_end();
893
894 actualDisplayFrameEndEvent->set_cookie(actualTimelineCookie);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800895 });
896
897 for (auto& surfaceFrame : mSurfaceFrames) {
898 surfaceFrame->trace(mToken);
899 }
900}
901
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700902void FrameTimeline::flushPendingPresentFences() {
903 for (size_t i = 0; i < mPendingPresentFences.size(); i++) {
904 const auto& pendingPresentFence = mPendingPresentFences[i];
905 nsecs_t signalTime = Fence::SIGNAL_TIME_INVALID;
906 if (pendingPresentFence.first && pendingPresentFence.first->isValid()) {
907 signalTime = pendingPresentFence.first->getSignalTime();
908 if (signalTime == Fence::SIGNAL_TIME_PENDING) {
909 continue;
910 }
911 }
912 if (signalTime != Fence::SIGNAL_TIME_INVALID) {
913 auto& displayFrame = pendingPresentFence.second;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800914 displayFrame->onPresent(signalTime);
915 displayFrame->trace(mSurfaceFlingerPid);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700916 }
917
918 mPendingPresentFences.erase(mPendingPresentFences.begin() + static_cast<int>(i));
919 --i;
920 }
921}
922
923void FrameTimeline::finalizeCurrentDisplayFrame() {
Adithya Srinivasan2d736322020-10-01 16:53:48 -0700924 while (mDisplayFrames.size() >= mMaxDisplayFrames) {
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700925 // We maintain only a fixed number of frames' data. Pop older frames
926 mDisplayFrames.pop_front();
927 }
928 mDisplayFrames.push_back(mCurrentDisplayFrame);
929 mCurrentDisplayFrame.reset();
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000930 mCurrentDisplayFrame = std::make_shared<DisplayFrame>(mTimeStats, mJankClassificationThresholds,
931 &mTraceCookieCounter);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700932}
933
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800934nsecs_t FrameTimeline::DisplayFrame::getBaseTime() const {
935 nsecs_t baseTime =
936 getMinTime(mPredictionState, mSurfaceFlingerPredictions, mSurfaceFlingerActuals);
937 for (const auto& surfaceFrame : mSurfaceFrames) {
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700938 nsecs_t surfaceFrameBaseTime = surfaceFrame->getBaseTime();
939 if (surfaceFrameBaseTime != 0) {
940 baseTime = std::min(baseTime, surfaceFrameBaseTime);
941 }
942 }
943 return baseTime;
944}
945
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800946void FrameTimeline::DisplayFrame::dumpJank(std::string& result, nsecs_t baseTime,
947 int displayFrameCount) const {
948 if (mJankType == JankType::None) {
949 // Check if any Surface Frame has been janky
950 bool isJanky = false;
951 for (const auto& surfaceFrame : mSurfaceFrames) {
952 if (surfaceFrame->getJankType() != JankType::None) {
953 isJanky = true;
954 break;
955 }
956 }
957 if (!isJanky) {
958 return;
959 }
960 }
961 StringAppendF(&result, "Display Frame %d", displayFrameCount);
962 dump(result, baseTime);
963}
964
965void FrameTimeline::DisplayFrame::dumpAll(std::string& result, nsecs_t baseTime) const {
966 dump(result, baseTime);
967}
968
969void FrameTimeline::DisplayFrame::dump(std::string& result, nsecs_t baseTime) const {
970 if (mJankType != JankType::None) {
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700971 // Easily identify a janky Display Frame in the dump
972 StringAppendF(&result, " [*] ");
973 }
974 StringAppendF(&result, "\n");
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800975 StringAppendF(&result, "Prediction State : %s\n", toString(mPredictionState).c_str());
976 StringAppendF(&result, "Jank Type : %s\n", jankTypeBitmaskToString(mJankType).c_str());
977 StringAppendF(&result, "Present Metadata : %s\n", toString(mFramePresentMetadata).c_str());
978 StringAppendF(&result, "Finish Metadata: %s\n", toString(mFrameReadyMetadata).c_str());
979 StringAppendF(&result, "Start Metadata: %s\n", toString(mFrameStartMetadata).c_str());
980 std::chrono::nanoseconds vsyncPeriod(mVsyncPeriod);
981 StringAppendF(&result, "Vsync Period: %10f\n",
982 std::chrono::duration<double, std::milli>(vsyncPeriod).count());
983 nsecs_t presentDelta =
984 mSurfaceFlingerActuals.presentTime - mSurfaceFlingerPredictions.presentTime;
985 std::chrono::nanoseconds presentDeltaNs(std::abs(presentDelta));
986 StringAppendF(&result, "Present delta: %10f\n",
987 std::chrono::duration<double, std::milli>(presentDeltaNs).count());
988 std::chrono::nanoseconds deltaToVsync(std::abs(presentDelta) % mVsyncPeriod);
989 StringAppendF(&result, "Present delta %% refreshrate: %10f\n",
990 std::chrono::duration<double, std::milli>(deltaToVsync).count());
991 dumpTable(result, mSurfaceFlingerPredictions, mSurfaceFlingerActuals, "", mPredictionState,
992 baseTime);
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700993 StringAppendF(&result, "\n");
994 std::string indent = " "; // 4 spaces
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800995 for (const auto& surfaceFrame : mSurfaceFrames) {
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700996 surfaceFrame->dump(result, indent, baseTime);
997 }
998 StringAppendF(&result, "\n");
999}
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001000
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -07001001void FrameTimeline::dumpAll(std::string& result) {
Adithya Srinivasanf279e042020-08-17 14:56:27 -07001002 std::lock_guard<std::mutex> lock(mMutex);
1003 StringAppendF(&result, "Number of display frames : %d\n", (int)mDisplayFrames.size());
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001004 nsecs_t baseTime = (mDisplayFrames.empty()) ? 0 : mDisplayFrames[0]->getBaseTime();
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -07001005 for (size_t i = 0; i < mDisplayFrames.size(); i++) {
1006 StringAppendF(&result, "Display Frame %d", static_cast<int>(i));
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001007 mDisplayFrames[i]->dumpAll(result, baseTime);
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -07001008 }
1009}
1010
1011void FrameTimeline::dumpJank(std::string& result) {
1012 std::lock_guard<std::mutex> lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001013 nsecs_t baseTime = (mDisplayFrames.empty()) ? 0 : mDisplayFrames[0]->getBaseTime();
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -07001014 for (size_t i = 0; i < mDisplayFrames.size(); i++) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001015 mDisplayFrames[i]->dumpJank(result, baseTime, static_cast<int>(i));
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -07001016 }
1017}
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001018
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -07001019void FrameTimeline::parseArgs(const Vector<String16>& args, std::string& result) {
1020 ATRACE_CALL();
1021 std::unordered_map<std::string, bool> argsMap;
1022 for (size_t i = 0; i < args.size(); i++) {
1023 argsMap[std::string(String8(args[i]).c_str())] = true;
1024 }
1025 if (argsMap.count("-jank")) {
1026 dumpJank(result);
1027 }
1028 if (argsMap.count("-all")) {
1029 dumpAll(result);
Adithya Srinivasanf279e042020-08-17 14:56:27 -07001030 }
1031}
1032
Adithya Srinivasan2d736322020-10-01 16:53:48 -07001033void FrameTimeline::setMaxDisplayFrames(uint32_t size) {
1034 std::lock_guard<std::mutex> lock(mMutex);
1035
1036 // The size can either increase or decrease, clear everything, to be consistent
1037 mDisplayFrames.clear();
1038 mPendingPresentFences.clear();
1039 mMaxDisplayFrames = size;
1040}
1041
1042void FrameTimeline::reset() {
1043 setMaxDisplayFrames(kDefaultMaxDisplayFrames);
1044}
1045
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -08001046} // namespace impl
1047} // namespace android::frametimeline