Loading services/surfaceflinger/Scheduler/EventThread.cpp +7 −1 Original line number Diff line number Diff line Loading @@ -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); Loading services/surfaceflinger/Scheduler/TimeKeeper.h +2 −0 Original line number Diff line number Diff line Loading @@ -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; Loading services/surfaceflinger/Scheduler/Timer.cpp +88 −20 Original line number Diff line number Diff line Loading @@ -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> Loading @@ -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)) { Timer::Timer() { reset(); mDispatchThread = std::thread([this]() { threadMain(); }); } Timer::~Timer() { endDispatch(); mDispatchThread.join(); cleanup(); } 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); } mDispatchThread = std::thread(std::bind(&Timer::dispatch, this)); void Timer::cleanup() { if (mTimerFd != -1) { close(mTimerFd); mTimerFd = -1; } Timer::~Timer() { endDispatch(); mDispatchThread.join(); if (mEpollFd != -1) { close(mEpollFd); mEpollFd = -1; } close(mPipes[kWritePipe]); if (mPipes[kReadPipe] != -1) { close(mPipes[kReadPipe]); close(mEpollFd); close(mTimerFd); mPipes[kReadPipe] = -1; } if (mPipes[kWritePipe] != -1) { close(mPipes[kWritePipe]); mPipes[kWritePipe] = -1; } } void Timer::endDispatch() { Loading Loading @@ -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) { Loading @@ -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; Loading @@ -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++); Loading @@ -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 services/surfaceflinger/Scheduler/Timer.h +14 −5 Original line number Diff line number Diff line Loading @@ -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 services/surfaceflinger/Scheduler/VSyncDispatchTimerQueue.cpp +8 −1 Original line number Diff line number Diff line Loading @@ -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) { Loading Loading @@ -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(); Loading Loading @@ -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); Loading Loading
services/surfaceflinger/Scheduler/EventThread.cpp +7 −1 Original line number Diff line number Diff line Loading @@ -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); Loading
services/surfaceflinger/Scheduler/TimeKeeper.h +2 −0 Original line number Diff line number Diff line Loading @@ -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; Loading
services/surfaceflinger/Scheduler/Timer.cpp +88 −20 Original line number Diff line number Diff line Loading @@ -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> Loading @@ -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)) { Timer::Timer() { reset(); mDispatchThread = std::thread([this]() { threadMain(); }); } Timer::~Timer() { endDispatch(); mDispatchThread.join(); cleanup(); } 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); } mDispatchThread = std::thread(std::bind(&Timer::dispatch, this)); void Timer::cleanup() { if (mTimerFd != -1) { close(mTimerFd); mTimerFd = -1; } Timer::~Timer() { endDispatch(); mDispatchThread.join(); if (mEpollFd != -1) { close(mEpollFd); mEpollFd = -1; } close(mPipes[kWritePipe]); if (mPipes[kReadPipe] != -1) { close(mPipes[kReadPipe]); close(mEpollFd); close(mTimerFd); mPipes[kReadPipe] = -1; } if (mPipes[kWritePipe] != -1) { close(mPipes[kWritePipe]); mPipes[kWritePipe] = -1; } } void Timer::endDispatch() { Loading Loading @@ -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) { Loading @@ -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; Loading @@ -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++); Loading @@ -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
services/surfaceflinger/Scheduler/Timer.h +14 −5 Original line number Diff line number Diff line Loading @@ -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
services/surfaceflinger/Scheduler/VSyncDispatchTimerQueue.cpp +8 −1 Original line number Diff line number Diff line Loading @@ -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) { Loading Loading @@ -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(); Loading Loading @@ -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); Loading