libs/hwui/JankTracker.cpp

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