1 /*
2  * Copyright (C) 2013 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 // TODO(b/129481165): remove the #pragma below and fix conversion issues
18 #pragma clang diagnostic push
19 #pragma clang diagnostic ignored "-Wconversion"
20 
21 #define ATRACE_TAG ATRACE_TAG_GRAPHICS
22 //#define LOG_NDEBUG 0
23 
24 // This is needed for stdint.h to define INT64_MAX in C++
25 #define __STDC_LIMIT_MACROS
26 
27 #include <math.h>
28 
29 #include <algorithm>
30 
31 #include <android-base/stringprintf.h>
32 #include <cutils/properties.h>
33 #include <log/log.h>
34 #include <utils/Thread.h>
35 #include <utils/Trace.h>
36 
37 #include <ui/FenceTime.h>
38 
39 #include "DispSync.h"
40 #include "EventLog/EventLog.h"
41 #include "SurfaceFlinger.h"
42 
43 using android::base::StringAppendF;
44 using std::max;
45 using std::min;
46 
47 namespace android {
48 
49 DispSync::~DispSync() = default;
50 DispSync::Callback::~Callback() = default;
51 
52 namespace impl {
53 
54 // Setting this to true adds a zero-phase tracer for correlating with hardware
55 // vsync events
56 static const bool kEnableZeroPhaseTracer = false;
57 
58 // This is the threshold used to determine when hardware vsync events are
59 // needed to re-synchronize the software vsync model with the hardware.  The
60 // error metric used is the mean of the squared difference between each
61 // present time and the nearest software-predicted vsync.
62 static const nsecs_t kErrorThreshold = 160000000000; // 400 usec squared
63 
64 #undef LOG_TAG
65 #define LOG_TAG "DispSyncThread"
66 class DispSyncThread : public Thread {
67 public:
DispSyncThread(const char * name,bool showTraceDetailedInfo)68     DispSyncThread(const char* name, bool showTraceDetailedInfo)
69           : mName(name),
70             mStop(false),
71             mModelLocked("DispSync:ModelLocked", false),
72             mPeriod(0),
73             mPhase(0),
74             mReferenceTime(0),
75             mWakeupLatency(0),
76             mFrameNumber(0),
77             mTraceDetailedInfo(showTraceDetailedInfo) {}
78 
~DispSyncThread()79     virtual ~DispSyncThread() {}
80 
updateModel(nsecs_t period,nsecs_t phase,nsecs_t referenceTime)81     void updateModel(nsecs_t period, nsecs_t phase, nsecs_t referenceTime) {
82         if (mTraceDetailedInfo) ATRACE_CALL();
83         Mutex::Autolock lock(mMutex);
84 
85         mPhase = phase;
86         const bool referenceTimeChanged = mReferenceTime != referenceTime;
87         mReferenceTime = referenceTime;
88         if (mPeriod != 0 && mPeriod != period && mReferenceTime != 0) {
89             // Inflate the reference time to be the most recent predicted
90             // vsync before the current time.
91             const nsecs_t now = systemTime(SYSTEM_TIME_MONOTONIC);
92             const nsecs_t baseTime = now - mReferenceTime;
93             const nsecs_t numOldPeriods = baseTime / mPeriod;
94             mReferenceTime = mReferenceTime + (numOldPeriods)*mPeriod;
95         }
96         mPeriod = period;
97         if (!mModelLocked && referenceTimeChanged) {
98             for (auto& eventListener : mEventListeners) {
99                 eventListener.mLastEventTime = mReferenceTime + mPhase + eventListener.mPhase;
100                 // If mLastEventTime is after mReferenceTime (can happen when positive phase offsets
101                 // are used) we treat it as like it happened in previous period.
102                 if (eventListener.mLastEventTime > mReferenceTime) {
103                     eventListener.mLastEventTime -= mPeriod;
104                 }
105             }
106         }
107         if (mTraceDetailedInfo) {
108             ATRACE_INT64("DispSync:Period", mPeriod);
109             ATRACE_INT64("DispSync:Phase", mPhase + mPeriod / 2);
110             ATRACE_INT64("DispSync:Reference Time", mReferenceTime);
111         }
112         ALOGV("[%s] updateModel: mPeriod = %" PRId64 ", mPhase = %" PRId64
113               " mReferenceTime = %" PRId64,
114               mName, ns2us(mPeriod), ns2us(mPhase), ns2us(mReferenceTime));
115         mCond.signal();
116     }
117 
stop()118     void stop() {
119         if (mTraceDetailedInfo) ATRACE_CALL();
120         Mutex::Autolock lock(mMutex);
121         mStop = true;
122         mCond.signal();
123     }
124 
lockModel()125     void lockModel() {
126         Mutex::Autolock lock(mMutex);
127         mModelLocked = true;
128     }
129 
unlockModel()130     void unlockModel() {
131         Mutex::Autolock lock(mMutex);
132         mModelLocked = false;
133     }
134 
threadLoop()135     virtual bool threadLoop() {
136         status_t err;
137         nsecs_t now = systemTime(SYSTEM_TIME_MONOTONIC);
138 
139         while (true) {
140             std::vector<CallbackInvocation> callbackInvocations;
141 
142             nsecs_t targetTime = 0;
143 
144             { // Scope for lock
145                 Mutex::Autolock lock(mMutex);
146 
147                 if (mTraceDetailedInfo) {
148                     ATRACE_INT64("DispSync:Frame", mFrameNumber);
149                 }
150                 ALOGV("[%s] Frame %" PRId64, mName, mFrameNumber);
151                 ++mFrameNumber;
152 
153                 if (mStop) {
154                     return false;
155                 }
156 
157                 if (mPeriod == 0) {
158                     err = mCond.wait(mMutex);
159                     if (err != NO_ERROR) {
160                         ALOGE("error waiting for new events: %s (%d)", strerror(-err), err);
161                         return false;
162                     }
163                     continue;
164                 }
165 
166                 targetTime = computeNextEventTimeLocked(now);
167 
168                 bool isWakeup = false;
169 
170                 if (now < targetTime) {
171                     if (mTraceDetailedInfo) ATRACE_NAME("DispSync waiting");
172 
173                     if (targetTime == INT64_MAX) {
174                         ALOGV("[%s] Waiting forever", mName);
175                         err = mCond.wait(mMutex);
176                     } else {
177                         ALOGV("[%s] Waiting until %" PRId64, mName, ns2us(targetTime));
178                         err = mCond.waitRelative(mMutex, targetTime - now);
179                     }
180 
181                     if (err == TIMED_OUT) {
182                         isWakeup = true;
183                     } else if (err != NO_ERROR) {
184                         ALOGE("error waiting for next event: %s (%d)", strerror(-err), err);
185                         return false;
186                     }
187                 }
188 
189                 now = systemTime(SYSTEM_TIME_MONOTONIC);
190 
191                 // Don't correct by more than 1.5 ms
192                 static const nsecs_t kMaxWakeupLatency = us2ns(1500);
193 
194                 if (isWakeup) {
195                     mWakeupLatency = ((mWakeupLatency * 63) + (now - targetTime)) / 64;
196                     mWakeupLatency = min(mWakeupLatency, kMaxWakeupLatency);
197                     if (mTraceDetailedInfo) {
198                         ATRACE_INT64("DispSync:WakeupLat", now - targetTime);
199                         ATRACE_INT64("DispSync:AvgWakeupLat", mWakeupLatency);
200                     }
201                 }
202 
203                 callbackInvocations =
204                         gatherCallbackInvocationsLocked(now, computeNextRefreshLocked(0, now));
205             }
206 
207             if (callbackInvocations.size() > 0) {
208                 fireCallbackInvocations(callbackInvocations);
209             }
210         }
211 
212         return false;
213     }
214 
addEventListener(const char * name,nsecs_t phase,DispSync::Callback * callback,nsecs_t lastCallbackTime)215     status_t addEventListener(const char* name, nsecs_t phase, DispSync::Callback* callback,
216                               nsecs_t lastCallbackTime) {
217         if (mTraceDetailedInfo) ATRACE_CALL();
218         Mutex::Autolock lock(mMutex);
219 
220         for (size_t i = 0; i < mEventListeners.size(); i++) {
221             if (mEventListeners[i].mCallback == callback) {
222                 return BAD_VALUE;
223             }
224         }
225 
226         EventListener listener;
227         listener.mName = name;
228         listener.mPhase = phase;
229         listener.mCallback = callback;
230 
231         // We want to allow the firstmost future event to fire without
232         // allowing any past events to fire. To do this extrapolate from
233         // mReferenceTime the most recent hardware vsync, and pin the
234         // last event time there.
235         const nsecs_t now = systemTime(SYSTEM_TIME_MONOTONIC);
236         if (mPeriod != 0) {
237             const nsecs_t baseTime = now - mReferenceTime;
238             const nsecs_t numPeriodsSinceReference = baseTime / mPeriod;
239             const nsecs_t predictedReference = mReferenceTime + numPeriodsSinceReference * mPeriod;
240             const nsecs_t phaseCorrection = mPhase + listener.mPhase;
241             const nsecs_t predictedLastEventTime = predictedReference + phaseCorrection;
242             if (predictedLastEventTime >= now) {
243                 // Make sure that the last event time does not exceed the current time.
244                 // If it would, then back the last event time by a period.
245                 listener.mLastEventTime = predictedLastEventTime - mPeriod;
246             } else {
247                 listener.mLastEventTime = predictedLastEventTime;
248             }
249         } else {
250             listener.mLastEventTime = now + mPhase - mWakeupLatency;
251         }
252 
253         if (lastCallbackTime <= 0) {
254             // If there is no prior callback time, try to infer one based on the
255             // logical last event time.
256             listener.mLastCallbackTime = listener.mLastEventTime + mWakeupLatency;
257         } else {
258             listener.mLastCallbackTime = lastCallbackTime;
259         }
260 
261         mEventListeners.push_back(listener);
262 
263         mCond.signal();
264 
265         return NO_ERROR;
266     }
267 
removeEventListener(DispSync::Callback * callback,nsecs_t * outLastCallback)268     status_t removeEventListener(DispSync::Callback* callback, nsecs_t* outLastCallback) {
269         if (mTraceDetailedInfo) ATRACE_CALL();
270         Mutex::Autolock lock(mMutex);
271 
272         for (std::vector<EventListener>::iterator it = mEventListeners.begin();
273              it != mEventListeners.end(); ++it) {
274             if (it->mCallback == callback) {
275                 *outLastCallback = it->mLastCallbackTime;
276                 mEventListeners.erase(it);
277                 mCond.signal();
278                 return NO_ERROR;
279             }
280         }
281 
282         return BAD_VALUE;
283     }
284 
changePhaseOffset(DispSync::Callback * callback,nsecs_t phase)285     status_t changePhaseOffset(DispSync::Callback* callback, nsecs_t phase) {
286         if (mTraceDetailedInfo) ATRACE_CALL();
287         Mutex::Autolock lock(mMutex);
288 
289         for (auto& eventListener : mEventListeners) {
290             if (eventListener.mCallback == callback) {
291                 const nsecs_t oldPhase = eventListener.mPhase;
292                 eventListener.mPhase = phase;
293 
294                 // Pretend that the last time this event was handled at the same frame but with the
295                 // new offset to allow for a seamless offset change without double-firing or
296                 // skipping.
297                 nsecs_t diff = oldPhase - phase;
298                 eventListener.mLastEventTime -= diff;
299                 eventListener.mLastCallbackTime -= diff;
300                 mCond.signal();
301                 return NO_ERROR;
302             }
303         }
304         return BAD_VALUE;
305     }
306 
computeNextRefresh(int periodOffset,nsecs_t now) const307     nsecs_t computeNextRefresh(int periodOffset, nsecs_t now) const {
308         Mutex::Autolock lock(mMutex);
309         return computeNextRefreshLocked(periodOffset, now);
310     }
311 
312 private:
313     struct EventListener {
314         const char* mName;
315         nsecs_t mPhase;
316         nsecs_t mLastEventTime;
317         nsecs_t mLastCallbackTime;
318         DispSync::Callback* mCallback;
319     };
320 
321     struct CallbackInvocation {
322         DispSync::Callback* mCallback;
323         nsecs_t mEventTime;
324         nsecs_t mExpectedVSyncTime;
325     };
326 
computeNextEventTimeLocked(nsecs_t now)327     nsecs_t computeNextEventTimeLocked(nsecs_t now) {
328         if (mTraceDetailedInfo) ATRACE_CALL();
329         ALOGV("[%s] computeNextEventTimeLocked", mName);
330         nsecs_t nextEventTime = INT64_MAX;
331         for (size_t i = 0; i < mEventListeners.size(); i++) {
332             nsecs_t t = computeListenerNextEventTimeLocked(mEventListeners[i], now);
333 
334             if (t < nextEventTime) {
335                 nextEventTime = t;
336             }
337         }
338 
339         ALOGV("[%s] nextEventTime = %" PRId64, mName, ns2us(nextEventTime));
340         return nextEventTime;
341     }
342 
343     // Sanity check that the duration is close enough in length to a period without
344     // falling into double-rate vsyncs.
isCloseToPeriod(nsecs_t duration)345     bool isCloseToPeriod(nsecs_t duration) {
346         // Ratio of 3/5 is arbitrary, but it must be greater than 1/2.
347         return duration < (3 * mPeriod) / 5;
348     }
349 
gatherCallbackInvocationsLocked(nsecs_t now,nsecs_t expectedVSyncTime)350     std::vector<CallbackInvocation> gatherCallbackInvocationsLocked(nsecs_t now,
351                                                                     nsecs_t expectedVSyncTime) {
352         if (mTraceDetailedInfo) ATRACE_CALL();
353         ALOGV("[%s] gatherCallbackInvocationsLocked @ %" PRId64, mName, ns2us(now));
354 
355         std::vector<CallbackInvocation> callbackInvocations;
356         nsecs_t onePeriodAgo = now - mPeriod;
357 
358         for (auto& eventListener : mEventListeners) {
359             nsecs_t t = computeListenerNextEventTimeLocked(eventListener, onePeriodAgo);
360 
361             if (t < now) {
362                 if (isCloseToPeriod(now - eventListener.mLastCallbackTime)) {
363                     eventListener.mLastEventTime = t;
364                     ALOGV("[%s] [%s] Skipping event due to model error", mName,
365                           eventListener.mName);
366                     continue;
367                 }
368 
369                 CallbackInvocation ci;
370                 ci.mCallback = eventListener.mCallback;
371                 ci.mEventTime = t;
372                 ci.mExpectedVSyncTime = expectedVSyncTime;
373                 if (eventListener.mPhase < 0) {
374                     ci.mExpectedVSyncTime += mPeriod;
375                 }
376                 ALOGV("[%s] [%s] Preparing to fire, latency: %" PRId64, mName, eventListener.mName,
377                       t - eventListener.mLastEventTime);
378                 callbackInvocations.push_back(ci);
379                 eventListener.mLastEventTime = t;
380                 eventListener.mLastCallbackTime = now;
381             }
382         }
383 
384         return callbackInvocations;
385     }
386 
computeListenerNextEventTimeLocked(const EventListener & listener,nsecs_t baseTime)387     nsecs_t computeListenerNextEventTimeLocked(const EventListener& listener, nsecs_t baseTime) {
388         if (mTraceDetailedInfo) ATRACE_CALL();
389         ALOGV("[%s] [%s] computeListenerNextEventTimeLocked(%" PRId64 ")", mName, listener.mName,
390               ns2us(baseTime));
391 
392         nsecs_t lastEventTime = listener.mLastEventTime + mWakeupLatency;
393         ALOGV("[%s] lastEventTime: %" PRId64, mName, ns2us(lastEventTime));
394         if (baseTime < lastEventTime) {
395             baseTime = lastEventTime;
396             ALOGV("[%s] Clamping baseTime to lastEventTime -> %" PRId64, mName, ns2us(baseTime));
397         }
398 
399         baseTime -= mReferenceTime;
400         ALOGV("[%s] Relative baseTime = %" PRId64, mName, ns2us(baseTime));
401         nsecs_t phase = mPhase + listener.mPhase;
402         ALOGV("[%s] Phase = %" PRId64, mName, ns2us(phase));
403         baseTime -= phase;
404         ALOGV("[%s] baseTime - phase = %" PRId64, mName, ns2us(baseTime));
405 
406         // If our previous time is before the reference (because the reference
407         // has since been updated), the division by mPeriod will truncate
408         // towards zero instead of computing the floor. Since in all cases
409         // before the reference we want the next time to be effectively now, we
410         // set baseTime to -mPeriod so that numPeriods will be -1.
411         // When we add 1 and the phase, we will be at the correct event time for
412         // this period.
413         if (baseTime < 0) {
414             ALOGV("[%s] Correcting negative baseTime", mName);
415             baseTime = -mPeriod;
416         }
417 
418         nsecs_t numPeriods = baseTime / mPeriod;
419         ALOGV("[%s] numPeriods = %" PRId64, mName, numPeriods);
420         nsecs_t t = (numPeriods + 1) * mPeriod + phase;
421         ALOGV("[%s] t = %" PRId64, mName, ns2us(t));
422         t += mReferenceTime;
423         ALOGV("[%s] Absolute t = %" PRId64, mName, ns2us(t));
424 
425         // Check that it's been slightly more than half a period since the last
426         // event so that we don't accidentally fall into double-rate vsyncs
427         if (isCloseToPeriod(t - listener.mLastEventTime)) {
428             t += mPeriod;
429             ALOGV("[%s] Modifying t -> %" PRId64, mName, ns2us(t));
430         }
431 
432         t -= mWakeupLatency;
433         ALOGV("[%s] Corrected for wakeup latency -> %" PRId64, mName, ns2us(t));
434 
435         return t;
436     }
437 
fireCallbackInvocations(const std::vector<CallbackInvocation> & callbacks)438     void fireCallbackInvocations(const std::vector<CallbackInvocation>& callbacks) {
439         if (mTraceDetailedInfo) ATRACE_CALL();
440         for (size_t i = 0; i < callbacks.size(); i++) {
441             callbacks[i].mCallback->onDispSyncEvent(callbacks[i].mEventTime,
442                                                     callbacks[i].mExpectedVSyncTime);
443         }
444     }
445 
computeNextRefreshLocked(int periodOffset,nsecs_t now) const446     nsecs_t computeNextRefreshLocked(int periodOffset, nsecs_t now) const {
447         nsecs_t phase = mReferenceTime + mPhase;
448         if (mPeriod == 0) {
449             return 0;
450         }
451         return (((now - phase) / mPeriod) + periodOffset + 1) * mPeriod + phase;
452     }
453 
454     const char* const mName;
455 
456     bool mStop;
457     TracedOrdinal<bool> mModelLocked;
458 
459     nsecs_t mPeriod;
460     nsecs_t mPhase;
461     nsecs_t mReferenceTime;
462     nsecs_t mWakeupLatency;
463 
464     int64_t mFrameNumber;
465 
466     std::vector<EventListener> mEventListeners;
467 
468     mutable Mutex mMutex;
469     Condition mCond;
470 
471     // Flag to turn on logging in systrace.
472     const bool mTraceDetailedInfo;
473 };
474 
475 #undef LOG_TAG
476 #define LOG_TAG "DispSync"
477 
478 class ZeroPhaseTracer : public DispSync::Callback {
479 public:
ZeroPhaseTracer()480     ZeroPhaseTracer() : mParity("ZERO_PHASE_VSYNC", false) {}
481 
onDispSyncEvent(nsecs_t,nsecs_t)482     virtual void onDispSyncEvent(nsecs_t /*when*/, nsecs_t /*expectedVSyncTimestamp*/) {
483         mParity = !mParity;
484     }
485 
486 private:
487     TracedOrdinal<bool> mParity;
488 };
489 
DispSync(const char * name,bool hasSyncFramework)490 DispSync::DispSync(const char* name, bool hasSyncFramework)
491       : mName(name), mIgnorePresentFences(!hasSyncFramework) {
492     // This flag offers the ability to turn on systrace logging from the shell.
493     char value[PROPERTY_VALUE_MAX];
494     property_get("debug.sf.dispsync_trace_detailed_info", value, "0");
495     mTraceDetailedInfo = atoi(value);
496 
497     mThread = new DispSyncThread(name, mTraceDetailedInfo);
498     mThread->run("DispSync", PRIORITY_URGENT_DISPLAY + PRIORITY_MORE_FAVORABLE);
499 
500     // set DispSync to SCHED_FIFO to minimize jitter
501     struct sched_param param = {0};
502     param.sched_priority = 2;
503     if (sched_setscheduler(mThread->getTid(), SCHED_FIFO, &param) != 0) {
504         ALOGE("Couldn't set SCHED_FIFO for DispSyncThread");
505     }
506 
507     beginResync();
508 
509     if (mTraceDetailedInfo && kEnableZeroPhaseTracer) {
510         mZeroPhaseTracer = std::make_unique<ZeroPhaseTracer>();
511         addEventListener("ZeroPhaseTracer", 0, mZeroPhaseTracer.get(), 0);
512     }
513 }
514 
~DispSync()515 DispSync::~DispSync() {
516     mThread->stop();
517     mThread->requestExitAndWait();
518 }
519 
reset()520 void DispSync::reset() {
521     Mutex::Autolock lock(mMutex);
522     resetLocked();
523 }
524 
resetLocked()525 void DispSync::resetLocked() {
526     mPhase = 0;
527     const size_t lastSampleIdx = (mFirstResyncSample + mNumResyncSamples - 1) % MAX_RESYNC_SAMPLES;
528     // Keep the most recent sample, when we resync to hardware we'll overwrite this
529     // with a more accurate signal
530     if (mResyncSamples[lastSampleIdx] != 0) {
531         mReferenceTime = mResyncSamples[lastSampleIdx];
532     }
533     mModelUpdated = false;
534     for (size_t i = 0; i < MAX_RESYNC_SAMPLES; i++) {
535         mResyncSamples[i] = 0;
536     }
537     mNumResyncSamples = 0;
538     mFirstResyncSample = 0;
539     mNumResyncSamplesSincePresent = 0;
540     mThread->unlockModel();
541     resetErrorLocked();
542 }
543 
addPresentFence(const std::shared_ptr<FenceTime> & fenceTime)544 bool DispSync::addPresentFence(const std::shared_ptr<FenceTime>& fenceTime) {
545     Mutex::Autolock lock(mMutex);
546 
547     if (mIgnorePresentFences) {
548         return true;
549     }
550 
551     mPresentFences[mPresentSampleOffset] = fenceTime;
552     mPresentSampleOffset = (mPresentSampleOffset + 1) % NUM_PRESENT_SAMPLES;
553     mNumResyncSamplesSincePresent = 0;
554 
555     updateErrorLocked();
556 
557     return !mModelUpdated || mError > kErrorThreshold;
558 }
559 
beginResync()560 void DispSync::beginResync() {
561     Mutex::Autolock lock(mMutex);
562     ALOGV("[%s] beginResync", mName);
563     resetLocked();
564 }
565 
addResyncSample(nsecs_t timestamp,std::optional<nsecs_t>,bool * periodFlushed)566 bool DispSync::addResyncSample(nsecs_t timestamp, std::optional<nsecs_t> /*hwcVsyncPeriod*/,
567                                bool* periodFlushed) {
568     Mutex::Autolock lock(mMutex);
569 
570     ALOGV("[%s] addResyncSample(%" PRId64 ")", mName, ns2us(timestamp));
571 
572     *periodFlushed = false;
573     const size_t idx = (mFirstResyncSample + mNumResyncSamples) % MAX_RESYNC_SAMPLES;
574     mResyncSamples[idx] = timestamp;
575     if (mNumResyncSamples == 0) {
576         mPhase = 0;
577         ALOGV("[%s] First resync sample: mPeriod = %" PRId64 ", mPhase = 0, "
578               "mReferenceTime = %" PRId64,
579               mName, ns2us(mPeriod), ns2us(timestamp));
580     } else if (mPendingPeriod > 0) {
581         // mNumResyncSamples > 0, so priorIdx won't overflow
582         const size_t priorIdx = (mFirstResyncSample + mNumResyncSamples - 1) % MAX_RESYNC_SAMPLES;
583         const nsecs_t lastTimestamp = mResyncSamples[priorIdx];
584 
585         const nsecs_t observedVsync = std::abs(timestamp - lastTimestamp);
586         if (std::abs(observedVsync - mPendingPeriod) <= std::abs(observedVsync - mIntendedPeriod)) {
587             // Either the observed vsync is closer to the pending period, (and
588             // thus we detected a period change), or the period change will
589             // no-op. In either case, reset the model and flush the pending
590             // period.
591             resetLocked();
592             mIntendedPeriod = mPendingPeriod;
593             mPeriod = mPendingPeriod;
594             mPendingPeriod = 0;
595             if (mTraceDetailedInfo) {
596                 ATRACE_INT("DispSync:PendingPeriod", mPendingPeriod);
597                 ATRACE_INT("DispSync:IntendedPeriod", mIntendedPeriod);
598             }
599             *periodFlushed = true;
600         }
601     }
602     // Always update the reference time with the most recent timestamp.
603     mReferenceTime = timestamp;
604     mThread->updateModel(mPeriod, mPhase, mReferenceTime);
605 
606     if (mNumResyncSamples < MAX_RESYNC_SAMPLES) {
607         mNumResyncSamples++;
608     } else {
609         mFirstResyncSample = (mFirstResyncSample + 1) % MAX_RESYNC_SAMPLES;
610     }
611 
612     updateModelLocked();
613 
614     if (mNumResyncSamplesSincePresent++ > MAX_RESYNC_SAMPLES_WITHOUT_PRESENT) {
615         resetErrorLocked();
616     }
617 
618     if (mIgnorePresentFences) {
619         // If we're ignoring the present fences we have no way to know whether
620         // or not we're synchronized with the HW vsyncs, so we just request
621         // that the HW vsync events be turned on.
622         return true;
623     }
624 
625     // Check against kErrorThreshold / 2 to add some hysteresis before having to
626     // resync again
627     bool modelLocked = mModelUpdated && mError < (kErrorThreshold / 2) && mPendingPeriod == 0;
628     ALOGV("[%s] addResyncSample returning %s", mName, modelLocked ? "locked" : "unlocked");
629     if (modelLocked) {
630         *periodFlushed = true;
631         mThread->lockModel();
632     }
633     return !modelLocked;
634 }
635 
endResync()636 void DispSync::endResync() {
637     mThread->lockModel();
638 }
639 
addEventListener(const char * name,nsecs_t phase,Callback * callback,nsecs_t lastCallbackTime)640 status_t DispSync::addEventListener(const char* name, nsecs_t phase, Callback* callback,
641                                     nsecs_t lastCallbackTime) {
642     Mutex::Autolock lock(mMutex);
643     return mThread->addEventListener(name, phase, callback, lastCallbackTime);
644 }
645 
removeEventListener(Callback * callback,nsecs_t * outLastCallbackTime)646 status_t DispSync::removeEventListener(Callback* callback, nsecs_t* outLastCallbackTime) {
647     Mutex::Autolock lock(mMutex);
648     return mThread->removeEventListener(callback, outLastCallbackTime);
649 }
650 
changePhaseOffset(Callback * callback,nsecs_t phase)651 status_t DispSync::changePhaseOffset(Callback* callback, nsecs_t phase) {
652     Mutex::Autolock lock(mMutex);
653     return mThread->changePhaseOffset(callback, phase);
654 }
655 
setPeriod(nsecs_t period)656 void DispSync::setPeriod(nsecs_t period) {
657     Mutex::Autolock lock(mMutex);
658 
659     const bool pendingPeriodShouldChange =
660             period != mIntendedPeriod || (period == mIntendedPeriod && mPendingPeriod != 0);
661 
662     if (pendingPeriodShouldChange) {
663         mPendingPeriod = period;
664     }
665     if (mTraceDetailedInfo) {
666         ATRACE_INT("DispSync:IntendedPeriod", mIntendedPeriod);
667         ATRACE_INT("DispSync:PendingPeriod", mPendingPeriod);
668     }
669 }
670 
getPeriod()671 nsecs_t DispSync::getPeriod() {
672     // lock mutex as mPeriod changes multiple times in updateModelLocked
673     Mutex::Autolock lock(mMutex);
674     return mPeriod;
675 }
676 
updateModelLocked()677 void DispSync::updateModelLocked() {
678     ALOGV("[%s] updateModelLocked %zu", mName, mNumResyncSamples);
679     if (mNumResyncSamples >= MIN_RESYNC_SAMPLES_FOR_UPDATE) {
680         ALOGV("[%s] Computing...", mName);
681         nsecs_t durationSum = 0;
682         nsecs_t minDuration = INT64_MAX;
683         nsecs_t maxDuration = 0;
684         // We skip the first 2 samples because the first vsync duration on some
685         // devices may be much more inaccurate than on other devices, e.g. due
686         // to delays in ramping up from a power collapse. By doing so this
687         // actually increases the accuracy of the DispSync model even though
688         // we're effectively relying on fewer sample points.
689         static constexpr size_t numSamplesSkipped = 2;
690         for (size_t i = numSamplesSkipped; i < mNumResyncSamples; i++) {
691             size_t idx = (mFirstResyncSample + i) % MAX_RESYNC_SAMPLES;
692             size_t prev = (idx + MAX_RESYNC_SAMPLES - 1) % MAX_RESYNC_SAMPLES;
693             nsecs_t duration = mResyncSamples[idx] - mResyncSamples[prev];
694             durationSum += duration;
695             minDuration = min(minDuration, duration);
696             maxDuration = max(maxDuration, duration);
697         }
698 
699         // Exclude the min and max from the average
700         durationSum -= minDuration + maxDuration;
701         mPeriod = durationSum / (mNumResyncSamples - numSamplesSkipped - 2);
702 
703         ALOGV("[%s] mPeriod = %" PRId64, mName, ns2us(mPeriod));
704 
705         double sampleAvgX = 0;
706         double sampleAvgY = 0;
707         double scale = 2.0 * M_PI / double(mPeriod);
708         for (size_t i = numSamplesSkipped; i < mNumResyncSamples; i++) {
709             size_t idx = (mFirstResyncSample + i) % MAX_RESYNC_SAMPLES;
710             nsecs_t sample = mResyncSamples[idx] - mReferenceTime;
711             double samplePhase = double(sample % mPeriod) * scale;
712             sampleAvgX += cos(samplePhase);
713             sampleAvgY += sin(samplePhase);
714         }
715 
716         sampleAvgX /= double(mNumResyncSamples - numSamplesSkipped);
717         sampleAvgY /= double(mNumResyncSamples - numSamplesSkipped);
718 
719         mPhase = nsecs_t(atan2(sampleAvgY, sampleAvgX) / scale);
720 
721         ALOGV("[%s] mPhase = %" PRId64, mName, ns2us(mPhase));
722 
723         if (mPhase < -(mPeriod / 2)) {
724             mPhase += mPeriod;
725             ALOGV("[%s] Adjusting mPhase -> %" PRId64, mName, ns2us(mPhase));
726         }
727 
728         mThread->updateModel(mPeriod, mPhase, mReferenceTime);
729         mModelUpdated = true;
730     }
731 }
732 
updateErrorLocked()733 void DispSync::updateErrorLocked() {
734     if (!mModelUpdated) {
735         return;
736     }
737 
738     int numErrSamples = 0;
739     nsecs_t sqErrSum = 0;
740 
741     for (size_t i = 0; i < NUM_PRESENT_SAMPLES; i++) {
742         // Only check for the cached value of signal time to avoid unecessary
743         // syscalls. It is the responsibility of the DispSync owner to
744         // call getSignalTime() periodically so the cache is updated when the
745         // fence signals.
746         nsecs_t time = mPresentFences[i]->getCachedSignalTime();
747         if (time == Fence::SIGNAL_TIME_PENDING || time == Fence::SIGNAL_TIME_INVALID) {
748             continue;
749         }
750 
751         nsecs_t sample = time - mReferenceTime;
752         if (sample <= mPhase) {
753             continue;
754         }
755 
756         nsecs_t sampleErr = (sample - mPhase) % mPeriod;
757         if (sampleErr > mPeriod / 2) {
758             sampleErr -= mPeriod;
759         }
760         sqErrSum += sampleErr * sampleErr;
761         numErrSamples++;
762     }
763 
764     if (numErrSamples > 0) {
765         mError = sqErrSum / numErrSamples;
766         mZeroErrSamplesCount = 0;
767     } else {
768         mError = 0;
769         // Use mod ACCEPTABLE_ZERO_ERR_SAMPLES_COUNT to avoid log spam.
770         mZeroErrSamplesCount++;
771         ALOGE_IF((mZeroErrSamplesCount % ACCEPTABLE_ZERO_ERR_SAMPLES_COUNT) == 0,
772                  "No present times for model error.");
773     }
774 
775     if (mTraceDetailedInfo) {
776         ATRACE_INT64("DispSync:Error", mError);
777     }
778 }
779 
resetErrorLocked()780 void DispSync::resetErrorLocked() {
781     mPresentSampleOffset = 0;
782     mError = 0;
783     mZeroErrSamplesCount = 0;
784     if (mTraceDetailedInfo) {
785         ATRACE_INT64("DispSync:Error", mError);
786     }
787     for (size_t i = 0; i < NUM_PRESENT_SAMPLES; i++) {
788         mPresentFences[i] = FenceTime::NO_FENCE;
789     }
790 }
791 
computeNextRefresh(int periodOffset,nsecs_t now) const792 nsecs_t DispSync::computeNextRefresh(int periodOffset, nsecs_t now) const {
793     Mutex::Autolock lock(mMutex);
794     nsecs_t phase = mReferenceTime + mPhase;
795     if (mPeriod == 0) {
796         return 0;
797     }
798     return (((now - phase) / mPeriod) + periodOffset + 1) * mPeriod + phase;
799 }
800 
setIgnorePresentFences(bool ignore)801 void DispSync::setIgnorePresentFences(bool ignore) {
802     Mutex::Autolock lock(mMutex);
803     if (mIgnorePresentFences != ignore) {
804         mIgnorePresentFences = ignore;
805         resetLocked();
806     }
807 }
808 
dump(std::string & result) const809 void DispSync::dump(std::string& result) const {
810     Mutex::Autolock lock(mMutex);
811     StringAppendF(&result, "present fences are %s\n", mIgnorePresentFences ? "ignored" : "used");
812     StringAppendF(&result, "mPeriod: %" PRId64 " ns (%.3f fps)\n", mPeriod, 1000000000.0 / mPeriod);
813     StringAppendF(&result, "mPhase: %" PRId64 " ns\n", mPhase);
814     StringAppendF(&result, "mError: %" PRId64 " ns (sqrt=%.1f)\n", mError, sqrt(mError));
815     StringAppendF(&result, "mNumResyncSamplesSincePresent: %d (limit %d)\n",
816                   mNumResyncSamplesSincePresent, MAX_RESYNC_SAMPLES_WITHOUT_PRESENT);
817     StringAppendF(&result, "mNumResyncSamples: %zd (max %d)\n", mNumResyncSamples,
818                   MAX_RESYNC_SAMPLES);
819 
820     result.append("mResyncSamples:\n");
821     nsecs_t previous = -1;
822     for (size_t i = 0; i < mNumResyncSamples; i++) {
823         size_t idx = (mFirstResyncSample + i) % MAX_RESYNC_SAMPLES;
824         nsecs_t sampleTime = mResyncSamples[idx];
825         if (i == 0) {
826             StringAppendF(&result, "  %" PRId64 "\n", sampleTime);
827         } else {
828             StringAppendF(&result, "  %" PRId64 " (+%" PRId64 ")\n", sampleTime,
829                           sampleTime - previous);
830         }
831         previous = sampleTime;
832     }
833 
834     StringAppendF(&result, "mPresentFences [%d]:\n", NUM_PRESENT_SAMPLES);
835     nsecs_t now = systemTime(SYSTEM_TIME_MONOTONIC);
836     previous = Fence::SIGNAL_TIME_INVALID;
837     for (size_t i = 0; i < NUM_PRESENT_SAMPLES; i++) {
838         size_t idx = (i + mPresentSampleOffset) % NUM_PRESENT_SAMPLES;
839         nsecs_t presentTime = mPresentFences[idx]->getSignalTime();
840         if (presentTime == Fence::SIGNAL_TIME_PENDING) {
841             StringAppendF(&result, "  [unsignaled fence]\n");
842         } else if (presentTime == Fence::SIGNAL_TIME_INVALID) {
843             StringAppendF(&result, "  [invalid fence]\n");
844         } else if (previous == Fence::SIGNAL_TIME_PENDING ||
845                    previous == Fence::SIGNAL_TIME_INVALID) {
846             StringAppendF(&result, "  %" PRId64 "  (%.3f ms ago)\n", presentTime,
847                           (now - presentTime) / 1000000.0);
848         } else {
849             StringAppendF(&result, "  %" PRId64 " (+%" PRId64 " / %.3f)  (%.3f ms ago)\n",
850                           presentTime, presentTime - previous,
851                           (presentTime - previous) / (double)mPeriod,
852                           (now - presentTime) / 1000000.0);
853         }
854         previous = presentTime;
855     }
856 
857     StringAppendF(&result, "current monotonic time: %" PRId64 "\n", now);
858 }
859 
expectedPresentTime(nsecs_t now)860 nsecs_t DispSync::expectedPresentTime(nsecs_t now) {
861     // The HWC doesn't currently have a way to report additional latency.
862     // Assume that whatever we submit now will appear right after the flip.
863     // For a smart panel this might be 1.  This is expressed in frames,
864     // rather than time, because we expect to have a constant frame delay
865     // regardless of the refresh rate.
866     const uint32_t hwcLatency = 0;
867 
868     // Ask DispSync when the next refresh will be (CLOCK_MONOTONIC).
869     return mThread->computeNextRefresh(hwcLatency, now);
870 }
871 
872 } // namespace impl
873 
874 } // namespace android
875 
876 // TODO(b/129481165): remove the #pragma below and fix conversion issues
877 #pragma clang diagnostic pop // ignored "-Wconversion"
878