From 8506e94f10e62f033366389aeb3f676f32b2fb37 Mon Sep 17 00:00:00 2001 From: Mathias Agopian Date: Fri, 10 Oct 2025 14:40:28 -0700 Subject: [PATCH] Improvements to FrameInfo (#9293) * fix a possible deadlock in AsyncJobQueue drainAndExit() could get stuck because it waited for the job queue to be empty, but that was not signaled. in fact, drainAndExit() didn't need to do that. * Improvements to FrameInfo - return the GPU Complete timestamp - return the app VSYNC timestamp - works TimerQueries are not supported The VSYNC time is just a convenience as it is the same value provided by the application during Renderer::beginFrame() or via Renderer::setVsyncTime(). --- filament/include/filament/Renderer.h | 2 + filament/src/FrameInfo.cpp | 147 ++++++++++++++++------- filament/src/FrameInfo.h | 29 ++++- filament/src/details/Renderer.cpp | 2 +- libs/utils/include/utils/AsyncJobQueue.h | 4 +- libs/utils/src/AsyncJobQueue.cpp | 29 +++-- 6 files changed, 157 insertions(+), 56 deletions(-) diff --git a/filament/include/filament/Renderer.h b/filament/include/filament/Renderer.h index 99c4a8b3d9..d5bdd6d109 100644 --- a/filament/include/filament/Renderer.h +++ b/filament/include/filament/Renderer.h @@ -97,6 +97,8 @@ public: time_point_ns endFrame; //!< Renderer::endFrame() time since epoch [ns] time_point_ns backendBeginFrame; //!< Backend thread time of frame start since epoch [ns] time_point_ns backendEndFrame; //!< Backend thread time of frame end since epoch [ns] + time_point_ns gpuFrameComplete; //!< GPU thread time of frame end since epoch [ns] or 0 + time_point_ns vsync; //!< VSYNC time of this frame since epoch [ns] }; /** diff --git a/filament/src/FrameInfo.cpp b/filament/src/FrameInfo.cpp index e99a4baa3b..ca1c5408e0 100644 --- a/filament/src/FrameInfo.cpp +++ b/filament/src/FrameInfo.cpp @@ -19,13 +19,15 @@ #include #include +#include #include -#include -#include #include #include +#include +#include +#include #include #include @@ -33,6 +35,7 @@ #include #include #include +#include #include #include @@ -42,24 +45,44 @@ namespace filament { using namespace utils; using namespace backend; -FrameInfoManager::FrameInfoManager(DriverApi& driver) noexcept { - for (auto& query : mQueries) { - query.handle = driver.createTimerQuery(); +FrameInfoManager::FrameInfoManager(DriverApi& driver) noexcept + : mJobQueue("FrameInfoGpuComplete", JobSystem::Priority::URGENT_DISPLAY), + mHasTimerQueries(driver.isFrameTimeSupported()) { + if (mHasTimerQueries) { + for (auto& query : mQueries) { + query.handle = driver.createTimerQuery(); + } } } FrameInfoManager::~FrameInfoManager() noexcept = default; void FrameInfoManager::terminate(DriverApi& driver) noexcept { - for (auto& query : mQueries) { - driver.destroyTimerQuery(query.handle); + if (mHasTimerQueries) { + for (auto const& query : mQueries) { + driver.destroyTimerQuery(query.handle); + } + } + + // wait for all pending callbacks to be called & terminate the thread + mJobQueue.drainAndExit(); + + // destroy the fences that are still alive + for (size_t i = 0, c = mFrameTimeHistory.size(); i < c; i++) { + auto& info = mFrameTimeHistory[i]; + if (info.fence) { + driver.destroyFence(std::move(info.fence)); + } } } -void FrameInfoManager::beginFrame(DriverApi& driver, Config const& config, uint32_t frameId) noexcept { +void FrameInfoManager::beginFrame(DriverApi& driver, Config const& config, + uint32_t frameId, std::chrono::steady_clock::time_point vsync) noexcept { auto& history = mFrameTimeHistory; // don't exceed the capacity, drop the oldest entry if (UTILS_LIKELY(history.size() == history.capacity())) { + assert_invariant(history.back().fence); + driver.destroyFence(std::move(history.back().fence)); history.pop_back(); } @@ -67,44 +90,54 @@ void FrameInfoManager::beginFrame(DriverApi& driver, Config const& config, uint3 auto& front = history.emplace_front(frameId); // store the current time + front.vsync = vsync; front.beginFrame = std::chrono::steady_clock::now(); - // references are not invalidated by CircularQueue<>, so we can associate a reference to - // the slot we created to the timer query used to find the frame time. - mQueries[mIndex].pInfo = std::addressof(front); - // issue the timer query - driver.beginTimerQuery(mQueries[mIndex].handle); + if (mHasTimerQueries) { + // references are not invalidated by CircularQueue<>, so we can associate a reference to + // the slot we created to the timer query used to find the frame time. + mQueries[mIndex].pInfo = std::addressof(front); + // issue the timer query + driver.beginTimerQuery(mQueries[mIndex].handle); + } + // issue the custom backend command to get the backend time driver.queueCommand([&front](){ front.backendBeginFrame = std::chrono::steady_clock::now(); }); - // now is a good time to check the oldest active query - while (mLast != mIndex) { - uint64_t elapsed = 0; - TimerQueryResult const result = driver.getTimerQueryValue(mQueries[mLast].handle, &elapsed); - switch (result) { - case TimerQueryResult::NOT_READY: - // nothing to do - break; - case TimerQueryResult::ERROR: - mLast = (mLast + 1) % POOL_COUNT; - break; - case TimerQueryResult::AVAILABLE: { - FILAMENT_TRACING_CONTEXT(FILAMENT_TRACING_CATEGORY_FILAMENT); - FILAMENT_TRACING_VALUE(FILAMENT_TRACING_CATEGORY_FILAMENT, "FrameInfo::elapsed", uint32_t(elapsed)); - // conversion to our duration happens here - pFront = mQueries[mLast].pInfo; - pFront->frameTime = std::chrono::duration(elapsed); - mLast = (mLast + 1) % POOL_COUNT; - denoiseFrameTime(history, config); + if (mHasTimerQueries) { + // now is a good time to check the oldest active query + while (mLast != mIndex) { + uint64_t elapsed = 0; + TimerQueryResult const result = driver.getTimerQueryValue(mQueries[mLast].handle, &elapsed); + switch (result) { + case TimerQueryResult::NOT_READY: + // nothing to do + break; + case TimerQueryResult::ERROR: + mLast = (mLast + 1) % POOL_COUNT; + break; + case TimerQueryResult::AVAILABLE: { + FILAMENT_TRACING_CONTEXT(FILAMENT_TRACING_CATEGORY_FILAMENT); + FILAMENT_TRACING_VALUE(FILAMENT_TRACING_CATEGORY_FILAMENT, "FrameInfo::elapsed", uint32_t(elapsed)); + // conversion to our duration happens here + pFront = mQueries[mLast].pInfo; + pFront->frameTime = std::chrono::duration(elapsed); + mLast = (mLast + 1) % POOL_COUNT; + denoiseFrameTime(history, config); + break; + } + } + if (result != TimerQueryResult::AVAILABLE) { break; } + // read the pending timer queries until we find one that's not ready } - if (result != TimerQueryResult::AVAILABLE) { - break; + } else { + if (mLast != mIndex) { + mLast = (mLast + 1) % POOL_COUNT; } - // read the pending timer queries until we find one that's not ready } #if 0 @@ -123,18 +156,42 @@ void FrameInfoManager::beginFrame(DriverApi& driver, Config const& config, uint3 } void FrameInfoManager::endFrame(DriverApi& driver) noexcept { + // create a Fence to capture the GPU complete time + FenceHandle const fence = driver.createFence(); + auto& front = mFrameTimeHistory.front(); - // close the timer query - driver.endTimerQuery(mQueries[mIndex].handle); + front.fence = fence; + front.endFrame = std::chrono::steady_clock::now(); + + if (mHasTimerQueries) { + // close the timer query + driver.endTimerQuery(mQueries[mIndex].handle); + } + // queue custom backend command to query the current time - driver.queueCommand([&front](){ + driver.queueCommand([&jobQueue = mJobQueue, &driver, &front] { // backend frame end-time front.backendEndFrame = std::chrono::steady_clock::now(); - // signal that the data is available - front.ready.store(true, std::memory_order_release); + + // now launch a job that'll wait for the gpu to complete + jobQueue.push([&driver, &front] { + FenceStatus const status = driver.fenceWait(front.fence, FENCE_WAIT_FOR_EVER); + if (status == FenceStatus::CONDITION_SATISFIED) { + front.gpuFrameComplete = std::chrono::steady_clock::now(); + } else if (status == FenceStatus::TIMEOUT_EXPIRED) { + // that should never happen because: + // - we wait forever + // - made sure that the createFence() command was processed on the backed + // (because we're inside a custom command) + } else { + // We got an error, fenceWait might not be supported + front.gpuFrameComplete = {}; + } + // finally, signal that the data is available + front.ready.store(true, std::memory_order_release); + }); }); - // and finally acquire the time on the main thread - front.endFrame = std::chrono::steady_clock::now(); + mIndex = (mIndex + 1) % POOL_COUNT; } @@ -180,7 +237,7 @@ FixedCapacityVector FrameInfoManager::getFrameInfoHistory( size_t const c = history.size(); for (; i < c; ++i) { auto const& entry = history[i]; - if (entry.ready.load(std::memory_order_acquire) && entry.valid) { + if (entry.ready.load(std::memory_order_acquire) && (entry.valid || !mHasTimerQueries)) { // once we found an entry ready, // we know by construction that all following ones are too break; @@ -197,7 +254,9 @@ FixedCapacityVector FrameInfoManager::getFrameInfoHistory( duration_cast(entry.beginFrame.time_since_epoch()).count(), duration_cast(entry.endFrame.time_since_epoch()).count(), duration_cast(entry.backendBeginFrame.time_since_epoch()).count(), - duration_cast(entry.backendEndFrame.time_since_epoch()).count() + duration_cast(entry.backendEndFrame.time_since_epoch()).count(), + duration_cast(entry.gpuFrameComplete.time_since_epoch()).count(), + duration_cast(entry.vsync.time_since_epoch()).count() }); } return result; diff --git a/filament/src/FrameInfo.h b/filament/src/FrameInfo.h index a110f235c7..aebaad4407 100644 --- a/filament/src/FrameInfo.h +++ b/filament/src/FrameInfo.h @@ -25,6 +25,7 @@ #include #include +#include #include #include @@ -56,11 +57,18 @@ struct FrameInfoImpl : public details::FrameInfo { time_point endFrame; // main thread endFrame time time_point backendBeginFrame; // backend thread beginFrame time (makeCurrent time) time_point backendEndFrame; // backend thread endFrame time (present time) + time_point gpuFrameComplete; // the frame is done rendering on the gpu + time_point vsync; // vsync time + backend::FenceHandle fence{}; // the fence used for gpuFrameComplete std::atomic_bool ready{}; // true once backend thread has populated its data explicit FrameInfoImpl(uint32_t const id) noexcept : frameId(id) { } + ~FrameInfoImpl() noexcept { + assert_invariant(!fence); + } + FrameInfoImpl(FrameInfoImpl&& rhs) noexcept : details::FrameInfo(rhs), frameId(rhs.frameId), @@ -68,6 +76,9 @@ struct FrameInfoImpl : public details::FrameInfo { endFrame(rhs.endFrame), backendBeginFrame(rhs.backendBeginFrame), backendEndFrame(rhs.backendEndFrame), + gpuFrameComplete(rhs.gpuFrameComplete), + vsync(rhs.vsync), + fence(rhs.fence), ready(rhs.ready.load()) { } @@ -79,6 +90,9 @@ struct FrameInfoImpl : public details::FrameInfo { endFrame = rhs.endFrame; backendBeginFrame = rhs.backendBeginFrame; backendEndFrame = rhs.backendEndFrame; + gpuFrameComplete = rhs.gpuFrameComplete; + vsync = rhs.vsync; + fence = rhs.fence; ready.store(rhs.ready.load()); return *this; } @@ -185,6 +199,16 @@ public: return operator[](0); } + T const& back() const noexcept { + assert_invariant(!empty()); + return operator[](size() - 1); + } + + T& back() noexcept { + assert_invariant(!empty()); + return operator[](size() - 1); + } + private: using Storage = std::aligned_storage_t; Storage mStorage[CAPACITY]; @@ -213,7 +237,8 @@ public: void terminate(backend::DriverApi& driver) noexcept; // call this immediately after "make current" - void beginFrame(backend::DriverApi& driver, Config const& config, uint32_t frameId) noexcept; + void beginFrame(backend::DriverApi& driver, Config const& config, + uint32_t frameId, std::chrono::steady_clock::time_point vsync) noexcept; // call this immediately before "swap buffers" void endFrame(backend::DriverApi& driver) noexcept; @@ -237,6 +262,8 @@ private: uint32_t mLast = 0; // index of oldest query still active FrameInfoImpl* pFront = nullptr; // the most recent slot with a valid frame time FrameHistoryQueue mFrameTimeHistory{}; + utils::AsyncJobQueue mJobQueue; + bool const mHasTimerQueries = false; }; diff --git a/filament/src/details/Renderer.cpp b/filament/src/details/Renderer.cpp index d701eade4a..467831d5f6 100644 --- a/filament/src/details/Renderer.cpp +++ b/filament/src/details/Renderer.cpp @@ -391,7 +391,7 @@ bool FRenderer::beginFrame(FSwapChain* swapChain, uint64_t vsyncSteadyClockTimeN mFrameInfoManager.beginFrame(driver, { .historySize = mFrameRateOptions.history - }, mFrameId); + }, mFrameId, appVsync); // ask the engine to do what it needs to (e.g. updates light buffer, materials...) engine.prepare(); diff --git a/libs/utils/include/utils/AsyncJobQueue.h b/libs/utils/include/utils/AsyncJobQueue.h index a67dd0217c..3cf9064362 100644 --- a/libs/utils/include/utils/AsyncJobQueue.h +++ b/libs/utils/include/utils/AsyncJobQueue.h @@ -28,8 +28,8 @@ namespace utils { /** - * Simple asynchronous job queue. This manages a thread that executes jobs submitted to it - * in order. + * Simple asynchronous job queue. This manages a *single*thread that executes jobs submitted + * to it in order. */ class AsyncJobQueue { public: diff --git a/libs/utils/src/AsyncJobQueue.cpp b/libs/utils/src/AsyncJobQueue.cpp index c0ec92ad2c..3b00daed66 100644 --- a/libs/utils/src/AsyncJobQueue.cpp +++ b/libs/utils/src/AsyncJobQueue.cpp @@ -15,8 +15,10 @@ */ #include +#include #include #include +#include #include #include @@ -28,17 +30,22 @@ AsyncJobQueue::AsyncJobQueue(const char* name, Priority priority) { mThread = std::thread([this, name, priority]() { JobSystem::setThreadName(name); JobSystem::setThreadPriority(priority); - auto& queue = mQueue; bool exitRequested; do { std::unique_lock lock(mLock); - mCondition.wait(lock, [this]() -> bool { return mExitRequested || !mQueue.empty(); }); + // wait until we get a job, or we're asked to exit + mCondition.wait(lock, [this]() -> bool { + return mExitRequested || !mQueue.empty(); + }); exitRequested = mExitRequested; - if (!queue.empty()) { - Job const job(std::move(queue.front())); - queue.erase(queue.begin()); - lock.unlock(); + auto const queue = std::move(mQueue); + // here we have drained the whole queue, and if exitRequested is set, we're guaranteed + // no more job will be added after we unlock. + lock.unlock(); + // execute the jobs without holding a lock. These jobs must be executed in order, + // front to back, and are allowed to be long-running (like waiting on a fence). + for (auto& job : queue) { job(); } } while (!exitRequested); @@ -51,7 +58,11 @@ AsyncJobQueue::~AsyncJobQueue() noexcept { void AsyncJobQueue::push(Job&& job) { std::unique_lock lock(mLock); - if (!mExitRequested) { + if (UTILS_UNLIKELY(mExitRequested)) { + LOG(WARNING) << "AsyncJobQueue::push() called after drainAndExit()"; + } + assert_invariant(!mExitRequested); + if (UTILS_LIKELY(!mExitRequested)) { mQueue.push_back(std::move(job)); lock.unlock(); mCondition.notify_one(); @@ -60,7 +71,9 @@ void AsyncJobQueue::push(Job&& job) { void AsyncJobQueue::drainAndExit() { std::unique_lock lock(mLock); - mCondition.wait(lock, [this] { return mQueue.empty(); }); + // we request the service thread to exit, but we're guaranteed that it'll only exit + // after all current callbacks are processed. In addition, once mExitRequested is set, + // no new jobs can be added, so we can join the thread. mExitRequested = true; lock.unlock(); mCondition.notify_one();