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#define ATRACE_TAG ATRACE_TAG_GRAPHICS
18//#define LOG_NDEBUG 0
19
20// This is needed for stdint.h to define INT64_MAX in C++
21#define __STDC_LIMIT_MACROS
22
23#include <math.h>
24
25#include <cutils/log.h>
26
27#include <ui/Fence.h>
28
29#include <utils/String8.h>
30#include <utils/Thread.h>
31#include <utils/Trace.h>
32#include <utils/Vector.h>
33
34#include "DispSync.h"
35#include "EventLog/EventLog.h"
36
37#include <algorithm>
38
39using std::max;
40using std::min;
41
42namespace android {
43
44// Setting this to true enables verbose tracing that can be used to debug
45// vsync event model or phase issues.
46static const bool kTraceDetailedInfo = false;
47
48// Setting this to true adds a zero-phase tracer for correlating with hardware
49// vsync events
50static const bool kEnableZeroPhaseTracer = false;
51
52// This is the threshold used to determine when hardware vsync events are
53// needed to re-synchronize the software vsync model with the hardware.  The
54// error metric used is the mean of the squared difference between each
55// present time and the nearest software-predicted vsync.
56static const nsecs_t kErrorThreshold = 160000000000;    // 400 usec squared
57
58// This is the offset from the present fence timestamps to the corresponding
59// vsync event.
60static const int64_t kPresentTimeOffset = PRESENT_TIME_OFFSET_FROM_VSYNC_NS;
61
62#undef LOG_TAG
63#define LOG_TAG "DispSyncThread"
64class DispSyncThread: public Thread {
65public:
66
67    DispSyncThread(const char* name):
68            mName(name),
69            mStop(false),
70            mPeriod(0),
71            mPhase(0),
72            mReferenceTime(0),
73            mWakeupLatency(0),
74            mFrameNumber(0) {}
75
76    virtual ~DispSyncThread() {}
77
78    void updateModel(nsecs_t period, nsecs_t phase, nsecs_t referenceTime) {
79        if (kTraceDetailedInfo) ATRACE_CALL();
80        Mutex::Autolock lock(mMutex);
81        mPeriod = period;
82        mPhase = phase;
83        mReferenceTime = referenceTime;
84        ALOGV("[%s] updateModel: mPeriod = %" PRId64 ", mPhase = %" PRId64
85                " mReferenceTime = %" PRId64, mName, ns2us(mPeriod),
86                ns2us(mPhase), ns2us(mReferenceTime));
87        mCond.signal();
88    }
89
90    void stop() {
91        if (kTraceDetailedInfo) ATRACE_CALL();
92        Mutex::Autolock lock(mMutex);
93        mStop = true;
94        mCond.signal();
95    }
96
97    virtual bool threadLoop() {
98        status_t err;
99        nsecs_t now = systemTime(SYSTEM_TIME_MONOTONIC);
100
101        while (true) {
102            Vector<CallbackInvocation> callbackInvocations;
103
104            nsecs_t targetTime = 0;
105
106            { // Scope for lock
107                Mutex::Autolock lock(mMutex);
108
109                if (kTraceDetailedInfo) {
110                    ATRACE_INT64("DispSync:Frame", mFrameNumber);
111                }
112                ALOGV("[%s] Frame %" PRId64, mName, mFrameNumber);
113                ++mFrameNumber;
114
115                if (mStop) {
116                    return false;
117                }
118
119                if (mPeriod == 0) {
120                    err = mCond.wait(mMutex);
121                    if (err != NO_ERROR) {
122                        ALOGE("error waiting for new events: %s (%d)",
123                                strerror(-err), err);
124                        return false;
125                    }
126                    continue;
127                }
128
129                targetTime = computeNextEventTimeLocked(now);
130
131                bool isWakeup = false;
132
133                if (now < targetTime) {
134                    if (kTraceDetailedInfo) ATRACE_NAME("DispSync waiting");
135
136                    if (targetTime == INT64_MAX) {
137                        ALOGV("[%s] Waiting forever", mName);
138                        err = mCond.wait(mMutex);
139                    } else {
140                        ALOGV("[%s] Waiting until %" PRId64, mName,
141                                ns2us(targetTime));
142                        err = mCond.waitRelative(mMutex, targetTime - now);
143                    }
144
145                    if (err == TIMED_OUT) {
146                        isWakeup = true;
147                    } else if (err != NO_ERROR) {
148                        ALOGE("error waiting for next event: %s (%d)",
149                                strerror(-err), err);
150                        return false;
151                    }
152                }
153
154                now = systemTime(SYSTEM_TIME_MONOTONIC);
155
156                // Don't correct by more than 1.5 ms
157                static const nsecs_t kMaxWakeupLatency = us2ns(1500);
158
159                if (isWakeup) {
160                    mWakeupLatency = ((mWakeupLatency * 63) +
161                            (now - targetTime)) / 64;
162                    mWakeupLatency = min(mWakeupLatency, kMaxWakeupLatency);
163                    if (kTraceDetailedInfo) {
164                        ATRACE_INT64("DispSync:WakeupLat", now - targetTime);
165                        ATRACE_INT64("DispSync:AvgWakeupLat", mWakeupLatency);
166                    }
167                }
168
169                callbackInvocations = gatherCallbackInvocationsLocked(now);
170            }
171
172            if (callbackInvocations.size() > 0) {
173                fireCallbackInvocations(callbackInvocations);
174            }
175        }
176
177        return false;
178    }
179
180    status_t addEventListener(const char* name, nsecs_t phase,
181            const sp<DispSync::Callback>& callback) {
182        if (kTraceDetailedInfo) ATRACE_CALL();
183        Mutex::Autolock lock(mMutex);
184
185        for (size_t i = 0; i < mEventListeners.size(); i++) {
186            if (mEventListeners[i].mCallback == callback) {
187                return BAD_VALUE;
188            }
189        }
190
191        EventListener listener;
192        listener.mName = name;
193        listener.mPhase = phase;
194        listener.mCallback = callback;
195
196        // We want to allow the firstmost future event to fire without
197        // allowing any past events to fire
198        listener.mLastEventTime = systemTime() - mPeriod / 2 + mPhase -
199                mWakeupLatency;
200
201        mEventListeners.push(listener);
202
203        mCond.signal();
204
205        return NO_ERROR;
206    }
207
208    status_t removeEventListener(const sp<DispSync::Callback>& callback) {
209        if (kTraceDetailedInfo) ATRACE_CALL();
210        Mutex::Autolock lock(mMutex);
211
212        for (size_t i = 0; i < mEventListeners.size(); i++) {
213            if (mEventListeners[i].mCallback == callback) {
214                mEventListeners.removeAt(i);
215                mCond.signal();
216                return NO_ERROR;
217            }
218        }
219
220        return BAD_VALUE;
221    }
222
223    // This method is only here to handle the kIgnorePresentFences case.
224    bool hasAnyEventListeners() {
225        if (kTraceDetailedInfo) ATRACE_CALL();
226        Mutex::Autolock lock(mMutex);
227        return !mEventListeners.empty();
228    }
229
230private:
231
232    struct EventListener {
233        const char* mName;
234        nsecs_t mPhase;
235        nsecs_t mLastEventTime;
236        sp<DispSync::Callback> mCallback;
237    };
238
239    struct CallbackInvocation {
240        sp<DispSync::Callback> mCallback;
241        nsecs_t mEventTime;
242    };
243
244    nsecs_t computeNextEventTimeLocked(nsecs_t now) {
245        if (kTraceDetailedInfo) ATRACE_CALL();
246        ALOGV("[%s] computeNextEventTimeLocked", mName);
247        nsecs_t nextEventTime = INT64_MAX;
248        for (size_t i = 0; i < mEventListeners.size(); i++) {
249            nsecs_t t = computeListenerNextEventTimeLocked(mEventListeners[i],
250                    now);
251
252            if (t < nextEventTime) {
253                nextEventTime = t;
254            }
255        }
256
257        ALOGV("[%s] nextEventTime = %" PRId64, mName, ns2us(nextEventTime));
258        return nextEventTime;
259    }
260
261    Vector<CallbackInvocation> gatherCallbackInvocationsLocked(nsecs_t now) {
262        if (kTraceDetailedInfo) ATRACE_CALL();
263        ALOGV("[%s] gatherCallbackInvocationsLocked @ %" PRId64, mName,
264                ns2us(now));
265
266        Vector<CallbackInvocation> callbackInvocations;
267        nsecs_t onePeriodAgo = now - mPeriod;
268
269        for (size_t i = 0; i < mEventListeners.size(); i++) {
270            nsecs_t t = computeListenerNextEventTimeLocked(mEventListeners[i],
271                    onePeriodAgo);
272
273            if (t < now) {
274                CallbackInvocation ci;
275                ci.mCallback = mEventListeners[i].mCallback;
276                ci.mEventTime = t;
277                ALOGV("[%s] [%s] Preparing to fire", mName,
278                        mEventListeners[i].mName);
279                callbackInvocations.push(ci);
280                mEventListeners.editItemAt(i).mLastEventTime = t;
281            }
282        }
283
284        return callbackInvocations;
285    }
286
287    nsecs_t computeListenerNextEventTimeLocked(const EventListener& listener,
288            nsecs_t baseTime) {
289        if (kTraceDetailedInfo) ATRACE_CALL();
290        ALOGV("[%s] [%s] computeListenerNextEventTimeLocked(%" PRId64 ")",
291                mName, listener.mName, ns2us(baseTime));
292
293        nsecs_t lastEventTime = listener.mLastEventTime + mWakeupLatency;
294        ALOGV("[%s] lastEventTime: %" PRId64, mName, ns2us(lastEventTime));
295        if (baseTime < lastEventTime) {
296            baseTime = lastEventTime;
297            ALOGV("[%s] Clamping baseTime to lastEventTime -> %" PRId64, mName,
298                    ns2us(baseTime));
299        }
300
301        baseTime -= mReferenceTime;
302        ALOGV("[%s] Relative baseTime = %" PRId64, mName, ns2us(baseTime));
303        nsecs_t phase = mPhase + listener.mPhase;
304        ALOGV("[%s] Phase = %" PRId64, mName, ns2us(phase));
305        baseTime -= phase;
306        ALOGV("[%s] baseTime - phase = %" PRId64, mName, ns2us(baseTime));
307
308        // If our previous time is before the reference (because the reference
309        // has since been updated), the division by mPeriod will truncate
310        // towards zero instead of computing the floor. Since in all cases
311        // before the reference we want the next time to be effectively now, we
312        // set baseTime to -mPeriod so that numPeriods will be -1.
313        // When we add 1 and the phase, we will be at the correct event time for
314        // this period.
315        if (baseTime < 0) {
316            ALOGV("[%s] Correcting negative baseTime", mName);
317            baseTime = -mPeriod;
318        }
319
320        nsecs_t numPeriods = baseTime / mPeriod;
321        ALOGV("[%s] numPeriods = %" PRId64, mName, numPeriods);
322        nsecs_t t = (numPeriods + 1) * mPeriod + phase;
323        ALOGV("[%s] t = %" PRId64, mName, ns2us(t));
324        t += mReferenceTime;
325        ALOGV("[%s] Absolute t = %" PRId64, mName, ns2us(t));
326
327        // Check that it's been slightly more than half a period since the last
328        // event so that we don't accidentally fall into double-rate vsyncs
329        if (t - listener.mLastEventTime < (3 * mPeriod / 5)) {
330            t += mPeriod;
331            ALOGV("[%s] Modifying t -> %" PRId64, mName, ns2us(t));
332        }
333
334        t -= mWakeupLatency;
335        ALOGV("[%s] Corrected for wakeup latency -> %" PRId64, mName, ns2us(t));
336
337        return t;
338    }
339
340    void fireCallbackInvocations(const Vector<CallbackInvocation>& callbacks) {
341        if (kTraceDetailedInfo) ATRACE_CALL();
342        for (size_t i = 0; i < callbacks.size(); i++) {
343            callbacks[i].mCallback->onDispSyncEvent(callbacks[i].mEventTime);
344        }
345    }
346
347    const char* const mName;
348
349    bool mStop;
350
351    nsecs_t mPeriod;
352    nsecs_t mPhase;
353    nsecs_t mReferenceTime;
354    nsecs_t mWakeupLatency;
355
356    int64_t mFrameNumber;
357
358    Vector<EventListener> mEventListeners;
359
360    Mutex mMutex;
361    Condition mCond;
362};
363
364#undef LOG_TAG
365#define LOG_TAG "DispSync"
366
367class ZeroPhaseTracer : public DispSync::Callback {
368public:
369    ZeroPhaseTracer() : mParity(false) {}
370
371    virtual void onDispSyncEvent(nsecs_t /*when*/) {
372        mParity = !mParity;
373        ATRACE_INT("ZERO_PHASE_VSYNC", mParity ? 1 : 0);
374    }
375
376private:
377    bool mParity;
378};
379
380DispSync::DispSync(const char* name) :
381        mName(name),
382        mRefreshSkipCount(0),
383        mThread(new DispSyncThread(name)) {
384
385    mThread->run("DispSync", PRIORITY_URGENT_DISPLAY + PRIORITY_MORE_FAVORABLE);
386
387    reset();
388    beginResync();
389
390    if (kTraceDetailedInfo) {
391        // If we're not getting present fences then the ZeroPhaseTracer
392        // would prevent HW vsync event from ever being turned off.
393        // Even if we're just ignoring the fences, the zero-phase tracing is
394        // not needed because any time there is an event registered we will
395        // turn on the HW vsync events.
396        if (!kIgnorePresentFences && kEnableZeroPhaseTracer) {
397            addEventListener("ZeroPhaseTracer", 0, new ZeroPhaseTracer());
398        }
399    }
400}
401
402DispSync::~DispSync() {}
403
404void DispSync::reset() {
405    Mutex::Autolock lock(mMutex);
406
407    mPhase = 0;
408    mReferenceTime = 0;
409    mModelUpdated = false;
410    mNumResyncSamples = 0;
411    mFirstResyncSample = 0;
412    mNumResyncSamplesSincePresent = 0;
413    resetErrorLocked();
414}
415
416bool DispSync::addPresentFence(const sp<Fence>& fence) {
417    Mutex::Autolock lock(mMutex);
418
419    mPresentFences[mPresentSampleOffset] = fence;
420    mPresentTimes[mPresentSampleOffset] = 0;
421    mPresentSampleOffset = (mPresentSampleOffset + 1) % NUM_PRESENT_SAMPLES;
422    mNumResyncSamplesSincePresent = 0;
423
424    for (size_t i = 0; i < NUM_PRESENT_SAMPLES; i++) {
425        const sp<Fence>& f(mPresentFences[i]);
426        if (f != NULL) {
427            nsecs_t t = f->getSignalTime();
428            if (t < INT64_MAX) {
429                mPresentFences[i].clear();
430                mPresentTimes[i] = t + kPresentTimeOffset;
431            }
432        }
433    }
434
435    updateErrorLocked();
436
437    return !mModelUpdated || mError > kErrorThreshold;
438}
439
440void DispSync::beginResync() {
441    Mutex::Autolock lock(mMutex);
442    ALOGV("[%s] beginResync", mName);
443    mModelUpdated = false;
444    mNumResyncSamples = 0;
445}
446
447bool DispSync::addResyncSample(nsecs_t timestamp) {
448    Mutex::Autolock lock(mMutex);
449
450    ALOGV("[%s] addResyncSample(%" PRId64 ")", mName, ns2us(timestamp));
451
452    size_t idx = (mFirstResyncSample + mNumResyncSamples) % MAX_RESYNC_SAMPLES;
453    mResyncSamples[idx] = timestamp;
454    if (mNumResyncSamples == 0) {
455        mPhase = 0;
456        mReferenceTime = timestamp;
457        ALOGV("[%s] First resync sample: mPeriod = %" PRId64 ", mPhase = 0, "
458                "mReferenceTime = %" PRId64, mName, ns2us(mPeriod),
459                ns2us(mReferenceTime));
460        mThread->updateModel(mPeriod, mPhase, mReferenceTime);
461    }
462
463    if (mNumResyncSamples < MAX_RESYNC_SAMPLES) {
464        mNumResyncSamples++;
465    } else {
466        mFirstResyncSample = (mFirstResyncSample + 1) % MAX_RESYNC_SAMPLES;
467    }
468
469    updateModelLocked();
470
471    if (mNumResyncSamplesSincePresent++ > MAX_RESYNC_SAMPLES_WITHOUT_PRESENT) {
472        resetErrorLocked();
473    }
474
475    if (kIgnorePresentFences) {
476        // If we don't have the sync framework we will never have
477        // addPresentFence called.  This means we have no way to know whether
478        // or not we're synchronized with the HW vsyncs, so we just request
479        // that the HW vsync events be turned on whenever we need to generate
480        // SW vsync events.
481        return mThread->hasAnyEventListeners();
482    }
483
484    // Check against kErrorThreshold / 2 to add some hysteresis before having to
485    // resync again
486    bool modelLocked = mModelUpdated && mError < (kErrorThreshold / 2);
487    ALOGV("[%s] addResyncSample returning %s", mName,
488            modelLocked ? "locked" : "unlocked");
489    return !modelLocked;
490}
491
492void DispSync::endResync() {
493}
494
495status_t DispSync::addEventListener(const char* name, nsecs_t phase,
496        const sp<Callback>& callback) {
497    Mutex::Autolock lock(mMutex);
498    return mThread->addEventListener(name, phase, callback);
499}
500
501void DispSync::setRefreshSkipCount(int count) {
502    Mutex::Autolock lock(mMutex);
503    ALOGD("setRefreshSkipCount(%d)", count);
504    mRefreshSkipCount = count;
505    updateModelLocked();
506}
507
508status_t DispSync::removeEventListener(const sp<Callback>& callback) {
509    Mutex::Autolock lock(mMutex);
510    return mThread->removeEventListener(callback);
511}
512
513void DispSync::setPeriod(nsecs_t period) {
514    Mutex::Autolock lock(mMutex);
515    mPeriod = period;
516    mPhase = 0;
517    mReferenceTime = 0;
518    mThread->updateModel(mPeriod, mPhase, mReferenceTime);
519}
520
521nsecs_t DispSync::getPeriod() {
522    // lock mutex as mPeriod changes multiple times in updateModelLocked
523    Mutex::Autolock lock(mMutex);
524    return mPeriod;
525}
526
527void DispSync::updateModelLocked() {
528    ALOGV("[%s] updateModelLocked %zu", mName, mNumResyncSamples);
529    if (mNumResyncSamples >= MIN_RESYNC_SAMPLES_FOR_UPDATE) {
530        ALOGV("[%s] Computing...", mName);
531        nsecs_t durationSum = 0;
532        nsecs_t minDuration = INT64_MAX;
533        nsecs_t maxDuration = 0;
534        for (size_t i = 1; i < mNumResyncSamples; i++) {
535            size_t idx = (mFirstResyncSample + i) % MAX_RESYNC_SAMPLES;
536            size_t prev = (idx + MAX_RESYNC_SAMPLES - 1) % MAX_RESYNC_SAMPLES;
537            nsecs_t duration = mResyncSamples[idx] - mResyncSamples[prev];
538            durationSum += duration;
539            minDuration = min(minDuration, duration);
540            maxDuration = max(maxDuration, duration);
541        }
542
543        // Exclude the min and max from the average
544        durationSum -= minDuration + maxDuration;
545        mPeriod = durationSum / (mNumResyncSamples - 3);
546
547        ALOGV("[%s] mPeriod = %" PRId64, mName, ns2us(mPeriod));
548
549        double sampleAvgX = 0;
550        double sampleAvgY = 0;
551        double scale = 2.0 * M_PI / double(mPeriod);
552        // Intentionally skip the first sample
553        for (size_t i = 1; i < mNumResyncSamples; i++) {
554            size_t idx = (mFirstResyncSample + i) % MAX_RESYNC_SAMPLES;
555            nsecs_t sample = mResyncSamples[idx] - mReferenceTime;
556            double samplePhase = double(sample % mPeriod) * scale;
557            sampleAvgX += cos(samplePhase);
558            sampleAvgY += sin(samplePhase);
559        }
560
561        sampleAvgX /= double(mNumResyncSamples - 1);
562        sampleAvgY /= double(mNumResyncSamples - 1);
563
564        mPhase = nsecs_t(atan2(sampleAvgY, sampleAvgX) / scale);
565
566        ALOGV("[%s] mPhase = %" PRId64, mName, ns2us(mPhase));
567
568        if (mPhase < -(mPeriod / 2)) {
569            mPhase += mPeriod;
570            ALOGV("[%s] Adjusting mPhase -> %" PRId64, mName, ns2us(mPhase));
571        }
572
573        if (kTraceDetailedInfo) {
574            ATRACE_INT64("DispSync:Period", mPeriod);
575            ATRACE_INT64("DispSync:Phase", mPhase + mPeriod / 2);
576        }
577
578        // Artificially inflate the period if requested.
579        mPeriod += mPeriod * mRefreshSkipCount;
580
581        mThread->updateModel(mPeriod, mPhase, mReferenceTime);
582        mModelUpdated = true;
583    }
584}
585
586void DispSync::updateErrorLocked() {
587    if (!mModelUpdated) {
588        return;
589    }
590
591    // Need to compare present fences against the un-adjusted refresh period,
592    // since they might arrive between two events.
593    nsecs_t period = mPeriod / (1 + mRefreshSkipCount);
594
595    int numErrSamples = 0;
596    nsecs_t sqErrSum = 0;
597
598    for (size_t i = 0; i < NUM_PRESENT_SAMPLES; i++) {
599        nsecs_t sample = mPresentTimes[i] - mReferenceTime;
600        if (sample > mPhase) {
601            nsecs_t sampleErr = (sample - mPhase) % period;
602            if (sampleErr > period / 2) {
603                sampleErr -= period;
604            }
605            sqErrSum += sampleErr * sampleErr;
606            numErrSamples++;
607        }
608    }
609
610    if (numErrSamples > 0) {
611        mError = sqErrSum / numErrSamples;
612    } else {
613        mError = 0;
614    }
615
616    if (kTraceDetailedInfo) {
617        ATRACE_INT64("DispSync:Error", mError);
618    }
619}
620
621void DispSync::resetErrorLocked() {
622    mPresentSampleOffset = 0;
623    mError = 0;
624    for (size_t i = 0; i < NUM_PRESENT_SAMPLES; i++) {
625        mPresentFences[i].clear();
626        mPresentTimes[i] = 0;
627    }
628}
629
630nsecs_t DispSync::computeNextRefresh(int periodOffset) const {
631    Mutex::Autolock lock(mMutex);
632    nsecs_t now = systemTime(SYSTEM_TIME_MONOTONIC);
633    nsecs_t phase = mReferenceTime + mPhase;
634    return (((now - phase) / mPeriod) + periodOffset + 1) * mPeriod + phase;
635}
636
637void DispSync::dump(String8& result) const {
638    Mutex::Autolock lock(mMutex);
639    result.appendFormat("present fences are %s\n",
640            kIgnorePresentFences ? "ignored" : "used");
641    result.appendFormat("mPeriod: %" PRId64 " ns (%.3f fps; skipCount=%d)\n",
642            mPeriod, 1000000000.0 / mPeriod, mRefreshSkipCount);
643    result.appendFormat("mPhase: %" PRId64 " ns\n", mPhase);
644    result.appendFormat("mError: %" PRId64 " ns (sqrt=%.1f)\n",
645            mError, sqrt(mError));
646    result.appendFormat("mNumResyncSamplesSincePresent: %d (limit %d)\n",
647            mNumResyncSamplesSincePresent, MAX_RESYNC_SAMPLES_WITHOUT_PRESENT);
648    result.appendFormat("mNumResyncSamples: %zd (max %d)\n",
649            mNumResyncSamples, MAX_RESYNC_SAMPLES);
650
651    result.appendFormat("mResyncSamples:\n");
652    nsecs_t previous = -1;
653    for (size_t i = 0; i < mNumResyncSamples; i++) {
654        size_t idx = (mFirstResyncSample + i) % MAX_RESYNC_SAMPLES;
655        nsecs_t sampleTime = mResyncSamples[idx];
656        if (i == 0) {
657            result.appendFormat("  %" PRId64 "\n", sampleTime);
658        } else {
659            result.appendFormat("  %" PRId64 " (+%" PRId64 ")\n",
660                    sampleTime, sampleTime - previous);
661        }
662        previous = sampleTime;
663    }
664
665    result.appendFormat("mPresentFences / mPresentTimes [%d]:\n",
666            NUM_PRESENT_SAMPLES);
667    nsecs_t now = systemTime(SYSTEM_TIME_MONOTONIC);
668    previous = 0;
669    for (size_t i = 0; i < NUM_PRESENT_SAMPLES; i++) {
670        size_t idx = (i + mPresentSampleOffset) % NUM_PRESENT_SAMPLES;
671        bool signaled = mPresentFences[idx] == NULL;
672        nsecs_t presentTime = mPresentTimes[idx];
673        if (!signaled) {
674            result.appendFormat("  [unsignaled fence]\n");
675        } else if (presentTime == 0) {
676            result.appendFormat("  0\n");
677        } else if (previous == 0) {
678            result.appendFormat("  %" PRId64 "  (%.3f ms ago)\n", presentTime,
679                    (now - presentTime) / 1000000.0);
680        } else {
681            result.appendFormat("  %" PRId64 " (+%" PRId64 " / %.3f)  (%.3f ms ago)\n",
682                    presentTime, presentTime - previous,
683                    (presentTime - previous) / (double) mPeriod,
684                    (now - presentTime) / 1000000.0);
685        }
686        previous = presentTime;
687    }
688
689    result.appendFormat("current monotonic time: %" PRId64 "\n", now);
690}
691
692} // namespace android
693