1 /*
2 * Copyright (C) 2015 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 #include "JankTracker.h"
18
19 #include <cutils/ashmem.h>
20 #include <errno.h>
21 #include <inttypes.h>
22 #include <log/log.h>
23 #include <sys/mman.h>
24
25 #include <algorithm>
26 #include <cmath>
27 #include <cstdio>
28 #include <limits>
29 #include <sstream>
30
31 #include "DeviceInfo.h"
32 #include "Properties.h"
33 #include "utils/TimeUtils.h"
34 #include "utils/Trace.h"
35
36 namespace android {
37 namespace uirenderer {
38
39 struct Comparison {
40 JankType type;
41 std::function<int64_t(nsecs_t)> computeThreadshold;
42 FrameInfoIndex start;
43 FrameInfoIndex end;
44 };
45
46 static const std::array<Comparison, 4> COMPARISONS{
__anon909821eb0102() 47 Comparison{JankType::kMissedVsync, [](nsecs_t) { return 1; }, FrameInfoIndex::IntendedVsync,
48 FrameInfoIndex::Vsync},
49
50 Comparison{JankType::kSlowUI,
__anon909821eb0202() 51 [](nsecs_t frameInterval) { return static_cast<int64_t>(.5 * frameInterval); },
52 FrameInfoIndex::Vsync, FrameInfoIndex::SyncStart},
53
54 Comparison{JankType::kSlowSync,
__anon909821eb0302() 55 [](nsecs_t frameInterval) { return static_cast<int64_t>(.2 * frameInterval); },
56 FrameInfoIndex::SyncStart, FrameInfoIndex::IssueDrawCommandsStart},
57
58 Comparison{JankType::kSlowRT,
__anon909821eb0402() 59 [](nsecs_t frameInterval) { return static_cast<int64_t>(.75 * frameInterval); },
60 FrameInfoIndex::IssueDrawCommandsStart, FrameInfoIndex::FrameCompleted},
61 };
62
63 // If the event exceeds 10 seconds throw it away, this isn't a jank event
64 // it's an ANR and will be handled as such
65 static const int64_t IGNORE_EXCEEDING = seconds_to_nanoseconds(10);
66
67 /*
68 * We don't track direct-drawing via Surface:lockHardwareCanvas()
69 * for now
70 *
71 * TODO: kSurfaceCanvas can negatively impact other drawing by using up
72 * time on the RenderThread, figure out how to attribute that as a jank-causer
73 */
74 static const int64_t EXEMPT_FRAMES_FLAGS = FrameInfoFlags::SurfaceCanvas;
75
76 // For testing purposes to try and eliminate test infra overhead we will
77 // consider any unknown delay of frame start as part of the test infrastructure
78 // and filter it out of the frame profile data
79 static FrameInfoIndex sFrameStart = FrameInfoIndex::IntendedVsync;
80
JankTracker(ProfileDataContainer * globalData)81 JankTracker::JankTracker(ProfileDataContainer* globalData)
82 : mData(globalData->getDataMutex())
83 , mDataMutex(globalData->getDataMutex()) {
84 mGlobalData = globalData;
85 nsecs_t frameIntervalNanos = DeviceInfo::getVsyncPeriod();
86 nsecs_t sfOffset = DeviceInfo::getCompositorOffset();
87 nsecs_t offsetDelta = sfOffset - DeviceInfo::getAppOffset();
88 // There are two different offset cases. If the offsetDelta is positive
89 // and small, then the intention is to give apps extra time by leveraging
90 // pipelining between the UI & RT threads. If the offsetDelta is large or
91 // negative, the intention is to subtract time from the total duration
92 // in which case we can't afford to wait for dequeueBuffer blockage.
93 if (offsetDelta <= 4_ms && offsetDelta >= 0) {
94 // SF will begin composition at VSYNC-app + offsetDelta. If we are triple
95 // buffered, this is the expected time at which dequeueBuffer will
96 // return due to the staggering of VSYNC-app & VSYNC-sf.
97 mDequeueTimeForgivenessLegacy = offsetDelta + 4_ms;
98 }
99 mFrameIntervalLegacy = frameIntervalNanos;
100 }
101
calculateLegacyJank(FrameInfo & frame)102 void JankTracker::calculateLegacyJank(FrameInfo& frame) REQUIRES(mDataMutex) {
103 // Fast-path for jank-free frames
104 int64_t totalDuration = frame.duration(sFrameStart, FrameInfoIndex::SwapBuffersCompleted);
105 if (mDequeueTimeForgivenessLegacy && frame[FrameInfoIndex::DequeueBufferDuration] > 500_us) {
106 nsecs_t expectedDequeueDuration = mDequeueTimeForgivenessLegacy
107 + frame[FrameInfoIndex::Vsync]
108 - frame[FrameInfoIndex::IssueDrawCommandsStart];
109 if (expectedDequeueDuration > 0) {
110 // Forgive only up to the expected amount, but not more than
111 // the actual time spent blocked.
112 nsecs_t forgiveAmount =
113 std::min(expectedDequeueDuration, frame[FrameInfoIndex::DequeueBufferDuration]);
114 if (forgiveAmount >= totalDuration) {
115 ALOGV("Impossible dequeue duration! dequeue duration reported %" PRId64
116 ", total duration %" PRId64,
117 forgiveAmount, totalDuration);
118 return;
119 }
120 totalDuration -= forgiveAmount;
121 }
122 }
123
124 if (totalDuration <= 0) {
125 ALOGV("Impossible totalDuration %" PRId64 " start=%" PRIi64 " gpuComplete=%" PRIi64,
126 totalDuration, frame[FrameInfoIndex::IntendedVsync],
127 frame[FrameInfoIndex::GpuCompleted]);
128 return;
129 }
130
131 // Only things like Surface.lockHardwareCanvas() are exempt from tracking
132 if (CC_UNLIKELY(frame[FrameInfoIndex::Flags] & EXEMPT_FRAMES_FLAGS)) {
133 return;
134 }
135
136 if (totalDuration > mFrameIntervalLegacy) {
137 mData->reportJankLegacy();
138 (*mGlobalData)->reportJankLegacy();
139 }
140
141 if (mSwapDeadlineLegacy < 0) {
142 mSwapDeadlineLegacy = frame[FrameInfoIndex::IntendedVsync] + mFrameIntervalLegacy;
143 }
144 bool isTripleBuffered = (mSwapDeadlineLegacy - frame[FrameInfoIndex::IntendedVsync])
145 > (mFrameIntervalLegacy * 0.1);
146
147 mSwapDeadlineLegacy = std::max(mSwapDeadlineLegacy + mFrameIntervalLegacy,
148 frame[FrameInfoIndex::IntendedVsync] + mFrameIntervalLegacy);
149
150 // If we hit the deadline, cool!
151 if (frame[FrameInfoIndex::FrameCompleted] < mSwapDeadlineLegacy
152 || totalDuration < mFrameIntervalLegacy) {
153 if (isTripleBuffered) {
154 mData->reportJankType(JankType::kHighInputLatency);
155 (*mGlobalData)->reportJankType(JankType::kHighInputLatency);
156 }
157 return;
158 }
159
160 mData->reportJankType(JankType::kMissedDeadlineLegacy);
161 (*mGlobalData)->reportJankType(JankType::kMissedDeadlineLegacy);
162
163 // Janked, reset the swap deadline
164 nsecs_t jitterNanos = frame[FrameInfoIndex::FrameCompleted] - frame[FrameInfoIndex::Vsync];
165 nsecs_t lastFrameOffset = jitterNanos % mFrameIntervalLegacy;
166 mSwapDeadlineLegacy = frame[FrameInfoIndex::FrameCompleted]
167 - lastFrameOffset + mFrameIntervalLegacy;
168 }
169
finishFrame(FrameInfo & frame,std::unique_ptr<FrameMetricsReporter> & reporter,int64_t frameNumber,int32_t surfaceControlId)170 void JankTracker::finishFrame(FrameInfo& frame, std::unique_ptr<FrameMetricsReporter>& reporter,
171 int64_t frameNumber, int32_t surfaceControlId) {
172 std::lock_guard lock(mDataMutex);
173
174 calculateLegacyJank(frame);
175
176 // Fast-path for jank-free frames
177 int64_t totalDuration = frame.duration(FrameInfoIndex::IntendedVsync,
178 FrameInfoIndex::FrameCompleted);
179
180 if (totalDuration <= 0) {
181 ALOGV("Impossible totalDuration %" PRId64, totalDuration);
182 return;
183 }
184 mData->reportFrame(totalDuration);
185 (*mGlobalData)->reportFrame(totalDuration);
186
187 // Only things like Surface.lockHardwareCanvas() are exempt from tracking
188 if (CC_UNLIKELY(frame[FrameInfoIndex::Flags] & EXEMPT_FRAMES_FLAGS)) {
189 return;
190 }
191
192 int64_t frameInterval = frame[FrameInfoIndex::FrameInterval];
193
194 // If we starter earlier than the intended frame start assuming an unstuffed scenario, it means
195 // that we are in a triple buffering situation.
196 bool isTripleBuffered = (mNextFrameStartUnstuffed - frame[FrameInfoIndex::IntendedVsync])
197 > (frameInterval * 0.1);
198
199 int64_t deadline = frame[FrameInfoIndex::FrameDeadline];
200
201 // If we are in triple buffering, we have enough buffers in queue to sustain a single frame
202 // drop without jank, so adjust the frame interval to the deadline.
203 if (isTripleBuffered) {
204 int64_t originalDeadlineDuration = deadline - frame[FrameInfoIndex::IntendedVsync];
205 deadline = mNextFrameStartUnstuffed + originalDeadlineDuration;
206 frame.set(FrameInfoIndex::FrameDeadline) = deadline;
207 }
208
209 // If we hit the deadline, cool!
210 if (frame[FrameInfoIndex::GpuCompleted] < deadline) {
211 if (isTripleBuffered) {
212 mData->reportJankType(JankType::kHighInputLatency);
213 (*mGlobalData)->reportJankType(JankType::kHighInputLatency);
214
215 // Buffer stuffing state gets carried over to next frame, unless there is a "pause"
216 mNextFrameStartUnstuffed += frameInterval;
217 }
218 } else {
219 mData->reportJankType(JankType::kMissedDeadline);
220 (*mGlobalData)->reportJankType(JankType::kMissedDeadline);
221 mData->reportJank();
222 (*mGlobalData)->reportJank();
223
224 // Janked, store the adjust deadline to detect triple buffering in next frame correctly.
225 nsecs_t jitterNanos = frame[FrameInfoIndex::GpuCompleted]
226 - frame[FrameInfoIndex::Vsync];
227 nsecs_t lastFrameOffset = jitterNanos % frameInterval;
228
229 // Note the time when the next frame would start in an unstuffed situation. If it starts
230 // earlier, we are in a stuffed situation.
231 mNextFrameStartUnstuffed = frame[FrameInfoIndex::GpuCompleted]
232 - lastFrameOffset + frameInterval;
233
234 recomputeThresholds(frameInterval);
235 for (auto& comparison : COMPARISONS) {
236 int64_t delta = frame.duration(comparison.start, comparison.end);
237 if (delta >= mThresholds[comparison.type] && delta < IGNORE_EXCEEDING) {
238 mData->reportJankType(comparison.type);
239 (*mGlobalData)->reportJankType(comparison.type);
240 }
241 }
242
243 // Log daveys since they are weird and we don't know what they are (b/70339576)
244 if (totalDuration >= 700_ms) {
245 static int sDaveyCount = 0;
246 std::stringstream ss;
247 ss << "Davey! duration=" << ns2ms(totalDuration) << "ms; ";
248 for (size_t i = 0; i < static_cast<size_t>(FrameInfoIndex::NumIndexes); i++) {
249 ss << FrameInfoNames[i] << "=" << frame[i] << ", ";
250 }
251 ALOGI("%s", ss.str().c_str());
252 // Just so we have something that counts up, the value is largely irrelevant
253 ATRACE_INT(ss.str().c_str(), ++sDaveyCount);
254 }
255 }
256
257 int64_t totalGPUDrawTime = frame.gpuDrawTime();
258 if (totalGPUDrawTime >= 0) {
259 mData->reportGPUFrame(totalGPUDrawTime);
260 (*mGlobalData)->reportGPUFrame(totalGPUDrawTime);
261 }
262
263 if (CC_UNLIKELY(reporter.get() != nullptr)) {
264 reporter->reportFrameMetrics(frame.data(), false /* hasPresentTime */, frameNumber,
265 surfaceControlId);
266 }
267 }
268
recomputeThresholds(int64_t frameBudget)269 void JankTracker::recomputeThresholds(int64_t frameBudget) REQUIRES(mDataMutex) {
270 if (mThresholdsFrameBudget == frameBudget) {
271 return;
272 }
273 mThresholdsFrameBudget = frameBudget;
274 for (auto& comparison : COMPARISONS) {
275 mThresholds[comparison.type] = comparison.computeThreadshold(frameBudget);
276 }
277 }
278
dumpData(int fd,const ProfileDataDescription * description,const ProfileData * data)279 void JankTracker::dumpData(int fd, const ProfileDataDescription* description,
280 const ProfileData* data) {
281
282 if (description) {
283 switch (description->type) {
284 case JankTrackerType::Generic:
285 break;
286 case JankTrackerType::Package:
287 dprintf(fd, "\nPackage: %s", description->name.c_str());
288 break;
289 case JankTrackerType::Window:
290 dprintf(fd, "\nWindow: %s", description->name.c_str());
291 break;
292 }
293 }
294 if (sFrameStart != FrameInfoIndex::IntendedVsync) {
295 dprintf(fd, "\nNote: Data has been filtered!");
296 }
297 data->dump(fd);
298 dprintf(fd, "\n");
299 }
300
dumpFrames(int fd)301 void JankTracker::dumpFrames(int fd) {
302 dprintf(fd, "\n\n---PROFILEDATA---\n");
303 for (size_t i = 0; i < static_cast<size_t>(FrameInfoIndex::NumIndexes); i++) {
304 dprintf(fd, "%s", FrameInfoNames[i]);
305 dprintf(fd, ",");
306 }
307 for (size_t i = 0; i < mFrames.size(); i++) {
308 FrameInfo& frame = mFrames[i];
309 if (frame[FrameInfoIndex::SyncStart] == 0) {
310 continue;
311 }
312 dprintf(fd, "\n");
313 for (int i = 0; i < static_cast<int>(FrameInfoIndex::NumIndexes); i++) {
314 dprintf(fd, "%" PRId64 ",", frame[i]);
315 }
316 }
317 dprintf(fd, "\n---PROFILEDATA---\n\n");
318 }
319
reset()320 void JankTracker::reset() REQUIRES(mDataMutex) {
321 mFrames.clear();
322 mData->reset();
323 (*mGlobalData)->reset();
324 sFrameStart = Properties::filterOutTestOverhead ? FrameInfoIndex::HandleInputStart
325 : FrameInfoIndex::IntendedVsync;
326 }
327
328 } /* namespace uirenderer */
329 } /* namespace android */
330