diff --git a/CMakeLists.txt b/CMakeLists.txt index e20ec99..a96a1f1 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -10,6 +10,10 @@ set(CMAKE_CXX_STANDARD_REQUIRED ON) set(CMAKE_SKIP_RPATH ON) set(CMAKE_EXPORT_COMPILE_COMMANDS ON) +if(CMAKE_BUILD_TYPE STREQUAL "Release") + add_definitions("-DLSFG_NO_DEBUG") +endif() + # subprojects include(cmake/FetchDXVK.cmake) include(cmake/FetchPeParse.cmake) diff --git a/include/utils/log.hpp b/include/utils/log.hpp index c249833..f85649e 100644 --- a/include/utils/log.hpp +++ b/include/utils/log.hpp @@ -2,35 +2,72 @@ #define LOG_HPP #include +#include #include +#include +#include namespace Log { + namespace Internal { + extern bool isSetup; + + extern std::set debugModules; + extern bool debugAllModules; + + extern std::ofstream logFile; + extern std::mutex logMutex; + + void setup(); + } + + template + void log(std::string_view color, std::string_view module, + std::format_string fmt, Args&&... args) { + Internal::setup(); + + std::string prefix = std::format("lsfg-vk({}): ", module); + std::string message = std::format(fmt, std::forward(args)...); + + std::lock_guard lock(Internal::logMutex); + std::cerr << color << prefix << message << "\033[0m" << '\n'; + if (Internal::logFile.is_open()) { + Internal::logFile << prefix << message << '\n'; + Internal::logFile.flush(); + } + } + const std::string_view WHITE = "\033[1;37m"; const std::string_view YELLOW = "\033[1;33m"; const std::string_view RED = "\033[1;31m"; + + template + void info(std::string_view module, std::format_string fmt, Args&&... args) { + log(WHITE, module, fmt, std::forward(args)...); + } + + template + void warn(std::string_view module, std::format_string fmt, Args&&... args) { + log(YELLOW, module, fmt, std::forward(args)...); + } + + template + void error(std::string_view module, std::format_string fmt, Args&&... args) { + log(RED, module, fmt, std::forward(args)...); + } + const std::string_view GRAY = "\033[1;90m"; - const std::string_view RESET = "\033[0m"; +#ifdef LSFG_NO_DEBUG +template +void debug(std::string_view, std::format_string, Args&&...) {} // NOLINT +#else template - void info(std::format_string fmt, Args&&... args) { - std::cerr << WHITE << std::format(fmt, std::forward(args)...) << RESET << '\n'; - } - - template - void warn(std::format_string fmt, Args&&... args) { - std::cerr << YELLOW << std::format(fmt, std::forward(args)...) << RESET << '\n'; - } - - template - void error(std::format_string fmt, Args&&... args) { - std::cerr << RED << std::format(fmt, std::forward(args)...) << RESET << '\n'; - } - - template - void debug(std::format_string fmt, Args&&... args) { - std::cerr << GRAY << std::format(fmt, std::forward(args)...) << RESET << '\n'; + void debug(std::string_view module, std::format_string fmt, Args&&... args) { + if (Internal::debugAllModules || Internal::debugModules.contains(std::string(module))) + log(GRAY, module, fmt, std::forward(args)...); } +#endif } diff --git a/src/context.cpp b/src/context.cpp index 2070bb9..2816f41 100644 --- a/src/context.cpp +++ b/src/context.cpp @@ -1,5 +1,6 @@ #include "context.hpp" #include "layer.hpp" +#include "utils/log.hpp" #include "utils/utils.hpp" #include @@ -11,7 +12,7 @@ LsContext::LsContext(const Hooks::DeviceInfo& info, VkSwapchainKHR swapchain, VkExtent2D extent, const std::vector& swapchainImages) : swapchain(swapchain), swapchainImages(swapchainImages), extent(extent) { - // initialize lsfg + // prepare textures for lsfg int frame_0_fd{}; this->frame_0 = Mini::Image( info.device, info.physicalDevice, @@ -19,6 +20,8 @@ LsContext::LsContext(const Hooks::DeviceInfo& info, VkSwapchainKHR swapchain, VK_IMAGE_USAGE_TRANSFER_DST_BIT, VK_IMAGE_ASPECT_COLOR_BIT, &frame_0_fd); + Log::info("context", "Created frame_0 image and obtained fd: {}", + frame_0_fd); int frame_1_fd{}; this->frame_1 = Mini::Image( @@ -27,27 +30,42 @@ LsContext::LsContext(const Hooks::DeviceInfo& info, VkSwapchainKHR swapchain, VK_IMAGE_USAGE_TRANSFER_DST_BIT, VK_IMAGE_ASPECT_COLOR_BIT, &frame_1_fd); + Log::info("context", "Created frame_1 image and obtained fd: {}", + frame_1_fd); std::vector out_n_fds(info.frameGen); - for (size_t i = 0; i < info.frameGen; ++i) + for (size_t i = 0; i < info.frameGen; ++i) { this->out_n.emplace_back( info.device, info.physicalDevice, extent, VK_FORMAT_R8G8B8A8_UNORM, VK_IMAGE_USAGE_TRANSFER_SRC_BIT, VK_IMAGE_ASPECT_COLOR_BIT, &out_n_fds.at(i)); + Log::info("context", "Created out_n[{}] image and obtained fd: {}", + i, out_n_fds.at(i)); + } + // initialize lsfg + Log::debug("context", "(entering LSFG initialization)"); Utils::storeLayerEnv(); LSFG::initialize(); Utils::restoreLayerEnv(); + Log::debug("context", "(exiting LSFG initialization)"); + Log::debug("context", "(entering LSFG context creation)"); this->lsfgCtxId = std::shared_ptr( new int32_t(LSFG::createContext(extent.width, extent.height, frame_0_fd, frame_1_fd, out_n_fds)), [](const int32_t* id) { + Log::info("context", + "(entering LSFG context deletion with id: {})", *id); LSFG::deleteContext(*id); + Log::info("context", + "(exiting LSFG context deletion with id: {})", *id); } ); + Log::info("context", "(exiting LSFG context creation with id: {})", + *this->lsfgCtxId); // prepare render passes this->cmdPool = Mini::CommandPool(info.device, info.queue.first); @@ -59,6 +77,8 @@ LsContext::LsContext(const Hooks::DeviceInfo& info, VkSwapchainKHR swapchain, pass.postCopySemaphores.resize(info.frameGen); pass.prevPostCopySemaphores.resize(info.frameGen); } + + Log::info("context", "Remaining misc context init finished successfully."); } VkResult LsContext::present(const Hooks::DeviceInfo& info, const void* pNext, VkQueue queue, @@ -66,6 +86,8 @@ VkResult LsContext::present(const Hooks::DeviceInfo& info, const void* pNext, Vk auto& pass = this->passInfos.at(this->frameIdx % 8); // 1. copy swapchain image to frame_0/frame_1 + Log::debug("context2", "1. Copying swapchain image {} to frame {}", + presentIdx, this->frameIdx % 2 == 0 ? "0" : "1"); int preCopySemaphoreFd{}; pass.preCopySemaphores.at(0) = Mini::Semaphore(info.device, &preCopySemaphoreFd); pass.preCopySemaphores.at(1) = Mini::Semaphore(info.device); @@ -91,16 +113,22 @@ VkResult LsContext::present(const Hooks::DeviceInfo& info, const void* pNext, Vk pass.preCopySemaphores.at(1).handle() }); // 2. render intermediary frames + Log::debug("context2", "2. Rendering intermediary frames"); std::vector renderSemaphoreFds(info.frameGen); for (size_t i = 0; i < info.frameGen; ++i) pass.renderSemaphores.at(i) = Mini::Semaphore(info.device, &renderSemaphoreFds.at(i)); + Log::debug("context2", + "(entering LSFG present with id: {})", *this->lsfgCtxId); LSFG::presentContext(*this->lsfgCtxId, preCopySemaphoreFd, renderSemaphoreFds); + Log::debug("context2", + "(exiting LSFG present with id: {})", *this->lsfgCtxId); for (size_t i = 0; i < info.frameGen; i++) { // 3. acquire next swapchain image + Log::debug("context2", "3. Acquiring next swapchain image for frame {}", i); pass.acquireSemaphores.at(i) = Mini::Semaphore(info.device); uint32_t imageIdx{}; auto res = Layer::ovkAcquireNextImageKHR(info.device, this->swapchain, UINT64_MAX, @@ -109,6 +137,7 @@ VkResult LsContext::present(const Hooks::DeviceInfo& info, const void* pNext, Vk throw LSFG::vulkan_error(res, "Failed to acquire next swapchain image"); // 4. copy output image to swapchain image + Log::debug("context2", "4. Copying output image to swapchain image for frame {}", i); pass.postCopySemaphores.at(i) = Mini::Semaphore(info.device); pass.prevPostCopySemaphores.at(i) = Mini::Semaphore(info.device); pass.postCopyBufs.at(i) = Mini::CommandBuffer(info.device, this->cmdPool); @@ -129,6 +158,7 @@ VkResult LsContext::present(const Hooks::DeviceInfo& info, const void* pNext, Vk pass.prevPostCopySemaphores.at(i).handle() }); // 5. present swapchain image + Log::debug("context2", "5. Presenting swapchain image for frame {}", i); std::vector waitSemaphores{ pass.postCopySemaphores.at(i).handle() }; if (i != 0) waitSemaphores.emplace_back(pass.prevPostCopySemaphores.at(i - 1).handle()); @@ -147,6 +177,7 @@ VkResult LsContext::present(const Hooks::DeviceInfo& info, const void* pNext, Vk } // 6. present actual next frame + Log::debug("context2", "6. Presenting actual next frame"); VkSemaphore lastPrevPostCopySemaphore = pass.prevPostCopySemaphores.at(info.frameGen - 1).handle(); const VkPresentInfoKHR presentInfo{ diff --git a/src/hooks.cpp b/src/hooks.cpp index 4809c06..a640f87 100644 --- a/src/hooks.cpp +++ b/src/hooks.cpp @@ -27,18 +27,26 @@ namespace { "VK_KHR_external_memory_capabilities", "VK_KHR_external_semaphore_capabilities" }); - - Log::info("lsfg-vk: Created Vulkan instance"); VkInstanceCreateInfo createInfo = *pCreateInfo; createInfo.enabledExtensionCount = static_cast(extensions.size()); createInfo.ppEnabledExtensionNames = extensions.data(); - return Layer::ovkCreateInstance(&createInfo, pAllocator, pInstance); + auto res = Layer::ovkCreateInstance(&createInfo, pAllocator, pInstance); + if (res != VK_SUCCESS) { + Log::error("hooks", "Failed to create Vulkan instance: {:x}", + static_cast(res)); + return res; + } + + Log::info("hooks", "Instance created successfully: {:x}", + reinterpret_cast(*pInstance)); + return res; } void myvkDestroyInstance( VkInstance instance, const VkAllocationCallbacks* pAllocator) { - Log::info("lsfg-vk: Destroyed Vulkan instance"); + Log::info("hooks", "Instance destroyed successfully: {:x}", + reinterpret_cast(instance)); Layer::ovkDestroyInstance(instance, pAllocator); } @@ -63,38 +71,59 @@ namespace { VkDeviceCreateInfo createInfo = *pCreateInfo; createInfo.enabledExtensionCount = static_cast(extensions.size()); createInfo.ppEnabledExtensionNames = extensions.data(); - return Layer::ovkCreateDevice(physicalDevice, &createInfo, pAllocator, pDevice); + auto res = Layer::ovkCreateDevice(physicalDevice, &createInfo, pAllocator, pDevice); + if (res != VK_SUCCESS) { + Log::error("hooks", "Failed to create Vulkan device: {:x}", + static_cast(res)); + return res; + } + + Log::info("hooks", "Device created successfully: {:x}", + reinterpret_cast(*pDevice)); + return res; } VkResult myvkCreateDevicePost( VkPhysicalDevice physicalDevice, VkDeviceCreateInfo* pCreateInfo, - const VkAllocationCallbacks* pAllocator, + const VkAllocationCallbacks*, // NOLINT VkDevice* pDevice) { // store device info + Log::debug("hooks", "Creating device info for device: {:x}", + reinterpret_cast(*pDevice)); try { - const char* frameGen = std::getenv("LSFG_MULTIPLIER"); - if (!frameGen) frameGen = "2"; + const char* frameGenEnv = std::getenv("LSFG_MULTIPLIER"); + const uint64_t frameGen = std::max(1, + std::stoul(frameGenEnv ? frameGenEnv : "2") - 1); + Log::debug("hooks", "Using {}x frame generation", + frameGen + 1); + + auto queue = Utils::findQueue(*pDevice, physicalDevice, pCreateInfo, + VK_QUEUE_GRAPHICS_BIT | VK_QUEUE_COMPUTE_BIT); + Log::debug("hooks", "Found queue at index {}: {:x}", + queue.first, reinterpret_cast(queue.second)); + devices.emplace(*pDevice, DeviceInfo { .device = *pDevice, .physicalDevice = physicalDevice, - .queue = Utils::findQueue(*pDevice, physicalDevice, pCreateInfo, - VK_QUEUE_GRAPHICS_BIT), - .frameGen = std::max(1, std::stoul(frameGen) - 1) + .queue = queue, + .frameGen = frameGen, }); } catch (const std::exception& e) { - Log::error("Failed to create device info: {}", e.what()); + Log::error("hooks", "Failed to create device info: {}", e.what()); return VK_ERROR_INITIALIZATION_FAILED; } - Log::info("lsfg-vk: Created Vulkan device"); + Log::info("hooks", "Device info created successfully for: {:x}", + reinterpret_cast(*pDevice)); return VK_SUCCESS; } void myvkDestroyDevice(VkDevice device, const VkAllocationCallbacks* pAllocator) { devices.erase(device); // erase device info - Log::info("lsfg-vk: Destroyed Vulkan device"); + Log::info("hooks", "Device & Device info destroyed successfully: {:x}", + reinterpret_cast(device)); Layer::ovkDestroyDevice(device, pAllocator); } @@ -118,10 +147,25 @@ namespace { createInfo.presentMode = VK_PRESENT_MODE_FIFO_KHR; // force vsync auto res = Layer::ovkCreateSwapchainKHR(device, &createInfo, pAllocator, pSwapchain); if (res != VK_SUCCESS) { - Log::error("Failed to create swapchain: {:x}", static_cast(res)); + Log::error("hooks", "Failed to create swapchain: {:x}", static_cast(res)); return res; } + Log::info("hooks", "Swapchain created successfully: {:x}", + reinterpret_cast(*pSwapchain)); + // retire previous swapchain if it exists + if (pCreateInfo->oldSwapchain) { + Log::debug("hooks", "Retiring previous swapchain context: {:x}", + reinterpret_cast(pCreateInfo->oldSwapchain)); + swapchains.erase(pCreateInfo->oldSwapchain); + swapchainToDeviceTable.erase(pCreateInfo->oldSwapchain); + Log::info("hooks", "Previous swapchain context retired successfully: {:x}", + reinterpret_cast(pCreateInfo->oldSwapchain)); + } + + // create swapchain context + Log::debug("hooks", "Creating swapchain context for device: {:x}", + reinterpret_cast(device)); try { // get swapchain images uint32_t imageCount{}; @@ -133,24 +177,25 @@ namespace { res = Layer::ovkGetSwapchainImagesKHR(device, *pSwapchain, &imageCount, swapchainImages.data()); if (res != VK_SUCCESS) throw LSFG::vulkan_error(res, "Failed to get swapchain images"); + Log::debug("hooks", "Swapchain has {} images", swapchainImages.size()); // create swapchain context swapchains.emplace(*pSwapchain, LsContext( deviceInfo, *pSwapchain, pCreateInfo->imageExtent, swapchainImages )); - swapchainToDeviceTable.emplace(*pSwapchain, device); } catch (const LSFG::vulkan_error& e) { - Log::error("Encountered Vulkan error {:x} while creating swapchain: {}", + Log::error("hooks", "Encountered Vulkan error {:x} while creating swapchain context: {}", static_cast(e.error()), e.what()); return e.error(); } catch (const std::exception& e) { - Log::error("Encountered error while creating swapchain: {}", e.what()); + Log::error("hooks", "Encountered error while creating swapchain context: {}", e.what()); return VK_ERROR_INITIALIZATION_FAILED; } - Log::info("lsfg-vk: Created swapchain with {} images", pCreateInfo->minImageCount); + Log::info("hooks", "Swapchain context created successfully for: {:x}", + reinterpret_cast(*pSwapchain)); return res; } @@ -160,21 +205,33 @@ namespace { auto& deviceInfo = devices.at(swapchainToDeviceTable.at(*pPresentInfo->pSwapchains)); auto& swapchain = swapchains.at(*pPresentInfo->pSwapchains); + Log::debug("hooks2", "Presenting swapchain: {:x} on queue: {:x}", + reinterpret_cast(*pPresentInfo->pSwapchains), + reinterpret_cast(queue)); + VkResult res{}; try { - std::vector waitSemaphores(pPresentInfo->waitSemaphoreCount); - std::copy_n(pPresentInfo->pWaitSemaphores, waitSemaphores.size(), waitSemaphores.data()); + std::vector semaphores(pPresentInfo->waitSemaphoreCount); + std::copy_n(pPresentInfo->pWaitSemaphores, semaphores.size(), semaphores.data()); + Log::debug("hooks2", "Waiting on {} semaphores", semaphores.size()); // present the next frame - return swapchain.present(deviceInfo, pPresentInfo->pNext, - queue, waitSemaphores, *pPresentInfo->pImageIndices); + res = swapchain.present(deviceInfo, pPresentInfo->pNext, + queue, semaphores, *pPresentInfo->pImageIndices); } catch (const LSFG::vulkan_error& e) { - Log::error("Encountered Vulkan error {:x} while presenting: {}", + Log::error("hooks2", "Encountered Vulkan error {:x} while presenting: {}", static_cast(e.error()), e.what()); return e.error(); } catch (const std::exception& e) { - Log::error("Encountered error while creating presenting: {}", e.what()); + Log::error("hooks2", "Encountered error while creating presenting: {}", + e.what()); return VK_ERROR_INITIALIZATION_FAILED; } + + // non VK_SUCCESS or VK_SUBOPTIMAL_KHR doesn't reach here + Log::debug("hooks2", "Presented swapchain {:x} on queue {:x} successfully", + reinterpret_cast(*pPresentInfo->pSwapchains), + reinterpret_cast(queue)); + return res; } void myvkDestroySwapchainKHR( @@ -184,7 +241,8 @@ namespace { swapchains.erase(swapchain); // erase swapchain context swapchainToDeviceTable.erase(swapchain); - Log::info("lsfg-vk: Destroyed swapchain"); + Log::info("hooks", "Swapchain & Swapchain context destroyed successfully: {:x}", + reinterpret_cast(swapchain)); Layer::ovkDestroySwapchainKHR(device, swapchain, pAllocator); } } diff --git a/src/layer.cpp b/src/layer.cpp index 007d2d4..d5ec26f 100644 --- a/src/layer.cpp +++ b/src/layer.cpp @@ -51,7 +51,7 @@ namespace { bool initInstanceFunc(VkInstance instance, const char* name, T* func) { *func = reinterpret_cast(next_vkGetInstanceProcAddr(instance, name)); if (!*func) { - Log::error("lsfg-vk(layer): Failed to get instance function pointer for {}", name); + Log::error("layer", "Failed to get instance function pointer for {}", name); return false; } return true; @@ -61,7 +61,7 @@ namespace { bool initDeviceFunc(VkDevice device, const char* name, T* func) { *func = reinterpret_cast(next_vkGetDeviceProcAddr(device, name)); if (!*func) { - Log::error("lsfg-vk(layer): Failed to get device function pointer for {}", name); + Log::error("layer", "Failed to get device function pointer for {}", name); return false; } return true; @@ -74,7 +74,7 @@ namespace { const VkInstanceCreateInfo* pCreateInfo, const VkAllocationCallbacks* pAllocator, VkInstance* pInstance) { - Log::debug("lsfg-vk(layer): Initializing lsfg-vk instance layer"); + Log::debug("layer", "Initializing lsfg-vk instance layer..."); // find layer creation info auto* layerDesc = const_cast( @@ -85,12 +85,15 @@ namespace { reinterpret_cast(layerDesc->pNext)); } if (!layerDesc) { - Log::error("lsfg-vk(layer): No layer creation info found in pNext chain"); + Log::error("layer", "No layer creation info found in pNext chain"); return VK_ERROR_INITIALIZATION_FAILED; } // advance link info (i don't really know what this does) next_vkGetInstanceProcAddr = layerDesc->u.pLayerInfo->pfnNextGetInstanceProcAddr; + Log::debug("layer", "Next instance proc addr: {:x}", + reinterpret_cast(next_vkGetInstanceProcAddr)); + layerDesc->u.pLayerInfo = layerDesc->u.pLayerInfo->pNext; // create instance @@ -101,7 +104,7 @@ namespace { Hooks::hooks["vkCreateInstance"]); auto res = layer_vkCreateInstance2(pCreateInfo, pAllocator, pInstance); if (res != VK_SUCCESS) { - Log::error("lsfg-vk(layer): Failed to create Vulkan instance: {:x}", + Log::error("layer", "Failed to create Vulkan instance: {:x}", static_cast(res)); return res; } @@ -112,11 +115,11 @@ namespace { success &= initInstanceFunc(*pInstance, "vkGetPhysicalDeviceQueueFamilyProperties", &next_vkGetPhysicalDeviceQueueFamilyProperties); success &= initInstanceFunc(*pInstance, "vkGetPhysicalDeviceMemoryProperties", &next_vkGetPhysicalDeviceMemoryProperties); if (!success) { - Log::error("lsfg-vk(layer): Failed to get instance function pointers"); + Log::error("layer", "Failed to get instance function pointers"); return VK_ERROR_INITIALIZATION_FAILED; } - Log::debug("lsfg-vk(layer): Successfully initialized lsfg-vk instance layer"); + Log::debug("layer", "Successfully initialized lsfg-vk instance layer"); return res; } // NOLINTEND @@ -125,7 +128,7 @@ namespace { const VkDeviceCreateInfo* pCreateInfo, const VkAllocationCallbacks* pAllocator, VkDevice* pDevice) { - Log::debug("lsfg-vk(layer): Initializing lsfg-vk device layer"); + Log::debug("layer", "Initializing lsfg-vk device layer..."); // find layer creation info auto* layerDesc = const_cast( @@ -136,24 +139,26 @@ namespace { reinterpret_cast(layerDesc->pNext)); } if (!layerDesc) { - Log::error("lsfg-vk(layer): No layer creation info found in pNext chain"); + Log::error("layer", "No layer creation info found in pNext chain"); return VK_ERROR_INITIALIZATION_FAILED; } // advance link info (i don't really know what this does) next_vkGetDeviceProcAddr = layerDesc->u.pLayerInfo->pfnNextGetDeviceProcAddr; + Log::debug("layer", "Next device proc addr: {:x}", + reinterpret_cast(next_vkGetDeviceProcAddr)); + layerDesc->u.pLayerInfo = layerDesc->u.pLayerInfo->pNext; // create device - auto success = initInstanceFunc(nullptr, "vkCreateDevice", - &next_vkCreateDevice); + auto success = initInstanceFunc(nullptr, "vkCreateDevice", &next_vkCreateDevice); if (!success) return VK_ERROR_INITIALIZATION_FAILED; auto* layer_vkCreateDevice2 = reinterpret_cast( Hooks::hooks["vkCreateDevicePre"]); auto res = layer_vkCreateDevice2(physicalDevice, pCreateInfo, pAllocator, pDevice); if (res != VK_SUCCESS) { - Log::error("lsfg-vk(layer): Failed to create Vulkan device: {:x}", + Log::error("layer", "Failed to create Vulkan device: {:x}", static_cast(res)); return res; } @@ -187,7 +192,7 @@ namespace { success &= initDeviceFunc(*pDevice, "vkCmdCopyImage", &next_vkCmdCopyImage); success &= initDeviceFunc(*pDevice, "vkAcquireNextImageKHR", &next_vkAcquireNextImageKHR); if (!success) { - Log::error("lsfg-vk(layer): Failed to get device function pointers"); + Log::error("layer", "Failed to get device function pointers"); return VK_ERROR_INITIALIZATION_FAILED; } @@ -195,12 +200,12 @@ namespace { Hooks::hooks["vkCreateDevicePost"]); res = layer_vkCreateDevice2(physicalDevice, pCreateInfo, pAllocator, pDevice); if (res != VK_SUCCESS) { - Log::error("lsfg-vk(layer): Failed to create Vulkan device: {:x}", + Log::error("layer", "Failed to create Vulkan device: {:x}", static_cast(res)); return res; } - Log::debug("lsfg-vk(layer): Successfully initialized lsfg-vk device layer"); + Log::debug("layer", "Successfully initialized lsfg-vk device layer"); return res; } // NOLINTEND } @@ -217,16 +222,16 @@ const std::unordered_map layerFunctions = { }; PFN_vkVoidFunction layer_vkGetInstanceProcAddr(VkInstance instance, const char* pName) { - std::string name(pName); + const std::string name(pName); auto it = layerFunctions.find(name); if (it != layerFunctions.end()) { - Log::debug("lsfg-vk(layer): Inserted layer function for {}", name); + Log::debug("layer", "Inserted layer function for {}", name); return it->second; } it = Hooks::hooks.find(name); if (it != Hooks::hooks.end()) { - Log::debug("lsfg-vk(layer): Inserted hook function for {}", name); + Log::debug("layer", "Inserted hook function for {}", name); return it->second; } @@ -234,16 +239,16 @@ PFN_vkVoidFunction layer_vkGetInstanceProcAddr(VkInstance instance, const char* } PFN_vkVoidFunction layer_vkGetDeviceProcAddr(VkDevice device, const char* pName) { - std::string name(pName); + const std::string name(pName); auto it = layerFunctions.find(name); if (it != layerFunctions.end()) { - Log::debug("lsfg-vk(layer): Inserted layer function for {}", name); + Log::debug("layer", "Inserted layer function for {}", name); return it->second; } it = Hooks::hooks.find(name); if (it != Hooks::hooks.end()) { - Log::debug("lsfg-vk(layer): Inserted hook function for {}", name); + Log::debug("layer", "Inserted hook function for {}", name); return it->second; } @@ -252,15 +257,29 @@ PFN_vkVoidFunction layer_vkGetDeviceProcAddr(VkDevice device, const char* pName) // original functions +#pragma clang diagnostic push +#pragma clang diagnostic ignored "-Wunsafe-buffer-usage" +// NOLINTBEGIN + VkResult Layer::ovkCreateInstance( const VkInstanceCreateInfo* pCreateInfo, const VkAllocationCallbacks* pAllocator, VkInstance* pInstance) { - return next_vkCreateInstance(pCreateInfo, pAllocator, pInstance); + Log::debug("vulkan", "vkCreateInstance called with {} extensions:", + pCreateInfo->enabledExtensionCount); + for (uint32_t i = 0; i < pCreateInfo->enabledExtensionCount; ++i) + Log::debug("vulkan", " - {}", pCreateInfo->ppEnabledExtensionNames[i]); + auto res = next_vkCreateInstance(pCreateInfo, pAllocator, pInstance); + Log::debug("vulkan", "vkCreateInstance({}) returned handle {:x}", + static_cast(res), + reinterpret_cast(*pInstance)); + return res; } void Layer::ovkDestroyInstance( VkInstance instance, const VkAllocationCallbacks* pAllocator) { + Log::debug("vulkan", "vkDestroyInstance called for instance {:x}", + reinterpret_cast(instance)); next_vkDestroyInstance(instance, pAllocator); } @@ -269,12 +288,24 @@ VkResult Layer::ovkCreateDevice( const VkDeviceCreateInfo* pCreateInfo, const VkAllocationCallbacks* pAllocator, VkDevice* pDevice) { - return next_vkCreateDevice(physicalDevice, pCreateInfo, pAllocator, pDevice); + Log::debug("vulkan", "vkCreateDevice called with {} extensions:", + pCreateInfo->enabledExtensionCount); + for (uint32_t i = 0; i < pCreateInfo->enabledExtensionCount; ++i) + Log::debug("vulkan", " - {}", pCreateInfo->ppEnabledExtensionNames[i]); + auto res = next_vkCreateDevice(physicalDevice, pCreateInfo, pAllocator, pDevice); + Log::debug("vulkan", "vkCreateDevice({}) returned handle {:x}", + static_cast(res), + reinterpret_cast(*pDevice)); + return res; } void Layer::ovkDestroyDevice( VkDevice device, const VkAllocationCallbacks* pAllocator) { + Log::debug("vulkan", "vkDestroyDevice called for device {:x}", + reinterpret_cast(device)); next_vkDestroyDevice(device, pAllocator); + Log::debug("vulkan", "Device {:x} destroyed successfully", + reinterpret_cast(device)); } PFN_vkVoidFunction Layer::ovkGetInstanceProcAddr( @@ -293,17 +324,39 @@ VkResult Layer::ovkCreateSwapchainKHR( const VkSwapchainCreateInfoKHR* pCreateInfo, const VkAllocationCallbacks* pAllocator, VkSwapchainKHR* pSwapchain) { - return next_vkCreateSwapchainKHR(device, pCreateInfo, pAllocator, pSwapchain); + Log::debug("vulkan", "vkCreateSwapchainKHR called with {} images, extent: {}x{}", + pCreateInfo->minImageCount, pCreateInfo->imageExtent.width, pCreateInfo->imageExtent.height); + auto res = next_vkCreateSwapchainKHR(device, pCreateInfo, pAllocator, pSwapchain); + Log::debug("vulkan", "vkCreateSwapchainKHR({}) returned handle {:x}", + static_cast(res), + reinterpret_cast(*pSwapchain)); + return res; } VkResult Layer::ovkQueuePresentKHR( VkQueue queue, const VkPresentInfoKHR* pPresentInfo) { - return next_vkQueuePresentKHR(queue, pPresentInfo); + Log::debug("vulkan2", "vkQueuePresentKHR called with {} wait semaphores:", + pPresentInfo->waitSemaphoreCount); + for (uint32_t i = 0; i < pPresentInfo->waitSemaphoreCount; i++) + Log::debug("vulkan2", " - {:x}", reinterpret_cast(pPresentInfo->pWaitSemaphores[i])); + Log::debug("vulkan2", "and {} signal semaphores:", + pPresentInfo->swapchainCount); + for (uint32_t i = 0; i < pPresentInfo->swapchainCount; i++) + Log::debug("vulkan2", " - {:x}", reinterpret_cast(pPresentInfo->pSwapchains[i])); + Log::debug("vulkan2", "and queue: {:x}, image: {}", + reinterpret_cast(queue), + *pPresentInfo->pImageIndices); + auto res = next_vkQueuePresentKHR(queue, pPresentInfo); + Log::debug("vulkan2", "vkQueuePresentKHR({}) returned", + static_cast(res)); + return res; } void Layer::ovkDestroySwapchainKHR( VkDevice device, VkSwapchainKHR swapchain, const VkAllocationCallbacks* pAllocator) { + Log::debug("vulkan", "vkDestroySwapchainKHR called for swapchain {:x}", + reinterpret_cast(swapchain)); next_vkDestroySwapchainKHR(device, swapchain, pAllocator); } @@ -312,30 +365,48 @@ VkResult Layer::ovkGetSwapchainImagesKHR( VkSwapchainKHR swapchain, uint32_t* pSwapchainImageCount, VkImage* pSwapchainImages) { - return next_vkGetSwapchainImagesKHR(device, swapchain, pSwapchainImageCount, pSwapchainImages); + Log::debug("vulkan", "vkGetSwapchainImagesKHR called for swapchain {:x}", + reinterpret_cast(swapchain)); + auto res = next_vkGetSwapchainImagesKHR(device, swapchain, pSwapchainImageCount, pSwapchainImages); + Log::debug("vulkan", "vkGetSwapchainImagesKHR({}) returned {} images", + static_cast(res), + *pSwapchainImageCount); + return res; } VkResult Layer::ovkAllocateCommandBuffers( VkDevice device, const VkCommandBufferAllocateInfo* pAllocateInfo, VkCommandBuffer* pCommandBuffers) { - return next_vkAllocateCommandBuffers(device, pAllocateInfo, pCommandBuffers); + Log::debug("vulkan2", "vkAllocateCommandBuffers called for command pool {:x}", + reinterpret_cast(pAllocateInfo->commandPool)); + auto res = next_vkAllocateCommandBuffers(device, pAllocateInfo, pCommandBuffers); + Log::debug("vulkan2", "vkAllocateCommandBuffers({}) returned command buffer: {}", + static_cast(res), + reinterpret_cast(*pCommandBuffers)); + return res; } void Layer::ovkFreeCommandBuffers( VkDevice device, VkCommandPool commandPool, uint32_t commandBufferCount, const VkCommandBuffer* pCommandBuffers) { + Log::debug("vulkan2", "vkFreeCommandBuffers called for command buffer: {:x}", + reinterpret_cast(*pCommandBuffers)); next_vkFreeCommandBuffers(device, commandPool, commandBufferCount, pCommandBuffers); } VkResult Layer::ovkBeginCommandBuffer( VkCommandBuffer commandBuffer, const VkCommandBufferBeginInfo* pBeginInfo) { + Log::debug("vulkan2", "vkBeginCommandBuffer called for command buffer {:x}", + reinterpret_cast(commandBuffer)); return next_vkBeginCommandBuffer(commandBuffer, pBeginInfo); } VkResult Layer::ovkEndCommandBuffer( VkCommandBuffer commandBuffer) { + Log::debug("vulkan2", "vkEndCommandBuffer called for command buffer {:x}", + reinterpret_cast(commandBuffer)); return next_vkEndCommandBuffer(commandBuffer); } @@ -344,12 +415,19 @@ VkResult Layer::ovkCreateCommandPool( const VkCommandPoolCreateInfo* pCreateInfo, const VkAllocationCallbacks* pAllocator, VkCommandPool* pCommandPool) { - return next_vkCreateCommandPool(device, pCreateInfo, pAllocator, pCommandPool); + Log::debug("vulkan", "vkCreateCommandPool called"); + auto res = next_vkCreateCommandPool(device, pCreateInfo, pAllocator, pCommandPool); + Log::debug("vulkan", "vkCreateCommandPool({}) returned handle {:x}", + static_cast(res), + reinterpret_cast(*pCommandPool)); + return res; } void Layer::ovkDestroyCommandPool( VkDevice device, VkCommandPool commandPool, const VkAllocationCallbacks* pAllocator) { + Log::debug("vulkan", "vkDestroyCommandPool called for command pool {:x}", + reinterpret_cast(commandPool)); next_vkDestroyCommandPool(device, commandPool, pAllocator); } @@ -358,12 +436,22 @@ VkResult Layer::ovkCreateImage( const VkImageCreateInfo* pCreateInfo, const VkAllocationCallbacks* pAllocator, VkImage* pImage) { - return next_vkCreateImage(device, pCreateInfo, pAllocator, pImage); + Log::debug("vulkan", "vkCreateImage called with format: {}, extent: {}x{}, usage: {}", + static_cast(pCreateInfo->format), + pCreateInfo->extent.width, pCreateInfo->extent.height, + static_cast(pCreateInfo->usage)); + auto res = next_vkCreateImage(device, pCreateInfo, pAllocator, pImage); + Log::debug("vulkan", "vkCreateImage({}) returned handle {:x}", + static_cast(res), + reinterpret_cast(*pImage)); + return res; } void Layer::ovkDestroyImage( VkDevice device, VkImage image, const VkAllocationCallbacks* pAllocator) { + Log::debug("vulkan", "vkDestroyImage called for image {:x}", + reinterpret_cast(image)); next_vkDestroyImage(device, image, pAllocator); } @@ -371,6 +459,8 @@ void Layer::ovkGetImageMemoryRequirements( VkDevice device, VkImage image, VkMemoryRequirements* pMemoryRequirements) { + Log::debug("vulkan", "vkGetImageMemoryRequirements called for image {:x}", + reinterpret_cast(image)); next_vkGetImageMemoryRequirements(device, image, pMemoryRequirements); } VkResult Layer::ovkBindImageMemory( @@ -378,7 +468,14 @@ VkResult Layer::ovkBindImageMemory( VkImage image, VkDeviceMemory memory, VkDeviceSize memoryOffset) { - return next_vkBindImageMemory(device, image, memory, memoryOffset); + Log::debug("vulkan", "vkBindImageMemory called for image {:x}, memory {:x}, offset: {}", + reinterpret_cast(image), + reinterpret_cast(memory), + memoryOffset); + auto res = next_vkBindImageMemory(device, image, memory, memoryOffset); + Log::debug("vulkan", "vkBindImageMemory({}) returned", + static_cast(res)); + return res; } VkResult Layer::ovkAllocateMemory( @@ -386,12 +483,21 @@ VkResult Layer::ovkAllocateMemory( const VkMemoryAllocateInfo* pAllocateInfo, const VkAllocationCallbacks* pAllocator, VkDeviceMemory* pMemory) { - return next_vkAllocateMemory(device, pAllocateInfo, pAllocator, pMemory); + Log::debug("vulkan", "vkAllocateMemory called with size: {}, memory type index: {}", + pAllocateInfo->allocationSize, + pAllocateInfo->memoryTypeIndex); + auto res = next_vkAllocateMemory(device, pAllocateInfo, pAllocator, pMemory); + Log::debug("vulkan", "vkAllocateMemory({}) returned handle {:x}", + static_cast(res), + reinterpret_cast(*pMemory)); + return res; } void Layer::ovkFreeMemory( VkDevice device, VkDeviceMemory memory, const VkAllocationCallbacks* pAllocator) { + Log::debug("vulkan", "vkFreeMemory called for memory {:x}", + reinterpret_cast(memory)); next_vkFreeMemory(device, memory, pAllocator); } @@ -400,12 +506,20 @@ VkResult Layer::ovkCreateSemaphore( const VkSemaphoreCreateInfo* pCreateInfo, const VkAllocationCallbacks* pAllocator, VkSemaphore* pSemaphore) { - return next_vkCreateSemaphore(device, pCreateInfo, pAllocator, pSemaphore); + Log::debug("vulkan2", "vkCreateSemaphore called", + static_cast(pCreateInfo->flags)); + auto res = next_vkCreateSemaphore(device, pCreateInfo, pAllocator, pSemaphore); + Log::debug("vulkan2", "vkCreateSemaphore({}) returned handle {:x}", + static_cast(res), + reinterpret_cast(*pSemaphore)); + return res; } void Layer::ovkDestroySemaphore( VkDevice device, VkSemaphore semaphore, const VkAllocationCallbacks* pAllocator) { + Log::debug("vulkan2", "vkDestroySemaphore called for semaphore {:x}", + reinterpret_cast(semaphore)); next_vkDestroySemaphore(device, semaphore, pAllocator); } @@ -413,24 +527,39 @@ VkResult Layer::ovkGetMemoryFdKHR( VkDevice device, const VkMemoryGetFdInfoKHR* pGetFdInfo, int* pFd) { - return next_vkGetMemoryFdKHR(device, pGetFdInfo, pFd); + Log::debug("vulkan", "vkGetMemoryFdKHR called for memory {:x}, handle type: {}", + reinterpret_cast(pGetFdInfo->memory), + static_cast(pGetFdInfo->handleType)); + auto res = next_vkGetMemoryFdKHR(device, pGetFdInfo, pFd); + Log::debug("vulkan", "vkGetMemoryFdKHR({}) returned fd: {}", + static_cast(res), *pFd); + return res; } VkResult Layer::ovkGetSemaphoreFdKHR( VkDevice device, const VkSemaphoreGetFdInfoKHR* pGetFdInfo, int* pFd) { - return next_vkGetSemaphoreFdKHR(device, pGetFdInfo, pFd); + Log::debug("vulkan2", "vkGetSemaphoreFdKHR called for semaphore {:x}", + reinterpret_cast(pGetFdInfo->semaphore)); + auto res = next_vkGetSemaphoreFdKHR(device, pGetFdInfo, pFd); + Log::debug("vulkan2", "vkGetSemaphoreFdKHR({}) returned fd: {}", + static_cast(res), *pFd); + return res; } void Layer::ovkGetPhysicalDeviceQueueFamilyProperties( VkPhysicalDevice physicalDevice, uint32_t* pQueueFamilyPropertyCount, VkQueueFamilyProperties* pQueueFamilyProperties) { + Log::debug("vulkan", "vkGetPhysicalDeviceQueueFamilyProperties called for physical device {:x}", + reinterpret_cast(physicalDevice)); next_vkGetPhysicalDeviceQueueFamilyProperties(physicalDevice, pQueueFamilyPropertyCount, pQueueFamilyProperties); } void Layer::ovkGetPhysicalDeviceMemoryProperties( VkPhysicalDevice physicalDevice, VkPhysicalDeviceMemoryProperties* pMemoryProperties) { + Log::debug("vulkan", "vkGetPhysicalDeviceMemoryProperties called for physical device {:x}", + reinterpret_cast(physicalDevice)); next_vkGetPhysicalDeviceMemoryProperties(physicalDevice, pMemoryProperties); } @@ -439,6 +568,10 @@ void Layer::ovkGetDeviceQueue( uint32_t queueFamilyIndex, uint32_t queueIndex, VkQueue* pQueue) { + Log::debug("vulkan", "vkGetDeviceQueue called for device {:x}, queue family index: {}, queue index: {}", + reinterpret_cast(device), + queueFamilyIndex, + queueIndex); next_vkGetDeviceQueue(device, queueFamilyIndex, queueIndex, pQueue); } VkResult Layer::ovkQueueSubmit( @@ -446,7 +579,21 @@ VkResult Layer::ovkQueueSubmit( uint32_t submitCount, const VkSubmitInfo* pSubmits, VkFence fence) { - return next_vkQueueSubmit(queue, submitCount, pSubmits, fence); + Log::debug("vulkan2", "vkQueueSubmit called for queue {:x}, submitting: {} with wait semaphores:", + reinterpret_cast(queue), + reinterpret_cast(*pSubmits->pCommandBuffers)); + for (uint32_t i = 0; i < pSubmits->waitSemaphoreCount; ++i) + Log::debug("vulkan2", " - {:x}", reinterpret_cast(pSubmits->pWaitSemaphores[i])); + Log::debug("vulkan2", "and {} signal semaphores:", + pSubmits->waitSemaphoreCount); + for (uint32_t i = 0; i < submitCount; ++i) + Log::debug("vulkan2", " - {:x}", reinterpret_cast(pSubmits[i].pSignalSemaphores)); + Log::debug("vulkan2", "and fence: {:x}", + reinterpret_cast(fence)); + auto res = next_vkQueueSubmit(queue, submitCount, pSubmits, fence); + Log::debug("vulkan2", "vkQueueSubmit({}) returned", + static_cast(res)); + return res; } void Layer::ovkCmdPipelineBarrier( @@ -460,6 +607,16 @@ void Layer::ovkCmdPipelineBarrier( const VkBufferMemoryBarrier* pBufferMemoryBarriers, uint32_t imageMemoryBarrierCount, const VkImageMemoryBarrier* pImageMemoryBarriers) { + Log::debug("vulkan2", "vkCmdPipelineBarrier called for command buffer {:x}, src stage: {}, dst stage: {}, transitioning:", + reinterpret_cast(commandBuffer), + static_cast(srcStageMask), + static_cast(dstStageMask)); + for (uint32_t i = 0; i < imageMemoryBarrierCount; ++i) { + Log::debug("vulkan2", " - image {:x}, old layout: {}, new layout: {}", + reinterpret_cast(pImageMemoryBarriers[i].image), + static_cast(pImageMemoryBarriers[i].oldLayout), + static_cast(pImageMemoryBarriers[i].newLayout)); + } next_vkCmdPipelineBarrier(commandBuffer, srcStageMask, dstStageMask, dependencyFlags, memoryBarrierCount, pMemoryBarriers, bufferMemoryBarrierCount, pBufferMemoryBarriers, @@ -473,6 +630,10 @@ void Layer::ovkCmdCopyImage( VkImageLayout dstImageLayout, uint32_t regionCount, const VkImageCopy* pRegions) { + Log::debug("vulkan2", "vkCmdCopyImage called for command buffer {:x}, src image {:x}, dst image {:x}", + reinterpret_cast(commandBuffer), + reinterpret_cast(srcImage), + reinterpret_cast(dstImage)); next_vkCmdCopyImage(commandBuffer, srcImage, srcImageLayout, dstImage, dstImageLayout, regionCount, pRegions); } @@ -483,5 +644,17 @@ VkResult Layer::ovkAcquireNextImageKHR( VkSemaphore semaphore, VkFence fence, uint32_t* pImageIndex) { - return next_vkAcquireNextImageKHR(device, swapchain, timeout, semaphore, fence, pImageIndex); + Log::debug("vulkan", "vkAcquireNextImageKHR called for swapchain {:x}, timeout: {}, semaphore: {:x}, fence: {:x}", + reinterpret_cast(swapchain), + timeout, + reinterpret_cast(semaphore), + reinterpret_cast(fence)); + auto res = next_vkAcquireNextImageKHR(device, swapchain, timeout, semaphore, fence, pImageIndex); + Log::debug("vulkan", "vkAcquireNextImageKHR({}) returned image index: {}", + static_cast(res), + *pImageIndex); + return res; } + +#pragma clang diagnostic pop +// NOLINTEND diff --git a/src/utils/log.cpp b/src/utils/log.cpp new file mode 100644 index 0000000..21405d0 --- /dev/null +++ b/src/utils/log.cpp @@ -0,0 +1,43 @@ +#include "utils/log.hpp" + +#include +#include + +using namespace Log; + +bool Internal::isSetup{}; + +std::set Internal::debugModules; +bool Internal::debugAllModules{}; + +std::ofstream Internal::logFile; +std::mutex Internal::logMutex; + +void Internal::setup() { + if (isSetup) return; + isSetup = true; + + // open log file + const char* env_log_file = std::getenv("LSFG_LOG_FILE"); + if (env_log_file) { + std::ostringstream filename; + filename << getpid() << "_" << env_log_file; + logFile.open(filename.str(), std::ios::app); + } + + // parse debug modules + const char* env_log_debug = std::getenv("LSFG_LOG_DEBUG"); + if (!env_log_debug) + return; + const std::string debugModulesStr(env_log_debug); + + std::stringstream ss(debugModulesStr); + std::string item; + while (std::getline(ss, item, ',')) { + if (item == "all") { + debugAllModules = true; + return; + } + debugModules.insert(item); + } + } diff --git a/src/utils/utils.cpp b/src/utils/utils.cpp index b32e0e6..8621f76 100644 --- a/src/utils/utils.cpp +++ b/src/utils/utils.cpp @@ -1,4 +1,5 @@ #include "utils/utils.hpp" +#include "utils/log.hpp" #include "layer.hpp" #include @@ -44,8 +45,12 @@ std::vector Utils::addExtensions(const char* const* extensions, siz for (const auto& e : requiredExtensions) { auto it = std::ranges::find(ext, e); - if (it == ext.end()) + if (it == ext.end()) { + Log::debug("hooks-init", "Adding extension: {}", e); ext.push_back(e); + } else { + Log::debug("hooks-init", "Extension {} already present", e); + } } return ext; @@ -148,6 +153,8 @@ namespace { std::optional layersEnvironment; } +// TODO: more environment variables? what about explicit disable? + void Utils::storeLayerEnv() { const char* env = std::getenv("VK_INSTANCE_LAYERS"); if (env)