Implement basic in-engine timing

src/editor/src/gui/core.cpp

@@ -18,6 +18,7 @@
 #include "engine/assets/model/Model.hpp"
 #include "engine/debug/DEBUG_NAMES.hpp"
 #include "engine/debug/profiling/counters.hpp"
+#include "engine/debug/timing/FlameGraph.hpp"
 #include "engine/descriptors/DescriptorPool.hpp"
 #include "engine/rendering/Renderer.hpp"
 #include "engine/tree/octtree/OctTreeNode.hpp"
@@ -170,13 +171,15 @@ namespace fgl::engine::gui
 	void startDrawImGui( [[maybe_unused]] FrameInfo& info )
 	{
 		beginImGui();
+
 		profiling::resetCounters();
 	}
 
 	void drawImGui( FrameInfo& info )
 	{
 		ZoneScoped;
-		// ImGui::ShowDemoWindow();
+		auto timer = debug::timing::push( "Draw ImGui" );
+		ImGui::ShowDemoWindow();
 
 		drawDock();
 

src/editor/src/gui/drawStats.cpp

@@ -3,6 +3,7 @@
 
 #include "core.hpp"
 #include "engine/debug/profiling/counters.hpp"
+#include "engine/debug/timing/FlameGraph.hpp"
 #include "engine/flags.hpp"
 #include "engine/math/literals/size.hpp"
 #include "engine/memory/buffers/Buffer.hpp"
@@ -65,18 +66,25 @@ namespace fgl::engine::gui
 
 		using namespace literals::size_literals;
 
-		ImGui::Text( "Device" );
-		ImGui::Text( "|- %s Allocated", to_string( gpu_allocated ).c_str() );
-		ImGui::Text( "|- %s Used ", to_string( gpu_used ).c_str() );
-		ImGui::Text( "|- %s Unused", to_string( gpu.free() ).c_str() );
-		ImGui::Text( "|- %s Available in most allocated buffer", to_string( gpu.m_largest_free_block ).c_str() );
+		if ( ImGui::TreeNode( "Device" ) )
+		{
+			ImGui::Text( "|- %s Allocated", to_string( gpu_allocated ).c_str() );
+			ImGui::Text( "|- %s Used ", to_string( gpu_used ).c_str() );
+			ImGui::Text( "|- %s Unused", to_string( gpu.free() ).c_str() );
+			ImGui::Text( "|- %s Available in most allocated buffer", to_string( gpu.m_largest_free_block ).c_str() );
+			ImGui::TreePop();
+		}
 
 		ImGui::Separator();
-		ImGui::Text( "Host" );
-		ImGui::Text( "|- %s Allocated", to_string( host_allocated ).c_str() );
-		ImGui::Text( "|- %s Used ", to_string( host_used ).c_str() );
-		ImGui::Text( "|- %s Unused", to_string( host.free() ).c_str() );
-		ImGui::Text( "|- %s Available in most allocated buffer", to_string( host.m_largest_free_block ).c_str() );
+
+		if ( ImGui::TreeNode( "Host" ) )
+		{
+			ImGui::Text( "|- %s Allocated", to_string( host_allocated ).c_str() );
+			ImGui::Text( "|- %s Used ", to_string( host_used ).c_str() );
+			ImGui::Text( "|- %s Unused", to_string( host.free() ).c_str() );
+			ImGui::Text( "|- %s Available in most allocated buffer", to_string( host.m_largest_free_block ).c_str() );
+			ImGui::TreePop();
+		}
 		ImGui::Separator();
 
 		if ( ImGui::CollapsingHeader( "Buffers" ) )
@@ -110,6 +118,11 @@ namespace fgl::engine::gui
 			drawMemoryStats();
 		}
 
+		if ( ImGui::CollapsingHeader( "Timings" ) )
+		{
+			debug::timing::render();
+		}
+
 		imGuiOctTreeSettings( info );
 
 		if ( ImGui::Button( "Reload shaders" ) )

src/editor/src/main.cpp

@@ -5,6 +5,7 @@
 
 #include "engine/EngineContext.hpp"
 #include "engine/camera/CameraManager.hpp"
+#include "engine/debug/timing/FlameGraph.hpp"
 #include "engine/gameobjects/components/CameraComponent.hpp"
 #include "gui/core.hpp"
 
@@ -33,6 +34,7 @@ int main()
 	//! Will be true until the window says it wants to close.
 	while ( engine_ctx.good() )
 	{
+		debug::timing::reset();
 		engine_ctx.tickDeltaTime();
 
 		engine_ctx.handleTransfers();
@@ -51,6 +53,8 @@ int main()
 		engine_ctx.renderFrame();
 
 		engine_ctx.finishFrame();
+		// This will 'end' the root node, Which is created on 'reset'
+		debug::timing::internal::pop();
 	}
 
 	return EXIT_SUCCESS;

src/engine/EngineContext.cpp

@@ -15,6 +15,7 @@
 #include "camera/Camera.hpp"
 #include "camera/CameraManager.hpp"
 #include "camera/CameraRenderer.hpp"
+#include "debug/timing/FlameGraph.hpp"
 #include "engine/assets/model/builders/SceneBuilder.hpp"
 #include "engine/assets/transfer/TransferManager.hpp"
 #include "engine/flags.hpp"
@@ -102,6 +103,7 @@ namespace fgl::engine
 
 	void EngineContext::processInput()
 	{
+		auto timer = debug::timing::push( "Process Inputs" );
 		glfwPollEvents();
 	}
 
@@ -120,6 +122,7 @@ namespace fgl::engine
 	void EngineContext::tickSimulation()
 	{
 		ZoneScoped;
+		auto timer = debug::timing::push( "Tick Simulation" );
 		// TODO: This is where we'll start doing physics stuff.
 		// The first step here should be culling things that aren't needed to be ticked.
 		// Perhaps implementing a tick system that doesn't care about the refresh rate might be good?
@@ -129,6 +132,7 @@ namespace fgl::engine
 	void EngineContext::renderCameras( FrameInfo frame_info )
 	{
 		ZoneScoped;
+		auto timer = debug::timing::push( "Render Cameras" );
 		for ( auto& current_camera_ptr : m_camera_manager.getCameras() )
 		{
 			if ( current_camera_ptr.expired() ) continue;
@@ -144,9 +148,9 @@ namespace fgl::engine
 	void EngineContext::renderFrame()
 	{
 		ZoneScoped;
-
 		if ( auto& command_buffer = m_renderer.beginFrame(); *command_buffer )
 		{
+			const auto timer = debug::timing::push( "Render Frame" );
 			const FrameIndex frame_index { m_renderer.getFrameIndex() };
 			const PresentIndex present_idx { m_renderer.getPresentIndex() };
 

src/engine/camera/Camera.cpp

@@ -11,6 +11,7 @@
 #include "CameraInfo.hpp"
 #include "CameraRenderer.hpp"
 #include "CameraSwapchain.hpp"
+#include "engine/debug/timing/FlameGraph.hpp"
 
 namespace fgl::engine
 {
@@ -67,6 +68,7 @@ namespace fgl::engine
 	void Camera::pass( FrameInfo& frame_info )
 	{
 		ZoneScopedN( "Camera::pass" );
+		auto timer = debug::timing::push( "Camera" );
 		if ( m_cold && m_swapchain )
 		{
 			//TODO: Make some way to destroy the swapchain in a deffered manner.

src/engine/clock.hpp

@@ -14,4 +14,6 @@ namespace fgl
 		std::chrono::high_resolution_clock,
 		std::chrono::steady_clock >;
 
-}
+	using profiling_clock = std::chrono::high_resolution_clock;
+
+} // namespace fgl

src/engine/debug/timing/FlameGraph.cpp

@@ -0,0 +1,190 @@
+//
+// Created by kj16609 on 10/29/24.
+//
+
+#include "FlameGraph.hpp"
+
+#include <cassert>
+#include <imgui.h>
+
+#include "engine/FGL_DEFINES.hpp"
+#include "engine/clock.hpp"
+#include "engine/debug/logging/logging.hpp"
+
+namespace fgl::engine::debug
+{
+
+	struct Node
+	{
+		std::string_view name { "" };
+		profiling_clock::time_point start {};
+		profiling_clock::time_point end {};
+		std::vector< Node > children {};
+		Node* parent { nullptr };
+		void drawImGui() const;
+
+		using duration = profiling_clock::duration;
+
+		duration getDuration() const { return end - start; }
+
+		duration getTotalTime() const
+		{
+			if ( parent != nullptr )
+				return parent->getTotalTime();
+			else
+				return getDuration();
+		}
+
+		Node() = default;
+
+		FGL_DELETE_COPY( Node );
+
+		Node( Node&& other ) :
+		  name( std::move( other.name ) ),
+		  start( other.start ),
+		  end( other.end ),
+		  children( std::move( other.children ) ),
+		  parent( other.parent )
+		{
+			for ( auto& child : children ) child.parent = this;
+		}
+
+		Node& operator=( Node&& other ) noexcept
+		{
+			name = std::move( other.name );
+			start = other.start;
+			end = other.end;
+			children = std::move( other.children );
+
+			for ( auto& child : children ) child.parent = this;
+
+			parent = other.parent;
+			return *this;
+		}
+	};
+
+	//! If true then the percentage will be of the total frame time instead of a percentage of the parent time
+	inline static bool percent_as_total { true };
+
+	void Node::drawImGui() const
+	{
+		const auto diff { end - start };
+
+		FGL_ASSERT( end > start, "Node ended before it began!" );
+
+		const auto time { getDuration() };
+
+		// Total runtime of the frame
+
+		double percent { 100.0f };
+
+		if ( percent_as_total )
+		{
+			const auto total_time { getTotalTime() };
+			percent = ( static_cast< double >( time.count() ) / static_cast< double >( total_time.count() ) ) * 100.0f;
+		}
+		else if ( parent )
+		{
+			const auto parent_time { this->parent->getDuration() };
+			percent = ( static_cast< double >( time.count() ) / static_cast< double >( parent_time.count() ) ) * 100.0f;
+		}
+
+		const std::string str { std::format(
+			"{} -- {:2.2f}ms, ({:2.2f}%)",
+			name,
+			( std::chrono::duration_cast< std::chrono::microseconds >( diff ).count() / 1000.0f ),
+			percent ) };
+
+		ImGuiTreeNodeFlags flags { ImGuiTreeNodeFlags_None };
+
+		if ( children.empty() ) flags |= ImGuiTreeNodeFlags_Leaf;
+
+		if ( ImGui::TreeNodeEx( name.data(), flags, str.c_str() ) )
+		{
+			for ( const auto& child : children ) child.drawImGui();
+
+			ImGui::TreePop();
+		}
+	}
+
+	inline static Node previous_root {};
+	inline static Node root {};
+	inline static Node* active { &root };
+
+	//TODO: Noop most of this so it won't hurt performance later when using a specific define set.
+
+	namespace timing
+	{
+		void reset()
+		{
+			previous_root = std::move( root );
+			root.name = "Update Time";
+			root.children.clear();
+			root.start = profiling_clock::now();
+			active = &root;
+		}
+
+		ScopedTimer push( const std::string_view name )
+		{
+			Node new_node {};
+			new_node.name = name;
+			new_node.parent = active;
+			new_node.start = profiling_clock::now();
+			assert( active );
+			active->children.emplace_back( std::move( new_node ) );
+			active = &active->children.back();
+			return {};
+		}
+
+		namespace internal
+		{
+			void pop()
+			{
+				auto getDepth = [ & ]() -> std::size_t
+				{
+					const Node* current { active };
+					std::size_t depth { 0 };
+					while ( current != nullptr )
+					{
+						current = current->parent;
+						++depth;
+					}
+					return depth;
+				};
+
+				std::string padding { "" };
+
+				for ( std::size_t i = 0; i < getDepth(); i++ )
+				{
+					padding += "\t";
+				}
+
+				FGL_ASSERT( active, "Active node in framegraph was null!" );
+				active->end = profiling_clock::now();
+
+				const auto diff { active->end - active->start };
+
+				FGL_ASSERT( diff >= decltype( diff ) { 0 }, "Popped node ended before it began!" );
+				FGL_ASSERT( active->end > active->start, "Node ended before it began!" );
+
+				active = active->parent;
+			}
+		} // namespace internal
+
+		void render()
+		{
+			ImGui::Checkbox( "Percentage of frame time", &percent_as_total );
+			ImGui::SameLine();
+			ImGui::TextDisabled( "(?)" );
+			if ( ImGui::BeginItemTooltip() )
+			{
+				ImGui::TextUnformatted(
+					"Changes the percentage output to be of the total frame time instead of the parent time" );
+				ImGui::EndTooltip();
+			}
+
+			previous_root.drawImGui();
+		}
+	} // namespace timing
+
+} // namespace fgl::engine::debug

src/engine/debug/timing/FlameGraph.hpp

@@ -0,0 +1,34 @@
+//
+// Created by kj16609 on 10/29/24.
+//
+
+#pragma once
+
+#include <string_view>
+
+namespace fgl::engine::debug
+{
+
+	namespace timing
+	{
+
+		struct ScopedTimer;
+
+		void reset();
+		[[nodiscard]] ScopedTimer push( std::string_view name );
+
+		namespace internal
+		{
+			void pop();
+		}
+
+		void render();
+
+		struct ScopedTimer
+		{
+			~ScopedTimer() { internal::pop(); }
+		};
+
+	} // namespace timing
+
+} // namespace fgl::engine::debug

src/engine/systems/render/DrawPair.cpp

@@ -52,7 +52,7 @@ namespace fgl::engine
 				{
 					const auto& model_transform { model_component_ptr->m_transform };
 
-					const Matrix< MatrixType::ModelToWorld > matrix { model_transform.mat() * obj_matrix };
+					const Matrix< MatrixType::ModelToWorld > world_matrix { model_transform.mat() * obj_matrix };
 
 					const auto& comp { *model_component_ptr };
 					for ( const Primitive& primitive : comp->m_primitives )
@@ -61,13 +61,14 @@ namespace fgl::engine
 
 						// Does this primitive pass the bounds check
 						const OrientedBoundingBox< CoordinateSpace::World > world_bounding_box {
-							matrix * primitive.getBoundingBox()
+							world_matrix * primitive.getBoundingBox()
 						};
 
+						// No. Skip it
 						if ( !intersects( frustum, world_bounding_box ) ) continue;
 
 						//assert( primitive.m_texture );
-						const ModelMatrixInfo matrix_info { .model_matrix = matrix,
+						const ModelMatrixInfo matrix_info { .model_matrix = world_matrix,
 							                                .material_id = primitive.m_material->getID() };
 
 						// If the textureless flag is on and we have a texture then skip the primitive.c
@@ -85,8 +86,6 @@ namespace fgl::engine
 							std::make_pair( matrix_info.material_id, primitive.m_index_buffer.getOffset() )
 						};
 
-						//debug::drawBoundingBox( matrix * primitive.m_bounding_box );
-
 						assert( primitive.m_index_buffer.size() > 0 );
 
 						profiling::addVertexDrawn( primitive.m_index_buffer.size() );

src/engine/systems/render/EntityRendererSystem.cpp

@@ -11,6 +11,7 @@
 #include "engine/assets/material/Material.hpp"
 #include "engine/camera/Camera.hpp"
 #include "engine/debug/profiling/counters.hpp"
+#include "engine/debug/timing/FlameGraph.hpp"
 #include "engine/rendering/pipelines/v2/AttachmentBuilder.hpp"
 #include "engine/rendering/pipelines/v2/Pipeline.hpp"
 #include "engine/rendering/pipelines/v2/PipelineBuilder.hpp"
@@ -97,6 +98,7 @@ namespace fgl::engine
 		ZoneScopedN( "Entity pass" );
 		[[maybe_unused]] auto& command_buffer { setupSystem( info ) };
 		TracyVkZone( info.tracy_ctx, *command_buffer, "Render entities" );
+		auto timer = debug::timing::push( "Render entities" );
 
 		texturelessPass( info );
 		texturedPass( info );

src/engine/tree/octtree/OctTreeNode.cpp

@@ -281,7 +281,7 @@ namespace fgl::engine
 			return false;
 
 #else
-		return !isEmpty() && frustum.intersects( m_fit_bounding_box );
+		return !isEmpty() && intersects( frustum, m_fit_bounding_box );
 #endif
 	}