From f58f3803503fe19e8153d1634bbcaf32fe45692a Mon Sep 17 00:00:00 2001
From: Tobias Frisch <tfrisch@uni-koblenz.de>
Date: Fri, 11 Aug 2023 15:13:06 +0200
Subject: [PATCH] Add log level for printing durations
Signed-off-by: Tobias Frisch <tfrisch@uni-koblenz.de>
---
include/vkcv/Logger.hpp | 20 +++++++++++++++++++
projects/indirect_draw/src/main.cpp | 30 +++++++++++++++++++++++++++++
2 files changed, 50 insertions(+)
diff --git a/include/vkcv/Logger.hpp b/include/vkcv/Logger.hpp
index 8a366b26..57e3a841 100644
--- a/include/vkcv/Logger.hpp
+++ b/include/vkcv/Logger.hpp
@@ -5,8 +5,10 @@
* @brief Logging macro function to print line of code specific information.
*/
+#include <bits/chrono.h>
#include <cstdio>
#include <exception>
+#include <chrono>
namespace vkcv {
@@ -14,6 +16,7 @@ namespace vkcv {
* @brief Enum class to specify the level of logging.
*/
enum class LogLevel {
+ TIME,
RAW_INFO,
INFO,
WARNING,
@@ -29,6 +32,7 @@ namespace vkcv {
*/
constexpr auto getLogOutput(LogLevel level) {
switch (level) {
+ case LogLevel::TIME:
case LogLevel::RAW_INFO:
case LogLevel::INFO:
return stdout;
@@ -46,6 +50,8 @@ namespace vkcv {
*/
constexpr const char* getLogName(LogLevel level) {
switch (level) {
+ case LogLevel::TIME:
+ return "TIME";
case LogLevel::RAW_INFO:
case LogLevel::INFO:
return "INFO";
@@ -58,6 +64,16 @@ namespace vkcv {
}
}
+ inline unsigned long getLogTime() {
+ const auto time_point = std::chrono::high_resolution_clock::now();
+ static auto last_time_point = time_point;
+
+ const auto duration = (time_point - last_time_point);
+ last_time_point = time_point;
+
+ return std::chrono::duration_cast<std::chrono::milliseconds>(duration).count();
+ }
+
#ifndef NDEBUG
#ifndef VKCV_DEBUG_MESSAGE_LEN
#define VKCV_DEBUG_MESSAGE_LEN 1024
@@ -78,6 +94,10 @@ namespace vkcv {
char output_message [VKCV_DEBUG_MESSAGE_LEN]; \
snprintf(output_message, VKCV_DEBUG_MESSAGE_LEN, __VA_ARGS__); \
auto output = getLogOutput(level); \
+ if (level == vkcv::LogLevel::TIME) { \
+ fprintf(output, "[%s]: %s (%lums)\n", vkcv::getLogName(level), \
+ output_message, vkcv::getLogTime()); \
+ } else \
if (level != vkcv::LogLevel::RAW_INFO) { \
fprintf(output, "[%s]: %s [%s, line %d: %s]\n", vkcv::getLogName(level), \
output_message, __FILE__, __LINE__, __PRETTY_FUNCTION__); \
diff --git a/projects/indirect_draw/src/main.cpp b/projects/indirect_draw/src/main.cpp
index 6aa0f362..424f2e07 100644
--- a/projects/indirect_draw/src/main.cpp
+++ b/projects/indirect_draw/src/main.cpp
@@ -270,6 +270,8 @@ void compileMeshForIndirectDraw(vkcv::Core &core,
int main(int argc, const char** argv) {
const std::string applicationName = "Indirect draw";
+ vkcv_log(vkcv::LogLevel::TIME, "Startup");
+
vkcv::Features features;
features.requireExtension(VK_KHR_SWAPCHAIN_EXTENSION_NAME);
features.requireFeature([](vk::PhysicalDeviceFeatures &features){
@@ -311,6 +313,8 @@ int main(int argc, const char** argv) {
}
);
+ vkcv_log(vkcv::LogLevel::TIME, "Features configured");
+
vkcv::Core core = vkcv::Core::create(
applicationName,
VK_MAKE_VERSION(0, 0, 1),
@@ -318,15 +322,23 @@ int main(int argc, const char** argv) {
features
);
+ vkcv_log(vkcv::LogLevel::TIME, "Core created");
+
vkcv::WindowHandle windowHandle = core.createWindow(applicationName,800,600,true);
vkcv::Window& window = core.getWindow(windowHandle);
+ vkcv_log(vkcv::LogLevel::TIME, "Window created");
+
vkcv::gui::GUI gui (core, windowHandle);
+ vkcv_log(vkcv::LogLevel::TIME, "GUI initialized");
+
vkcv::asset::Scene asset_scene;
const char* path = argc > 1 ? argv[1] : "resources/Sponza/Sponza.gltf";
int result = vkcv::asset::loadScene(path, asset_scene);
+ vkcv_log(vkcv::LogLevel::TIME, "Scene loaded");
+
if (result == 1) {
std::cout << "Loading Sponza successful!" << std::endl;
} else {
@@ -351,6 +363,7 @@ int main(int argc, const char** argv) {
return EXIT_FAILURE;
}
+ vkcv_log(vkcv::LogLevel::TIME, "Scene verified");
vkcv::ShaderProgram sponzaProgram;
vkcv::shader::GLSLCompiler compiler;
@@ -364,12 +377,16 @@ int main(int argc, const char** argv) {
{ vkcv::ShaderStage::COMPUTE, std::filesystem::path("resources/shaders/culling.comp") },
}, nullptr);
+ vkcv_log(vkcv::LogLevel::TIME, "Shaders compiled");
+
// vertex layout for the pipeline. (assumed to be) used by all sponza meshes.
const std::vector<vkcv::VertexAttachment> vertexAttachments = sponzaProgram.getVertexAttachments();
const vkcv::VertexLayout sponzaVertexLayout {
{ vkcv::createVertexBinding(0, { vertexAttachments }) }
};
+ vkcv_log(vkcv::LogLevel::TIME, "Vertex layout configured");
+
std::vector<uint8_t> compiledVertexBuffer; // IGNORED, since the vertex buffer is not interleaved!
std::vector<uint8_t> compiledIndexBuffer;
@@ -382,12 +399,16 @@ int main(int argc, const char** argv) {
compiledIndexBuffer,
compiledMaterial,
indexedIndirectCommands);
+
+ vkcv_log(vkcv::LogLevel::TIME, "Mesh compiled");
std::vector<std::vector<Vertex>> interleavedVertices;
std::vector<glm::vec4> compiledBoundingBoxBuffer;
interleaveScene(asset_scene,
interleavedVertices,
compiledBoundingBoxBuffer);
+
+ vkcv_log(vkcv::LogLevel::TIME, "Scene interleaved");
std::vector<Vertex> compiledInterleavedVertexBuffer;
for(auto& vertexGroup : interleavedVertices )
@@ -435,6 +456,8 @@ int main(int argc, const char** argv) {
);
modelBuffer.fill(modelMatrix);
+ vkcv_log(vkcv::LogLevel::TIME, "Buffers filled");
+
const std::vector<vkcv::VertexBufferBinding> vertexBufferBindings = {
vkcv::vertexBufferBinding(vkCompiledVertexBuffer)
};
@@ -464,6 +487,8 @@ int main(int argc, const char** argv) {
setWrites.writeStorageBuffer(1, modelBuffer.getHandle());
core.writeDescriptorSet(descriptorSet, setWrites);
+ vkcv_log(vkcv::LogLevel::TIME, "DescriptorSets written");
+
vkcv::GraphicsPipelineHandle sponzaPipelineHandle = core.createGraphicsPipeline(
vkcv::GraphicsPipelineConfig(
sponzaProgram,
@@ -478,6 +503,8 @@ int main(int argc, const char** argv) {
return EXIT_FAILURE;
}
+ vkcv_log(vkcv::LogLevel::TIME, "Graphics pipeline created");
+
vkcv::DescriptorBindings cullingBindings = cullingProgram.getReflectedDescriptors().at(0);
vkcv::DescriptorSetLayoutHandle cullingSetLayout = core.createDescriptorSetLayout(cullingBindings);
vkcv::DescriptorSetHandle cullingDescSet = core.createDescriptorSet(cullingSetLayout);
@@ -493,6 +520,7 @@ int main(int argc, const char** argv) {
cullingWrites.writeUniformBuffer(0, cameraPlaneBuffer.getHandle());
core.writeDescriptorSet(cullingDescSet, cullingWrites);
+ vkcv_log(vkcv::LogLevel::TIME, "Culling descriptor set written");
const vkcv::ComputePipelineConfig computeCullingConfig {
cullingProgram,
@@ -504,6 +532,8 @@ int main(int argc, const char** argv) {
return EXIT_FAILURE;
}
+ vkcv_log(vkcv::LogLevel::TIME, "Compute pipeline created");
+
vkcv::camera::CameraManager cameraManager (window);
auto camHandle = cameraManager.addCamera(vkcv::camera::ControllerType::PILOT);
--
GitLab