Home | History | Annotate | Download | only in hwui 
      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 <statslog.h>
     22 #include <sys/mman.h>
     23 
     24 #include <algorithm>
     25 #include <cmath>
     26 #include <cstdio>
     27 #include <limits>
     28 
     29 #include <cutils/ashmem.h>
     30 #include <log/log.h>
     31 #include <sstream>
     32 
     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{
     48         Comparison{JankType::kMissedVsync, [](nsecs_t) { return 1; }, FrameInfoIndex::IntendedVsync,
     49                    FrameInfoIndex::Vsync},
     50 
     51         Comparison{JankType::kSlowUI,
     52                    [](nsecs_t frameInterval) { return static_cast<int64_t>(.5 * frameInterval); },
     53                    FrameInfoIndex::Vsync, FrameInfoIndex::SyncStart},
     54 
     55         Comparison{JankType::kSlowSync,
     56                    [](nsecs_t frameInterval) { return static_cast<int64_t>(.2 * frameInterval); },
     57                    FrameInfoIndex::SyncStart, FrameInfoIndex::IssueDrawCommandsStart},
     58 
     59         Comparison{JankType::kSlowRT,
     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 
     82 JankTracker::JankTracker(ProfileDataContainer* globalData, const DisplayInfo& displayInfo) {
     83     mGlobalData = globalData;
     84     nsecs_t frameIntervalNanos = static_cast<nsecs_t>(1_s / displayInfo.fps);
     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     setFrameInterval(frameIntervalNanos);
     99 }
    100 
    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 
    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     bool isTripleBuffered = mSwapDeadline > frame[FrameInfoIndex::IntendedVsync];
    143 
    144     mSwapDeadline = std::max(mSwapDeadline + mFrameInterval,
    145                              frame[FrameInfoIndex::IntendedVsync] + mFrameInterval);
    146 
    147     // If we hit the deadline, cool!
    148     if (frame[FrameInfoIndex::FrameCompleted] < mSwapDeadline || totalDuration < mFrameInterval) {
    149         if (isTripleBuffered) {
    150             mData->reportJankType(JankType::kHighInputLatency);
    151             (*mGlobalData)->reportJankType(JankType::kHighInputLatency);
    152         }
    153         return;
    154     }
    155 
    156     mData->reportJankType(JankType::kMissedDeadline);
    157     (*mGlobalData)->reportJankType(JankType::kMissedDeadline);
    158 
    159     // Janked, reset the swap deadline
    160     nsecs_t jitterNanos = frame[FrameInfoIndex::FrameCompleted] - frame[FrameInfoIndex::Vsync];
    161     nsecs_t lastFrameOffset = jitterNanos % mFrameInterval;
    162     mSwapDeadline = frame[FrameInfoIndex::FrameCompleted] - lastFrameOffset + mFrameInterval;
    163 
    164     for (auto& comparison : COMPARISONS) {
    165         int64_t delta = frame.duration(comparison.start, comparison.end);
    166         if (delta >= mThresholds[comparison.type] && delta < IGNORE_EXCEEDING) {
    167             mData->reportJankType(comparison.type);
    168             (*mGlobalData)->reportJankType(comparison.type);
    169         }
    170     }
    171 
    172     // Log daveys since they are weird and we don't know what they are (b/70339576)
    173     if (totalDuration >= 700_ms) {
    174         static int sDaveyCount = 0;
    175         std::stringstream ss;
    176         ss << "Davey! duration=" << ns2ms(totalDuration) << "ms; ";
    177         for (size_t i = 0; i < static_cast<size_t>(FrameInfoIndex::NumIndexes); i++) {
    178             ss << FrameInfoNames[i] << "=" << frame[i] << ", ";
    179         }
    180         ALOGI("%s", ss.str().c_str());
    181         // Just so we have something that counts up, the value is largely irrelevant
    182         ATRACE_INT(ss.str().c_str(), ++sDaveyCount);
    183         android::util::stats_write(android::util::DAVEY_OCCURRED, getuid(), ns2ms(totalDuration));
    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