Robust logging using spdlog

shg8 · Feb 21, 2024 · 4ea6795 · 4ea6795
1 parent 69f3b7a
commit 4ea6795
Show file tree

Hide file tree

Showing 7 changed files with 69 additions and 31 deletions.
diff --git a/3dgs/GSScene.cpp b/3dgs/GSScene.cpp
@@ -10,6 +10,7 @@
 #include "../vulkan/Utils.h"
 #include "../vulkan/DescriptorSet.h"
 #include "../vulkan/pipelines/ComputePipeline.h"
+#include "spdlog/spdlog.h"
 
 struct VertexStorage {
     glm::vec3 position;
@@ -58,9 +59,8 @@ void GSScene::load(const std::shared_ptr<VulkanContext>&context) {
     vertexBuffer->uploadFrom(vertexStagingBuffer);
 
     auto endTime = std::chrono::high_resolution_clock::now();
-    std::cout << "Loaded " << filename << " in "
-            << std::chrono::duration_cast<std::chrono::milliseconds>(endTime - startTime).count() << "ms"
-            << std::endl;
+    spdlog::info("Loaded {} in {}ms", filename,
+                 std::chrono::duration_cast<std::chrono::milliseconds>(endTime - startTime).count());
 
     precomputeCov3D(context);
 }
@@ -176,5 +176,5 @@ void GSScene::precomputeCov3D(const std::shared_ptr<VulkanContext>&context) {
     commandBuffer->dispatch(numGroups, 1, 1);
     context->endOneTimeCommandBuffer(std::move(commandBuffer), VulkanContext::Queue::COMPUTE);
 
-    std::cout << "Precomputed Cov3D" << std::endl;
+    spdlog::info("Precomputed Cov3D");
 }
diff --git a/3dgs/Renderer.cpp b/3dgs/Renderer.cpp
@@ -13,6 +13,8 @@
 
 #include "../vulkan/Utils.h"
 
+#include <spdlog/spdlog.h>
+
 #define SORT_ALLOCATE_MULTIPLIER 10
 
 void Renderer::initialize() {
@@ -77,7 +79,8 @@ void Renderer::retrieveTimestamps() {
 }
 
 void Renderer::initializeVulkan() {
-    window = std::make_shared<Window>("Vulkan Splatting", 1920, 1080);
+    spdlog::debug("Initializing Vulkan");
+    window = std::make_shared<Window>("Vulkan Splatting", 800, 600);
     context = std::make_shared<VulkanContext>(Window::getRequiredInstanceExtensions(), std::vector<std::string>{},
                                               configuration.enableVulkanValidationLayers);
 
@@ -112,6 +115,7 @@ void Renderer::initializeVulkan() {
 }
 
 void Renderer::loadSceneToGPU() {
+    spdlog::debug("Loading scene to GPU");
     scene = std::make_shared<GSScene>(configuration.scene);
     scene->load(context);
 
@@ -120,6 +124,7 @@ void Renderer::loadSceneToGPU() {
 }
 
 void Renderer::createPreprocessPipeline() {
+    spdlog::debug("Creating preprocess pipeline");
     uniformBuffer = Buffer::uniform(context, sizeof(UniformBuffer));
     vertexAttributeBuffer = Buffer::storage(context, scene->getNumVertices() * sizeof(VertexAttributeBuffer), false);
     tileOverlapBuffer = Buffer::storage(context, scene->getNumVertices() * sizeof(uint32_t), false);
@@ -153,6 +158,7 @@ Renderer::Renderer(RendererConfiguration configuration) : configuration(std::mov
 }
 
 void Renderer::createGui() {
+    spdlog::debug("Creating GUI");
     if (!configuration.enableGui) {
         return;
     }
@@ -163,6 +169,7 @@ void Renderer::createGui() {
 }
 
 void Renderer::createPrefixSumPipeline() {
+    spdlog::debug("Creating prefix sum pipeline");
     prefixSumPingBuffer = Buffer::storage(context, scene->getNumVertices() * sizeof(uint32_t), false);
     prefixSumPongBuffer = Buffer::storage(context, scene->getNumVertices() * sizeof(uint32_t), false);
     totalSumBufferHost = Buffer::staging(context, sizeof(uint32_t));
@@ -181,6 +188,7 @@ void Renderer::createPrefixSumPipeline() {
 }
 
 void Renderer::createRadixSortPipeline() {
+    spdlog::debug("Creating radix sort pipeline");
     sortKBufferEven = Buffer::storage(context, scene->getNumVertices() * sizeof(uint64_t) * SORT_ALLOCATE_MULTIPLIER,
                                       false);
     sortKBufferOdd = Buffer::storage(context, scene->getNumVertices() * sizeof(uint64_t) * SORT_ALLOCATE_MULTIPLIER,
@@ -239,6 +247,7 @@ void Renderer::createRadixSortPipeline() {
 }
 
 void Renderer::createPreprocessSortPipeline() {
+    spdlog::debug("Creating preprocess sort pipeline");
     preprocessSortPipeline = std::make_shared<ComputePipeline>(context, "preprocess_sort");
     auto descriptorSet = std::make_shared<DescriptorSet>(context, FRAMES_IN_FLIGHT);
     descriptorSet->bindBufferToDescriptorSet(0, vk::DescriptorType::eStorageBuffer, vk::ShaderStageFlagBits::eCompute,
@@ -259,6 +268,7 @@ void Renderer::createPreprocessSortPipeline() {
 }
 
 void Renderer::createTileBoundaryPipeline() {
+    spdlog::debug("Creating tile boundary pipeline");
     auto [width, height] = window->getFramebufferSize();
     auto tileX = (width + 16 - 1) / 16;
     auto tileY = (height + 16 - 1) / 16;
@@ -280,6 +290,7 @@ void Renderer::createTileBoundaryPipeline() {
 }
 
 void Renderer::createRenderPipeline() {
+    spdlog::debug("Creating render pipeline");
     renderPipeline = std::make_shared<ComputePipeline>(context, "render");
     auto inputSet = std::make_shared<DescriptorSet>(context, FRAMES_IN_FLIGHT);
     inputSet->bindBufferToDescriptorSet(0, vk::DescriptorType::eStorageBuffer, vk::ShaderStageFlagBits::eCompute,
@@ -366,7 +377,7 @@ void Renderer::run() {
         auto now = std::chrono::high_resolution_clock::now();
         auto diff = std::chrono::duration_cast<std::chrono::milliseconds>(now - lastFpsTime).count();
         if (diff > 1000) {
-            std::cout << "FPS: " << fpsCounter << std::endl;
+            spdlog::debug("FPS: {}", fpsCounter);
             fpsCounter = 0;
             lastFpsTime = now;
         } else {
@@ -400,6 +411,7 @@ void Renderer::run() {
 }
 
 void Renderer::createCommandPool() {
+    spdlog::debug("Creating command pool");
     vk::CommandPoolCreateInfo poolInfo = {};
     poolInfo.queueFamilyIndex = context->queues[VulkanContext::Queue::COMPUTE].queueFamily;
     poolInfo.flags = vk::CommandPoolCreateFlagBits::eResetCommandBuffer;
@@ -408,6 +420,7 @@ void Renderer::createCommandPool() {
 }
 
 void Renderer::recordPreprocessCommandBuffer() {
+    spdlog::debug("Recording preprocess command buffer");
     vk::CommandBufferAllocateInfo allocateInfo = {commandPool.get(), vk::CommandBufferLevel::ePrimary, 1};
     auto buffers = context->device->allocateCommandBuffersUnique(allocateInfo);
     preprocessCommandBuffer = std::move(buffers[0]);

diff --git a/CMakeLists.txt b/CMakeLists.txt
@@ -50,6 +50,12 @@ FetchContent_Declare(libenvpp
 )
 FetchContent_MakeAvailable(libenvpp)
 
+FetchContent_Declare(spdlog
+        GIT_REPOSITORY https://github.com/gabime/spdlog.git
+        GIT_TAG v1.13.0
+)
+FetchContent_MakeAvailable(spdlog)
+
 FetchContent_Declare(imgui
         GIT_REPOSITORY https://github.com/ocornut/imgui.git
         GIT_TAG v1.90.3
@@ -145,6 +151,7 @@ target_include_directories(vulkan_splatting PUBLIC
         ${glm_SOURCE_DIR}
         ${imgui_SOURCE_DIR}
         ${imgui_SOURCE_DIR}/backends
+        ${spdlog_SOURCE_DIR}/include
 )
 
 target_link_libraries(vulkan_splatting PUBLIC glfw libenvpp::libenvpp)

diff --git a/main.cpp b/main.cpp
@@ -3,13 +3,17 @@
 
 #include "3dgs/Renderer.h"
 #include "args.hxx"
+#include "spdlog/spdlog.h"
 
 int main(int argc, char** argv) {
+    spdlog::set_pattern("[%H:%M:%S] [%^%L%$] %v");
+
     args::ArgumentParser parser("Vulkan Splatting");
     args::HelpFlag helpFlag{parser, "help", "Display this help menu", {'h', "help"}};
     args::Flag validationLayersFlag{
-        parser, "validation-layers", "Enable Vulkan validation layers", {'v', "validation-layers"}
+        parser, "validation-layers", "Enable Vulkan validation layers", {"validation"}
     };
+    args::Flag verboseFlag{parser, "verbose", "Enable verbose logging", {'v', "verbose"}};
     args::ValueFlag<uint8_t> physicalDeviceIdFlag{
         parser, "physical-device", "Select physical device by index", {'d', "device"}
     };
@@ -31,14 +35,8 @@ int main(int argc, char** argv) {
         return 0;
     }
     catch (const args::ParseError& e) {
-        std::cerr << e.what() << std::endl;
-        std::cerr << parser;
-        return 1;
-    }
-
-    if (!scenePath) {
-        std::cerr << "Scene path is required" << std::endl;
-        std::cerr << parser;
+        std::cout << e.what() << std::endl;
+        std::cout << parser;
         return 1;
     }
 
@@ -48,6 +46,10 @@ int main(int argc, char** argv) {
     auto immediateSwapchain = pre.register_variable<bool>("IMMEDIATE_SWAPCHAIN");
     auto envVars = pre.parse_and_validate();
 
+    if (args::get(verboseFlag)) {
+        spdlog::set_level(spdlog::level::debug);
+    }
+
     RendererConfiguration config{
         envVars.get_or(validationLayers, false),
         envVars.get(physicalDeviceId).has_value()
@@ -57,6 +59,12 @@ int main(int argc, char** argv) {
         args::get(scenePath)
     };
 
+    // check that the scene file exists
+    if (!std::filesystem::exists(config.scene)) {
+        spdlog::critical("File does not exist: {}", config.scene);
+        return 0;
+    }
+
     if (validationLayersFlag) {
         config.enableVulkanValidationLayers = args::get(validationLayersFlag);
     }
@@ -81,6 +89,7 @@ int main(int argc, char** argv) {
     renderer.run();
 #ifndef DEBUG
     } catch (const std::exception& e) {
+        spdlog::critical(e.what());
         std::cout << e.what() << std::endl;
         return 0;
     }

diff --git a/vulkan/Buffer.cpp b/vulkan/Buffer.cpp
@@ -103,7 +103,6 @@ void Buffer::downloadTo(std::shared_ptr<Buffer> buffer, vk::DeviceSize srcOffset
 
 Buffer::~Buffer() {
     vmaDestroyBuffer(context->allocator, buffer, allocation);
-    std::cout << "Destroyed buffer" << std::endl;
 }
 
 std::shared_ptr<Buffer> Buffer::uniform(std::shared_ptr<VulkanContext> context, uint32_t size, bool concurrentSharing) {

diff --git a/vulkan/Swapchain.cpp b/vulkan/Swapchain.cpp
@@ -1,5 +1,7 @@
 #include "Swapchain.h"
 
+#include "spdlog/spdlog.h"
+
 Swapchain::Swapchain(const std::shared_ptr<VulkanContext>&context, const std::shared_ptr<Window>&window,
                      bool immediate) : context(
                                            context), window(window), immediate(immediate) {
@@ -24,6 +26,7 @@ void Swapchain::createSwapchain() {
             break;
         }
     }
+    spdlog::debug("Surface format: {}", surfaceFormat.format);
 
     presentMode = vk::PresentModeKHR::eFifo;
     for (const auto&availablePresentMode: presentModes) {
@@ -37,6 +40,7 @@ void Swapchain::createSwapchain() {
             break;
         }
     }
+    spdlog::debug("Present mode: {}", presentMode);
 
     auto extent = capabilities.currentExtent;
     if (capabilities.currentExtent.width == UINT32_MAX) {
@@ -87,6 +91,7 @@ void Swapchain::createSwapchain() {
     swapchainFormat = surfaceFormat.format;
 
     swapchain = context->device->createSwapchainKHRUnique(createInfo);
+    spdlog::debug("Swapchain created");
 }
 
 void Swapchain::createSwapchainImages() {
@@ -120,4 +125,5 @@ void Swapchain::recreate() {
 
     createSwapchain();
     createSwapchainImages();
+    spdlog::debug("Swapchain recreated");
 }
diff --git a/vulkan/VulkanContext.cpp b/vulkan/VulkanContext.cpp
@@ -4,23 +4,13 @@
 #include <unordered_map>
 
 #include "Utils.h"
+#include <spdlog/spdlog.h>
 
 VULKAN_HPP_DEFAULT_DISPATCH_LOADER_DYNAMIC_STORAGE
 
 VkBool32 debugCallback(VkDebugUtilsMessageSeverityFlagBitsEXT messageSeverity,
                        VkDebugUtilsMessageTypeFlagsEXT messageType,
                        const VkDebugUtilsMessengerCallbackDataEXT* pCallbackData, void* pUserData) {
-    const char* severity = "???";
-    if (messageSeverity & VK_DEBUG_UTILS_MESSAGE_SEVERITY_VERBOSE_BIT_EXT) {
-        severity = "VERBOSE";
-    } else if (messageSeverity & VK_DEBUG_UTILS_MESSAGE_SEVERITY_INFO_BIT_EXT) {
-        severity = "INFO";
-    } else if (messageSeverity & VK_DEBUG_UTILS_MESSAGE_SEVERITY_WARNING_BIT_EXT) {
-        severity = "WARNING";
-    } else if (messageSeverity & VK_DEBUG_UTILS_MESSAGE_SEVERITY_ERROR_BIT_EXT) {
-        severity = "ERROR";
-    }
-
     const char* type = "???";
     if (messageType & VK_DEBUG_UTILS_MESSAGE_TYPE_GENERAL_BIT_EXT) {
         type = "GENERAL";
@@ -30,7 +20,16 @@ VkBool32 debugCallback(VkDebugUtilsMessageSeverityFlagBitsEXT messageSeverity,
         type = "PERFORMANCE";
     }
 
-    std::cerr << "[" << severity << "][" << type << "]: " << pCallbackData->pMessage << std::endl;
+    const char* severity = "???";
+    if (messageSeverity & VK_DEBUG_UTILS_MESSAGE_SEVERITY_VERBOSE_BIT_EXT) {
+        spdlog::debug("[{}]: {}",  type, pCallbackData->pMessage);
+    } else if (messageSeverity & VK_DEBUG_UTILS_MESSAGE_SEVERITY_INFO_BIT_EXT) {
+        spdlog::info("[{}]: {}", type, pCallbackData->pMessage);
+    } else if (messageSeverity & VK_DEBUG_UTILS_MESSAGE_SEVERITY_WARNING_BIT_EXT) {
+        spdlog::warn("[{}]: {}", type, pCallbackData->pMessage);
+    } else if (messageSeverity & VK_DEBUG_UTILS_MESSAGE_SEVERITY_ERROR_BIT_EXT) {
+        spdlog::critical("[{}]: {}", type, pCallbackData->pMessage);
+    }
 
     return VK_FALSE;
 }
@@ -92,6 +91,7 @@ void VulkanContext::createInstance() {
 
     instance = vk::createInstanceUnique(createInfoChain.get<vk::InstanceCreateInfo>());
     VULKAN_HPP_DEFAULT_DISPATCHER.init(*instance);
+    spdlog::debug("Vulkan instance created");
 }
 
 bool VulkanContext::isDeviceSuitable(vk::PhysicalDevice device, std::optional<vk::SurfaceKHR> surface) {
@@ -128,17 +128,19 @@ void VulkanContext::selectPhysicalDevice(std::optional<uint8_t> id, std::optiona
     }
     auto devices = instance->enumeratePhysicalDevices();
 
+
+    spdlog::info("Available physical devices:");
     int ind = 0;
     for (auto& device: devices) {
-        std::cout << "[" << ind++ << "] " << device.getProperties().deviceName << std::endl;
+        spdlog::info("[{}] {}", ind++, device.getProperties().deviceName);
     }
 
     if (id.has_value()) {
         if (devices.size() <= id.value()) {
             throw std::runtime_error("Invalid physical device id");
         }
         physicalDevice = devices[id.value()];
-        std::cout << "Selected physical device (by index): " << physicalDevice.getProperties().deviceName << std::endl;
+        spdlog::info("Selected physical device (by index): {}", physicalDevice.getProperties().deviceName);
         return;
     }
 
@@ -162,7 +164,7 @@ void VulkanContext::selectPhysicalDevice(std::optional<uint8_t> id, std::optiona
         }
     }
 
-    std::cout << "Selected physical device (automatically): " << physicalDevice.getProperties().deviceName << std::endl;
+    spdlog::info("Selected physical device (automatically): {}", physicalDevice.getProperties().deviceName);
 }
 
 VulkanContext::QueueFamilyIndices VulkanContext::findQueueFamilies() {
@@ -249,6 +251,8 @@ void VulkanContext::createLogicalDevice(vk::PhysicalDeviceFeatures deviceFeature
         }
     }
 
+    spdlog::debug("Logical device created");
+
     // Create VMA
     setupVma();
     createCommandPool();