Track frame events incrementally and per layer.

* Replaces FenceTracker, which was owned by SurfaceFlinger,
    with FrameEventHistory, which is owned by Layer.
* Updates FrameEventHistory as events occur.
* Changes SurfaceFlinger flag "--fences" to
    "--frame-events".

Test: adb shell /data/nativetest/libgui_test/libgui_test
--gtest_filter=*GetFrameTimestamps*

Change-Id: I868c2ef93964656d7e41848243433499e7f45fe7
diff --git a/libs/gui/Android.bp b/libs/gui/Android.bp
index 9ba85a6..bf758ce 100644
--- a/libs/gui/Android.bp
+++ b/libs/gui/Android.bp
@@ -71,6 +71,7 @@
         "ConsumerBase.cpp",
         "CpuConsumer.cpp",
         "DisplayEventReceiver.cpp",
+        "FrameTimestamps.cpp",
         "GLConsumer.cpp",
         "GraphicBufferAlloc.cpp",
         "GuiConfig.cpp",
diff --git a/libs/gui/BufferQueue.cpp b/libs/gui/BufferQueue.cpp
index 47f5eba..6d4335e 100644
--- a/libs/gui/BufferQueue.cpp
+++ b/libs/gui/BufferQueue.cpp
@@ -61,13 +61,15 @@
     }
 }
 
-bool BufferQueue::ProxyConsumerListener::getFrameTimestamps(
-        uint64_t frameNumber, FrameTimestamps* outTimestamps) const {
+bool BufferQueue::ProxyConsumerListener::addAndGetFrameTimestamps(
+        const NewFrameEventsEntry* newTimestamps,
+        uint64_t frameNumber, FrameTimestamps* outTimestamps) {
     sp<ConsumerListener> listener(mConsumerListener.promote());
-    if (listener != NULL) {
-        return listener->getFrameTimestamps(frameNumber, outTimestamps);
+    if (listener == nullptr) {
+        return false;
     }
-    return false;
+    return listener->addAndGetFrameTimestamps(
+            newTimestamps, frameNumber, outTimestamps);
 }
 
 void BufferQueue::createBufferQueue(sp<IGraphicBufferProducer>* outProducer,
diff --git a/libs/gui/BufferQueueProducer.cpp b/libs/gui/BufferQueueProducer.cpp
index 81d4f31..6bd1cfd 100644
--- a/libs/gui/BufferQueueProducer.cpp
+++ b/libs/gui/BufferQueueProducer.cpp
@@ -740,19 +740,19 @@
     ATRACE_CALL();
     ATRACE_BUFFER_INDEX(slot);
 
-    int64_t timestamp;
+    int64_t requestedPresentTimestamp;
     bool isAutoTimestamp;
     android_dataspace dataSpace;
     Rect crop(Rect::EMPTY_RECT);
     int scalingMode;
     uint32_t transform;
     uint32_t stickyTransform;
-    sp<Fence> fence;
-    input.deflate(&timestamp, &isAutoTimestamp, &dataSpace, &crop, &scalingMode,
-            &transform, &fence, &stickyTransform);
+    sp<Fence> acquireFence;
+    input.deflate(&requestedPresentTimestamp, &isAutoTimestamp, &dataSpace,
+            &crop, &scalingMode, &transform, &acquireFence, &stickyTransform);
     Region surfaceDamage = input.getSurfaceDamage();
 
-    if (fence == NULL) {
+    if (acquireFence == NULL) {
         BQ_LOGE("queueBuffer: fence is NULL");
         return BAD_VALUE;
     }
@@ -771,6 +771,7 @@
     sp<IConsumerListener> frameAvailableListener;
     sp<IConsumerListener> frameReplacedListener;
     int callbackTicket = 0;
+    uint64_t currentFrameNumber = 0;
     BufferItem item;
     { // Autolock scope
         Mutex::Autolock lock(mCore->mMutex);
@@ -809,8 +810,9 @@
 
         BQ_LOGV("queueBuffer: slot=%d/%" PRIu64 " time=%" PRIu64 " dataSpace=%d"
                 " crop=[%d,%d,%d,%d] transform=%#x scale=%s",
-                slot, mCore->mFrameCounter + 1, timestamp, dataSpace,
-                crop.left, crop.top, crop.right, crop.bottom, transform,
+                slot, mCore->mFrameCounter + 1, requestedPresentTimestamp,
+                dataSpace, crop.left, crop.top, crop.right, crop.bottom,
+                transform,
                 BufferItem::scalingModeName(static_cast<uint32_t>(scalingMode)));
 
         const sp<GraphicBuffer>& graphicBuffer(mSlots[slot].mGraphicBuffer);
@@ -828,11 +830,14 @@
             dataSpace = mCore->mDefaultBufferDataSpace;
         }
 
-        mSlots[slot].mFence = fence;
+        mSlots[slot].mFence = acquireFence;
         mSlots[slot].mBufferState.queue();
 
+        // Increment the frame counter and store a local version of it
+        // for use outside the lock on mCore->mMutex.
         ++mCore->mFrameCounter;
-        mSlots[slot].mFrameNumber = mCore->mFrameCounter;
+        currentFrameNumber = mCore->mFrameCounter;
+        mSlots[slot].mFrameNumber = currentFrameNumber;
 
         item.mAcquireCalled = mSlots[slot].mAcquireCalled;
         item.mGraphicBuffer = mSlots[slot].mGraphicBuffer;
@@ -842,12 +847,12 @@
         item.mTransformToDisplayInverse =
                 (transform & NATIVE_WINDOW_TRANSFORM_INVERSE_DISPLAY) != 0;
         item.mScalingMode = static_cast<uint32_t>(scalingMode);
-        item.mTimestamp = timestamp;
+        item.mTimestamp = requestedPresentTimestamp;
         item.mIsAutoTimestamp = isAutoTimestamp;
         item.mDataSpace = dataSpace;
-        item.mFrameNumber = mCore->mFrameCounter;
+        item.mFrameNumber = currentFrameNumber;
         item.mSlot = slot;
-        item.mFence = fence;
+        item.mFence = acquireFence;
         item.mIsDroppable = mCore->mAsyncMode ||
                 mCore->mDequeueBufferCannotBlock ||
                 (mCore->mSharedBufferMode && mCore->mSharedBufferSlot == slot);
@@ -958,10 +963,20 @@
         // small trade-off in favor of latency rather than throughput.
         mLastQueueBufferFence->waitForever("Throttling EGL Production");
     }
-    mLastQueueBufferFence = fence;
+    mLastQueueBufferFence = acquireFence;
     mLastQueuedCrop = item.mCrop;
     mLastQueuedTransform = item.mTransform;
 
+    // Update and get FrameEventHistory.
+    nsecs_t postedTime = systemTime(SYSTEM_TIME_MONOTONIC);
+    NewFrameEventsEntry newFrameEventsEntry = {
+        currentFrameNumber,
+        postedTime,
+        requestedPresentTimestamp,
+        acquireFence
+    };
+    addAndGetFrameTimestamps(&newFrameEventsEntry, 0, nullptr);
+
     return NO_ERROR;
 }
 
@@ -1449,18 +1464,28 @@
     return NO_ERROR;
 }
 
-bool BufferQueueProducer::getFrameTimestamps(uint64_t frameNumber,
-        FrameTimestamps* outTimestamps) const {
-    ATRACE_CALL();
-    BQ_LOGV("getFrameTimestamps, %" PRIu64, frameNumber);
-    sp<IConsumerListener> listener;
+bool BufferQueueProducer::getFrameTimestamps(
+        uint64_t frameNumber, FrameTimestamps* outTimestamps) {
+    return addAndGetFrameTimestamps(nullptr, frameNumber, outTimestamps);
+}
 
+bool BufferQueueProducer::addAndGetFrameTimestamps(
+        const NewFrameEventsEntry* newTimestamps,
+        uint64_t frameNumber, FrameTimestamps* outTimestamps) {
+    if (newTimestamps == nullptr && outTimestamps == nullptr) {
+        return false;
+    }
+
+    ATRACE_CALL();
+    BQ_LOGV("addAndGetFrameTimestamps");
+    sp<IConsumerListener> listener;
     {
         Mutex::Autolock lock(mCore->mMutex);
         listener = mCore->mConsumerListener;
     }
     if (listener != NULL) {
-        return listener->getFrameTimestamps(frameNumber, outTimestamps);
+        return listener->addAndGetFrameTimestamps(
+                newTimestamps, frameNumber, outTimestamps);
     }
     return false;
 }
diff --git a/libs/gui/FrameTimestamps.cpp b/libs/gui/FrameTimestamps.cpp
new file mode 100644
index 0000000..a919911
--- /dev/null
+++ b/libs/gui/FrameTimestamps.cpp
@@ -0,0 +1,290 @@
+/*
+* Copyright 2016 The Android Open Source Project
+*
+* Licensed under the Apache License, Version 2.0 (the "License");
+* you may not use this file except in compliance with the License.
+* You may obtain a copy of the License at
+*
+*      http://www.apache.org/licenses/LICENSE-2.0
+*
+* Unless required by applicable law or agreed to in writing, software
+* distributed under the License is distributed on an "AS IS" BASIS,
+* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+* See the License for the specific language governing permissions and
+* limitations under the License.
+*/
+
+#include <gui/FrameTimestamps.h>
+
+#include <inttypes.h>
+#include <utils/String8.h>
+
+#include <algorithm>
+#include <limits>
+
+namespace android {
+
+static inline bool isValidTimestamp(nsecs_t time) {
+    return time > 0 && time < INT64_MAX;
+}
+
+// ============================================================================
+// FrameTimestamps
+// ============================================================================
+
+FrameTimestamps::FrameTimestamps(const FrameEvents& events) :
+    frameNumber(events.frameNumber),
+    postedTime(events.postedTime),
+    requestedPresentTime(events.requestedPresentTime),
+    acquireTime(events.acquireTime),
+    refreshStartTime(events.firstRefreshStartTime),
+    glCompositionDoneTime(events.gpuCompositionDoneTime),
+    displayPresentTime(events.displayPresentTime),
+    displayRetireTime(events.displayRetireTime),
+    releaseTime(events.releaseTime) {}
+
+
+// ============================================================================
+// FrameEvents
+// ============================================================================
+
+static void checkFenceForCompletion(sp<Fence>* fence, nsecs_t* dstTime) {
+    if ((*fence)->isValid()) {
+        nsecs_t time = (*fence)->getSignalTime();
+        if (isValidTimestamp(time)) {
+            *dstTime = time;
+            *fence = Fence::NO_FENCE;
+        }
+    }
+}
+
+void FrameEvents::checkFencesForCompletion() {
+    checkFenceForCompletion(&acquireFence, &acquireTime);
+    checkFenceForCompletion(&gpuCompositionDoneFence, &gpuCompositionDoneTime);
+    checkFenceForCompletion(&displayPresentFence, &displayPresentTime);
+    checkFenceForCompletion(&displayRetireFence, &displayRetireTime);
+    checkFenceForCompletion(&releaseFence, &releaseTime);
+}
+
+void FrameEvents::dump(String8& outString) const
+{
+    if (!valid) {
+        return;
+    }
+
+    outString.appendFormat("-- Frame %" PRIu64 "\n", frameNumber);
+    outString.appendFormat("--- Posted      \t%" PRId64 "\n", postedTime);
+    outString.appendFormat("--- Req. Present\t%" PRId64 "\n", requestedPresentTime);
+
+    outString.appendFormat("--- Latched     \t");
+    if (isValidTimestamp(latchTime)) {
+        outString.appendFormat("%" PRId64 "\n", latchTime);
+    } else {
+        outString.appendFormat("Pending\n");
+    }
+
+    outString.appendFormat("--- Refresh (First)\t");
+    if (isValidTimestamp(firstRefreshStartTime)) {
+        outString.appendFormat("%" PRId64 "\n", firstRefreshStartTime);
+    } else {
+        outString.appendFormat("Pending\n");
+    }
+
+    outString.appendFormat("--- Refresh (Last)\t");
+    if (isValidTimestamp(lastRefreshStartTime)) {
+        outString.appendFormat("%" PRId64 "\n", lastRefreshStartTime);
+    } else {
+        outString.appendFormat("Pending\n");
+    }
+
+    outString.appendFormat("--- Acquire     \t");
+    if (isValidTimestamp(acquireTime)) {
+        outString.appendFormat("%" PRId64 "\n", acquireTime);
+    } else {
+        outString.appendFormat("Pending\n");
+    }
+
+    outString.appendFormat("--- GPU Composite Done\t");
+    if (isValidTimestamp(gpuCompositionDoneTime)) {
+        outString.appendFormat("%" PRId64 "\n", gpuCompositionDoneTime);
+    } else if (!addPostCompositeCalled || gpuCompositionDoneFence->isValid()) {
+        outString.appendFormat("Pending\n");
+    } else {
+        outString.appendFormat("N/A\n");
+    }
+
+    outString.appendFormat("--- Display Present\t");
+    if (isValidTimestamp(displayPresentTime)) {
+        outString.appendFormat("%" PRId64 "\n", displayPresentTime);
+    } else if (!addPostCompositeCalled || displayPresentFence->isValid()) {
+        outString.appendFormat("Pending\n");
+    } else {
+        outString.appendFormat("N/A\n");
+    }
+
+    outString.appendFormat("--- Display Retire\t");
+    if (isValidTimestamp(displayRetireTime)) {
+        outString.appendFormat("%" PRId64 "\n", displayRetireTime);
+    } else if (!addRetireCalled || displayRetireFence->isValid()) {
+        outString.appendFormat("Pending\n");
+    } else {
+        outString.appendFormat("N/A\n");
+    }
+
+    outString.appendFormat("--- Release     \t");
+    if (isValidTimestamp(releaseTime)) {
+        outString.appendFormat("%" PRId64 "\n", releaseTime);
+    } else {
+        outString.appendFormat("Pending\n");
+    }
+}
+
+
+// ============================================================================
+// FrameEventHistory
+// ============================================================================
+
+namespace {
+
+struct FrameNumberEqual {
+    FrameNumberEqual(uint64_t frameNumber) : mFrameNumber(frameNumber) {}
+    bool operator()(const FrameEvents& frame) {
+        return frame.valid && mFrameNumber == frame.frameNumber;
+    }
+    const uint64_t mFrameNumber;
+};
+
+}  // namespace
+
+
+FrameEvents* FrameEventHistory::getFrame(uint64_t frameNumber) {
+    auto frame = std::find_if(
+            mFrames.begin(), mFrames.end(), FrameNumberEqual(frameNumber));
+    return frame == mFrames.end() ? nullptr : &(*frame);
+}
+
+FrameEvents* FrameEventHistory::getFrame(uint64_t frameNumber, size_t* iHint) {
+    *iHint = std::min(*iHint, mFrames.size());
+    auto hint = mFrames.begin() + *iHint;
+    auto frame = std::find_if(
+            hint, mFrames.end(), FrameNumberEqual(frameNumber));
+    if (frame == mFrames.end()) {
+        frame = std::find_if(
+                mFrames.begin(), hint, FrameNumberEqual(frameNumber));
+        if (frame == hint) {
+            return nullptr;
+        }
+    }
+    *iHint = static_cast<size_t>(std::distance(mFrames.begin(), frame));
+    return &(*frame);
+}
+
+void FrameEventHistory::checkFencesForCompletion() {
+    for (auto& frame : mFrames) {
+        frame.checkFencesForCompletion();
+    }
+}
+
+// Uses !|valid| as the MSB.
+static bool FrameNumberLessThan(
+        const FrameEvents& lhs, const FrameEvents& rhs) {
+    if (lhs.valid == rhs.valid) {
+        return lhs.frameNumber < rhs.frameNumber;
+    }
+    return lhs.valid;
+}
+
+void FrameEventHistory::dump(String8& outString) const {
+    auto earliestFrame = std::min_element(
+            mFrames.begin(), mFrames.end(), &FrameNumberLessThan);
+    if (!earliestFrame->valid) {
+        outString.appendFormat("-- N/A\n");
+        return;
+    }
+    for (auto frame = earliestFrame; frame != mFrames.end(); ++frame) {
+        frame->dump(outString);
+    }
+    for (auto frame = mFrames.begin(); frame != earliestFrame; ++frame) {
+        frame->dump(outString);
+    }
+}
+
+void FrameEventHistory::addQueue(const NewFrameEventsEntry& newFrameEntry) {
+    // Overwrite all fields of the frame with default values unless set here.
+    FrameEvents newTimestamps;
+    newTimestamps.frameNumber = newFrameEntry.frameNumber;
+    newTimestamps.postedTime = newFrameEntry.postedTime;
+    newTimestamps.requestedPresentTime = newFrameEntry.requestedPresentTime;
+    newTimestamps.acquireFence = newFrameEntry.acquireFence;
+    newTimestamps.valid = true;
+    mFrames[mQueueOffset] = newTimestamps;
+
+    mQueueOffset = mQueueOffset + 1;
+    if (mQueueOffset >= mFrames.size()) {
+        mQueueOffset = 0;
+    }
+}
+
+void FrameEventHistory::addLatch(uint64_t frameNumber, nsecs_t latchTime) {
+    FrameEvents* frame = getFrame(frameNumber, &mCompositionOffset);
+    if (frame == nullptr) {
+        ALOGE("FrameEventHistory::addLatch: Did not find frame.");
+        return;
+    }
+    frame->latchTime = latchTime;
+    return;
+}
+
+void FrameEventHistory::addPreComposition(
+        uint64_t frameNumber, nsecs_t refreshStartTime) {
+    FrameEvents* frame = getFrame(frameNumber, &mCompositionOffset);
+    if (frame == nullptr) {
+        ALOGE("FrameEventHistory::addPreComposition: Did not find frame.");
+        return;
+    }
+    frame->lastRefreshStartTime = refreshStartTime;
+    if (!isValidTimestamp(frame->firstRefreshStartTime)) {
+        frame->firstRefreshStartTime = refreshStartTime;
+    }
+}
+
+void FrameEventHistory::addPostComposition(uint64_t frameNumber,
+        sp<Fence> gpuCompositionDone, sp<Fence> displayPresent) {
+    FrameEvents* frame = getFrame(frameNumber, &mCompositionOffset);
+    if (frame == nullptr) {
+        ALOGE("FrameEventHistory::addPostComposition: Did not find frame.");
+        return;
+    }
+
+    // Only get GPU and present info for the first composite.
+    if (!frame->addPostCompositeCalled) {
+        frame->addPostCompositeCalled = true;
+        frame->gpuCompositionDoneFence = gpuCompositionDone;
+        if (!frame->displayPresentFence->isValid()) {
+            frame->displayPresentFence = displayPresent;
+        }
+    }
+}
+
+void FrameEventHistory::addRetire(
+        uint64_t frameNumber, sp<Fence> displayRetire) {
+    FrameEvents* frame = getFrame(frameNumber, &mRetireOffset);
+    if (frame == nullptr) {
+        ALOGE("FrameEventHistory::addRetire: Did not find frame.");
+        return;
+    }
+    frame->addRetireCalled = true;
+    frame->displayRetireFence = displayRetire;
+}
+
+void FrameEventHistory::addRelease(
+        uint64_t frameNumber, sp<Fence> release) {
+    FrameEvents* frame = getFrame(frameNumber, &mReleaseOffset);
+    if (frame == nullptr) {
+        ALOGE("FrameEventHistory::addRelease: Did not find frame.");
+        return;
+    }
+    frame->releaseFence = release;
+}
+
+} // namespace android
diff --git a/libs/gui/IGraphicBufferProducer.cpp b/libs/gui/IGraphicBufferProducer.cpp
index 89f852c..a4de7eb 100644
--- a/libs/gui/IGraphicBufferProducer.cpp
+++ b/libs/gui/IGraphicBufferProducer.cpp
@@ -430,7 +430,7 @@
     }
 
     virtual bool getFrameTimestamps(uint64_t frameNumber,
-                FrameTimestamps* outTimestamps) const {
+                FrameTimestamps* outTimestamps) {
         Parcel data, reply;
         status_t result = data.writeInterfaceToken(
                 IGraphicBufferProducer::getInterfaceDescriptor());