diff options
8 files changed, 126 insertions, 27 deletions
diff --git a/services/surfaceflinger/Scheduler/EventThread.cpp b/services/surfaceflinger/Scheduler/EventThread.cpp index 0d6a92e08f..8347650636 100644 --- a/services/surfaceflinger/Scheduler/EventThread.cpp +++ b/services/surfaceflinger/Scheduler/EventThread.cpp @@ -429,7 +429,13 @@ void EventThread::threadMain(std::unique_lock<std::mutex>& lock) { 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 the debug info line-by-line to avoid logcat overflow + auto pos = debugInfo.find('\n'); + while (pos != std::string::npos) { + ALOGW("%s", debugInfo.substr(0, pos).c_str()); + debugInfo = debugInfo.substr(pos + 1); + pos = debugInfo.find('\n'); + } } LOG_FATAL_IF(!mVSyncState); diff --git a/services/surfaceflinger/Scheduler/TimeKeeper.h b/services/surfaceflinger/Scheduler/TimeKeeper.h index 38f07081bb..da2195c253 100644 --- a/services/surfaceflinger/Scheduler/TimeKeeper.h +++ b/services/surfaceflinger/Scheduler/TimeKeeper.h @@ -53,6 +53,8 @@ public: */ virtual void alarmCancel() = 0; + virtual void dump(std::string& result) const = 0; + protected: TimeKeeper(TimeKeeper const&) = delete; TimeKeeper& operator=(TimeKeeper const&) = delete; diff --git a/services/surfaceflinger/Scheduler/Timer.cpp b/services/surfaceflinger/Scheduler/Timer.cpp index 8f81c2c65e..7c5058e431 100644 --- a/services/surfaceflinger/Scheduler/Timer.cpp +++ b/services/surfaceflinger/Scheduler/Timer.cpp @@ -17,6 +17,7 @@ #undef LOG_TAG #define LOG_TAG "SchedulerTimer" #define ATRACE_TAG ATRACE_TAG_GRAPHICS +#include <android-base/stringprintf.h> #include <log/log.h> #include <sys/epoll.h> #include <sys/timerfd.h> @@ -29,28 +30,53 @@ #include "Timer.h" namespace android::scheduler { +using base::StringAppendF; static constexpr size_t kReadPipe = 0; static constexpr size_t kWritePipe = 1; -Timer::Timer() - : mTimerFd(timerfd_create(CLOCK_MONOTONIC, TFD_CLOEXEC | TFD_NONBLOCK)), - mEpollFd(epoll_create1(EPOLL_CLOEXEC)) { - if (pipe2(mPipes.data(), O_CLOEXEC | O_NONBLOCK)) { - ALOGE("could not create TimerDispatch mPipes"); - }; - - mDispatchThread = std::thread(std::bind(&Timer::dispatch, this)); +Timer::Timer() { + reset(); + mDispatchThread = std::thread([this]() { threadMain(); }); } Timer::~Timer() { endDispatch(); mDispatchThread.join(); + cleanup(); +} - close(mPipes[kWritePipe]); - close(mPipes[kReadPipe]); - close(mEpollFd); - close(mTimerFd); +void Timer::reset() { + cleanup(); + mTimerFd = timerfd_create(CLOCK_MONOTONIC, TFD_CLOEXEC | TFD_NONBLOCK); + mEpollFd = epoll_create1(EPOLL_CLOEXEC); + if (pipe2(mPipes.data(), O_CLOEXEC | O_NONBLOCK)) { + ALOGE("could not create TimerDispatch mPipes"); + return; + }; + setDebugState(DebugState::Reset); +} + +void Timer::cleanup() { + if (mTimerFd != -1) { + close(mTimerFd); + mTimerFd = -1; + } + + if (mEpollFd != -1) { + close(mEpollFd); + mEpollFd = -1; + } + + if (mPipes[kReadPipe] != -1) { + close(mPipes[kReadPipe]); + mPipes[kReadPipe] = -1; + } + + if (mPipes[kWritePipe] != -1) { + close(mPipes[kWritePipe]); + mPipes[kWritePipe] = -1; + } } void Timer::endDispatch() { @@ -99,7 +125,14 @@ void Timer::alarmCancel() { } } -void Timer::dispatch() { +void Timer::threadMain() { + while (dispatch()) { + reset(); + } +} + +bool Timer::dispatch() { + setDebugState(DebugState::Running); struct sched_param param = {0}; param.sched_priority = 2; if (pthread_setschedparam(pthread_self(), SCHED_FIFO, ¶m) != 0) { @@ -116,7 +149,7 @@ void Timer::dispatch() { timerEvent.data.u32 = DispatchType::TIMER; if (epoll_ctl(mEpollFd, EPOLL_CTL_ADD, mTimerFd, &timerEvent) == -1) { ALOGE("Error adding timer fd to epoll dispatch loop"); - return; + return true; } epoll_event terminateEvent; @@ -124,18 +157,20 @@ void Timer::dispatch() { terminateEvent.data.u32 = DispatchType::TERMINATE; if (epoll_ctl(mEpollFd, EPOLL_CTL_ADD, mPipes[kReadPipe], &terminateEvent) == -1) { ALOGE("Error adding control fd to dispatch loop"); - return; + return true; } uint64_t iteration = 0; char const traceNamePrefix[] = "TimerIteration #"; static constexpr size_t maxlen = arrayLen(traceNamePrefix) + max64print; std::array<char, maxlen> str_buffer; - auto timing = true; - while (timing) { + + while (true) { + setDebugState(DebugState::Waiting); epoll_event events[DispatchType::MAX_DISPATCH_TYPE]; int nfds = epoll_wait(mEpollFd, events, DispatchType::MAX_DISPATCH_TYPE, -1); + setDebugState(DebugState::Running); if (ATRACE_ENABLED()) { snprintf(str_buffer.data(), str_buffer.size(), "%s%" PRIu64, traceNamePrefix, iteration++); @@ -144,29 +179,62 @@ void Timer::dispatch() { if (nfds == -1) { if (errno != EINTR) { - timing = false; - continue; + ALOGE("Error waiting on epoll: %s", strerror(errno)); + return true; } } for (auto i = 0; i < nfds; i++) { if (events[i].data.u32 == DispatchType::TIMER) { static uint64_t mIgnored = 0; + setDebugState(DebugState::Reading); read(mTimerFd, &mIgnored, sizeof(mIgnored)); + setDebugState(DebugState::Running); std::function<void()> cb; { std::lock_guard<decltype(mMutex)> lk(mMutex); cb = mCallback; } if (cb) { + setDebugState(DebugState::InCallback); cb(); + setDebugState(DebugState::Running); } } if (events[i].data.u32 == DispatchType::TERMINATE) { - timing = false; + ALOGE("Terminated"); + setDebugState(DebugState::Running); + return false; } } } } +void Timer::setDebugState(DebugState state) { + std::lock_guard lk(mMutex); + mDebugState = state; +} + +const char* Timer::strDebugState(DebugState state) const { + switch (state) { + case DebugState::Reset: + return "Reset"; + case DebugState::Running: + return "Running"; + case DebugState::Waiting: + return "Waiting"; + case DebugState::Reading: + return "Reading"; + case DebugState::InCallback: + return "InCallback"; + case DebugState::Terminated: + return "Terminated"; + } +} + +void Timer::dump(std::string& result) const { + std::lock_guard lk(mMutex); + StringAppendF(&result, "\t\tDebugState: %s\n", strDebugState(mDebugState)); +} + } // namespace android::scheduler diff --git a/services/surfaceflinger/Scheduler/Timer.h b/services/surfaceflinger/Scheduler/Timer.h index 0ae82c83a5..a8e2d5a53d 100644 --- a/services/surfaceflinger/Scheduler/Timer.h +++ b/services/surfaceflinger/Scheduler/Timer.h @@ -34,18 +34,27 @@ public: // Most users will want to serialize thes calls so as to be aware of the timer state. void alarmIn(std::function<void()> const& cb, nsecs_t fireIn) final; void alarmCancel() final; + void dump(std::string& result) const final; private: - int const mTimerFd; - int const mEpollFd; - std::array<int, 2> mPipes; + enum class DebugState { Reset, Running, Waiting, Reading, InCallback, Terminated }; + void reset(); + void cleanup(); + void setDebugState(DebugState state) EXCLUDES(mMutex); + const char* strDebugState(DebugState state) const; + + int mTimerFd = -1; + int mEpollFd = -1; + std::array<int, 2> mPipes = {-1, -1}; std::thread mDispatchThread; - void dispatch(); + void threadMain(); + bool dispatch(); void endDispatch(); - std::mutex mMutex; + mutable std::mutex mMutex; std::function<void()> mCallback GUARDED_BY(mMutex); + DebugState mDebugState GUARDED_BY(mMutex); }; } // namespace android::scheduler diff --git a/services/surfaceflinger/Scheduler/VSyncDispatchTimerQueue.cpp b/services/surfaceflinger/Scheduler/VSyncDispatchTimerQueue.cpp index 460d4a5c3c..cd156176c7 100644 --- a/services/surfaceflinger/Scheduler/VSyncDispatchTimerQueue.cpp +++ b/services/surfaceflinger/Scheduler/VSyncDispatchTimerQueue.cpp @@ -168,6 +168,7 @@ void VSyncDispatchTimerQueue::setTimer(nsecs_t targetTime, nsecs_t now) { mIntendedWakeupTime = targetTime; mTimeKeeper->alarmIn(std::bind(&VSyncDispatchTimerQueue::timerCallback, this), targetTime - now); + mLastTimerSchedule = mTimeKeeper->now(); } void VSyncDispatchTimerQueue::rearmTimer(nsecs_t now) { @@ -226,6 +227,7 @@ void VSyncDispatchTimerQueue::timerCallback() { std::vector<Invocation> invocations; { std::lock_guard<decltype(mMutex)> lk(mMutex); + mLastTimerCallback = mTimeKeeper->now(); for (auto it = mCallbacks.begin(); it != mCallbacks.end(); it++) { auto& callback = it->second; auto const wakeupTime = callback->wakeupTime(); @@ -322,10 +324,15 @@ CancelResult VSyncDispatchTimerQueue::cancel(CallbackToken token) { void VSyncDispatchTimerQueue::dump(std::string& result) const { std::lock_guard<decltype(mMutex)> lk(mMutex); + StringAppendF(&result, "\tTimer:\n"); + mTimeKeeper->dump(result); StringAppendF(&result, "\tmTimerSlack: %.2fms mMinVsyncDistance: %.2fms\n", mTimerSlack / 1e6f, mMinVsyncDistance / 1e6f); StringAppendF(&result, "\tmIntendedWakeupTime: %.2fms from now\n", - (mIntendedWakeupTime - systemTime()) / 1e6f); + (mIntendedWakeupTime - mTimeKeeper->now()) / 1e6f); + StringAppendF(&result, "\tmLastTimerCallback: %.2fms ago mLastTimerSchedule: %.2fms ago\n", + (mTimeKeeper->now() - mLastTimerCallback) / 1e6f, + (mTimeKeeper->now() - mLastTimerSchedule) / 1e6f); StringAppendF(&result, "\tCallbacks:\n"); for (const auto& [token, entry] : mCallbacks) { entry->dump(result); diff --git a/services/surfaceflinger/Scheduler/VSyncDispatchTimerQueue.h b/services/surfaceflinger/Scheduler/VSyncDispatchTimerQueue.h index 390e0c460f..26a8ec0b07 100644 --- a/services/surfaceflinger/Scheduler/VSyncDispatchTimerQueue.h +++ b/services/surfaceflinger/Scheduler/VSyncDispatchTimerQueue.h @@ -152,6 +152,10 @@ private: std::array<char, maxlen> str_buffer; void note(std::string_view name, nsecs_t in, nsecs_t vs); } mTraceBuffer GUARDED_BY(mMutex); + + // For debugging purposes + nsecs_t mLastTimerCallback GUARDED_BY(mMutex) = kInvalidTime; + nsecs_t mLastTimerSchedule GUARDED_BY(mMutex) = kInvalidTime; }; } // namespace android::scheduler diff --git a/services/surfaceflinger/SurfaceFlinger.cpp b/services/surfaceflinger/SurfaceFlinger.cpp index 2da92b3145..4d66c3859f 100644 --- a/services/surfaceflinger/SurfaceFlinger.cpp +++ b/services/surfaceflinger/SurfaceFlinger.cpp @@ -4373,6 +4373,7 @@ void SurfaceFlinger::dumpVSync(std::string& result) const { mDebugDisplayConfigSetByBackdoor ? "yes" : "no"); mScheduler->dump(mAppConnectionHandle, result); + mScheduler->getPrimaryDispSync().dump(result); } void SurfaceFlinger::dumpStaticScreenStats(std::string& result) const { diff --git a/services/surfaceflinger/tests/unittests/VSyncDispatchTimerQueueTest.cpp b/services/surfaceflinger/tests/unittests/VSyncDispatchTimerQueueTest.cpp index 3543361f7b..1899bed8ef 100644 --- a/services/surfaceflinger/tests/unittests/VSyncDispatchTimerQueueTest.cpp +++ b/services/surfaceflinger/tests/unittests/VSyncDispatchTimerQueueTest.cpp @@ -71,6 +71,7 @@ public: MOCK_CONST_METHOD0(now, nsecs_t()); MOCK_METHOD2(alarmIn, void(std::function<void()> const&, nsecs_t time)); MOCK_METHOD0(alarmCancel, void()); + MOCK_CONST_METHOD1(dump, void(std::string&)); void alarmInDefaultBehavior(std::function<void()> const& callback, nsecs_t time) { mCallback = callback; @@ -188,6 +189,7 @@ protected: } void alarmCancel() final { mControllableClock.alarmCancel(); } nsecs_t now() const final { return mControllableClock.now(); } + void dump(std::string&) const final {} private: TimeKeeper& mControllableClock; |