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
31namespace android {
32namespace uirenderer {
33
34static 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
42struct Comparison {
43    FrameInfoIndex start;
44    FrameInfoIndex end;
45};
46
47static 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
57static 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 */
66static 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
70static const uint32_t kBucketMinThreshold = 5;
71// If a frame is > this, start counting in increments of 2ms
72static const uint32_t kBucket2msIntervals = 32;
73// If a frame is > this, start counting in increments of 4ms
74static 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
79static FrameInfoIndex sFrameStart = FrameInfoIndex::IntendedVsync;
80
81// The interval of the slow frame histogram
82static const uint32_t kSlowFrameBucketIntervalMs = 50;
83// The start point of the slow frame bucket in ms
84static 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
88static 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
110static 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
123JankTracker::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
147JankTracker::~JankTracker() {
148    freeData();
149}
150
151void JankTracker::freeData() {
152    if (mIsMapped) {
153        munmap(mData, sizeof(ProfileData));
154    } else {
155        delete mData;
156    }
157    mIsMapped = false;
158    mData = nullptr;
159}
160
161void 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
206void 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
229void 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
279void 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
287void 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
314void 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
326uint32_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 */
346