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{
__anond0ea453f0102() 47         Comparison{JankType::kMissedVsync, [](nsecs_t) { return 1; }, FrameInfoIndex::IntendedVsync,
48                    FrameInfoIndex::Vsync},
49 
50         Comparison{JankType::kSlowUI,
__anond0ea453f0202() 51                    [](nsecs_t frameInterval) { return static_cast<int64_t>(.5 * frameInterval); },
52                    FrameInfoIndex::Vsync, FrameInfoIndex::SyncStart},
53 
54         Comparison{JankType::kSlowSync,
__anond0ea453f0302() 55                    [](nsecs_t frameInterval) { return static_cast<int64_t>(.2 * frameInterval); },
56                    FrameInfoIndex::SyncStart, FrameInfoIndex::IssueDrawCommandsStart},
57 
58         Comparison{JankType::kSlowRT,
__anond0ea453f0402() 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 
JankTracker(ProfileDataContainer * globalData,const DisplayInfo & displayInfo)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 
setFrameInterval(nsecs_t frameInterval)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 
finishFrame(const FrameInfo & frame)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 
dumpData(int fd,const ProfileDataDescription * description,const ProfileData * data)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 
dumpFrames(int fd)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 
reset()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