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 <statslog.h>
24 #include <sys/mman.h>
25
26 #include <algorithm>
27 #include <cmath>
28 #include <cstdio>
29 #include <limits>
30 #include <sstream>
31
32 #include "DeviceInfo.h"
33 #include "Properties.h"
34 #include "utils/TimeUtils.h"
35 #include "utils/Trace.h"
36
37 namespace android {
38 namespace uirenderer {
39
40 struct Comparison {
41 JankType type;
42 std::function<int64_t(nsecs_t)> computeThreadshold;
43 FrameInfoIndex start;
44 FrameInfoIndex end;
45 };
46
47 static const std::array<Comparison, 4> COMPARISONS{
__anone5bea62a0102() 48 Comparison{JankType::kMissedVsync, [](nsecs_t) { return 1; }, FrameInfoIndex::IntendedVsync,
49 FrameInfoIndex::Vsync},
50
51 Comparison{JankType::kSlowUI,
__anone5bea62a0202() 52 [](nsecs_t frameInterval) { return static_cast<int64_t>(.5 * frameInterval); },
53 FrameInfoIndex::Vsync, FrameInfoIndex::SyncStart},
54
55 Comparison{JankType::kSlowSync,
__anone5bea62a0302() 56 [](nsecs_t frameInterval) { return static_cast<int64_t>(.2 * frameInterval); },
57 FrameInfoIndex::SyncStart, FrameInfoIndex::IssueDrawCommandsStart},
58
59 Comparison{JankType::kSlowRT,
__anone5bea62a0402() 60 [](nsecs_t frameInterval) { return static_cast<int64_t>(.75 * frameInterval); },
61 FrameInfoIndex::IssueDrawCommandsStart, FrameInfoIndex::FrameCompleted},
62 };
63
64 // If the event exceeds 10 seconds throw it away, this isn't a jank event
65 // it's an ANR and will be handled as such
66 static const int64_t IGNORE_EXCEEDING = seconds_to_nanoseconds(10);
67
68 /*
69 * We don't track direct-drawing via Surface:lockHardwareCanvas()
70 * for now
71 *
72 * TODO: kSurfaceCanvas can negatively impact other drawing by using up
73 * time on the RenderThread, figure out how to attribute that as a jank-causer
74 */
75 static const int64_t EXEMPT_FRAMES_FLAGS = FrameInfoFlags::SurfaceCanvas;
76
77 // For testing purposes to try and eliminate test infra overhead we will
78 // consider any unknown delay of frame start as part of the test infrastructure
79 // and filter it out of the frame profile data
80 static FrameInfoIndex sFrameStart = FrameInfoIndex::IntendedVsync;
81
JankTracker(ProfileDataContainer * globalData)82 JankTracker::JankTracker(ProfileDataContainer* globalData) {
83 mGlobalData = globalData;
84 nsecs_t frameIntervalNanos = DeviceInfo::getVsyncPeriod();
85 nsecs_t sfOffset = DeviceInfo::getCompositorOffset();
86 nsecs_t offsetDelta = sfOffset - DeviceInfo::getAppOffset();
87 // There are two different offset cases. If the offsetDelta is positive
88 // and small, then the intention is to give apps extra time by leveraging
89 // pipelining between the UI & RT threads. If the offsetDelta is large or
90 // negative, the intention is to subtract time from the total duration
91 // in which case we can't afford to wait for dequeueBuffer blockage.
92 if (offsetDelta <= 4_ms && offsetDelta >= 0) {
93 // SF will begin composition at VSYNC-app + offsetDelta. If we are triple
94 // buffered, this is the expected time at which dequeueBuffer will
95 // return due to the staggering of VSYNC-app & VSYNC-sf.
96 mDequeueTimeForgiveness = offsetDelta + 4_ms;
97 }
98 setFrameInterval(frameIntervalNanos);
99 }
100
setFrameInterval(nsecs_t frameInterval)101 void JankTracker::setFrameInterval(nsecs_t frameInterval) {
102 mFrameInterval = frameInterval;
103
104 for (auto& comparison : COMPARISONS) {
105 mThresholds[comparison.type] = comparison.computeThreadshold(frameInterval);
106 }
107 }
108
finishFrame(const FrameInfo & frame)109 void JankTracker::finishFrame(const FrameInfo& frame) {
110 // Fast-path for jank-free frames
111 int64_t totalDuration = frame.duration(sFrameStart, FrameInfoIndex::FrameCompleted);
112 if (mDequeueTimeForgiveness && frame[FrameInfoIndex::DequeueBufferDuration] > 500_us) {
113 nsecs_t expectedDequeueDuration = mDequeueTimeForgiveness + frame[FrameInfoIndex::Vsync] -
114 frame[FrameInfoIndex::IssueDrawCommandsStart];
115 if (expectedDequeueDuration > 0) {
116 // Forgive only up to the expected amount, but not more than
117 // the actual time spent blocked.
118 nsecs_t forgiveAmount =
119 std::min(expectedDequeueDuration, frame[FrameInfoIndex::DequeueBufferDuration]);
120 LOG_ALWAYS_FATAL_IF(forgiveAmount >= totalDuration,
121 "Impossible dequeue duration! dequeue duration reported %" PRId64
122 ", total duration %" PRId64,
123 forgiveAmount, totalDuration);
124 totalDuration -= forgiveAmount;
125 }
126 }
127
128 LOG_ALWAYS_FATAL_IF(totalDuration <= 0, "Impossible totalDuration %" PRId64, totalDuration);
129 mData->reportFrame(totalDuration);
130 (*mGlobalData)->reportFrame(totalDuration);
131
132 // Only things like Surface.lockHardwareCanvas() are exempt from tracking
133 if (CC_UNLIKELY(frame[FrameInfoIndex::Flags] & EXEMPT_FRAMES_FLAGS)) {
134 return;
135 }
136
137 if (totalDuration > mFrameInterval) {
138 mData->reportJank();
139 (*mGlobalData)->reportJank();
140 }
141
142 if (mSwapDeadline < 0) {
143 mSwapDeadline = frame[FrameInfoIndex::IntendedVsync] + mFrameInterval;
144 }
145 bool isTripleBuffered = (mSwapDeadline - frame[FrameInfoIndex::IntendedVsync]) > (mFrameInterval * 0.1);
146
147 mSwapDeadline = std::max(mSwapDeadline + mFrameInterval,
148 frame[FrameInfoIndex::IntendedVsync] + mFrameInterval);
149
150 // If we hit the deadline, cool!
151 if (frame[FrameInfoIndex::FrameCompleted] < mSwapDeadline || totalDuration < mFrameInterval) {
152 if (isTripleBuffered) {
153 mData->reportJankType(JankType::kHighInputLatency);
154 (*mGlobalData)->reportJankType(JankType::kHighInputLatency);
155 }
156 return;
157 }
158
159 mData->reportJankType(JankType::kMissedDeadline);
160 (*mGlobalData)->reportJankType(JankType::kMissedDeadline);
161
162 // Janked, reset the swap deadline
163 nsecs_t jitterNanos = frame[FrameInfoIndex::FrameCompleted] - frame[FrameInfoIndex::Vsync];
164 nsecs_t lastFrameOffset = jitterNanos % mFrameInterval;
165 mSwapDeadline = frame[FrameInfoIndex::FrameCompleted] - lastFrameOffset + mFrameInterval;
166
167 for (auto& comparison : COMPARISONS) {
168 int64_t delta = frame.duration(comparison.start, comparison.end);
169 if (delta >= mThresholds[comparison.type] && delta < IGNORE_EXCEEDING) {
170 mData->reportJankType(comparison.type);
171 (*mGlobalData)->reportJankType(comparison.type);
172 }
173 }
174
175 // Log daveys since they are weird and we don't know what they are (b/70339576)
176 if (totalDuration >= 700_ms) {
177 static int sDaveyCount = 0;
178 std::stringstream ss;
179 ss << "Davey! duration=" << ns2ms(totalDuration) << "ms; ";
180 for (size_t i = 0; i < static_cast<size_t>(FrameInfoIndex::NumIndexes); i++) {
181 ss << FrameInfoNames[i] << "=" << frame[i] << ", ";
182 }
183 ALOGI("%s", ss.str().c_str());
184 // Just so we have something that counts up, the value is largely irrelevant
185 ATRACE_INT(ss.str().c_str(), ++sDaveyCount);
186 android::util::stats_write(android::util::DAVEY_OCCURRED, getuid(), ns2ms(totalDuration));
187 }
188 }
189
dumpData(int fd,const ProfileDataDescription * description,const ProfileData * data)190 void JankTracker::dumpData(int fd, const ProfileDataDescription* description,
191 const ProfileData* data) {
192 if (description) {
193 switch (description->type) {
194 case JankTrackerType::Generic:
195 break;
196 case JankTrackerType::Package:
197 dprintf(fd, "\nPackage: %s", description->name.c_str());
198 break;
199 case JankTrackerType::Window:
200 dprintf(fd, "\nWindow: %s", description->name.c_str());
201 break;
202 }
203 }
204 if (sFrameStart != FrameInfoIndex::IntendedVsync) {
205 dprintf(fd, "\nNote: Data has been filtered!");
206 }
207 data->dump(fd);
208 dprintf(fd, "\n");
209 }
210
dumpFrames(int fd)211 void JankTracker::dumpFrames(int fd) {
212 dprintf(fd, "\n\n---PROFILEDATA---\n");
213 for (size_t i = 0; i < static_cast<size_t>(FrameInfoIndex::NumIndexes); i++) {
214 dprintf(fd, "%s", FrameInfoNames[i].c_str());
215 dprintf(fd, ",");
216 }
217 for (size_t i = 0; i < mFrames.size(); i++) {
218 FrameInfo& frame = mFrames[i];
219 if (frame[FrameInfoIndex::SyncStart] == 0) {
220 continue;
221 }
222 dprintf(fd, "\n");
223 for (int i = 0; i < static_cast<int>(FrameInfoIndex::NumIndexes); i++) {
224 dprintf(fd, "%" PRId64 ",", frame[i]);
225 }
226 }
227 dprintf(fd, "\n---PROFILEDATA---\n\n");
228 }
229
reset()230 void JankTracker::reset() {
231 mFrames.clear();
232 mData->reset();
233 (*mGlobalData)->reset();
234 sFrameStart = Properties::filterOutTestOverhead ? FrameInfoIndex::HandleInputStart
235 : FrameInfoIndex::IntendedVsync;
236 }
237
finishGpuDraw(const FrameInfo & frame)238 void JankTracker::finishGpuDraw(const FrameInfo& frame) {
239 int64_t totalGPUDrawTime = frame.gpuDrawTime();
240 if (totalGPUDrawTime >= 0) {
241 mData->reportGPUFrame(totalGPUDrawTime);
242 (*mGlobalData)->reportGPUFrame(totalGPUDrawTime);
243 }
244 }
245
246 } /* namespace uirenderer */
247 } /* namespace android */
248