Add log level for printing durations

Signed-off-by: Tobias Frisch <tfrisch@uni-koblenz.de>

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__);        \

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);