SF: Adding Layer History to SF.

Calculate average and median between the timestamp differences that come in for
individual layers, and store them to systrace.

See go/surface-flinger-scheduler for more details and systrace links.

Test: SF tests updated.
Bug: 113612090
Change-Id: I934bbe36ab57d16a5b219c7cb8e0580112238671
diff --git a/services/surfaceflinger/BufferQueueLayer.cpp b/services/surfaceflinger/BufferQueueLayer.cpp
index 78ab23a..162f391 100644
--- a/services/surfaceflinger/BufferQueueLayer.cpp
+++ b/services/surfaceflinger/BufferQueueLayer.cpp
@@ -352,9 +352,10 @@
 void BufferQueueLayer::onFrameAvailable(const BufferItem& item) {
     // Add this buffer from our internal queue tracker
     { // Autolock scope
-        // Report the timestamp to the Scheduler.
+        // Report the requested present time to the Scheduler.
         if (mFlinger->mUseScheduler) {
-            mFlinger->mScheduler->addNewFrameTimestamp(item.mTimestamp, item.mIsAutoTimestamp);
+            mFlinger->mScheduler->addFramePresentTimeForLayer(item.mTimestamp,
+                                                              item.mIsAutoTimestamp, mName.c_str());
         }
 
         Mutex::Autolock lock(mQueueItemLock);
@@ -382,7 +383,7 @@
 
     mFlinger->mInterceptor->saveBufferUpdate(this, item.mGraphicBuffer->getWidth(),
                                              item.mGraphicBuffer->getHeight(), item.mFrameNumber);
-    
+
     // If this layer is orphaned, then we run a fake vsync pulse so that
     // dequeueBuffer doesn't block indefinitely.
     if (isRemovedFromCurrentState()) {
diff --git a/services/surfaceflinger/Scheduler/LayerHistory.cpp b/services/surfaceflinger/Scheduler/LayerHistory.cpp
index e944eb9..1f47949 100644
--- a/services/surfaceflinger/Scheduler/LayerHistory.cpp
+++ b/services/surfaceflinger/Scheduler/LayerHistory.cpp
@@ -39,11 +39,15 @@
 void LayerHistory::incrementCounter() {
     mCounter++;
     mCounter = mCounter % ARRAY_SIZE;
+    // Clear all the previous data from the history. This is a ring buffer, so we are
+    // reusing memory.
     mElements[mCounter].clear();
 }
 
 const std::unordered_map<std::string, nsecs_t>& LayerHistory::get(size_t index) const {
-    return mElements.at(index);
+    // For the purposes of the layer history, the index = 0 always needs to start at the
+    // current counter, and then decrement to access the layers in correct historical order.
+    return mElements.at((ARRAY_SIZE + (mCounter - (index % ARRAY_SIZE))) % ARRAY_SIZE);
 }
 
 } // namespace android
\ No newline at end of file
diff --git a/services/surfaceflinger/Scheduler/LayerHistory.h b/services/surfaceflinger/Scheduler/LayerHistory.h
index 1a7f9cd..76c1352 100644
--- a/services/surfaceflinger/Scheduler/LayerHistory.h
+++ b/services/surfaceflinger/Scheduler/LayerHistory.h
@@ -42,14 +42,17 @@
     ~LayerHistory();
 
     // Method for inserting layers and their requested present time into the ring buffer.
-    // The elements are going to be inserted into an unordered_map at the position of
-    // mCounter.
+    // The elements are going to be inserted into an unordered_map at the position 'now'.
     void insert(const std::string layerName, nsecs_t presentTime);
     // Method for incrementing the current slot in the ring buffer. It also clears the
     // unordered_map, if it was created previously.
     void incrementCounter();
-    // Returns unordered_map at the given at index.
+    // Returns unordered_map at the given at index. The index is decremented from 'now'. For
+    // example, 0 is now, 1 is previous frame.
     const std::unordered_map<std::string, nsecs_t>& get(size_t index) const;
+    // Returns the total size of the ring buffer. The value is always the same regardless
+    // of how many slots we filled in.
+    static constexpr size_t getSize() { return ARRAY_SIZE; }
 
 private:
     size_t mCounter = 0;
diff --git a/services/surfaceflinger/Scheduler/Scheduler.cpp b/services/surfaceflinger/Scheduler/Scheduler.cpp
index 4286cc9..4d3ae33 100644
--- a/services/surfaceflinger/Scheduler/Scheduler.cpp
+++ b/services/surfaceflinger/Scheduler/Scheduler.cpp
@@ -30,6 +30,7 @@
 
 #include <gui/ISurfaceComposer.h>
 #include <ui/DisplayStatInfo.h>
+#include <utils/Timers.h>
 #include <utils/Trace.h>
 
 #include "DispSync.h"
@@ -205,15 +206,95 @@
     mHWVsyncAvailable = makeAvailable;
 }
 
-void Scheduler::addNewFrameTimestamp(const nsecs_t newFrameTimestamp, bool isAutoTimestamp) {
+void Scheduler::addFramePresentTimeForLayer(const nsecs_t framePresentTime, bool isAutoTimestamp,
+                                            const std::string layerName) {
+    // This is V1 logic. It calculates the average FPS based on the timestamp frequency
+    // regardless of which layer the timestamp came from.
+    // For now, the averages and FPS are recorded in the systrace.
+    determineTimestampAverage(isAutoTimestamp, framePresentTime);
+
+    // This is V2 logic. It calculates the average and median timestamp difference based on the
+    // individual layer history. The results are recorded in the systrace.
+    determineLayerTimestampStats(layerName, framePresentTime);
+}
+
+void Scheduler::incrementFrameCounter() {
+    mLayerHistory.incrementCounter();
+}
+
+nsecs_t Scheduler::calculateAverage() const {
+    nsecs_t sum = std::accumulate(mTimeDifferences.begin(), mTimeDifferences.end(), 0);
+    return (sum / ARRAY_SIZE);
+}
+
+void Scheduler::updateFrameSkipping(const int64_t skipCount) {
+    ATRACE_INT("FrameSkipCount", skipCount);
+    if (mSkipCount != skipCount) {
+        // Only update DispSync if it hasn't been updated yet.
+        mPrimaryDispSync->setRefreshSkipCount(skipCount);
+        mSkipCount = skipCount;
+    }
+}
+
+void Scheduler::determineLayerTimestampStats(const std::string layerName,
+                                             const nsecs_t framePresentTime) {
+    mLayerHistory.insert(layerName, framePresentTime);
+    std::vector<int64_t> differencesMs;
+
+    // Traverse through the layer history, and determine the differences in present times.
+    nsecs_t newestPresentTime = framePresentTime;
+    for (int i = 1; i < mLayerHistory.getSize(); i++) {
+        std::unordered_map<std::string, nsecs_t> layers = mLayerHistory.get(i);
+        for (auto layer : layers) {
+            if (layer.first != layerName) {
+                continue;
+            }
+            int64_t differenceMs = (newestPresentTime - layer.second) / 1000000;
+            ALOGD("%d Layer %s: %" PRId64, i, layerName.c_str(), differenceMs);
+            // Dismiss noise.
+            if (differenceMs > 10 && differenceMs < 60) {
+                differencesMs.push_back(differenceMs);
+            }
+            newestPresentTime = layer.second;
+        }
+    }
+    // Average is a good indicator for when 24fps videos are playing, because the frames come in
+    // 33, and 49 ms intervals with occasional 41ms.
+    int64_t average =
+            std::accumulate(differencesMs.begin(), differencesMs.end(), 0) / differencesMs.size();
+    const auto tag = "TimestampAvg_" + layerName;
+    ATRACE_INT(tag.c_str(), average);
+
+    // Mode and median are good indicators for 30 and 60 fps videos, because the majority of frames
+    // come in 16, or 33 ms intervals.
+    // TODO(b/113612090): Calculate mode. Median is good for now, since we want a given interval to
+    // repeat at least ARRAY_SIZE/2 + 1 times.
+    if (differencesMs.size() > 0) {
+        const auto tagMedian = "TimestampMedian_" + layerName;
+        ATRACE_INT(tagMedian.c_str(), calculateMedian(&differencesMs));
+    }
+}
+
+int64_t Scheduler::calculateMedian(std::vector<int64_t>* v) {
+    if (!v || v->size() == 0) {
+        return 0;
+    }
+
+    size_t n = v->size() / 2;
+    nth_element(v->begin(), v->begin() + n, v->end());
+    return v->at(n);
+}
+
+void Scheduler::determineTimestampAverage(bool isAutoTimestamp, const nsecs_t framePresentTime) {
     ATRACE_INT("AutoTimestamp", isAutoTimestamp);
+
     // Video does not have timestamp automatically set, so we discard timestamps that are
     // coming in from other sources for now.
     if (isAutoTimestamp) {
         return;
     }
-    int64_t differenceMs = (newFrameTimestamp - mPreviousFrameTimestamp) / 1000000;
-    mPreviousFrameTimestamp = newFrameTimestamp;
+    int64_t differenceMs = (framePresentTime - mPreviousFrameTimestamp) / 1000000;
+    mPreviousFrameTimestamp = framePresentTime;
 
     if (differenceMs < 10 || differenceMs > 100) {
         // Dismiss noise.
@@ -240,18 +321,4 @@
     updateFrameSkipping(0);
 }
 
-nsecs_t Scheduler::calculateAverage() const {
-    nsecs_t sum = std::accumulate(mTimeDifferences.begin(), mTimeDifferences.end(), 0);
-    return (sum / ARRAY_SIZE);
-}
-
-void Scheduler::updateFrameSkipping(const int64_t skipCount) {
-    ATRACE_INT("FrameSkipCount", skipCount);
-    if (mSkipCount != skipCount) {
-        // Only update DispSync if it hasn't been updated yet.
-        mPrimaryDispSync->setRefreshSkipCount(skipCount);
-        mSkipCount = skipCount;
-    }
-}
-
 } // namespace android
diff --git a/services/surfaceflinger/Scheduler/Scheduler.h b/services/surfaceflinger/Scheduler/Scheduler.h
index dd1f24b..adfc071 100644
--- a/services/surfaceflinger/Scheduler/Scheduler.h
+++ b/services/surfaceflinger/Scheduler/Scheduler.h
@@ -26,6 +26,7 @@
 #include "EventControlThread.h"
 #include "EventThread.h"
 #include "InjectVSyncSource.h"
+#include "LayerHistory.h"
 
 namespace android {
 
@@ -103,9 +104,15 @@
     void addPresentFence(const std::shared_ptr<FenceTime>& fenceTime);
     void setIgnorePresentFences(bool ignore);
     void makeHWSyncAvailable(bool makeAvailable);
-    void addNewFrameTimestamp(const nsecs_t newFrameTimestamp, bool isAutoTimestamp);
+    // Adds the present time for given layer to the history of present times.
+    void addFramePresentTimeForLayer(const nsecs_t framePresentTime, bool isAutoTimestamp,
+                                     const std::string layerName);
+    // Increments counter in the layer history to indicate that SF has started a new frame.
+    void incrementFrameCounter();
 
 protected:
+    friend class SchedulerTest;
+
     virtual std::unique_ptr<EventThread> makeEventThread(
             const std::string& connectionName, DispSync* dispSync, int64_t phaseOffsetNs,
             impl::EventThread::ResyncWithRateLimitCallback resyncCallback,
@@ -114,6 +121,15 @@
 private:
     nsecs_t calculateAverage() const;
     void updateFrameSkipping(const int64_t skipCount);
+    // Collects the statistical mean (average) and median between timestamp
+    // intervals for each frame for each layer.
+    void determineLayerTimestampStats(const std::string layerName, const nsecs_t framePresentTime);
+    // Calculates the statistical median in the vector. Return 0 if the vector is empty. The
+    // function modifies the vector contents.
+    int64_t calculateMedian(std::vector<int64_t>* v);
+    // Collects the average difference between timestamps for each frame regardless
+    // of which layer the timestamp came from.
+    void determineTimestampAverage(bool isAutoTimestamp, const nsecs_t framePresentTime);
 
     // TODO(b/113612090): Instead of letting BufferQueueLayer to access mDispSync directly, it
     // should make request to Scheduler to compute next refresh.
@@ -150,6 +166,8 @@
     static constexpr size_t ARRAY_SIZE = 30;
     std::array<int64_t, ARRAY_SIZE> mTimeDifferences;
     size_t mCounter = 0;
+
+    LayerHistory mLayerHistory;
 };
 
 } // namespace android
diff --git a/services/surfaceflinger/SurfaceFlinger.cpp b/services/surfaceflinger/SurfaceFlinger.cpp
index 7150660..d81dea9 100644
--- a/services/surfaceflinger/SurfaceFlinger.cpp
+++ b/services/surfaceflinger/SurfaceFlinger.cpp
@@ -1489,6 +1489,10 @@
     ATRACE_CALL();
     switch (what) {
         case MessageQueue::INVALIDATE: {
+            if (mUseScheduler) {
+                // This call is made each time SF wakes up and creates a new frame.
+                mScheduler->incrementFrameCounter();
+            }
             bool frameMissed = !mHadClientComposition &&
                     mPreviousPresentFence != Fence::NO_FENCE &&
                     (mPreviousPresentFence->getSignalTime() ==
diff --git a/services/surfaceflinger/tests/unittests/LayerHistoryTest.cpp b/services/surfaceflinger/tests/unittests/LayerHistoryTest.cpp
index b518f10..3fb1a6e 100644
--- a/services/surfaceflinger/tests/unittests/LayerHistoryTest.cpp
+++ b/services/surfaceflinger/tests/unittests/LayerHistoryTest.cpp
@@ -85,11 +85,13 @@
 
     // Because the counter was incremented, the elements were inserted into different
     // containers.
+    // We expect the get method to access the slot at the current counter of the index
+    // is 0.
     const std::unordered_map<std::string, nsecs_t>& testMap1 = mLayerHistory->get(0);
     EXPECT_EQ(1, testMap1.size());
-    auto element = testMap1.find("TestLayer0");
-    EXPECT_EQ("TestLayer0", element->first);
-    EXPECT_EQ(0, element->second);
+    auto element = testMap1.find("TestLayer3");
+    EXPECT_EQ("TestLayer3", element->first);
+    EXPECT_EQ(3, element->second);
 
     const std::unordered_map<std::string, nsecs_t>& testMap2 = mLayerHistory->get(1);
     EXPECT_EQ(2, testMap2.size());
@@ -102,9 +104,9 @@
 
     const std::unordered_map<std::string, nsecs_t>& testMap3 = mLayerHistory->get(2);
     EXPECT_EQ(1, testMap3.size());
-    element = testMap3.find("TestLayer3");
-    EXPECT_EQ("TestLayer3", element->first);
-    EXPECT_EQ(3, element->second);
+    element = testMap3.find("TestLayer0");
+    EXPECT_EQ("TestLayer0", element->first);
+    EXPECT_EQ(0, element->second);
 
     // Testing accessing object at an empty container will return an empty map.
     const std::unordered_map<std::string, nsecs_t>& emptyMap = mLayerHistory->get(3);
@@ -113,7 +115,6 @@
 
 TEST_F(LayerHistoryTest, clearTheMap) {
     mLayerHistory->insert("TestLayer0", 0);
-    mLayerHistory->incrementCounter();
 
     const std::unordered_map<std::string, nsecs_t>& testMap1 = mLayerHistory->get(0);
     EXPECT_EQ(1, testMap1.size());
@@ -121,6 +122,7 @@
     EXPECT_EQ("TestLayer0", element->first);
     EXPECT_EQ(0, element->second);
 
+    mLayerHistory->incrementCounter();
     // The array currently contains 30 elements.
     for (int i = 1; i < 30; ++i) {
         mLayerHistory->insert("TestLayer0", i);
@@ -140,5 +142,33 @@
     EXPECT_EQ(testMap3.end(), element);
 }
 
+TEST_F(LayerHistoryTest, testingGet) {
+    // The array currently contains 30 elements.
+    for (int i = 0; i < 30; ++i) {
+        const auto name = "TestLayer" + std::to_string(i);
+        mLayerHistory->insert(name, i);
+        mLayerHistory->incrementCounter();
+    }
+
+    // The counter should be set to 0, and the map at 0 should be cleared.
+    const std::unordered_map<std::string, nsecs_t>& testMap1 = mLayerHistory->get(0);
+    EXPECT_EQ(0, testMap1.size());
+
+    // This should return (ARRAY_SIZE + (counter - 3)) % ARRAY_SIZE
+    const std::unordered_map<std::string, nsecs_t>& testMap2 = mLayerHistory->get(3);
+    EXPECT_EQ(1, testMap2.size());
+    auto element = testMap2.find("TestLayer27");
+    EXPECT_EQ("TestLayer27", element->first);
+    EXPECT_EQ(27, element->second);
+
+    // If the user gives an out of bound index, we should mod it with ARRAY_SIZE first,
+    // so requesting element 40 would be the same as requesting element 10.
+    const std::unordered_map<std::string, nsecs_t>& testMap3 = mLayerHistory->get(40);
+    EXPECT_EQ(1, testMap3.size());
+    element = testMap3.find("TestLayer20");
+    EXPECT_EQ("TestLayer20", element->first);
+    EXPECT_EQ(20, element->second);
+}
+
 } // namespace
 } // namespace android
\ No newline at end of file
diff --git a/services/surfaceflinger/tests/unittests/SchedulerTest.cpp b/services/surfaceflinger/tests/unittests/SchedulerTest.cpp
index be91a9c..e967742 100644
--- a/services/surfaceflinger/tests/unittests/SchedulerTest.cpp
+++ b/services/surfaceflinger/tests/unittests/SchedulerTest.cpp
@@ -59,6 +59,8 @@
     SchedulerTest();
     ~SchedulerTest() override;
 
+    int64_t calculateMedian(std::vector<int64_t>* v);
+
     sp<Scheduler::ConnectionHandle> mConnectionHandle;
     mock::DispSync* mPrimaryDispSync = new mock::DispSync();
     mock::EventThread* mEventThread;
@@ -95,6 +97,10 @@
     ALOGD("**** Tearing down after %s.%s\n", test_info->test_case_name(), test_info->name());
 }
 
+int64_t SchedulerTest::calculateMedian(std::vector<int64_t>* v) {
+    return mScheduler->calculateMedian(v);
+}
+
 namespace {
 /* ------------------------------------------------------------------------
  * Test cases
@@ -185,5 +191,37 @@
     ASSERT_NO_FATAL_FAILURE(mScheduler->setPhaseOffset(mConnectionHandle, 10));
 }
 
+TEST_F(SchedulerTest, calculateMedian) {
+    std::vector<int64_t> testVector;
+    // Calling the function on empty vector returns 0.
+    EXPECT_EQ(0, calculateMedian(&testVector));
+
+    testVector.push_back(33);
+    EXPECT_EQ(33, calculateMedian(&testVector));
+    testVector.push_back(33);
+    testVector.push_back(33);
+    EXPECT_EQ(33, calculateMedian(&testVector));
+    testVector.push_back(42);
+    EXPECT_EQ(33, calculateMedian(&testVector));
+    testVector.push_back(33);
+    EXPECT_EQ(33, calculateMedian(&testVector));
+    testVector.push_back(42);
+    EXPECT_EQ(33, calculateMedian(&testVector));
+    testVector.push_back(42);
+    EXPECT_EQ(33, calculateMedian(&testVector));
+    testVector.push_back(42);
+    EXPECT_EQ(42, calculateMedian(&testVector));
+    testVector.push_back(60);
+    EXPECT_EQ(42, calculateMedian(&testVector));
+    testVector.push_back(60);
+    EXPECT_EQ(42, calculateMedian(&testVector));
+    testVector.push_back(33);
+    EXPECT_EQ(42, calculateMedian(&testVector));
+    testVector.push_back(33);
+    EXPECT_EQ(42, calculateMedian(&testVector));
+    testVector.push_back(33);
+    EXPECT_EQ(33, calculateMedian(&testVector));
+}
+
 } // namespace
-} // namespace android
\ No newline at end of file
+} // namespace android