Disable DispSync resync when not needed

If app and SF events aren't using phase offsets, we don't need
to maintain the DispSync model.  We just turn hardware VSYNC on
whenever something wants to draw.  This avoids some edge cases
where we were doing too much resync work.

Also, updated the systrace output.  The "VsyncOn" line was a
combination of SF and app event threads, and would occasionally
be very weird.  Removed VsyncOn, renamed VSYNC to VSYNC-app,
and added VSYNC-sf.

Also, added more details to the --dispsync dumpsys output.

Also, renamed global constants to not look like local variables.

Bug 15516453

Change-Id: I0da10b72f0d9a7b7eb5202d87cc18967f698adbd
diff --git a/services/surfaceflinger/DispSync.cpp b/services/surfaceflinger/DispSync.cpp
index d771e2c..c60834e 100644
--- a/services/surfaceflinger/DispSync.cpp
+++ b/services/surfaceflinger/DispSync.cpp
@@ -37,25 +37,17 @@
 
 // Setting this to true enables verbose tracing that can be used to debug
 // vsync event model or phase issues.
-static const bool traceDetailedInfo = false;
+static const bool kTraceDetailedInfo = false;
 
 // This is the threshold used to determine when hardware vsync events are
 // needed to re-synchronize the software vsync model with the hardware.  The
 // error metric used is the mean of the squared difference between each
 // present time and the nearest software-predicted vsync.
-static const nsecs_t errorThreshold = 160000000000;
-
-// This works around the lack of support for the sync framework on some
-// devices.
-#ifdef RUNNING_WITHOUT_SYNC_FRAMEWORK
-static const bool runningWithoutSyncFramework = true;
-#else
-static const bool runningWithoutSyncFramework = false;
-#endif
+static const nsecs_t kErrorThreshold = 160000000000;    // 400 usec squared
 
 // This is the offset from the present fence timestamps to the corresponding
 // vsync event.
-static const int64_t presentTimeOffset = PRESENT_TIME_OFFSET_FROM_VSYNC_NS;
+static const int64_t kPresentTimeOffset = PRESENT_TIME_OFFSET_FROM_VSYNC_NS;
 
 class DispSyncThread: public Thread {
 public:
@@ -138,7 +130,7 @@
                         // Don't correct by more than 500 us
                         mWakeupLatency = 500000;
                     }
-                    if (traceDetailedInfo) {
+                    if (kTraceDetailedInfo) {
                         ATRACE_INT64("DispSync:WakeupLat", now - nextEventTime);
                         ATRACE_INT64("DispSync:AvgWakeupLat", mWakeupLatency);
                     }
@@ -207,8 +199,7 @@
         return BAD_VALUE;
     }
 
-    // This method is only here to handle the runningWithoutSyncFramework
-    // case.
+    // This method is only here to handle the kIgnorePresentFences case.
     bool hasAnyEventListeners() {
         Mutex::Autolock lock(mMutex);
         return !mEventListeners.empty();
@@ -320,12 +311,13 @@
     reset();
     beginResync();
 
-    if (traceDetailedInfo) {
-        // If runningWithoutSyncFramework is true then the ZeroPhaseTracer
+    if (kTraceDetailedInfo) {
+        // If we're not getting present fences then the ZeroPhaseTracer
         // would prevent HW vsync event from ever being turned off.
-        // Furthermore the zero-phase tracing is not needed because any time
-        // there is an event registered we will turn on the HW vsync events.
-        if (!runningWithoutSyncFramework) {
+        // Even if we're just ignoring the fences, the zero-phase tracing is
+        // not needed because any time there is an event registered we will
+        // turn on the HW vsync events.
+        if (!kIgnorePresentFences) {
             addEventListener(0, new ZeroPhaseTracer());
         }
     }
@@ -356,14 +348,14 @@
             nsecs_t t = f->getSignalTime();
             if (t < INT64_MAX) {
                 mPresentFences[i].clear();
-                mPresentTimes[i] = t + presentTimeOffset;
+                mPresentTimes[i] = t + kPresentTimeOffset;
             }
         }
     }
 
     updateErrorLocked();
 
-    return mPeriod == 0 || mError > errorThreshold;
+    return mPeriod == 0 || mError > kErrorThreshold;
 }
 
 void DispSync::beginResync() {
@@ -390,7 +382,7 @@
         resetErrorLocked();
     }
 
-    if (runningWithoutSyncFramework) {
+    if (kIgnorePresentFences) {
         // If we don't have the sync framework we will never have
         // addPresentFence called.  This means we have no way to know whether
         // or not we're synchronized with the HW vsyncs, so we just request
@@ -399,7 +391,7 @@
         return mThread->hasAnyEventListeners();
     }
 
-    return mPeriod == 0 || mError > errorThreshold;
+    return mPeriod == 0 || mError > kErrorThreshold;
 }
 
 void DispSync::endResync() {
@@ -459,7 +451,7 @@
             mPhase += mPeriod;
         }
 
-        if (traceDetailedInfo) {
+        if (kTraceDetailedInfo) {
             ATRACE_INT64("DispSync:Period", mPeriod);
             ATRACE_INT64("DispSync:Phase", mPhase);
         }
@@ -494,7 +486,7 @@
         mError = 0;
     }
 
-    if (traceDetailedInfo) {
+    if (kTraceDetailedInfo) {
         ATRACE_INT64("DispSync:Error", mError);
     }
 }
@@ -516,13 +508,16 @@
 
 void DispSync::dump(String8& result) const {
     Mutex::Autolock lock(mMutex);
-    result.appendFormat("mPeriod: %"PRId64" ns\n", mPeriod);
-    result.appendFormat("mPhase: %"PRId64" ns\n", mPhase);
-    result.appendFormat("mError: %"PRId64" ns (sqrt: %.1f)\n",
+    result.appendFormat("present fences are %s\n",
+            kIgnorePresentFences ? "ignored" : "used");
+    result.appendFormat("mPeriod: %" PRId64 " ns (%.3f fps)\n",
+            mPeriod, 1000000000.0 / mPeriod);
+    result.appendFormat("mPhase: %" PRId64 " ns\n", mPhase);
+    result.appendFormat("mError: %" PRId64 " ns (sqrt=%.1f)\n",
             mError, sqrt(mError));
-    result.appendFormat("mNumResyncSamplesSincePresent: %d (max %d)\n",
+    result.appendFormat("mNumResyncSamplesSincePresent: %d (limit %d)\n",
             mNumResyncSamplesSincePresent, MAX_RESYNC_SAMPLES_WITHOUT_PRESENT);
-    result.appendFormat("mNumResyncSamples: %d (max %d)\n",
+    result.appendFormat("mNumResyncSamples: %zd (max %d)\n",
             mNumResyncSamples, MAX_RESYNC_SAMPLES);
 
     result.appendFormat("mResyncSamples:\n");
@@ -531,9 +526,9 @@
         size_t idx = (mFirstResyncSample + i) % MAX_RESYNC_SAMPLES;
         nsecs_t sampleTime = mResyncSamples[idx];
         if (i == 0) {
-            result.appendFormat("  %"PRId64"\n", sampleTime);
+            result.appendFormat("  %" PRId64 "\n", sampleTime);
         } else {
-            result.appendFormat("  %"PRId64" (+%"PRId64")\n",
+            result.appendFormat("  %" PRId64 " (+%" PRId64 ")\n",
                     sampleTime, sampleTime - previous);
         }
         previous = sampleTime;
@@ -541,6 +536,7 @@
 
     result.appendFormat("mPresentFences / mPresentTimes [%d]:\n",
             NUM_PRESENT_SAMPLES);
+    nsecs_t now = systemTime(SYSTEM_TIME_MONOTONIC);
     previous = 0;
     for (size_t i = 0; i < NUM_PRESENT_SAMPLES; i++) {
         size_t idx = (i + mPresentSampleOffset) % NUM_PRESENT_SAMPLES;
@@ -548,15 +544,21 @@
         nsecs_t presentTime = mPresentTimes[idx];
         if (!signaled) {
             result.appendFormat("  [unsignaled fence]\n");
+        } else if (presentTime == 0) {
+            result.appendFormat("  0\n");
         } else if (previous == 0) {
-            result.appendFormat("  %"PRId64"\n", presentTime);
+            result.appendFormat("  %" PRId64 "  (%.3f ms ago)\n", presentTime,
+                    (now - presentTime) / 1000000.0);
         } else {
-            result.appendFormat("  %"PRId64" (+%"PRId64" / %.3f)\n",
+            result.appendFormat("  %" PRId64 " (+%" PRId64 " / %.3f)  (%.3f ms ago)\n",
                     presentTime, presentTime - previous,
-                    (presentTime - previous) / (double) mPeriod);
+                    (presentTime - previous) / (double) mPeriod,
+                    (now - presentTime) / 1000000.0);
         }
         previous = presentTime;
     }
+
+    result.appendFormat("current monotonic time: %" PRId64 "\n", now);
 }
 
 } // namespace android
diff --git a/services/surfaceflinger/DispSync.h b/services/surfaceflinger/DispSync.h
index a33ce5d..5106bc8 100644
--- a/services/surfaceflinger/DispSync.h
+++ b/services/surfaceflinger/DispSync.h
@@ -25,6 +25,18 @@
 
 namespace android {
 
+// Ignore present (retire) fences if the device doesn't have support for the
+// sync framework, or if all phase offsets are zero.  The latter is useful
+// because it allows us to avoid resync bursts on devices that don't need
+// phase-offset VSYNC events.
+#if defined(RUNNING_WITHOUT_SYNC_FRAMEWORK) || \
+        (VSYNC_EVENT_PHASE_OFFSET_NS == 0 && SF_VSYNC_EVENT_PHASE_OFFSET_NS == 0)
+static const bool kIgnorePresentFences = true;
+#else
+static const bool kIgnorePresentFences = false;
+#endif
+
+
 class String8;
 class Fence;
 class DispSyncThread;
diff --git a/services/surfaceflinger/SurfaceFlinger.cpp b/services/surfaceflinger/SurfaceFlinger.cpp
index 7152f93..3bdbb4f 100644
--- a/services/surfaceflinger/SurfaceFlinger.cpp
+++ b/services/surfaceflinger/SurfaceFlinger.cpp
@@ -88,14 +88,6 @@
 
 namespace android {
 
-// This works around the lack of support for the sync framework on some
-// devices.
-#ifdef RUNNING_WITHOUT_SYNC_FRAMEWORK
-static const bool runningWithoutSyncFramework = true;
-#else
-static const bool runningWithoutSyncFramework = false;
-#endif
-
 // This is the phase offset in nanoseconds of the software vsync event
 // relative to the vsync event reported by HWComposer.  The software vsync
 // event is when SurfaceFlinger and Choreographer-based applications run each
@@ -322,10 +314,13 @@
 
 class DispSyncSource : public VSyncSource, private DispSync::Callback {
 public:
-    DispSyncSource(DispSync* dispSync, nsecs_t phaseOffset, bool traceVsync) :
+    DispSyncSource(DispSync* dispSync, nsecs_t phaseOffset, bool traceVsync,
+        const char* label) :
             mValue(0),
             mPhaseOffset(phaseOffset),
             mTraceVsync(traceVsync),
+            mVsyncOnLabel(String8::format("VsyncOn-%s", label)),
+            mVsyncEventLabel(String8::format("VSYNC-%s", label)),
             mDispSync(dispSync) {}
 
     virtual ~DispSyncSource() {}
@@ -340,7 +335,7 @@
                 ALOGE("error registering vsync callback: %s (%d)",
                         strerror(-err), err);
             }
-            ATRACE_INT("VsyncOn", 1);
+            //ATRACE_INT(mVsyncOnLabel.string(), 1);
         } else {
             status_t err = mDispSync->removeEventListener(
                     static_cast<DispSync::Callback*>(this));
@@ -348,7 +343,7 @@
                 ALOGE("error unregistering vsync callback: %s (%d)",
                         strerror(-err), err);
             }
-            ATRACE_INT("VsyncOn", 0);
+            //ATRACE_INT(mVsyncOnLabel.string(), 0);
         }
     }
 
@@ -366,7 +361,7 @@
 
             if (mTraceVsync) {
                 mValue = (mValue + 1) % 2;
-                ATRACE_INT("VSYNC", mValue);
+                ATRACE_INT(mVsyncEventLabel.string(), mValue);
             }
         }
 
@@ -379,6 +374,8 @@
 
     const nsecs_t mPhaseOffset;
     const bool mTraceVsync;
+    const String8 mVsyncOnLabel;
+    const String8 mVsyncEventLabel;
 
     DispSync* mDispSync;
     sp<VSyncSource::Callback> mCallback;
@@ -449,10 +446,10 @@
 
     // start the EventThread
     sp<VSyncSource> vsyncSrc = new DispSyncSource(&mPrimaryDispSync,
-            vsyncPhaseOffsetNs, true);
+            vsyncPhaseOffsetNs, true, "app");
     mEventThread = new EventThread(vsyncSrc);
     sp<VSyncSource> sfVsyncSrc = new DispSyncSource(&mPrimaryDispSync,
-            sfVsyncPhaseOffsetNs, false);
+            sfVsyncPhaseOffsetNs, true, "sf");
     mSFEventThread = new EventThread(sfVsyncSrc);
     mEventQueue.setEventThread(mSFEventThread);
 
@@ -858,7 +855,7 @@
         }
     }
 
-    if (runningWithoutSyncFramework) {
+    if (kIgnorePresentFences) {
         const sp<const DisplayDevice> hw(getDefaultDisplayDevice());
         if (hw->isScreenAcquired()) {
             enableHardwareVsync();