blob: c994434a15644a306bbaebcc12f02689f3c96a10 [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) {
98 // TODO(b/175843808): Make this a switch case if jankType becomes an enum class
99 std::vector<std::string> janks;
100 if (jankType == JankType::None) {
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700101 return "None";
102 }
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800103 if (jankType & JankType::DisplayHAL) {
104 janks.emplace_back("Display HAL");
105 }
106 if (jankType & JankType::SurfaceFlingerCpuDeadlineMissed) {
107 janks.emplace_back("SurfaceFlinger CPU Deadline Missed");
108 }
109 if (jankType & JankType::SurfaceFlingerGpuDeadlineMissed) {
110 janks.emplace_back("SurfaceFlinger GPU Deadline Missed");
111 }
112 if (jankType & JankType::AppDeadlineMissed) {
113 janks.emplace_back("App Deadline Missed");
114 }
115 if (jankType & JankType::PredictionError) {
116 janks.emplace_back("Prediction Error");
117 }
118 if (jankType & JankType::SurfaceFlingerScheduling) {
119 janks.emplace_back("SurfaceFlinger Scheduling");
120 }
121 if (jankType & JankType::BufferStuffing) {
122 janks.emplace_back("Buffer Stuffing");
123 }
124 if (jankType & JankType::Unknown) {
125 janks.emplace_back("Unknown jank");
126 }
127 return std::accumulate(janks.begin(), janks.end(), std::string(),
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700128 [](const std::string& l, const std::string& r) {
129 return l.empty() ? r : l + ", " + r;
130 });
131}
132
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800133std::string toString(FramePresentMetadata presentMetadata) {
134 switch (presentMetadata) {
135 case FramePresentMetadata::OnTimePresent:
136 return "On Time Present";
137 case FramePresentMetadata::LatePresent:
138 return "Late Present";
139 case FramePresentMetadata::EarlyPresent:
140 return "Early Present";
141 case FramePresentMetadata::UnknownPresent:
142 return "Unknown Present";
Adithya Srinivasan01189672020-10-20 14:23:05 -0700143 }
Adithya Srinivasan01189672020-10-20 14:23:05 -0700144}
145
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800146std::string toString(FrameReadyMetadata finishMetadata) {
147 switch (finishMetadata) {
148 case FrameReadyMetadata::OnTimeFinish:
149 return "On Time Finish";
150 case FrameReadyMetadata::LateFinish:
151 return "Late Finish";
152 case FrameReadyMetadata::UnknownFinish:
153 return "Unknown Finish";
154 }
155}
156
157std::string toString(FrameStartMetadata startMetadata) {
158 switch (startMetadata) {
159 case FrameStartMetadata::OnTimeStart:
160 return "On Time Start";
161 case FrameStartMetadata::LateStart:
162 return "Late Start";
163 case FrameStartMetadata::EarlyStart:
164 return "Early Start";
165 case FrameStartMetadata::UnknownStart:
166 return "Unknown Start";
167 }
168}
169
170std::string toString(SurfaceFrame::PresentState presentState) {
171 using PresentState = SurfaceFrame::PresentState;
172 switch (presentState) {
173 case PresentState::Presented:
174 return "Presented";
175 case PresentState::Dropped:
176 return "Dropped";
177 case PresentState::Unknown:
178 return "Unknown";
179 }
180}
181
182FrameTimelineEvent::PresentType toProto(FramePresentMetadata presentMetadata) {
183 switch (presentMetadata) {
184 case FramePresentMetadata::EarlyPresent:
185 return FrameTimelineEvent::PRESENT_EARLY;
186 case FramePresentMetadata::LatePresent:
187 return FrameTimelineEvent::PRESENT_LATE;
188 case FramePresentMetadata::OnTimePresent:
189 return FrameTimelineEvent::PRESENT_ON_TIME;
190 case FramePresentMetadata::UnknownPresent:
191 return FrameTimelineEvent::PRESENT_UNSPECIFIED;
192 }
193}
194
195FrameTimelineEvent::JankType jankTypeBitmaskToProto(int32_t jankType) {
196 // TODO(b/175843808): Either make the proto a bitmask or jankType an enum class
Adithya Srinivasan01189672020-10-20 14:23:05 -0700197 switch (jankType) {
Jorim Jaggi5814ab82020-12-03 20:45:58 +0100198 case JankType::None:
Adithya Srinivasan01189672020-10-20 14:23:05 -0700199 return FrameTimelineEvent::JANK_NONE;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800200 case JankType::DisplayHAL:
Adithya Srinivasan01189672020-10-20 14:23:05 -0700201 return FrameTimelineEvent::JANK_DISPLAY_HAL;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800202 case JankType::SurfaceFlingerCpuDeadlineMissed:
203 case JankType::SurfaceFlingerGpuDeadlineMissed:
Adithya Srinivasan01189672020-10-20 14:23:05 -0700204 return FrameTimelineEvent::JANK_SF_DEADLINE_MISSED;
Jorim Jaggi5814ab82020-12-03 20:45:58 +0100205 case JankType::AppDeadlineMissed:
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800206 case JankType::PredictionError:
Adithya Srinivasan01189672020-10-20 14:23:05 -0700207 return FrameTimelineEvent::JANK_APP_DEADLINE_MISSED;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800208 case JankType::SurfaceFlingerScheduling:
209 return FrameTimelineEvent::JANK_SF_SCHEDULING;
210 case JankType::BufferStuffing:
211 return FrameTimelineEvent::JANK_BUFFER_STUFFING;
Adithya Srinivasan01189672020-10-20 14:23:05 -0700212 default:
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800213 // TODO(b/175843808): Remove default if JankType becomes an enum class
Adithya Srinivasan01189672020-10-20 14:23:05 -0700214 return FrameTimelineEvent::JANK_UNKNOWN;
215 }
216}
217
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800218// Returns the smallest timestamp from the set of predictions and actuals.
219nsecs_t getMinTime(PredictionState predictionState, TimelineItem predictions,
220 TimelineItem actuals) {
221 nsecs_t minTime = std::numeric_limits<nsecs_t>::max();
222 if (predictionState == PredictionState::Valid) {
223 // Checking start time for predictions is enough because start time is always lesser than
224 // endTime and presentTime.
225 minTime = std::min(minTime, predictions.startTime);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700226 }
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700227
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800228 // Need to check startTime, endTime and presentTime for actuals because some frames might not
229 // have them set.
230 if (actuals.startTime != 0) {
231 minTime = std::min(minTime, actuals.startTime);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700232 }
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800233 if (actuals.endTime != 0) {
234 minTime = std::min(minTime, actuals.endTime);
235 }
236 if (actuals.presentTime != 0) {
237 minTime = std::min(minTime, actuals.endTime);
238 }
239 return minTime;
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700240}
241
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000242int64_t TraceCookieCounter::getCookieForTracing() {
243 return ++mTraceCookie;
244}
245
Adithya Srinivasan01189672020-10-20 14:23:05 -0700246SurfaceFrame::SurfaceFrame(int64_t token, pid_t ownerPid, uid_t ownerUid, std::string layerName,
Adithya Srinivasan9febda82020-10-19 10:49:41 -0700247 std::string debugName, PredictionState predictionState,
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800248 frametimeline::TimelineItem&& predictions,
249 std::shared_ptr<TimeStats> timeStats,
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000250 JankClassificationThresholds thresholds,
251 TraceCookieCounter* traceCookieCounter)
Adithya Srinivasan01189672020-10-20 14:23:05 -0700252 : mToken(token),
253 mOwnerPid(ownerPid),
Adithya Srinivasan9febda82020-10-19 10:49:41 -0700254 mOwnerUid(ownerUid),
Alec Mouri9a29e672020-09-14 12:39:14 -0700255 mLayerName(std::move(layerName)),
256 mDebugName(std::move(debugName)),
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700257 mPresentState(PresentState::Unknown),
258 mPredictionState(predictionState),
259 mPredictions(predictions),
260 mActuals({0, 0, 0}),
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800261 mTimeStats(timeStats),
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000262 mJankClassificationThresholds(thresholds),
263 mTraceCookieCounter(*traceCookieCounter) {}
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700264
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -0700265void SurfaceFrame::setActualStartTime(nsecs_t actualStartTime) {
266 std::lock_guard<std::mutex> lock(mMutex);
267 mActuals.startTime = actualStartTime;
268}
269
270void SurfaceFrame::setActualQueueTime(nsecs_t actualQueueTime) {
271 std::lock_guard<std::mutex> lock(mMutex);
272 mActualQueueTime = actualQueueTime;
273}
Ady Abraham7f8a1e62020-09-28 16:09:35 -0700274void SurfaceFrame::setAcquireFenceTime(nsecs_t acquireFenceTime) {
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -0700275 std::lock_guard<std::mutex> lock(mMutex);
Ady Abraham7f8a1e62020-09-28 16:09:35 -0700276 mActuals.endTime = std::max(acquireFenceTime, mActualQueueTime);
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -0700277}
278
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800279void SurfaceFrame::setPresentState(PresentState presentState, nsecs_t lastLatchTime) {
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700280 std::lock_guard<std::mutex> lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800281 mPresentState = presentState;
282 mLastLatchTime = lastLatchTime;
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700283}
284
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800285std::optional<int32_t> SurfaceFrame::getJankType() const {
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700286 std::lock_guard<std::mutex> lock(mMutex);
Jorim Jaggi9c03b502020-11-24 23:51:31 +0100287 if (mActuals.presentTime == 0) {
288 return std::nullopt;
289 }
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700290 return mJankType;
291}
292
293nsecs_t SurfaceFrame::getBaseTime() const {
294 std::lock_guard<std::mutex> lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800295 return getMinTime(mPredictionState, mPredictions, mActuals);
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700296}
297
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800298TimelineItem SurfaceFrame::getActuals() const {
299 std::lock_guard<std::mutex> lock(mMutex);
300 return mActuals;
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700301}
302
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800303SurfaceFrame::PresentState SurfaceFrame::getPresentState() const {
304 std::lock_guard<std::mutex> lock(mMutex);
305 return mPresentState;
306}
307
308FramePresentMetadata SurfaceFrame::getFramePresentMetadata() const {
309 std::lock_guard<std::mutex> lock(mMutex);
310 return mFramePresentMetadata;
311}
312
313FrameReadyMetadata SurfaceFrame::getFrameReadyMetadata() const {
314 std::lock_guard<std::mutex> lock(mMutex);
315 return mFrameReadyMetadata;
316}
317
318void SurfaceFrame::dump(std::string& result, const std::string& indent, nsecs_t baseTime) const {
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700319 std::lock_guard<std::mutex> lock(mMutex);
320 StringAppendF(&result, "%s", indent.c_str());
Alec Mouri9a29e672020-09-14 12:39:14 -0700321 StringAppendF(&result, "Layer - %s", mDebugName.c_str());
Jorim Jaggi5814ab82020-12-03 20:45:58 +0100322 if (mJankType != JankType::None) {
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700323 // Easily identify a janky Surface Frame in the dump
324 StringAppendF(&result, " [*] ");
325 }
326 StringAppendF(&result, "\n");
327 StringAppendF(&result, "%s", indent.c_str());
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800328 StringAppendF(&result, "Token: %" PRId64 "\n", mToken);
329 StringAppendF(&result, "%s", indent.c_str());
Adithya Srinivasan9febda82020-10-19 10:49:41 -0700330 StringAppendF(&result, "Owner Pid : %d\n", mOwnerPid);
331 StringAppendF(&result, "%s", indent.c_str());
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800332 StringAppendF(&result, "Present State : %s\n", toString(mPresentState).c_str());
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700333 StringAppendF(&result, "%s", indent.c_str());
334 StringAppendF(&result, "Prediction State : %s\n", toString(mPredictionState).c_str());
335 StringAppendF(&result, "%s", indent.c_str());
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800336 StringAppendF(&result, "Jank Type : %s\n", jankTypeBitmaskToString(mJankType).c_str());
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700337 StringAppendF(&result, "%s", indent.c_str());
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800338 StringAppendF(&result, "Present Metadata : %s\n", toString(mFramePresentMetadata).c_str());
339 StringAppendF(&result, "%s", indent.c_str());
340 StringAppendF(&result, "Finish Metadata: %s\n", toString(mFrameReadyMetadata).c_str());
341 std::chrono::nanoseconds latchTime(
342 std::max(static_cast<int64_t>(0), mLastLatchTime - baseTime));
343 StringAppendF(&result, "%s", indent.c_str());
344 StringAppendF(&result, "Last latch time: %10f\n",
345 std::chrono::duration<double, std::milli>(latchTime).count());
346 if (mPredictionState == PredictionState::Valid) {
347 nsecs_t presentDelta = mActuals.presentTime - mPredictions.presentTime;
348 std::chrono::nanoseconds presentDeltaNs(std::abs(presentDelta));
349 StringAppendF(&result, "%s", indent.c_str());
350 StringAppendF(&result, "Present delta: %10f\n",
351 std::chrono::duration<double, std::milli>(presentDeltaNs).count());
352 }
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700353 dumpTable(result, mPredictions, mActuals, indent, mPredictionState, baseTime);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700354}
355
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800356void SurfaceFrame::onPresent(nsecs_t presentTime, int32_t displayFrameJankType,
357 nsecs_t vsyncPeriod) {
358 std::lock_guard<std::mutex> lock(mMutex);
359 if (mPresentState != PresentState::Presented) {
360 // No need to update dropped buffers
361 return;
362 }
363
364 mActuals.presentTime = presentTime;
365 // Jank Analysis for SurfaceFrame
366 if (mPredictionState == PredictionState::None) {
367 // Cannot do jank classification on frames that don't have a token.
368 return;
369 }
370 if (mPredictionState == PredictionState::Expired) {
371 // We do not know what happened here to classify this correctly. This could
372 // potentially be AppDeadlineMissed but that's assuming no app will request frames
373 // 120ms apart.
374 mJankType = JankType::Unknown;
375 mFramePresentMetadata = FramePresentMetadata::UnknownPresent;
376 mFrameReadyMetadata = FrameReadyMetadata::UnknownFinish;
377 mTimeStats->incrementJankyFrames(mOwnerUid, mLayerName, mJankType);
378 return;
379 }
380
381 const nsecs_t presentDelta = mActuals.presentTime - mPredictions.presentTime;
382 const nsecs_t deadlineDelta = mActuals.endTime - mPredictions.endTime;
383 const nsecs_t deltaToVsync = std::abs(presentDelta) % vsyncPeriod;
384
385 if (deadlineDelta > mJankClassificationThresholds.deadlineThreshold) {
386 mFrameReadyMetadata = FrameReadyMetadata::LateFinish;
387 } else {
388 mFrameReadyMetadata = FrameReadyMetadata::OnTimeFinish;
389 }
390
391 if (std::abs(presentDelta) > mJankClassificationThresholds.presentThreshold) {
392 mFramePresentMetadata = presentDelta > 0 ? FramePresentMetadata::LatePresent
393 : FramePresentMetadata::EarlyPresent;
394 } else {
395 mFramePresentMetadata = FramePresentMetadata::OnTimePresent;
396 }
397
398 if (mFramePresentMetadata == FramePresentMetadata::OnTimePresent) {
399 // Frames presented on time are not janky.
400 mJankType = JankType::None;
401 } else if (mFramePresentMetadata == FramePresentMetadata::EarlyPresent) {
402 if (mFrameReadyMetadata == FrameReadyMetadata::OnTimeFinish) {
403 // Finish on time, Present early
404 if (deltaToVsync < mJankClassificationThresholds.presentThreshold ||
405 deltaToVsync >= vsyncPeriod - mJankClassificationThresholds.presentThreshold) {
406 // Delta factor of vsync
407 mJankType = JankType::SurfaceFlingerScheduling;
408 } else {
409 // Delta not a factor of vsync
410 mJankType = JankType::PredictionError;
411 }
412 } else if (mFrameReadyMetadata == FrameReadyMetadata::LateFinish) {
413 // Finish late, Present early
414 mJankType = JankType::Unknown;
415 }
416 } else {
417 if (mLastLatchTime != 0 && mPredictions.endTime <= mLastLatchTime) {
418 // Buffer Stuffing.
419 mJankType |= JankType::BufferStuffing;
420 }
421 if (mFrameReadyMetadata == FrameReadyMetadata::OnTimeFinish) {
422 // Finish on time, Present late
423 if (displayFrameJankType != JankType::None) {
424 // Propagate displayFrame's jank if it exists
425 mJankType |= displayFrameJankType;
426 } else {
427 if (deltaToVsync < mJankClassificationThresholds.presentThreshold ||
428 deltaToVsync >= vsyncPeriod - mJankClassificationThresholds.presentThreshold) {
429 // Delta factor of vsync
430 mJankType |= JankType::SurfaceFlingerScheduling;
431 } else {
432 // Delta not a factor of vsync
433 mJankType |= JankType::PredictionError;
434 }
435 }
436 } else if (mFrameReadyMetadata == FrameReadyMetadata::LateFinish) {
437 // Finish late, Present late
438 if (displayFrameJankType == JankType::None) {
439 // Display frame is not janky, so purely app's fault
440 mJankType |= JankType::AppDeadlineMissed;
441 } else {
442 // Propagate DisplayFrame's jankType if it is janky
443 mJankType |= displayFrameJankType;
444 }
445 }
446 }
447 mTimeStats->incrementJankyFrames(mOwnerUid, mLayerName, mJankType);
448}
449
450void SurfaceFrame::trace(int64_t displayFrameToken) {
451 using FrameTimelineDataSource = impl::FrameTimeline::FrameTimelineDataSource;
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000452 {
Adithya Srinivasan01189672020-10-20 14:23:05 -0700453 std::lock_guard<std::mutex> lock(mMutex);
454 if (mToken == ISurfaceComposer::INVALID_VSYNC_ID) {
455 ALOGD("Cannot trace SurfaceFrame - %s with invalid token", mLayerName.c_str());
456 return;
457 } else if (displayFrameToken == ISurfaceComposer::INVALID_VSYNC_ID) {
458 ALOGD("Cannot trace SurfaceFrame - %s with invalid displayFrameToken",
459 mLayerName.c_str());
460 return;
461 }
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000462 }
463
464 int64_t expectedTimelineCookie = mTraceCookieCounter.getCookieForTracing();
465 // Expected timeline start
466 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
467 std::lock_guard<std::mutex> lock(mMutex);
Adithya Srinivasan01189672020-10-20 14:23:05 -0700468 auto packet = ctx.NewTracePacket();
469 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000470 packet->set_timestamp(static_cast<uint64_t>(mPredictions.startTime));
Adithya Srinivasan01189672020-10-20 14:23:05 -0700471
472 auto* event = packet->set_frame_timeline_event();
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000473 auto* expectedSurfaceFrameStartEvent = event->set_expected_surface_frame_start();
Adithya Srinivasan01189672020-10-20 14:23:05 -0700474
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000475 expectedSurfaceFrameStartEvent->set_cookie(expectedTimelineCookie);
476
477 expectedSurfaceFrameStartEvent->set_token(mToken);
478 expectedSurfaceFrameStartEvent->set_display_frame_token(displayFrameToken);
479
480 expectedSurfaceFrameStartEvent->set_pid(mOwnerPid);
481 expectedSurfaceFrameStartEvent->set_layer_name(mDebugName);
482 });
483 // Expected timeline end
484 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
485 std::lock_guard<std::mutex> lock(mMutex);
486 auto packet = ctx.NewTracePacket();
487 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
488 packet->set_timestamp(static_cast<uint64_t>(mPredictions.endTime));
489
490 auto* event = packet->set_frame_timeline_event();
491 auto* expectedSurfaceFrameEndEvent = event->set_frame_end();
492
493 expectedSurfaceFrameEndEvent->set_cookie(expectedTimelineCookie);
494 });
495
496 int64_t actualTimelineCookie = mTraceCookieCounter.getCookieForTracing();
497 // Actual timeline start
498 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
499 std::lock_guard<std::mutex> lock(mMutex);
500 auto packet = ctx.NewTracePacket();
501 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
502 // Actual start time is not yet available, so use expected start instead
503 packet->set_timestamp(static_cast<uint64_t>(mPredictions.startTime));
504
505 auto* event = packet->set_frame_timeline_event();
506 auto* actualSurfaceFrameStartEvent = event->set_actual_surface_frame_start();
507
508 actualSurfaceFrameStartEvent->set_cookie(actualTimelineCookie);
509
510 actualSurfaceFrameStartEvent->set_token(mToken);
511 actualSurfaceFrameStartEvent->set_display_frame_token(displayFrameToken);
512
513 actualSurfaceFrameStartEvent->set_pid(mOwnerPid);
514 actualSurfaceFrameStartEvent->set_layer_name(mDebugName);
Adithya Srinivasan01189672020-10-20 14:23:05 -0700515
516 if (mPresentState == PresentState::Dropped) {
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000517 actualSurfaceFrameStartEvent->set_present_type(FrameTimelineEvent::PRESENT_DROPPED);
Adithya Srinivasan01189672020-10-20 14:23:05 -0700518 } else if (mPresentState == PresentState::Unknown) {
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000519 actualSurfaceFrameStartEvent->set_present_type(FrameTimelineEvent::PRESENT_UNSPECIFIED);
Adithya Srinivasan01189672020-10-20 14:23:05 -0700520 } else {
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000521 actualSurfaceFrameStartEvent->set_present_type(toProto(mFramePresentMetadata));
Adithya Srinivasan01189672020-10-20 14:23:05 -0700522 }
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000523 actualSurfaceFrameStartEvent->set_on_time_finish(mFrameReadyMetadata ==
524 FrameReadyMetadata::OnTimeFinish);
525 actualSurfaceFrameStartEvent->set_gpu_composition(mGpuComposition);
526 actualSurfaceFrameStartEvent->set_jank_type(jankTypeBitmaskToProto(mJankType));
527 });
528 // Actual timeline end
529 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
530 std::lock_guard<std::mutex> lock(mMutex);
531 auto packet = ctx.NewTracePacket();
532 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
533 packet->set_timestamp(static_cast<uint64_t>(mActuals.endTime));
Adithya Srinivasan01189672020-10-20 14:23:05 -0700534
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000535 auto* event = packet->set_frame_timeline_event();
536 auto* actualSurfaceFrameEndEvent = event->set_frame_end();
Adithya Srinivasan01189672020-10-20 14:23:05 -0700537
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000538 actualSurfaceFrameEndEvent->set_cookie(actualTimelineCookie);
Adithya Srinivasan01189672020-10-20 14:23:05 -0700539 });
540}
541
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800542namespace impl {
543
544int64_t TokenManager::generateTokenForPredictions(TimelineItem&& predictions) {
545 ATRACE_CALL();
546 std::lock_guard<std::mutex> lock(mMutex);
547 const int64_t assignedToken = mCurrentToken++;
548 mPredictions[assignedToken] = {systemTime(), predictions};
549 flushTokens(systemTime());
550 return assignedToken;
551}
552
553std::optional<TimelineItem> TokenManager::getPredictionsForToken(int64_t token) const {
554 std::lock_guard<std::mutex> lock(mMutex);
555 auto predictionsIterator = mPredictions.find(token);
556 if (predictionsIterator != mPredictions.end()) {
557 return predictionsIterator->second.predictions;
558 }
559 return {};
560}
561
562void TokenManager::flushTokens(nsecs_t flushTime) {
563 for (auto it = mPredictions.begin(); it != mPredictions.end();) {
564 if (flushTime - it->second.timestamp >= kMaxRetentionTime) {
565 it = mPredictions.erase(it);
566 } else {
567 // Tokens are ordered by time. If i'th token is within the retention time, then the
568 // i+1'th token will also be within retention time.
569 break;
570 }
571 }
572}
573
574FrameTimeline::FrameTimeline(std::shared_ptr<TimeStats> timeStats, pid_t surfaceFlingerPid,
575 JankClassificationThresholds thresholds)
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000576 : mMaxDisplayFrames(kDefaultMaxDisplayFrames),
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800577 mTimeStats(std::move(timeStats)),
578 mSurfaceFlingerPid(surfaceFlingerPid),
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000579 mJankClassificationThresholds(thresholds) {
580 mCurrentDisplayFrame =
581 std::make_shared<DisplayFrame>(mTimeStats, thresholds, &mTraceCookieCounter);
582}
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700583
Adithya Srinivasan01189672020-10-20 14:23:05 -0700584void FrameTimeline::onBootFinished() {
585 perfetto::TracingInitArgs args;
586 args.backends = perfetto::kSystemBackend;
587 perfetto::Tracing::Initialize(args);
588 registerDataSource();
589}
590
591void FrameTimeline::registerDataSource() {
592 perfetto::DataSourceDescriptor dsd;
593 dsd.set_name(kFrameTimelineDataSource);
594 FrameTimelineDataSource::Register(dsd);
595}
596
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800597std::shared_ptr<SurfaceFrame> FrameTimeline::createSurfaceFrameForToken(
598 std::optional<int64_t> token, pid_t ownerPid, uid_t ownerUid, std::string layerName,
599 std::string debugName) {
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -0700600 ATRACE_CALL();
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700601 if (!token) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800602 return std::make_shared<SurfaceFrame>(ISurfaceComposer::INVALID_VSYNC_ID, ownerPid,
603 ownerUid, std::move(layerName), std::move(debugName),
604 PredictionState::None, TimelineItem(), mTimeStats,
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000605 mJankClassificationThresholds, &mTraceCookieCounter);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700606 }
607 std::optional<TimelineItem> predictions = mTokenManager.getPredictionsForToken(*token);
608 if (predictions) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800609 return std::make_shared<SurfaceFrame>(*token, ownerPid, ownerUid, std::move(layerName),
610 std::move(debugName), PredictionState::Valid,
611 std::move(*predictions), mTimeStats,
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000612 mJankClassificationThresholds, &mTraceCookieCounter);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700613 }
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800614 return std::make_shared<SurfaceFrame>(*token, ownerPid, ownerUid, std::move(layerName),
615 std::move(debugName), PredictionState::Expired,
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000616 TimelineItem(), mTimeStats, mJankClassificationThresholds,
617 &mTraceCookieCounter);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700618}
619
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800620FrameTimeline::DisplayFrame::DisplayFrame(std::shared_ptr<TimeStats> timeStats,
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000621 JankClassificationThresholds thresholds,
622 TraceCookieCounter* traceCookieCounter)
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800623 : mSurfaceFlingerPredictions(TimelineItem()),
624 mSurfaceFlingerActuals(TimelineItem()),
625 mTimeStats(timeStats),
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000626 mJankClassificationThresholds(thresholds),
627 mTraceCookieCounter(*traceCookieCounter) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800628 mSurfaceFrames.reserve(kNumSurfaceFramesInitial);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700629}
630
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800631void FrameTimeline::addSurfaceFrame(std::shared_ptr<SurfaceFrame> surfaceFrame) {
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -0700632 ATRACE_CALL();
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700633 std::lock_guard<std::mutex> lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800634 mCurrentDisplayFrame->addSurfaceFrame(surfaceFrame);
635}
636
637void FrameTimeline::setSfWakeUp(int64_t token, nsecs_t wakeUpTime, nsecs_t vsyncPeriod) {
638 ATRACE_CALL();
639 std::lock_guard<std::mutex> lock(mMutex);
640 mCurrentDisplayFrame->onSfWakeUp(token, vsyncPeriod,
641 mTokenManager.getPredictionsForToken(token), wakeUpTime);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700642}
643
644void FrameTimeline::setSfPresent(nsecs_t sfPresentTime,
645 const std::shared_ptr<FenceTime>& presentFence) {
Adithya Srinivasan5f683cf2020-09-15 14:21:04 -0700646 ATRACE_CALL();
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700647 std::lock_guard<std::mutex> lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800648 mCurrentDisplayFrame->setActualEndTime(sfPresentTime);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700649 mPendingPresentFences.emplace_back(std::make_pair(presentFence, mCurrentDisplayFrame));
650 flushPendingPresentFences();
651 finalizeCurrentDisplayFrame();
652}
653
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800654void FrameTimeline::DisplayFrame::addSurfaceFrame(std::shared_ptr<SurfaceFrame> surfaceFrame) {
655 mSurfaceFrames.push_back(surfaceFrame);
656}
657
658void FrameTimeline::DisplayFrame::onSfWakeUp(int64_t token, nsecs_t vsyncPeriod,
659 std::optional<TimelineItem> predictions,
660 nsecs_t wakeUpTime) {
661 mToken = token;
662 mVsyncPeriod = vsyncPeriod;
663 if (!predictions) {
664 mPredictionState = PredictionState::Expired;
665 } else {
666 mPredictionState = PredictionState::Valid;
667 mSurfaceFlingerPredictions = *predictions;
668 }
669 mSurfaceFlingerActuals.startTime = wakeUpTime;
670}
671
672void FrameTimeline::DisplayFrame::setTokenAndVsyncPeriod(int64_t token, nsecs_t vsyncPeriod) {
673 mToken = token;
674 mVsyncPeriod = vsyncPeriod;
675}
676
677void FrameTimeline::DisplayFrame::setPredictions(PredictionState predictionState,
678 TimelineItem predictions) {
679 mPredictionState = predictionState;
680 mSurfaceFlingerPredictions = predictions;
681}
682
683void FrameTimeline::DisplayFrame::setActualStartTime(nsecs_t actualStartTime) {
684 mSurfaceFlingerActuals.startTime = actualStartTime;
685}
686
687void FrameTimeline::DisplayFrame::setActualEndTime(nsecs_t actualEndTime) {
688 mSurfaceFlingerActuals.endTime = actualEndTime;
689}
690
691void FrameTimeline::DisplayFrame::onPresent(nsecs_t signalTime) {
692 mSurfaceFlingerActuals.presentTime = signalTime;
693 int32_t totalJankReasons = JankType::None;
694
695 // Delta between the expected present and the actual present
696 const nsecs_t presentDelta =
697 mSurfaceFlingerActuals.presentTime - mSurfaceFlingerPredictions.presentTime;
698 // How far off was the presentDelta when compared to the vsyncPeriod. Used in checking if there
699 // was a prediction error or not.
700 nsecs_t deltaToVsync = std::abs(presentDelta) % mVsyncPeriod;
701 if (std::abs(presentDelta) > mJankClassificationThresholds.presentThreshold) {
702 mFramePresentMetadata = presentDelta > 0 ? FramePresentMetadata::LatePresent
703 : FramePresentMetadata::EarlyPresent;
704 } else {
705 mFramePresentMetadata = FramePresentMetadata::OnTimePresent;
706 }
707
708 if (mSurfaceFlingerActuals.endTime - mSurfaceFlingerPredictions.endTime >
709 mJankClassificationThresholds.deadlineThreshold) {
710 mFrameReadyMetadata = FrameReadyMetadata::LateFinish;
711 } else {
712 mFrameReadyMetadata = FrameReadyMetadata::OnTimeFinish;
713 }
714
715 if (std::abs(mSurfaceFlingerActuals.startTime - mSurfaceFlingerPredictions.startTime) >
716 mJankClassificationThresholds.startThreshold) {
717 mFrameStartMetadata =
718 mSurfaceFlingerActuals.startTime > mSurfaceFlingerPredictions.startTime
719 ? FrameStartMetadata::LateStart
720 : FrameStartMetadata::EarlyStart;
721 }
722
723 if (mFramePresentMetadata != FramePresentMetadata::OnTimePresent) {
724 // Do jank classification only if present is not on time
725 if (mFramePresentMetadata == FramePresentMetadata::EarlyPresent) {
726 if (mFrameReadyMetadata == FrameReadyMetadata::OnTimeFinish) {
727 // Finish on time, Present early
728 if (deltaToVsync < mJankClassificationThresholds.presentThreshold ||
729 deltaToVsync >=
730 (mVsyncPeriod - mJankClassificationThresholds.presentThreshold)) {
731 // Delta is a factor of vsync if its within the presentTheshold on either side
732 // of the vsyncPeriod. Example: 0-2ms and 9-11ms are both within the threshold
733 // of the vsyncPeriod if the threshold was 2ms and the vsyncPeriod was 11ms.
734 mJankType = JankType::SurfaceFlingerScheduling;
735 } else {
736 // Delta is not a factor of vsync,
737 mJankType = JankType::PredictionError;
738 }
739 } else if (mFrameReadyMetadata == FrameReadyMetadata::LateFinish) {
740 // Finish late, Present early
741 mJankType = JankType::SurfaceFlingerScheduling;
742 } else {
743 // Finish time unknown
744 mJankType = JankType::Unknown;
745 }
746 } else if (mFramePresentMetadata == FramePresentMetadata::LatePresent) {
747 if (mFrameReadyMetadata == FrameReadyMetadata::OnTimeFinish) {
748 // Finish on time, Present late
749 if (deltaToVsync < mJankClassificationThresholds.presentThreshold ||
750 deltaToVsync >=
751 (mVsyncPeriod - mJankClassificationThresholds.presentThreshold)) {
752 // Delta is a factor of vsync if its within the presentTheshold on either side
753 // of the vsyncPeriod. Example: 0-2ms and 9-11ms are both within the threshold
754 // of the vsyncPeriod if the threshold was 2ms and the vsyncPeriod was 11ms.
755 mJankType = JankType::DisplayHAL;
756 } else {
757 // Delta is not a factor of vsync
758 mJankType = JankType::PredictionError;
759 }
760 } else if (mFrameReadyMetadata == FrameReadyMetadata::LateFinish) {
761 // Finish late, Present late
762 mJankType = JankType::SurfaceFlingerCpuDeadlineMissed;
763 } else {
764 // Finish time unknown
765 mJankType = JankType::Unknown;
766 }
767 } else {
768 // Present unknown
769 mJankType = JankType::Unknown;
770 }
771 }
772 totalJankReasons |= mJankType;
773
774 for (auto& surfaceFrame : mSurfaceFrames) {
775 surfaceFrame->onPresent(signalTime, mJankType, mVsyncPeriod);
776 auto surfaceFrameJankType = surfaceFrame->getJankType();
777 if (surfaceFrameJankType != std::nullopt) {
778 totalJankReasons |= *surfaceFrameJankType;
779 }
780 }
781 mTimeStats->incrementJankyFrames(totalJankReasons);
782}
783
784void FrameTimeline::DisplayFrame::trace(pid_t surfaceFlingerPid) const {
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000785 if (mToken == ISurfaceComposer::INVALID_VSYNC_ID) {
786 ALOGD("Cannot trace DisplayFrame with invalid token");
787 return;
788 }
789
790 int64_t expectedTimelineCookie = mTraceCookieCounter.getCookieForTracing();
791 // Expected timeline start
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800792 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800793 auto packet = ctx.NewTracePacket();
794 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000795 packet->set_timestamp(static_cast<uint64_t>(mSurfaceFlingerPredictions.startTime));
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800796
797 auto* event = packet->set_frame_timeline_event();
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000798 auto* expectedDisplayFrameStartEvent = event->set_expected_display_frame_start();
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800799
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000800 expectedDisplayFrameStartEvent->set_cookie(expectedTimelineCookie);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800801
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000802 expectedDisplayFrameStartEvent->set_token(mToken);
803 expectedDisplayFrameStartEvent->set_pid(surfaceFlingerPid);
804 });
805 // Expected timeline end
806 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
807 auto packet = ctx.NewTracePacket();
808 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
809 packet->set_timestamp(static_cast<uint64_t>(mSurfaceFlingerPredictions.endTime));
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800810
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000811 auto* event = packet->set_frame_timeline_event();
812 auto* expectedDisplayFrameEndEvent = event->set_frame_end();
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800813
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000814 expectedDisplayFrameEndEvent->set_cookie(expectedTimelineCookie);
815 });
816
817 int64_t actualTimelineCookie = mTraceCookieCounter.getCookieForTracing();
818 // Expected timeline start
819 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
820 auto packet = ctx.NewTracePacket();
821 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
822 packet->set_timestamp(static_cast<uint64_t>(mSurfaceFlingerActuals.startTime));
823
824 auto* event = packet->set_frame_timeline_event();
825 auto* actualDisplayFrameStartEvent = event->set_actual_display_frame_start();
826
827 actualDisplayFrameStartEvent->set_cookie(actualTimelineCookie);
828
829 actualDisplayFrameStartEvent->set_token(mToken);
830 actualDisplayFrameStartEvent->set_pid(surfaceFlingerPid);
831
832 actualDisplayFrameStartEvent->set_present_type(toProto(mFramePresentMetadata));
833 actualDisplayFrameStartEvent->set_on_time_finish(mFrameReadyMetadata ==
834 FrameReadyMetadata::OnTimeFinish);
835 actualDisplayFrameStartEvent->set_gpu_composition(mGpuComposition);
836 actualDisplayFrameStartEvent->set_jank_type(jankTypeBitmaskToProto(mJankType));
837 });
838 // Expected timeline end
839 FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
840 auto packet = ctx.NewTracePacket();
841 packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
842 packet->set_timestamp(static_cast<uint64_t>(mSurfaceFlingerActuals.endTime));
843
844 auto* event = packet->set_frame_timeline_event();
845 auto* actualDisplayFrameEndEvent = event->set_frame_end();
846
847 actualDisplayFrameEndEvent->set_cookie(actualTimelineCookie);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800848 });
849
850 for (auto& surfaceFrame : mSurfaceFrames) {
851 surfaceFrame->trace(mToken);
852 }
853}
854
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700855void FrameTimeline::flushPendingPresentFences() {
856 for (size_t i = 0; i < mPendingPresentFences.size(); i++) {
857 const auto& pendingPresentFence = mPendingPresentFences[i];
858 nsecs_t signalTime = Fence::SIGNAL_TIME_INVALID;
859 if (pendingPresentFence.first && pendingPresentFence.first->isValid()) {
860 signalTime = pendingPresentFence.first->getSignalTime();
861 if (signalTime == Fence::SIGNAL_TIME_PENDING) {
862 continue;
863 }
864 }
865 if (signalTime != Fence::SIGNAL_TIME_INVALID) {
866 auto& displayFrame = pendingPresentFence.second;
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800867 displayFrame->onPresent(signalTime);
868 displayFrame->trace(mSurfaceFlingerPid);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700869 }
870
871 mPendingPresentFences.erase(mPendingPresentFences.begin() + static_cast<int>(i));
872 --i;
873 }
874}
875
876void FrameTimeline::finalizeCurrentDisplayFrame() {
Adithya Srinivasan2d736322020-10-01 16:53:48 -0700877 while (mDisplayFrames.size() >= mMaxDisplayFrames) {
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700878 // We maintain only a fixed number of frames' data. Pop older frames
879 mDisplayFrames.pop_front();
880 }
881 mDisplayFrames.push_back(mCurrentDisplayFrame);
882 mCurrentDisplayFrame.reset();
Adithya Srinivasan05bd2d12021-01-11 18:49:58 +0000883 mCurrentDisplayFrame = std::make_shared<DisplayFrame>(mTimeStats, mJankClassificationThresholds,
884 &mTraceCookieCounter);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700885}
886
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800887nsecs_t FrameTimeline::DisplayFrame::getBaseTime() const {
888 nsecs_t baseTime =
889 getMinTime(mPredictionState, mSurfaceFlingerPredictions, mSurfaceFlingerActuals);
890 for (const auto& surfaceFrame : mSurfaceFrames) {
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700891 nsecs_t surfaceFrameBaseTime = surfaceFrame->getBaseTime();
892 if (surfaceFrameBaseTime != 0) {
893 baseTime = std::min(baseTime, surfaceFrameBaseTime);
894 }
895 }
896 return baseTime;
897}
898
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800899void FrameTimeline::DisplayFrame::dumpJank(std::string& result, nsecs_t baseTime,
900 int displayFrameCount) const {
901 if (mJankType == JankType::None) {
902 // Check if any Surface Frame has been janky
903 bool isJanky = false;
904 for (const auto& surfaceFrame : mSurfaceFrames) {
905 if (surfaceFrame->getJankType() != JankType::None) {
906 isJanky = true;
907 break;
908 }
909 }
910 if (!isJanky) {
911 return;
912 }
913 }
914 StringAppendF(&result, "Display Frame %d", displayFrameCount);
915 dump(result, baseTime);
916}
917
918void FrameTimeline::DisplayFrame::dumpAll(std::string& result, nsecs_t baseTime) const {
919 dump(result, baseTime);
920}
921
922void FrameTimeline::DisplayFrame::dump(std::string& result, nsecs_t baseTime) const {
923 if (mJankType != JankType::None) {
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700924 // Easily identify a janky Display Frame in the dump
925 StringAppendF(&result, " [*] ");
926 }
927 StringAppendF(&result, "\n");
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800928 StringAppendF(&result, "Prediction State : %s\n", toString(mPredictionState).c_str());
929 StringAppendF(&result, "Jank Type : %s\n", jankTypeBitmaskToString(mJankType).c_str());
930 StringAppendF(&result, "Present Metadata : %s\n", toString(mFramePresentMetadata).c_str());
931 StringAppendF(&result, "Finish Metadata: %s\n", toString(mFrameReadyMetadata).c_str());
932 StringAppendF(&result, "Start Metadata: %s\n", toString(mFrameStartMetadata).c_str());
933 std::chrono::nanoseconds vsyncPeriod(mVsyncPeriod);
934 StringAppendF(&result, "Vsync Period: %10f\n",
935 std::chrono::duration<double, std::milli>(vsyncPeriod).count());
936 nsecs_t presentDelta =
937 mSurfaceFlingerActuals.presentTime - mSurfaceFlingerPredictions.presentTime;
938 std::chrono::nanoseconds presentDeltaNs(std::abs(presentDelta));
939 StringAppendF(&result, "Present delta: %10f\n",
940 std::chrono::duration<double, std::milli>(presentDeltaNs).count());
941 std::chrono::nanoseconds deltaToVsync(std::abs(presentDelta) % mVsyncPeriod);
942 StringAppendF(&result, "Present delta %% refreshrate: %10f\n",
943 std::chrono::duration<double, std::milli>(deltaToVsync).count());
944 dumpTable(result, mSurfaceFlingerPredictions, mSurfaceFlingerActuals, "", mPredictionState,
945 baseTime);
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700946 StringAppendF(&result, "\n");
947 std::string indent = " "; // 4 spaces
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800948 for (const auto& surfaceFrame : mSurfaceFrames) {
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700949 surfaceFrame->dump(result, indent, baseTime);
950 }
951 StringAppendF(&result, "\n");
952}
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800953
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700954void FrameTimeline::dumpAll(std::string& result) {
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700955 std::lock_guard<std::mutex> lock(mMutex);
956 StringAppendF(&result, "Number of display frames : %d\n", (int)mDisplayFrames.size());
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800957 nsecs_t baseTime = (mDisplayFrames.empty()) ? 0 : mDisplayFrames[0]->getBaseTime();
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700958 for (size_t i = 0; i < mDisplayFrames.size(); i++) {
959 StringAppendF(&result, "Display Frame %d", static_cast<int>(i));
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800960 mDisplayFrames[i]->dumpAll(result, baseTime);
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700961 }
962}
963
964void FrameTimeline::dumpJank(std::string& result) {
965 std::lock_guard<std::mutex> lock(mMutex);
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800966 nsecs_t baseTime = (mDisplayFrames.empty()) ? 0 : mDisplayFrames[0]->getBaseTime();
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700967 for (size_t i = 0; i < mDisplayFrames.size(); i++) {
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800968 mDisplayFrames[i]->dumpJank(result, baseTime, static_cast<int>(i));
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700969 }
970}
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800971
Adithya Srinivasan8fc601d2020-09-25 13:51:09 -0700972void FrameTimeline::parseArgs(const Vector<String16>& args, std::string& result) {
973 ATRACE_CALL();
974 std::unordered_map<std::string, bool> argsMap;
975 for (size_t i = 0; i < args.size(); i++) {
976 argsMap[std::string(String8(args[i]).c_str())] = true;
977 }
978 if (argsMap.count("-jank")) {
979 dumpJank(result);
980 }
981 if (argsMap.count("-all")) {
982 dumpAll(result);
Adithya Srinivasanf279e042020-08-17 14:56:27 -0700983 }
984}
985
Adithya Srinivasan2d736322020-10-01 16:53:48 -0700986void FrameTimeline::setMaxDisplayFrames(uint32_t size) {
987 std::lock_guard<std::mutex> lock(mMutex);
988
989 // The size can either increase or decrease, clear everything, to be consistent
990 mDisplayFrames.clear();
991 mPendingPresentFences.clear();
992 mMaxDisplayFrames = size;
993}
994
995void FrameTimeline::reset() {
996 setMaxDisplayFrames(kDefaultMaxDisplayFrames);
997}
998
Adithya Srinivasan9b2ca3e2020-11-10 10:14:17 -0800999} // namespace impl
1000} // namespace android::frametimeline