From 5c11b237f3dc8a3d2a6e3671dd89e89dd75ddfe7 Mon Sep 17 00:00:00 2001 From: Powei Feng Date: Thu, 15 Jun 2023 11:27:48 -0700 Subject: [PATCH] vulkan: address debugUtils bug (#6904) vkCmdEndDebugUtilsLabelEXT expects that a label was "pushed" onto the command queue (as described in the spec). It is possible to push labels across command buffers, but the pushed label must still be in the queue (unexecuted) when End is called. This implies that we need to make sure the labels are in a good state (all popped) when vkQueueSubmit is called. - We add a stack to carry the labels across vkQueueSubmit. - Also add CPU time durations between push and pop to provide rough CPU execution times (in debug). - Add systrace markers for Android systrace --- .../backend/src/vulkan/VulkanCommands.cpp | 160 +++++++++++++++++- filament/backend/src/vulkan/VulkanCommands.h | 45 ++++- filament/backend/src/vulkan/VulkanContext.cpp | 2 + filament/backend/src/vulkan/VulkanContext.h | 2 +- filament/backend/src/vulkan/VulkanDriver.cpp | 101 +++-------- filament/backend/src/vulkan/VulkanDriver.h | 1 - 6 files changed, 226 insertions(+), 85 deletions(-) diff --git a/filament/backend/src/vulkan/VulkanCommands.cpp b/filament/backend/src/vulkan/VulkanCommands.cpp index abd1b5612d..324de0ae0d 100644 --- a/filament/backend/src/vulkan/VulkanCommands.cpp +++ b/filament/backend/src/vulkan/VulkanCommands.cpp @@ -22,6 +22,8 @@ #include "VulkanCommands.h" #include "VulkanConstants.h" +#include "VulkanContext.h" +#include "VulkanDriver.h" #include #include @@ -32,6 +34,8 @@ using namespace utils; namespace filament::backend { +using Timestamp = VulkanGroupMarkers::Timestamp; + VulkanCmdFence::VulkanCmdFence(VkDevice device, bool signaled) : device(device) { VkFenceCreateInfo fenceCreateInfo { .sType = VK_STRUCTURE_TYPE_FENCE_CREATE_INFO }; if (signaled) { @@ -64,10 +68,51 @@ static VkCommandPool createPool(VkDevice device, uint32_t queueFamilyIndex) { } -VulkanCommands::VulkanCommands(VkDevice device, VkQueue queue, uint32_t queueFamilyIndex) : mDevice(device), - mQueue(queue), mPool(createPool(mDevice, queueFamilyIndex)) { - VkSemaphoreCreateInfo sci { .sType = VK_STRUCTURE_TYPE_SEMAPHORE_CREATE_INFO }; - for (auto& semaphore : mSubmissionSignals) { +void VulkanGroupMarkers::push(std::string const& marker, Timestamp start) noexcept { + mMarkers.push(marker); +#if FILAMENT_VULKAN_VERBOSE + mTimestamps.push(start.time_since_epoch().count() > 0.0 + ? start + : std::chrono::high_resolution_clock::now()); +#endif +} + +std::pair VulkanGroupMarkers::pop() noexcept { + auto const marker = mMarkers.top(); + mMarkers.pop(); + +#if FILAMENT_VULKAN_VERBOSE + auto const topTimestamp = mTimestamps.top(); + mTimestamps.pop(); + return std::make_pair(marker, topTimestamp); +#else + return std::make_pair(marker, Timestamp{}); +#endif +} + +std::pair VulkanGroupMarkers::top() const { + assert_invariant(!empty()); + auto const marker = mMarkers.top(); +#if FILAMENT_VULKAN_VERBOSE + auto const topTimestamp = mTimestamps.top(); + return std::make_pair(marker, topTimestamp); +#else + return std::make_pair(marker, Timestamp{}); +#endif +} + +bool VulkanGroupMarkers::empty() const noexcept { + return mMarkers.empty(); +} + +VulkanCommands::VulkanCommands(VkDevice device, VkQueue queue, uint32_t queueFamilyIndex, + VulkanContext* context) + : mDevice(device), + mQueue(queue), + mPool(createPool(mDevice, queueFamilyIndex)), + mContext(context) { + VkSemaphoreCreateInfo sci{.sType = VK_STRUCTURE_TYPE_SEMAPHORE_CREATE_INFO}; + for (auto& semaphore: mSubmissionSignals) { vkCreateSemaphore(mDevice, &sci, nullptr, &semaphore); } } @@ -139,6 +184,13 @@ VulkanCommandBuffer const& VulkanCommands::get(bool blockOnGC) { mObserver->onCommandBuffer(*mCurrent); } + // We push the current markers onto a temporary stack. This must be placed after mCurrent is set + // to the new command buffer since pushGroupMarker also calls get(). + while (mCarriedOverMarkers && !mCarriedOverMarkers->empty()) { + auto [marker, time] = mCarriedOverMarkers->pop(); + pushGroupMarker(marker.c_str(), time); + } + return *mCurrent; } @@ -195,6 +247,17 @@ bool VulkanCommands::flush() { << io::endl; } + // Before actually submitting, we need to pop any leftover group markers. + while (mGroupMarkers && !mGroupMarkers->empty()) { + if (!mCarriedOverMarkers) { + mCarriedOverMarkers = std::make_unique(); + } + auto const [marker, time] = mGroupMarkers->top(); + mCarriedOverMarkers->push(marker, time); + // We still need to call through to vkCmdEndDebugUtilsLabelEXT. + popGroupMarker(); + } + auto& cmdfence = mCurrent->fence; std::unique_lock lock(cmdfence->mutex); cmdfence->status.store(VK_NOT_READY); @@ -270,7 +333,94 @@ void VulkanCommands::updateFences() { } } -} // namespace filament::backend +void VulkanCommands::pushGroupMarker(char const* str, VulkanGroupMarkers::Timestamp timestamp) { +#if FILAMENT_VULKAN_VERBOSE + // If the timestamp is not 0, then we are carrying over a marker across buffer submits. + // If it is 0, then this is a normal marker push and we should just print debug line as usual. + if (timestamp.time_since_epoch().count() == 0.0) { + utils::slog.d << "----> " << str << utils::io::endl; + } +#endif + + // TODO: Add group marker color to the Driver API + const VkCommandBuffer cmdbuffer = get().cmdbuffer; + + if (!mGroupMarkers) { + mGroupMarkers = std::make_unique(); + } + mGroupMarkers->push(str, timestamp); + + if (mContext->isDebugUtilsSupported()) { + VkDebugUtilsLabelEXT labelInfo = { + .sType = VK_STRUCTURE_TYPE_DEBUG_UTILS_LABEL_EXT, + .pLabelName = str, + .color = {0, 1, 0, 1}, + }; + vkCmdBeginDebugUtilsLabelEXT(cmdbuffer, &labelInfo); + } else if (mContext->isDebugMarkersSupported()) { + VkDebugMarkerMarkerInfoEXT markerInfo = { + .sType = VK_STRUCTURE_TYPE_DEBUG_MARKER_MARKER_INFO_EXT, + .pMarkerName = str, + .color = {0.0f, 1.0f, 0.0f, 1.0f}, + }; + vkCmdDebugMarkerBeginEXT(cmdbuffer, &markerInfo); + } +} + +void VulkanCommands::popGroupMarker() { + assert_invariant(mGroupMarkers); + + if (!mGroupMarkers->empty()) { + const VkCommandBuffer cmdbuffer = get().cmdbuffer; + #if FILAMENT_VULKAN_VERBOSE + auto const [marker, startTime] = mGroupMarkers->pop(); + auto const endTime = std::chrono::high_resolution_clock::now(); + std::chrono::duration diff = endTime - startTime; + utils::slog.d << "<---- " << marker << " elapsed: " << (diff.count() * 1000) << " ms\n" + << utils::io::flush; + #else + mGroupMarkers->pop(); + #endif + + if (mContext->isDebugUtilsSupported()) { + vkCmdEndDebugUtilsLabelEXT(cmdbuffer); + } else if (mContext->isDebugMarkersSupported()) { + vkCmdDebugMarkerEndEXT(cmdbuffer); + } + } else if (mCarriedOverMarkers && !mCarriedOverMarkers->empty()) { + // It could be that pop is called between flush() and get() (new command buffer), in which + // case the marker is in "carried over" state. We'd just remove that + mCarriedOverMarkers->pop(); + } +} + +void VulkanCommands::insertEventMarker(char const* string, uint32_t len) { + VkCommandBuffer const cmdbuffer = get().cmdbuffer; + if (mContext->isDebugUtilsSupported()) { + VkDebugUtilsLabelEXT labelInfo = { + .sType = VK_STRUCTURE_TYPE_DEBUG_UTILS_LABEL_EXT, + .pLabelName = string, + .color = {1, 1, 0, 1}, + }; + vkCmdInsertDebugUtilsLabelEXT(cmdbuffer, &labelInfo); + } else if (mContext->isDebugMarkersSupported()) { + VkDebugMarkerMarkerInfoEXT markerInfo = { + .sType = VK_STRUCTURE_TYPE_DEBUG_MARKER_MARKER_INFO_EXT, + .pMarkerName = string, + .color = {0.0f, 1.0f, 0.0f, 1.0f}, + }; + vkCmdDebugMarkerInsertEXT(cmdbuffer, &markerInfo); + } +} + +std::string VulkanCommands::getTopGroupMarker() const { + if (!mGroupMarkers || mGroupMarkers->empty()) { + return ""; + } + return std::get<0>(mGroupMarkers->top()); +} + +}// namespace filament::backend #if defined(_MSC_VER) #pragma warning( pop ) diff --git a/filament/backend/src/vulkan/VulkanCommands.h b/filament/backend/src/vulkan/VulkanCommands.h index 7ab07b57b1..811796c31d 100644 --- a/filament/backend/src/vulkan/VulkanCommands.h +++ b/filament/backend/src/vulkan/VulkanCommands.h @@ -26,8 +26,31 @@ #include +#include +#include +#include +#include + namespace filament::backend { +struct VulkanContext; + +class VulkanGroupMarkers { +public: + using Timestamp = std::chrono::time_point; + + void push(std::string const& marker, Timestamp start = {}) noexcept; + std::pair pop() noexcept; + std::pair top() const; + bool empty() const noexcept; + +private: + std::stack mMarkers; +#if FILAMENT_VULKAN_VERBOSE + std::stack mTimestamps; +#endif +}; + // Wrapper to enable use of shared_ptr for implementing shared ownership of low-level Vulkan fences. struct VulkanCmdFence { VulkanCmdFence(VkDevice device, bool signaled = false); @@ -86,7 +109,8 @@ public: // class VulkanCommands { public: - VulkanCommands(VkDevice device, VkQueue queue, uint32_t queueFamilyIndex); + VulkanCommands(VkDevice device, VkQueue queue, uint32_t queueFamilyIndex, + VulkanContext* context); ~VulkanCommands(); // Creates a "current" command buffer if none exists, otherwise returns the current one. @@ -121,11 +145,21 @@ class VulkanCommands { // The observer's event handler can only be called during get(). void setObserver(CommandBufferObserver* observer) { mObserver = observer; } + void pushGroupMarker(char const* str, VulkanGroupMarkers::Timestamp timestamp = {}); + + void popGroupMarker(); + + void insertEventMarker(char const* string, uint32_t len); + + std::string getTopGroupMarker() const; + private: static constexpr int CAPACITY = VK_MAX_COMMAND_BUFFERS; - const VkDevice mDevice; - const VkQueue mQueue; - const VkCommandPool mPool; + VkDevice const mDevice; + VkQueue const mQueue; + VkCommandPool const mPool; + VulkanContext const* mContext; + VulkanCommandBuffer* mCurrent = nullptr; VkSemaphore mSubmissionSignal = {}; VkSemaphore mInjectedSignal = {}; @@ -133,6 +167,9 @@ class VulkanCommands { VkSemaphore mSubmissionSignals[CAPACITY] = {}; size_t mAvailableCount = CAPACITY; CommandBufferObserver* mObserver = nullptr; + + std::unique_ptr mGroupMarkers; + std::unique_ptr mCarriedOverMarkers; }; } // namespace filament::backend diff --git a/filament/backend/src/vulkan/VulkanContext.cpp b/filament/backend/src/vulkan/VulkanContext.cpp index 14726274b9..84f456f571 100644 --- a/filament/backend/src/vulkan/VulkanContext.cpp +++ b/filament/backend/src/vulkan/VulkanContext.cpp @@ -15,6 +15,8 @@ */ #include "VulkanContext.h" + +#include "VulkanCommands.h" #include "VulkanHandles.h" #include "VulkanMemory.h" #include "VulkanTexture.h" diff --git a/filament/backend/src/vulkan/VulkanContext.h b/filament/backend/src/vulkan/VulkanContext.h index 0355ed4c4e..a22951deb6 100644 --- a/filament/backend/src/vulkan/VulkanContext.h +++ b/filament/backend/src/vulkan/VulkanContext.h @@ -17,7 +17,6 @@ #ifndef TNT_FILAMENT_BACKEND_VULKANCONTEXT_H #define TNT_FILAMENT_BACKEND_VULKANCONTEXT_H -#include "VulkanCommands.h" #include "VulkanConstants.h" #include "VulkanImageUtility.h" #include "VulkanPipelineCache.h" @@ -38,6 +37,7 @@ struct VulkanSwapChain; struct VulkanTexture; class VulkanStagePool; struct VulkanTimerQuery; +struct VulkanCommandBuffer; struct VulkanAttachment { VulkanTexture* texture; diff --git a/filament/backend/src/vulkan/VulkanDriver.cpp b/filament/backend/src/vulkan/VulkanDriver.cpp index 5598ef7b79..d956385e61 100644 --- a/filament/backend/src/vulkan/VulkanDriver.cpp +++ b/filament/backend/src/vulkan/VulkanDriver.cpp @@ -30,16 +30,12 @@ #include #include #include +#include #ifndef NDEBUG #include #endif -#if FILAMENT_VULKAN_VERBOSE -#include -static std::stack renderPassMarkers; -#endif - using namespace bluevk; using utils::FixedCapacityVector; @@ -186,7 +182,7 @@ VulkanDriver::VulkanDriver(VulkanPlatform* platform, VulkanContext const& contex #endif mTimestamps = std::make_unique(mPlatform->getDevice()); mCommands = std::make_unique(mPlatform->getDevice(), - mPlatform->getGraphicsQueue(), mPlatform->getGraphicsQueueFamilyIndex()); + mPlatform->getGraphicsQueue(), mPlatform->getGraphicsQueueFamilyIndex(), &mContext); mCommands->setObserver(&mPipelineCache); mPipelineCache.setDevice(mPlatform->getDevice(), mAllocator); @@ -1146,15 +1142,18 @@ void VulkanDriver::beginRenderPass(Handle rth, const RenderPassP VkFramebuffer vkfb = mFramebufferCache.getFramebuffer(fbkey); // Assign a label to the framebuffer for debugging purposes. - if (UTILS_UNLIKELY(mContext.isDebugUtilsSupported()) && !mCurrentDebugMarker.empty()) { - const VkDebugUtilsObjectNameInfoEXT info = { - VK_STRUCTURE_TYPE_DEBUG_UTILS_OBJECT_NAME_INFO_EXT, - nullptr, - VK_OBJECT_TYPE_FRAMEBUFFER, - reinterpret_cast(vkfb), - mCurrentDebugMarker.c_str(), - }; - vkSetDebugUtilsObjectNameEXT(mPlatform->getDevice(), &info); + if (UTILS_UNLIKELY(mContext.isDebugUtilsSupported())) { + auto const topMarker = mCommands->getTopGroupMarker(); + if (!topMarker.empty()) { + const VkDebugUtilsObjectNameInfoEXT info = { + VK_STRUCTURE_TYPE_DEBUG_UTILS_OBJECT_NAME_INFO_EXT, + nullptr, + VK_OBJECT_TYPE_FRAMEBUFFER, + reinterpret_cast(vkfb), + topMarker.c_str(), + }; + vkSetDebugUtilsObjectNameEXT(mPlatform->getDevice(), &info); + } } // The current command buffer now owns a reference to the render target and its attachments. @@ -1375,75 +1374,29 @@ void VulkanDriver::bindSamplers(uint32_t index, Handle sbh) { } void VulkanDriver::insertEventMarker(char const* string, uint32_t len) { - constexpr float MARKER_COLOR[] = { 0.0f, 1.0f, 0.0f, 1.0f }; - VkCommandBuffer const cmdbuffer = mCommands->get().cmdbuffer; - if (mContext.isDebugUtilsSupported()) { - VkDebugUtilsLabelEXT labelInfo = { - .sType = VK_STRUCTURE_TYPE_DEBUG_UTILS_LABEL_EXT, - .pLabelName = string, - .color = {1, 1, 0, 1}, - }; - vkCmdInsertDebugUtilsLabelEXT(cmdbuffer, &labelInfo); - } else if (mContext.isDebugMarkersSupported()) { - VkDebugMarkerMarkerInfoEXT markerInfo = {}; - markerInfo.sType = VK_STRUCTURE_TYPE_DEBUG_MARKER_MARKER_INFO_EXT; - memcpy(markerInfo.color, &MARKER_COLOR[0], sizeof(MARKER_COLOR)); - markerInfo.pMarkerName = string; - vkCmdDebugMarkerInsertEXT(cmdbuffer, &markerInfo); - } + mCommands->insertEventMarker(string, len); } -void VulkanDriver::pushGroupMarker(char const* string, uint32_t len) { - -#if FILAMENT_VULKAN_VERBOSE - renderPassMarkers.push(std::string(string)); - utils::slog.d << "----> " << string << utils::io::endl; -#endif - - // TODO: Add group marker color to the Driver API - constexpr float MARKER_COLOR[] = { 0.0f, 1.0f, 0.0f, 1.0f }; - const VkCommandBuffer cmdbuffer = mCommands->get().cmdbuffer; - if (mContext.isDebugUtilsSupported()) { - VkDebugUtilsLabelEXT labelInfo = { - .sType = VK_STRUCTURE_TYPE_DEBUG_UTILS_LABEL_EXT, - .pLabelName = string, - .color = {0, 1, 0, 1}, - }; - vkCmdBeginDebugUtilsLabelEXT(cmdbuffer, &labelInfo); - mCurrentDebugMarker = string; - } else if (mContext.isDebugMarkersSupported()) { - VkDebugMarkerMarkerInfoEXT markerInfo = {}; - markerInfo.sType = VK_STRUCTURE_TYPE_DEBUG_MARKER_MARKER_INFO_EXT; - memcpy(markerInfo.color, &MARKER_COLOR[0], sizeof(MARKER_COLOR)); - markerInfo.pMarkerName = string; - vkCmdDebugMarkerBeginEXT(cmdbuffer, &markerInfo); +void VulkanDriver::pushGroupMarker(char const* string, uint32_t) { + // Turns out all the markers are 0-terminated, so we can just pass it without len. + mCommands->pushGroupMarker(string); + { + SYSTRACE_CONTEXT(); + SYSTRACE_NAME_BEGIN(string); } } void VulkanDriver::popGroupMarker(int) { - -#if FILAMENT_VULKAN_VERBOSE - std::string const& marker = renderPassMarkers.top(); - renderPassMarkers.pop(); - utils::slog.d << "<---- " << marker << utils::io::endl; -#endif - - const VkCommandBuffer cmdbuffer = mCommands->get().cmdbuffer; - if (mContext.isDebugUtilsSupported()) { - vkCmdEndDebugUtilsLabelEXT(cmdbuffer); - mCurrentDebugMarker.clear(); - } else if (mContext.isDebugMarkersSupported()) { - vkCmdDebugMarkerEndEXT(cmdbuffer); + mCommands->popGroupMarker(); + { + SYSTRACE_CONTEXT(); + SYSTRACE_NAME_END(); } } -void VulkanDriver::startCapture(int) { +void VulkanDriver::startCapture(int) {} -} - -void VulkanDriver::stopCapture(int) { - -} +void VulkanDriver::stopCapture(int) {} void VulkanDriver::readPixels(Handle src, uint32_t x, uint32_t y, uint32_t width, uint32_t height, PixelBufferDescriptor&& pbd) { diff --git a/filament/backend/src/vulkan/VulkanDriver.h b/filament/backend/src/vulkan/VulkanDriver.h index f6dae95e4b..a98218e194 100644 --- a/filament/backend/src/vulkan/VulkanDriver.h +++ b/filament/backend/src/vulkan/VulkanDriver.h @@ -148,7 +148,6 @@ private: VmaAllocator mAllocator = VK_NULL_HANDLE; VkDebugReportCallbackEXT mDebugCallback = VK_NULL_HANDLE; VkDebugUtilsMessengerEXT mDebugMessenger = VK_NULL_HANDLE; - std::string mCurrentDebugMarker; VulkanContext mContext = {}; HandleAllocatorVK mHandleAllocator;