commit 5e7371cec37711a0a822a7b553a340a4605efc89
author Ady Abraham <adyabr@google.com> Tue Mar 24 14:47:24 2020 -0700
committer Ady Abraham <adyabr@google.com> Tue Mar 24 15:45:03 2020 -0700
tree 9795af16bd5c406a13fdf5f7253e94e55d4c8432
parent 0002e6c4f5205e2b2f091bac99d9bb5f31b6167b

SurfaceFlinger: add debug information when vsync is not generated

Print debug information about VsyncReactor internal state when
we expect a vsync event but it is not generated.

Bug: 151892277
Test: adb shell dumpsys SurfaceFlinger --dispsync
Test: simulate a missed vsync and observed logcat
Change-Id: Ia98cb884321d0c25610c4d721f422d9cd05c8c5e

services/surfaceflinger/Scheduler/VSyncDispatchTimerQueue.cpp

diff --git a/services/surfaceflinger/Scheduler/VSyncDispatchTimerQueue.cpp b/services/surfaceflinger/Scheduler/VSyncDispatchTimerQueue.cpp
index d0f18ab..460d4a5 100644
--- a/services/surfaceflinger/Scheduler/VSyncDispatchTimerQueue.cpp
+++ b/services/surfaceflinger/Scheduler/VSyncDispatchTimerQueue.cpp
@@ -15,6 +15,7 @@
  */
 
 #define ATRACE_TAG ATRACE_TAG_GRAPHICS
+#include <android-base/stringprintf.h>
 #include <utils/Trace.h>
 #include <vector>
 
@@ -23,6 +24,7 @@
 #include "VSyncTracker.h"
 
 namespace android::scheduler {
+using base::StringAppendF;
 
 VSyncDispatch::~VSyncDispatch() = default;
 VSyncTracker::~VSyncTracker() = default;
@@ -122,6 +124,28 @@
     mCv.wait(lk, [this]() REQUIRES(mRunningMutex) { return !mRunning; });
 }
 
+void VSyncDispatchTimerQueueEntry::dump(std::string& result) const {
+    std::lock_guard<std::mutex> lk(mRunningMutex);
+    std::string armedInfo;
+    if (mArmedInfo) {
+        StringAppendF(&armedInfo, "[wake up in %.2fms for vsync %.2fms from now]",
+                      (mArmedInfo->mActualWakeupTime - systemTime()) / 1e6f,
+                      (mArmedInfo->mActualVsyncTime - systemTime()) / 1e6f);
+    }
+
+    StringAppendF(&result, "\t\t%s: %s %s\n", mName.c_str(),
+                  mRunning ? "(in callback function)" : "", armedInfo.c_str());
+    StringAppendF(&result, "\t\t\tmWorkDuration: %.2fms mEarliestVsync: %.2fms relative to now\n",
+                  mWorkDuration / 1e6f, (mEarliestVsync - systemTime()) / 1e6f);
+
+    if (mLastDispatchTime) {
+        StringAppendF(&result, "\t\t\tmLastDispatchTime: %.2fms ago\n",
+                      (systemTime() - *mLastDispatchTime) / 1e6f);
+    } else {
+        StringAppendF(&result, "\t\t\tmLastDispatchTime unknown\n");
+    }
+}
+
 VSyncDispatchTimerQueue::VSyncDispatchTimerQueue(std::unique_ptr<TimeKeeper> tk,
                                                  VSyncTracker& tracker, nsecs_t timerSlack,
                                                  nsecs_t minVsyncDistance)
@@ -296,6 +320,18 @@
     return CancelResult::TooLate;
 }
 
+void VSyncDispatchTimerQueue::dump(std::string& result) const {
+    std::lock_guard<decltype(mMutex)> lk(mMutex);
+    StringAppendF(&result, "\tmTimerSlack: %.2fms mMinVsyncDistance: %.2fms\n", mTimerSlack / 1e6f,
+                  mMinVsyncDistance / 1e6f);
+    StringAppendF(&result, "\tmIntendedWakeupTime: %.2fms from now\n",
+                  (mIntendedWakeupTime - systemTime()) / 1e6f);
+    StringAppendF(&result, "\tCallbacks:\n");
+    for (const auto& [token, entry] : mCallbacks) {
+        entry->dump(result);
+    }
+}
+
 VSyncCallbackRegistration::VSyncCallbackRegistration(VSyncDispatch& dispatch,
                                                      VSyncDispatch::Callback const& callbackFn,
                                                      std::string const& callbackName)