JankTracker.cpp revision 52eb4e01a49fe2e94555c000de38bbcbbb13401b
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#include "JankTracker.h" 17 18#include <errno.h> 19#include <inttypes.h> 20 21#include <algorithm> 22#include <cmath> 23#include <cstdio> 24#include <limits> 25#include <sys/mman.h> 26 27#include <cutils/ashmem.h> 28#include <log/log.h> 29 30#include "Properties.h" 31#include "utils/TimeUtils.h" 32 33namespace android { 34namespace uirenderer { 35 36static const char* JANK_TYPE_NAMES[] = { 37 "Missed Vsync", 38 "High input latency", 39 "Slow UI thread", 40 "Slow bitmap uploads", 41 "Slow issue draw commands", 42}; 43 44struct Comparison { 45 FrameInfoIndex start; 46 FrameInfoIndex end; 47}; 48 49static const Comparison COMPARISONS[] = { 50 {FrameInfoIndex::IntendedVsync, FrameInfoIndex::Vsync}, 51 {FrameInfoIndex::OldestInputEvent, FrameInfoIndex::Vsync}, 52 {FrameInfoIndex::Vsync, FrameInfoIndex::SyncStart}, 53 {FrameInfoIndex::SyncStart, FrameInfoIndex::IssueDrawCommandsStart}, 54 {FrameInfoIndex::IssueDrawCommandsStart, FrameInfoIndex::FrameCompleted}, 55}; 56 57// If the event exceeds 10 seconds throw it away, this isn't a jank event 58// it's an ANR and will be handled as such 59static const int64_t IGNORE_EXCEEDING = seconds_to_nanoseconds(10); 60 61/* 62 * We don't track direct-drawing via Surface:lockHardwareCanvas() 63 * for now 64 * 65 * TODO: kSurfaceCanvas can negatively impact other drawing by using up 66 * time on the RenderThread, figure out how to attribute that as a jank-causer 67 */ 68static const int64_t EXEMPT_FRAMES_FLAGS = FrameInfoFlags::SurfaceCanvas; 69 70// The bucketing algorithm controls so to speak 71// If a frame is <= to this it goes in bucket 0 72static const uint32_t kBucketMinThreshold = 5; 73// If a frame is > this, start counting in increments of 2ms 74static const uint32_t kBucket2msIntervals = 32; 75// If a frame is > this, start counting in increments of 4ms 76static const uint32_t kBucket4msIntervals = 48; 77 78// For testing purposes to try and eliminate test infra overhead we will 79// consider any unknown delay of frame start as part of the test infrastructure 80// and filter it out of the frame profile data 81static FrameInfoIndex sFrameStart = FrameInfoIndex::IntendedVsync; 82 83// The interval of the slow frame histogram 84static const uint32_t kSlowFrameBucketIntervalMs = 50; 85// The start point of the slow frame bucket in ms 86static const uint32_t kSlowFrameBucketStartMs = 150; 87 88// This will be called every frame, performance sensitive 89// Uses bit twiddling to avoid branching while achieving the packing desired 90static uint32_t frameCountIndexForFrameTime(nsecs_t frameTime) { 91 uint32_t index = static_cast<uint32_t>(ns2ms(frameTime)); 92 // If index > kBucketMinThreshold mask will be 0xFFFFFFFF as a result 93 // of negating 1 (twos compliment, yaay) else mask will be 0 94 uint32_t mask = -(index > kBucketMinThreshold); 95 // If index > threshold, this will essentially perform: 96 // amountAboveThreshold = index - threshold; 97 // index = threshold + (amountAboveThreshold / 2) 98 // However if index is <= this will do nothing. It will underflow, do 99 // a right shift by 0 (no-op), then overflow back to the original value 100 index = ((index - kBucket4msIntervals) >> (index > kBucket4msIntervals)) 101 + kBucket4msIntervals; 102 index = ((index - kBucket2msIntervals) >> (index > kBucket2msIntervals)) 103 + kBucket2msIntervals; 104 // If index was < minThreshold at the start of all this it's going to 105 // be a pretty garbage value right now. However, mask is 0 so we'll end 106 // up with the desired result of 0. 107 index = (index - kBucketMinThreshold) & mask; 108 return index; 109} 110 111// Only called when dumping stats, less performance sensitive 112static uint32_t frameTimeForFrameCountIndex(uint32_t index) { 113 index = index + kBucketMinThreshold; 114 if (index > kBucket2msIntervals) { 115 index += (index - kBucket2msIntervals); 116 } 117 if (index > kBucket4msIntervals) { 118 // This works because it was already doubled by the above if 119 // 1 is added to shift slightly more towards the middle of the bucket 120 index += (index - kBucket4msIntervals) + 1; 121 } 122 return index; 123} 124 125JankTracker::JankTracker(const DisplayInfo& displayInfo) { 126 // By default this will use malloc memory. It may be moved later to ashmem 127 // if there is shared space for it and a request comes in to do that. 128 mData = new ProfileData; 129 reset(); 130 nsecs_t frameIntervalNanos = static_cast<nsecs_t>(1_s / displayInfo.fps); 131#if USE_HWC2 132 nsecs_t sfOffset = frameIntervalNanos - (displayInfo.presentationDeadline - 1_ms); 133 nsecs_t offsetDelta = sfOffset - displayInfo.appVsyncOffset; 134 // There are two different offset cases. If the offsetDelta is positive 135 // and small, then the intention is to give apps extra time by leveraging 136 // pipelining between the UI & RT threads. If the offsetDelta is large or 137 // negative, the intention is to subtract time from the total duration 138 // in which case we can't afford to wait for dequeueBuffer blockage. 139 if (offsetDelta <= 4_ms && offsetDelta >= 0) { 140 // SF will begin composition at VSYNC-app + offsetDelta. If we are triple 141 // buffered, this is the expected time at which dequeueBuffer will 142 // return due to the staggering of VSYNC-app & VSYNC-sf. 143 mDequeueTimeForgiveness = offsetDelta + 4_ms; 144 } 145#endif 146 setFrameInterval(frameIntervalNanos); 147} 148 149JankTracker::~JankTracker() { 150 freeData(); 151} 152 153void JankTracker::freeData() { 154 if (mIsMapped) { 155 munmap(mData, sizeof(ProfileData)); 156 } else { 157 delete mData; 158 } 159 mIsMapped = false; 160 mData = nullptr; 161} 162 163void JankTracker::switchStorageToAshmem(int ashmemfd) { 164 int regionSize = ashmem_get_size_region(ashmemfd); 165 if (regionSize < static_cast<int>(sizeof(ProfileData))) { 166 ALOGW("Ashmem region is too small! Received %d, required %u", 167 regionSize, static_cast<unsigned int>(sizeof(ProfileData))); 168 return; 169 } 170 ProfileData* newData = reinterpret_cast<ProfileData*>( 171 mmap(NULL, sizeof(ProfileData), PROT_READ | PROT_WRITE, 172 MAP_SHARED, ashmemfd, 0)); 173 if (newData == MAP_FAILED) { 174 int err = errno; 175 ALOGW("Failed to move profile data to ashmem fd %d, error = %d", 176 ashmemfd, err); 177 return; 178 } 179 180 // The new buffer may have historical data that we want to build on top of 181 // But let's make sure we don't overflow Just In Case 182 uint32_t divider = 0; 183 if (newData->totalFrameCount > (1 << 24)) { 184 divider = 4; 185 } 186 for (size_t i = 0; i < mData->jankTypeCounts.size(); i++) { 187 newData->jankTypeCounts[i] >>= divider; 188 newData->jankTypeCounts[i] += mData->jankTypeCounts[i]; 189 } 190 for (size_t i = 0; i < mData->frameCounts.size(); i++) { 191 newData->frameCounts[i] >>= divider; 192 newData->frameCounts[i] += mData->frameCounts[i]; 193 } 194 newData->jankFrameCount >>= divider; 195 newData->jankFrameCount += mData->jankFrameCount; 196 newData->totalFrameCount >>= divider; 197 newData->totalFrameCount += mData->totalFrameCount; 198 if (newData->statStartTime > mData->statStartTime 199 || newData->statStartTime == 0) { 200 newData->statStartTime = mData->statStartTime; 201 } 202 203 freeData(); 204 mData = newData; 205 mIsMapped = true; 206} 207 208void JankTracker::setFrameInterval(nsecs_t frameInterval) { 209 mFrameInterval = frameInterval; 210 mThresholds[kMissedVsync] = 1; 211 /* 212 * Due to interpolation and sample rate differences between the touch 213 * panel and the display (example, 85hz touch panel driving a 60hz display) 214 * we call high latency 1.5 * frameinterval 215 * 216 * NOTE: Be careful when tuning this! A theoretical 1,000hz touch panel 217 * on a 60hz display will show kOldestInputEvent - kIntendedVsync of being 15ms 218 * Thus this must always be larger than frameInterval, or it will fail 219 */ 220 mThresholds[kHighInputLatency] = static_cast<int64_t>(1.5 * frameInterval); 221 222 // Note that these do not add up to 1. This is intentional. It's to deal 223 // with variance in values, and should be sort of an upper-bound on what 224 // is reasonable to expect. 225 mThresholds[kSlowUI] = static_cast<int64_t>(.5 * frameInterval); 226 mThresholds[kSlowSync] = static_cast<int64_t>(.2 * frameInterval); 227 mThresholds[kSlowRT] = static_cast<int64_t>(.75 * frameInterval); 228 229} 230 231void JankTracker::addFrame(const FrameInfo& frame) { 232 mData->totalFrameCount++; 233 // Fast-path for jank-free frames 234 int64_t totalDuration = frame.duration(sFrameStart, FrameInfoIndex::FrameCompleted); 235 if (mDequeueTimeForgiveness 236 && frame[FrameInfoIndex::DequeueBufferDuration] > 500_us) { 237 nsecs_t expectedDequeueDuration = 238 mDequeueTimeForgiveness + frame[FrameInfoIndex::Vsync] 239 - frame[FrameInfoIndex::IssueDrawCommandsStart]; 240 if (expectedDequeueDuration > 0) { 241 // Forgive only up to the expected amount, but not more than 242 // the actual time spent blocked. 243 nsecs_t forgiveAmount = std::min(expectedDequeueDuration, 244 frame[FrameInfoIndex::DequeueBufferDuration]); 245 totalDuration -= forgiveAmount; 246 } 247 } 248 uint32_t framebucket = frameCountIndexForFrameTime(totalDuration); 249 // Keep the fast path as fast as possible. 250 if (CC_LIKELY(totalDuration < mFrameInterval)) { 251 mData->frameCounts[framebucket]++; 252 return; 253 } 254 255 // Only things like Surface.lockHardwareCanvas() are exempt from tracking 256 if (frame[FrameInfoIndex::Flags] & EXEMPT_FRAMES_FLAGS) { 257 return; 258 } 259 260 if (framebucket <= mData->frameCounts.size()) { 261 mData->frameCounts[framebucket]++; 262 } else { 263 framebucket = (ns2ms(totalDuration) - kSlowFrameBucketStartMs) 264 / kSlowFrameBucketIntervalMs; 265 framebucket = std::min(framebucket, 266 static_cast<uint32_t>(mData->slowFrameCounts.size() - 1)); 267 framebucket = std::max(framebucket, 0u); 268 mData->slowFrameCounts[framebucket]++; 269 } 270 271 mData->jankFrameCount++; 272 273 for (int i = 0; i < NUM_BUCKETS; i++) { 274 int64_t delta = frame.duration(COMPARISONS[i].start, COMPARISONS[i].end); 275 if (delta >= mThresholds[i] && delta < IGNORE_EXCEEDING) { 276 mData->jankTypeCounts[i]++; 277 } 278 } 279} 280 281void JankTracker::dumpBuffer(const void* buffer, size_t bufsize, int fd) { 282 if (bufsize < sizeof(ProfileData)) { 283 return; 284 } 285 const ProfileData* data = reinterpret_cast<const ProfileData*>(buffer); 286 dumpData(data, fd); 287} 288 289void JankTracker::dumpData(const ProfileData* data, int fd) { 290 if (sFrameStart != FrameInfoIndex::IntendedVsync) { 291 dprintf(fd, "\nNote: Data has been filtered!"); 292 } 293 dprintf(fd, "\nStats since: %" PRIu64 "ns", data->statStartTime); 294 dprintf(fd, "\nTotal frames rendered: %u", data->totalFrameCount); 295 dprintf(fd, "\nJanky frames: %u (%.2f%%)", data->jankFrameCount, 296 (float) data->jankFrameCount / (float) data->totalFrameCount * 100.0f); 297 dprintf(fd, "\n50th percentile: %ums", findPercentile(data, 50)); 298 dprintf(fd, "\n90th percentile: %ums", findPercentile(data, 90)); 299 dprintf(fd, "\n95th percentile: %ums", findPercentile(data, 95)); 300 dprintf(fd, "\n99th percentile: %ums", findPercentile(data, 99)); 301 for (int i = 0; i < NUM_BUCKETS; i++) { 302 dprintf(fd, "\nNumber %s: %u", JANK_TYPE_NAMES[i], data->jankTypeCounts[i]); 303 } 304 dprintf(fd, "\nHISTOGRAM:"); 305 for (size_t i = 0; i < data->frameCounts.size(); i++) { 306 dprintf(fd, " %ums=%u", frameTimeForFrameCountIndex(i), 307 data->frameCounts[i]); 308 } 309 for (size_t i = 0; i < data->slowFrameCounts.size(); i++) { 310 dprintf(fd, " %zums=%u", (i * kSlowFrameBucketIntervalMs) + kSlowFrameBucketStartMs, 311 data->slowFrameCounts[i]); 312 } 313 dprintf(fd, "\n"); 314} 315 316void JankTracker::reset() { 317 mData->jankTypeCounts.fill(0); 318 mData->frameCounts.fill(0); 319 mData->slowFrameCounts.fill(0); 320 mData->totalFrameCount = 0; 321 mData->jankFrameCount = 0; 322 mData->statStartTime = systemTime(CLOCK_MONOTONIC); 323 sFrameStart = Properties::filterOutTestOverhead 324 ? FrameInfoIndex::HandleInputStart 325 : FrameInfoIndex::IntendedVsync; 326} 327 328uint32_t JankTracker::findPercentile(const ProfileData* data, int percentile) { 329 int pos = percentile * data->totalFrameCount / 100; 330 int remaining = data->totalFrameCount - pos; 331 for (int i = data->slowFrameCounts.size() - 1; i >= 0; i--) { 332 remaining -= data->slowFrameCounts[i]; 333 if (remaining <= 0) { 334 return (i * kSlowFrameBucketIntervalMs) + kSlowFrameBucketStartMs; 335 } 336 } 337 for (int i = data->frameCounts.size() - 1; i >= 0; i--) { 338 remaining -= data->frameCounts[i]; 339 if (remaining <= 0) { 340 return frameTimeForFrameCountIndex(i); 341 } 342 } 343 return 0; 344} 345 346} /* namespace uirenderer */ 347} /* namespace android */ 348