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 <errno.h> 20 #include <inttypes.h> 21 #include <sys/mman.h> 22 23 #include <algorithm> 24 #include <cmath> 25 #include <cstdio> 26 #include <limits> 27 28 #include <cutils/ashmem.h> 29 #include <log/log.h> 30 #include <sstream> 31 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{ 47 Comparison{JankType::kMissedVsync, [](nsecs_t) { return 1; }, FrameInfoIndex::IntendedVsync, 48 FrameInfoIndex::Vsync}, 49 50 Comparison{JankType::kSlowUI, 51 [](nsecs_t frameInterval) { return static_cast<int64_t>(.5 * frameInterval); }, 52 FrameInfoIndex::Vsync, FrameInfoIndex::SyncStart}, 53 54 Comparison{JankType::kSlowSync, 55 [](nsecs_t frameInterval) { return static_cast<int64_t>(.2 * frameInterval); }, 56 FrameInfoIndex::SyncStart, FrameInfoIndex::IssueDrawCommandsStart}, 57 58 Comparison{JankType::kSlowRT, 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 81 JankTracker::JankTracker(ProfileDataContainer* globalData, const DisplayInfo& displayInfo) { 82 mGlobalData = globalData; 83 nsecs_t frameIntervalNanos = static_cast<nsecs_t>(1_s / displayInfo.fps); 84 #if USE_HWC2 85 nsecs_t sfOffset = frameIntervalNanos - (displayInfo.presentationDeadline - 1_ms); 86 nsecs_t offsetDelta = sfOffset - displayInfo.appVsyncOffset; 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 #endif 99 setFrameInterval(frameIntervalNanos); 100 } 101 102 void JankTracker::setFrameInterval(nsecs_t frameInterval) { 103 mFrameInterval = frameInterval; 104 105 for (auto& comparison : COMPARISONS) { 106 mThresholds[comparison.type] = comparison.computeThreadshold(frameInterval); 107 } 108 } 109 110 void JankTracker::finishFrame(const FrameInfo& frame) { 111 // Fast-path for jank-free frames 112 int64_t totalDuration = frame.duration(sFrameStart, FrameInfoIndex::FrameCompleted); 113 if (mDequeueTimeForgiveness && frame[FrameInfoIndex::DequeueBufferDuration] > 500_us) { 114 nsecs_t expectedDequeueDuration = mDequeueTimeForgiveness + frame[FrameInfoIndex::Vsync] - 115 frame[FrameInfoIndex::IssueDrawCommandsStart]; 116 if (expectedDequeueDuration > 0) { 117 // Forgive only up to the expected amount, but not more than 118 // the actual time spent blocked. 119 nsecs_t forgiveAmount = 120 std::min(expectedDequeueDuration, frame[FrameInfoIndex::DequeueBufferDuration]); 121 LOG_ALWAYS_FATAL_IF(forgiveAmount >= totalDuration, 122 "Impossible dequeue duration! dequeue duration reported %" PRId64 123 ", total duration %" PRId64, 124 forgiveAmount, totalDuration); 125 totalDuration -= forgiveAmount; 126 } 127 } 128 129 LOG_ALWAYS_FATAL_IF(totalDuration <= 0, "Impossible totalDuration %" PRId64, totalDuration); 130 mData->reportFrame(totalDuration); 131 (*mGlobalData)->reportFrame(totalDuration); 132 133 // Only things like Surface.lockHardwareCanvas() are exempt from tracking 134 if (CC_UNLIKELY(frame[FrameInfoIndex::Flags] & EXEMPT_FRAMES_FLAGS)) { 135 return; 136 } 137 138 if (totalDuration > mFrameInterval) { 139 mData->reportJank(); 140 (*mGlobalData)->reportJank(); 141 } 142 143 bool isTripleBuffered = mSwapDeadline > frame[FrameInfoIndex::IntendedVsync]; 144 145 mSwapDeadline = std::max(mSwapDeadline + mFrameInterval, 146 frame[FrameInfoIndex::IntendedVsync] + mFrameInterval); 147 148 // If we hit the deadline, cool! 149 if (frame[FrameInfoIndex::FrameCompleted] < mSwapDeadline) { 150 if (isTripleBuffered) { 151 mData->reportJankType(JankType::kHighInputLatency); 152 (*mGlobalData)->reportJankType(JankType::kHighInputLatency); 153 } 154 return; 155 } 156 157 mData->reportJankType(JankType::kMissedDeadline); 158 (*mGlobalData)->reportJankType(JankType::kMissedDeadline); 159 160 // Janked, reset the swap deadline 161 nsecs_t jitterNanos = frame[FrameInfoIndex::FrameCompleted] - frame[FrameInfoIndex::Vsync]; 162 nsecs_t lastFrameOffset = jitterNanos % mFrameInterval; 163 mSwapDeadline = frame[FrameInfoIndex::FrameCompleted] - lastFrameOffset + mFrameInterval; 164 165 for (auto& comparison : COMPARISONS) { 166 int64_t delta = frame.duration(comparison.start, comparison.end); 167 if (delta >= mThresholds[comparison.type] && delta < IGNORE_EXCEEDING) { 168 mData->reportJankType(comparison.type); 169 (*mGlobalData)->reportJankType(comparison.type); 170 } 171 } 172 173 // Log daveys since they are weird and we don't know what they are (b/70339576) 174 if (totalDuration >= 700_ms) { 175 static int sDaveyCount = 0; 176 std::stringstream ss; 177 ss << "Davey! duration=" << ns2ms(totalDuration) << "ms; "; 178 for (size_t i = 0; i < static_cast<size_t>(FrameInfoIndex::NumIndexes); i++) { 179 ss << FrameInfoNames[i] << "=" << frame[i] << ", "; 180 } 181 ALOGI("%s", ss.str().c_str()); 182 // Just so we have something that counts up, the value is largely irrelevant 183 ATRACE_INT(ss.str().c_str(), ++sDaveyCount); 184 } 185 } 186 187 void JankTracker::dumpData(int fd, const ProfileDataDescription* description, 188 const ProfileData* data) { 189 if (description) { 190 switch (description->type) { 191 case JankTrackerType::Generic: 192 break; 193 case JankTrackerType::Package: 194 dprintf(fd, "\nPackage: %s", description->name.c_str()); 195 break; 196 case JankTrackerType::Window: 197 dprintf(fd, "\nWindow: %s", description->name.c_str()); 198 break; 199 } 200 } 201 if (sFrameStart != FrameInfoIndex::IntendedVsync) { 202 dprintf(fd, "\nNote: Data has been filtered!"); 203 } 204 data->dump(fd); 205 dprintf(fd, "\n"); 206 } 207 208 void JankTracker::dumpFrames(int fd) { 209 dprintf(fd, "\n\n---PROFILEDATA---\n"); 210 for (size_t i = 0; i < static_cast<size_t>(FrameInfoIndex::NumIndexes); i++) { 211 dprintf(fd, "%s", FrameInfoNames[i].c_str()); 212 dprintf(fd, ","); 213 } 214 for (size_t i = 0; i < mFrames.size(); i++) { 215 FrameInfo& frame = mFrames[i]; 216 if (frame[FrameInfoIndex::SyncStart] == 0) { 217 continue; 218 } 219 dprintf(fd, "\n"); 220 for (int i = 0; i < static_cast<int>(FrameInfoIndex::NumIndexes); i++) { 221 dprintf(fd, "%" PRId64 ",", frame[i]); 222 } 223 } 224 dprintf(fd, "\n---PROFILEDATA---\n\n"); 225 } 226 227 void JankTracker::reset() { 228 mFrames.clear(); 229 mData->reset(); 230 (*mGlobalData)->reset(); 231 sFrameStart = Properties::filterOutTestOverhead ? FrameInfoIndex::HandleInputStart 232 : FrameInfoIndex::IntendedVsync; 233 } 234 235 } /* namespace uirenderer */ 236 } /* namespace android */ 237
