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
diff --git a/services/surfaceflinger/Scheduler/DispSyncSource.cpp b/services/surfaceflinger/Scheduler/DispSyncSource.cpp
index 776e984..4e3f85f 100644
--- a/services/surfaceflinger/Scheduler/DispSyncSource.cpp
+++ b/services/surfaceflinger/Scheduler/DispSyncSource.cpp
@@ -30,6 +30,7 @@
#include "EventThread.h"
namespace android {
+using base::StringAppendF;
DispSyncSource::DispSyncSource(DispSync* dispSync, nsecs_t phaseOffset, bool traceVsync,
const char* name)
@@ -107,6 +108,12 @@
}
}
+void DispSyncSource::dump(std::string& result) const {
+ std::lock_guard lock(mVsyncMutex);
+ StringAppendF(&result, "DispSyncSource: %s(%s)\n", mName, mEnabled ? "enabled" : "disabled");
+ mDispSync->dump(result);
+}
+
} // namespace android
// TODO(b/129481165): remove the #pragma below and fix conversion issues
diff --git a/services/surfaceflinger/Scheduler/DispSyncSource.h b/services/surfaceflinger/Scheduler/DispSyncSource.h
index 328b8c1..f278712 100644
--- a/services/surfaceflinger/Scheduler/DispSyncSource.h
+++ b/services/surfaceflinger/Scheduler/DispSyncSource.h
@@ -36,6 +36,8 @@
void setCallback(VSyncSource::Callback* callback) override;
void setPhaseOffset(nsecs_t phaseOffset) override;
+ void dump(std::string&) const override;
+
private:
// The following method is the implementation of the DispSync::Callback.
virtual void onDispSyncEvent(nsecs_t when);
@@ -52,7 +54,7 @@
std::mutex mCallbackMutex;
VSyncSource::Callback* mCallback GUARDED_BY(mCallbackMutex) = nullptr;
- std::mutex mVsyncMutex;
+ mutable std::mutex mVsyncMutex;
TracedOrdinal<nsecs_t> mPhaseOffset GUARDED_BY(mVsyncMutex);
bool mEnabled GUARDED_BY(mVsyncMutex) = false;
};
diff --git a/services/surfaceflinger/Scheduler/EventThread.cpp b/services/surfaceflinger/Scheduler/EventThread.cpp
index acab5a6..0d6a92e 100644
--- a/services/surfaceflinger/Scheduler/EventThread.cpp
+++ b/services/surfaceflinger/Scheduler/EventThread.cpp
@@ -425,7 +425,12 @@
// display is off, keep feeding clients at 60 Hz.
const auto timeout = mState == State::SyntheticVSync ? 16ms : 1000ms;
if (mCondition.wait_for(lock, timeout) == std::cv_status::timeout) {
- ALOGW_IF(mState == State::VSync, "Faking VSYNC due to driver stall");
+ if (mState == State::VSync) {
+ ALOGW("Faking VSYNC due to driver stall for thread %s", mThreadName);
+ std::string debugInfo = "VsyncSource debug info:\n";
+ mVSyncSource->dump(debugInfo);
+ ALOGW("%s", debugInfo.c_str());
+ }
LOG_FATAL_IF(!mVSyncState);
mPendingEvents.push_back(makeVSync(mVSyncState->displayId,
diff --git a/services/surfaceflinger/Scheduler/EventThread.h b/services/surfaceflinger/Scheduler/EventThread.h
index 466234d..98b1876 100644
--- a/services/surfaceflinger/Scheduler/EventThread.h
+++ b/services/surfaceflinger/Scheduler/EventThread.h
@@ -66,6 +66,8 @@
virtual void setVSyncEnabled(bool enable) = 0;
virtual void setCallback(Callback* callback) = 0;
virtual void setPhaseOffset(nsecs_t phaseOffset) = 0;
+
+ virtual void dump(std::string& result) const = 0;
};
class EventThreadConnection : public BnDisplayEventConnection {
diff --git a/services/surfaceflinger/Scheduler/InjectVSyncSource.h b/services/surfaceflinger/Scheduler/InjectVSyncSource.h
index fa46e6f..31da588 100644
--- a/services/surfaceflinger/Scheduler/InjectVSyncSource.h
+++ b/services/surfaceflinger/Scheduler/InjectVSyncSource.h
@@ -45,6 +45,7 @@
const char* getName() const override { return "inject"; }
void setVSyncEnabled(bool) override {}
void setPhaseOffset(nsecs_t) override {}
+ void dump(std::string&) const override {}
private:
std::mutex mCallbackMutex;
diff --git a/services/surfaceflinger/Scheduler/VSyncDispatch.h b/services/surfaceflinger/Scheduler/VSyncDispatch.h
index a6fb3a4..2a2d7c5 100644
--- a/services/surfaceflinger/Scheduler/VSyncDispatch.h
+++ b/services/surfaceflinger/Scheduler/VSyncDispatch.h
@@ -108,6 +108,8 @@
*/
virtual CancelResult cancel(CallbackToken token) = 0;
+ virtual void dump(std::string& result) const = 0;
+
protected:
VSyncDispatch() = default;
VSyncDispatch(VSyncDispatch const&) = delete;
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)
diff --git a/services/surfaceflinger/Scheduler/VSyncDispatchTimerQueue.h b/services/surfaceflinger/Scheduler/VSyncDispatchTimerQueue.h
index fd0a034..390e0c4 100644
--- a/services/surfaceflinger/Scheduler/VSyncDispatchTimerQueue.h
+++ b/services/surfaceflinger/Scheduler/VSyncDispatchTimerQueue.h
@@ -71,6 +71,8 @@
// Block calling thread while the callback is executing.
void ensureNotRunning();
+ void dump(std::string& result) const;
+
private:
std::string const mName;
VSyncDispatch::Callback const mCallback;
@@ -86,7 +88,7 @@
std::optional<ArmingInfo> mArmedInfo;
std::optional<nsecs_t> mLastDispatchTime;
- std::mutex mRunningMutex;
+ mutable std::mutex mRunningMutex;
std::condition_variable mCv;
bool mRunning GUARDED_BY(mRunningMutex) = false;
};
@@ -112,6 +114,7 @@
void unregisterCallback(CallbackToken token) final;
ScheduleResult schedule(CallbackToken token, nsecs_t workDuration, nsecs_t earliestVsync) final;
CancelResult cancel(CallbackToken token) final;
+ void dump(std::string& result) const final;
private:
VSyncDispatchTimerQueue(VSyncDispatchTimerQueue const&) = delete;
diff --git a/services/surfaceflinger/Scheduler/VSyncPredictor.cpp b/services/surfaceflinger/Scheduler/VSyncPredictor.cpp
index 257b8b1..a3cb772 100644
--- a/services/surfaceflinger/Scheduler/VSyncPredictor.cpp
+++ b/services/surfaceflinger/Scheduler/VSyncPredictor.cpp
@@ -22,6 +22,7 @@
//#define LOG_NDEBUG 0
#include "VSyncPredictor.h"
#include <android-base/logging.h>
+#include <android-base/stringprintf.h>
#include <cutils/compiler.h>
#include <cutils/properties.h>
#include <utils/Log.h>
@@ -31,6 +32,7 @@
#include <sstream>
namespace android::scheduler {
+using base::StringAppendF;
static auto constexpr kMaxPercent = 100u;
@@ -263,6 +265,18 @@
clearTimestamps();
}
+void VSyncPredictor::dump(std::string& result) const {
+ std::lock_guard<std::mutex> lk(mMutex);
+ StringAppendF(&result, "\tmIdealPeriod=%.2f\n", mIdealPeriod / 1e6f);
+ StringAppendF(&result, "\tRefresh Rate Map:\n");
+ for (const auto& [idealPeriod, periodInterceptTuple] : mRateMap) {
+ StringAppendF(&result,
+ "\t\tFor ideal period %.2fms: period = %.2fms, intercept = %" PRId64 "\n",
+ idealPeriod / 1e6f, std::get<0>(periodInterceptTuple) / 1e6f,
+ std::get<1>(periodInterceptTuple));
+ }
+}
+
} // namespace android::scheduler
// TODO(b/129481165): remove the #pragma below and fix conversion issues
diff --git a/services/surfaceflinger/Scheduler/VSyncPredictor.h b/services/surfaceflinger/Scheduler/VSyncPredictor.h
index ef1d88a..3ca878d 100644
--- a/services/surfaceflinger/Scheduler/VSyncPredictor.h
+++ b/services/surfaceflinger/Scheduler/VSyncPredictor.h
@@ -60,6 +60,8 @@
std::tuple<nsecs_t /* slope */, nsecs_t /* intercept */> getVSyncPredictionModel() const;
+ void dump(std::string& result) const final;
+
private:
VSyncPredictor(VSyncPredictor const&) = delete;
VSyncPredictor& operator=(VSyncPredictor const&) = delete;
diff --git a/services/surfaceflinger/Scheduler/VSyncReactor.cpp b/services/surfaceflinger/Scheduler/VSyncReactor.cpp
index 8987dcd..892ae62 100644
--- a/services/surfaceflinger/Scheduler/VSyncReactor.cpp
+++ b/services/surfaceflinger/Scheduler/VSyncReactor.cpp
@@ -28,6 +28,7 @@
#include "VSyncTracker.h"
namespace android::scheduler {
+using base::StringAppendF;
Clock::~Clock() = default;
nsecs_t SystemClock::now() const {
@@ -73,11 +74,12 @@
public:
CallbackRepeater(VSyncDispatch& dispatch, DispSync::Callback* cb, const char* name,
nsecs_t period, nsecs_t offset, nsecs_t notBefore)
- : mCallback(cb),
+ : mName(name),
+ mCallback(cb),
mRegistration(dispatch,
std::bind(&CallbackRepeater::callback, this, std::placeholders::_1,
std::placeholders::_2),
- std::string(name)),
+ mName),
mPeriod(period),
mOffset(offset),
mLastCallTime(notBefore) {}
@@ -112,6 +114,13 @@
mRegistration.cancel();
}
+ void dump(std::string& result) const {
+ std::lock_guard<std::mutex> lk(mMutex);
+ StringAppendF(&result, "\t%s: mPeriod=%.2f last vsync time %.2fms relative to now (%s)\n",
+ mName.c_str(), mPeriod / 1e6f, (mLastCallTime - systemTime()) / 1e6f,
+ mStopped ? "stopped" : "running");
+ }
+
private:
void callback(nsecs_t vsynctime, nsecs_t wakeupTime) {
{
@@ -137,6 +146,7 @@
// Note change in sign between the two defnitions.
nsecs_t calculateWorkload() REQUIRES(mMutex) { return mPeriod - mOffset; }
+ const std::string mName;
DispSync::Callback* const mCallback;
std::mutex mutable mMutex;
@@ -349,7 +359,35 @@
}
void VSyncReactor::dump(std::string& result) const {
- result += "VsyncReactor in use\n"; // TODO (b/144927823): add more information!
+ std::lock_guard<std::mutex> lk(mMutex);
+ StringAppendF(&result, "VsyncReactor in use\n");
+ StringAppendF(&result, "Has %zu unfired fences\n", mUnfiredFences.size());
+ StringAppendF(&result, "mInternalIgnoreFences=%d mExternalIgnoreFences=%d\n",
+ mInternalIgnoreFences, mExternalIgnoreFences);
+ StringAppendF(&result, "mMoreSamplesNeeded=%d mPeriodConfirmationInProgress=%d\n",
+ mMoreSamplesNeeded, mPeriodConfirmationInProgress);
+ if (mPeriodTransitioningTo) {
+ StringAppendF(&result, "mPeriodTransitioningTo=%" PRId64 "\n", *mPeriodTransitioningTo);
+ } else {
+ StringAppendF(&result, "mPeriodTransitioningTo=nullptr\n");
+ }
+
+ if (mLastHwVsync) {
+ StringAppendF(&result, "Last HW vsync was %.2fms ago\n",
+ (mClock->now() - *mLastHwVsync) / 1e6f);
+ } else {
+ StringAppendF(&result, "No Last HW vsync\n");
+ }
+
+ StringAppendF(&result, "CallbackRepeaters:\n");
+ for (const auto& [callback, repeater] : mCallbacks) {
+ repeater->dump(result);
+ }
+
+ StringAppendF(&result, "VSyncTracker:\n");
+ mTracker->dump(result);
+ StringAppendF(&result, "VSyncDispatch:\n");
+ mDispatch->dump(result);
}
void VSyncReactor::reset() {}
diff --git a/services/surfaceflinger/Scheduler/VSyncReactor.h b/services/surfaceflinger/Scheduler/VSyncReactor.h
index 7d8a8e3..5ee29f8 100644
--- a/services/surfaceflinger/Scheduler/VSyncReactor.h
+++ b/services/surfaceflinger/Scheduler/VSyncReactor.h
@@ -75,7 +75,7 @@
std::unique_ptr<VSyncDispatch> const mDispatch;
size_t const mPendingLimit;
- std::mutex mMutex;
+ mutable std::mutex mMutex;
bool mInternalIgnoreFences GUARDED_BY(mMutex) = false;
bool mExternalIgnoreFences GUARDED_BY(mMutex) = false;
std::vector<std::shared_ptr<FenceTime>> mUnfiredFences GUARDED_BY(mMutex);
diff --git a/services/surfaceflinger/Scheduler/VSyncTracker.h b/services/surfaceflinger/Scheduler/VSyncTracker.h
index a25b8a9..05a6fc3 100644
--- a/services/surfaceflinger/Scheduler/VSyncTracker.h
+++ b/services/surfaceflinger/Scheduler/VSyncTracker.h
@@ -66,6 +66,8 @@
/* Inform the tracker that the samples it has are not accurate for prediction. */
virtual void resetModel() = 0;
+ virtual void dump(std::string& result) const = 0;
+
protected:
VSyncTracker(VSyncTracker const&) = delete;
VSyncTracker& operator=(VSyncTracker const&) = delete;
diff --git a/services/surfaceflinger/tests/unittests/EventThreadTest.cpp b/services/surfaceflinger/tests/unittests/EventThreadTest.cpp
index 65b3e35..ba5c0c2 100644
--- a/services/surfaceflinger/tests/unittests/EventThreadTest.cpp
+++ b/services/surfaceflinger/tests/unittests/EventThreadTest.cpp
@@ -48,6 +48,7 @@
MOCK_METHOD1(setCallback, void(VSyncSource::Callback*));
MOCK_METHOD1(setPhaseOffset, void(nsecs_t));
MOCK_METHOD1(pauseVsyncCallback, void(bool));
+ MOCK_CONST_METHOD1(dump, void(std::string&));
};
} // namespace
diff --git a/services/surfaceflinger/tests/unittests/VSyncDispatchRealtimeTest.cpp b/services/surfaceflinger/tests/unittests/VSyncDispatchRealtimeTest.cpp
index caac61d..be49ef3 100644
--- a/services/surfaceflinger/tests/unittests/VSyncDispatchRealtimeTest.cpp
+++ b/services/surfaceflinger/tests/unittests/VSyncDispatchRealtimeTest.cpp
@@ -51,6 +51,7 @@
void setPeriod(nsecs_t) final {}
void resetModel() final {}
+ void dump(std::string&) const final {}
private:
nsecs_t const mPeriod;
@@ -85,6 +86,7 @@
void setPeriod(nsecs_t) final {}
void resetModel() final {}
+ void dump(std::string&) const final {}
private:
std::mutex mutable mMutex;
diff --git a/services/surfaceflinger/tests/unittests/VSyncDispatchTimerQueueTest.cpp b/services/surfaceflinger/tests/unittests/VSyncDispatchTimerQueueTest.cpp
index 3ab38e4..3543361 100644
--- a/services/surfaceflinger/tests/unittests/VSyncDispatchTimerQueueTest.cpp
+++ b/services/surfaceflinger/tests/unittests/VSyncDispatchTimerQueueTest.cpp
@@ -47,6 +47,7 @@
MOCK_CONST_METHOD0(currentPeriod, nsecs_t());
MOCK_METHOD1(setPeriod, void(nsecs_t));
MOCK_METHOD0(resetModel, void());
+ MOCK_CONST_METHOD1(dump, void(std::string&));
nsecs_t nextVSyncTime(nsecs_t timePoint) const {
if (timePoint % mPeriod == 0) {
diff --git a/services/surfaceflinger/tests/unittests/VSyncReactorTest.cpp b/services/surfaceflinger/tests/unittests/VSyncReactorTest.cpp
index ac95938..4f150ef 100644
--- a/services/surfaceflinger/tests/unittests/VSyncReactorTest.cpp
+++ b/services/surfaceflinger/tests/unittests/VSyncReactorTest.cpp
@@ -41,6 +41,7 @@
MOCK_CONST_METHOD0(currentPeriod, nsecs_t());
MOCK_METHOD1(setPeriod, void(nsecs_t));
MOCK_METHOD0(resetModel, void());
+ MOCK_CONST_METHOD1(dump, void(std::string&));
};
class VSyncTrackerWrapper : public VSyncTracker {
@@ -56,6 +57,7 @@
nsecs_t currentPeriod() const final { return mTracker->currentPeriod(); }
void setPeriod(nsecs_t period) final { mTracker->setPeriod(period); }
void resetModel() final { mTracker->resetModel(); }
+ void dump(std::string& result) const final { mTracker->dump(result); }
private:
std::shared_ptr<VSyncTracker> const mTracker;
@@ -83,6 +85,7 @@
MOCK_METHOD1(unregisterCallback, void(CallbackToken));
MOCK_METHOD3(schedule, ScheduleResult(CallbackToken, nsecs_t, nsecs_t));
MOCK_METHOD1(cancel, CancelResult(CallbackToken token));
+ MOCK_CONST_METHOD1(dump, void(std::string&));
};
class VSyncDispatchWrapper : public VSyncDispatch {
@@ -102,6 +105,8 @@
CancelResult cancel(CallbackToken token) final { return mDispatch->cancel(token); }
+ void dump(std::string& result) const final { return mDispatch->dump(result); }
+
private:
std::shared_ptr<VSyncDispatch> const mDispatch;
};