commit e5c49d5b893b3847bff76bffaf411886320e27a4
author Yiwei Zhang <zzyiwei@google.com> Mon Oct 29 00:15:31 2018 -0700
committer Yiwei Zhang <zzyiwei@google.com> Tue Oct 30 16:39:43 2018 -0700
tree ccb3c0e3e3796ba8757ca58e3eea45804d0d0a6e
parent 27631c9c42e8cfbfd7b42d60818b7954dcfbbc1e

SF TimeStats: fix a display on time logic bug

When TimeStats is disabled, dumpsys should not flush extra display on
time into the stats. Also, update the present to present histogram to
only collect stats when display is on power mode normal.

Bug: b/79872109
Test: dumpsys SurfaceFlinger --timestats <options>
Change-Id: Id8d5ce83e5b303acaf9ba9fcf2fb6fb9518683f7

services/surfaceflinger/TimeStats/TimeStats.cpp

diff --git a/services/surfaceflinger/TimeStats/TimeStats.cpp b/services/surfaceflinger/TimeStats/TimeStats.cpp
index 43fa262..c219afd 100644
--- a/services/surfaceflinger/TimeStats/TimeStats.cpp
+++ b/services/surfaceflinger/TimeStats/TimeStats.cpp
@@ -451,6 +451,8 @@
 }
 
 void TimeStats::flushPowerTimeLocked() {
+    if (!mEnabled.load()) return;
+
     nsecs_t curTime = systemTime();
     // elapsedTime is in milliseconds.
     int64_t elapsedTime = (curTime - mPowerTime.prevTime) / 1000000;
@@ -500,10 +502,14 @@
         ALOGV("GlobalPresentFenceTime[%" PRId64 "]",
               mGlobalRecord.presentFences.front()->getSignalTime());
 
-        const int32_t presentToPresentMs = msBetween(mGlobalRecord.prevPresentTime, curPresentTime);
-        ALOGV("Global present2present[%d]", presentToPresentMs);
+        if (mGlobalRecord.prevPresentTime != 0) {
+            const int32_t presentToPresentMs =
+                    msBetween(mGlobalRecord.prevPresentTime, curPresentTime);
+            ALOGV("Global present2present[%d] prev[%" PRId64 "] curr[%" PRId64 "]",
+                  presentToPresentMs, mGlobalRecord.prevPresentTime, curPresentTime);
+            mTimeStats.presentToPresent.insert(presentToPresentMs);
+        }
 
-        mTimeStats.presentToPresent.insert(presentToPresentMs);
         mGlobalRecord.prevPresentTime = curPresentTime;
         mGlobalRecord.presentFences.pop_front();
     }
@@ -514,7 +520,15 @@
 
     ATRACE_CALL();
     std::lock_guard<std::mutex> lock(mMutex);
-    if (presentFence == nullptr) {
+    if (presentFence == nullptr || !presentFence->isValid()) {
+        mGlobalRecord.prevPresentTime = 0;
+        return;
+    }
+
+    if (mPowerTime.powerMode != HWC_POWER_MODE_NORMAL) {
+        // Try flushing the last present fence on HWC_POWER_MODE_NORMAL.
+        flushAvailableGlobalRecordsToStatsLocked();
+        mGlobalRecord.presentFences.clear();
         mGlobalRecord.prevPresentTime = 0;
         return;
     }
@@ -537,10 +551,10 @@
     ATRACE_CALL();
 
     std::lock_guard<std::mutex> lock(mMutex);
-    ALOGD("Enabled");
     mEnabled.store(true);
     mTimeStats.statsStart = static_cast<int64_t>(std::time(0));
     mPowerTime.prevTime = systemTime();
+    ALOGD("Enabled");
 }
 
 void TimeStats::disable() {
@@ -549,16 +563,17 @@
     ATRACE_CALL();
 
     std::lock_guard<std::mutex> lock(mMutex);
-    ALOGD("Disabled");
+    flushPowerTimeLocked();
     mEnabled.store(false);
     mTimeStats.statsEnd = static_cast<int64_t>(std::time(0));
+    ALOGD("Disabled");
 }
 
 void TimeStats::clear() {
     ATRACE_CALL();
 
     std::lock_guard<std::mutex> lock(mMutex);
-    ALOGD("Cleared");
+    mTimeStatsTracker.clear();
     mTimeStats.stats.clear();
     mTimeStats.statsStart = (mEnabled.load() ? static_cast<int64_t>(std::time(0)) : 0);
     mTimeStats.statsEnd = 0;
@@ -568,6 +583,9 @@
     mTimeStats.displayOnTime = 0;
     mTimeStats.presentToPresent.hist.clear();
     mPowerTime.prevTime = systemTime();
+    mGlobalRecord.prevPresentTime = 0;
+    mGlobalRecord.presentFences.clear();
+    ALOGD("Cleared");
 }
 
 bool TimeStats::isEnabled() {