perf(debug): cpu timers of the simulation and the main loop, cpu time of the frame parts next to the gpu, renderer data of the debug panel in folding sections

application/application.cpp

@@ -491,12 +491,14 @@ int eu07_application::run()
 	while (!glfwWindowShouldClose(m_windows.front()) && !m_modestack.empty())
 	{
 		Timer::subsystem.mainloop_total.start();
+		Timer::subsystem.loop_input.start();
 		glfwPollEvents();
 
 		if (m_headtrack)
 			m_headtrack->update();
 
 		begin_ui_frame();
+		Timer::subsystem.loop_input.stop();
 
 		// -------------------------------------------------------------------
 		// multiplayer command relaying logic can seem a bit complex
@@ -624,10 +626,14 @@ int eu07_application::run()
 
 		// keep streamed terrain loaded around the active camera in every mode (editor + driver),
 		// once the simulation is live (avoid streaming while the scenery is still loading)
+		Timer::subsystem.loop_terrain.start();
 		if (simulation::is_ready && EditorTerrain.active())
 			EditorTerrain.update(Global.pCamera.Pos);
+		Timer::subsystem.loop_terrain.stop();
 
+		Timer::subsystem.loop_tasks.start();
 		m_taskqueue.update();
+		Timer::subsystem.loop_tasks.stop();
 		opengl_texture::reset_unit_cache();
 
 		if (!GfxRenderer->Render())

application/drivermode.cpp

@@ -167,9 +167,13 @@ bool driver_mode::update()
 
 	double const deltatime = Timer::GetDeltaTime(); // 0.0 gdy pauza
 
+	Timer::subsystem.sim_scripting.start();
 	simulation::State.update_clocks();
 	simulation::State.update_scripting_interface();
+	Timer::subsystem.sim_scripting.stop();
+	Timer::subsystem.sim_environment.start();
 	simulation::Environment.update();
+	Timer::subsystem.sim_environment.stop();
 
 	if (deltatime != 0.0 || false == simulation::is_ready)
 	{
@@ -233,6 +237,7 @@ bool driver_mode::update()
 		Timer::subsystem.sim_dynamics.stop();
 
 		// secondary fixed step simulation time routines
+		Timer::subsystem.sim_secondary.start();
 		while (m_secondaryupdateaccumulator >= m_secondaryupdaterate)
 		{
 
@@ -252,6 +257,7 @@ bool driver_mode::update()
 
 			m_secondaryupdateaccumulator -= m_secondaryupdaterate; // these should be inexpensive enough we have no cap
 		}
+		Timer::subsystem.sim_secondary.stop();
 
 		// variable step simulation time routines
 
@@ -298,24 +304,33 @@ bool driver_mode::update()
 		else
 			TSubModel::iInstance = 0;
 
+		Timer::subsystem.sim_trains.start();
 		if (Global.trainThreads > 0)
 			simulation::Trains.updateAsync(deltatime);
 		else
 			simulation::Trains.update(deltatime);
+		Timer::subsystem.sim_trains.stop();
+		Timer::subsystem.sim_events.start();
 		simulation::Events.update();
 		simulation::Region->update_events();
+		Timer::subsystem.sim_events.stop();
+		Timer::subsystem.sim_lights.start();
 		simulation::Lights.update();
+		Timer::subsystem.sim_lights.stop();
 	}
 
 	// render time routines follow:
 
 	auto const deltarealtime = Timer::GetDeltaRenderTime(); // nie uwzględnia pauzowania ani mnożenia czasu
+	Timer::subsystem.sim_commands.start();
 	simulation::State.process_commands();
+	Timer::subsystem.sim_commands.stop();
 
 	// fixed step render time routines
 
 	fTime50Hz += deltarealtime; // w pauzie też trzeba zliczać czas, bo przy dużym FPS będzie problem z odczytem ramek
 	bool runonce{false};
+	Timer::subsystem.sim_ui.start();
 	while (fTime50Hz >= 1.0 / 50.0)
 	{
 #ifdef _WIN32
@@ -406,22 +421,33 @@ bool driver_mode::update()
 
 		fTime50Hz -= 1.0 / 50.0;
 	}
+	Timer::subsystem.sim_ui.stop();
 
 	// variable step render time routines
 
+	Timer::subsystem.sim_camera.start();
 	update_camera(deltarealtime);
+	Timer::subsystem.sim_camera.stop();
 
+	Timer::subsystem.sim_precipitation.start();
 	simulation::Environment.update_precipitation(); // has to be launched after camera step to work properly
+	Timer::subsystem.sim_precipitation.stop();
 
 	Timer::subsystem.sim_total.stop();
 
+	Timer::subsystem.loop_audio.start();
 	simulation::Region->update_sounds();
 	audio::renderer.update(Global.iPause ? 0.0 : deltarealtime);
+	Timer::subsystem.loop_audio.stop();
 
 	// NOTE: particle system runs on simulation time, but needs actual camera position to determine how to update each particle source
+	Timer::subsystem.loop_particles.start();
 	simulation::Particles.update();
+	Timer::subsystem.loop_particles.stop();
 
+	Timer::subsystem.loop_renderer_update.start();
 	GfxRenderer->Update(deltarealtime);
+	Timer::subsystem.loop_renderer_update.stop();
 
 	simulation::is_ready = simulation::is_ready || (simulation::Train != nullptr && simulation::Train->is_cab_initialized) || Global.local_start_vehicle == "ghostview";
 

application/driveruipanels.cpp

@@ -600,7 +600,7 @@ debug_panel::render() {
             ImGui::Checkbox( "Debug Traction", &DebugTractionFlag );
         }
         render_section( "Camera", m_cameralines );
-        render_section( "Gfx Renderer / Statistics", m_rendererlines );
+        render_section_renderer();
         render_section_settings();
 		render_section_developer(); // Developer tools
 #ifdef WITH_UART
@@ -1438,7 +1438,7 @@ debug_panel::update_section_camera( std::vector<text_line> &Output ) const {
 }
 
 void
-debug_panel::update_section_renderer( std::vector<text_line> &Output ) const {
+debug_panel::update_section_renderer( std::vector<text_line> &Output ) {
 
             // gfx renderer data
             auto textline =
@@ -1471,9 +1471,12 @@ debug_panel::update_section_renderer( std::vector<text_line> &Output ) const {
 
 			Output.emplace_back( textline, Global.UITextColor );
 
-            // renderer stats
+            // renderer stats, in sections when the renderer has them (render_section_renderer())
-            Output.emplace_back( GfxRenderer->info_times(), Global.UITextColor );
+            m_renderersections = GfxRenderer->info_sections();
-            Output.emplace_back( GfxRenderer->info_stats(), Global.UITextColor );
+            if( m_renderersections.empty() ) {
+                Output.emplace_back( GfxRenderer->info_times(), Global.UITextColor );
+                Output.emplace_back( GfxRenderer->info_stats(), Global.UITextColor );
+            }
 
             // CPU related
             Output.emplace_back("CPU:", Global.UITextColor);
@@ -1493,6 +1496,26 @@ debug_panel::render_section( std::string const &Header, std::vector<text_line> c
     return render_section( Lines );
 }
 
+// the lines of the renderer, then its data in sections which fold, the long lines wrapped to the width of the panel
+bool
+debug_panel::render_section_renderer() {
+
+    if( false == render_section( "Gfx Renderer / Statistics", m_rendererlines ) ) { return false; }
+
+    ImGui::PushStyleColor( ImGuiCol_Text, { Global.UITextColor.r, Global.UITextColor.g, Global.UITextColor.b, Global.UITextColor.a } );
+    ImGui::PushTextWrapPos( 0.f );
+    for( auto const &section : m_renderersections ) {
+        ImGui::SetNextItemOpen( section.open, ImGuiCond_Once );
+        if( true == ImGui::TreeNode( section.title.c_str() ) ) {
+            ImGui::TextUnformatted( section.text.c_str() );
+            ImGui::TreePop();
+        }
+    }
+    ImGui::PopTextWrapPos();
+    ImGui::PopStyleColor();
+    return true;
+}
+
 bool
 debug_panel::render_section( std::vector<text_line> const &Lines ) const {
 

application/driveruipanels.h

@@ -11,6 +11,7 @@ http://mozilla.org/MPL/2.0/.
 
 #include "application/uilayer.h"
 #include "utilities/Classes.h"
+#include "rendering/renderer.h"
 
 class drivingaid_panel : public ui_expandable_panel {
 
@@ -87,7 +88,7 @@ private:
     void update_section_eventqueue( std::vector<text_line> &Output );
     void update_section_powergrid( std::vector<text_line> &Output ) const;
     void update_section_camera( std::vector<text_line> &Output ) const;
-    void update_section_renderer( std::vector<text_line> &Output ) const;
+    void update_section_renderer( std::vector<text_line> &Output );
 #ifdef WITH_UART
     void update_section_uart( std::vector<text_line> &Output ) const;
 #endif
@@ -99,6 +100,7 @@ private:
     bool render_section( std::vector<text_line> const &Lines ) const;
     bool render_section_scenario();
     bool render_section_eventqueue();
+    bool render_section_renderer();
     bool render_section_settings() const;
 	bool render_section_developer() const;
 	    // members
@@ -114,6 +116,7 @@ private:
     std::vector<text_line> m_eventqueuelines;
     std::vector<text_line> m_powergridlines;
     std::vector<text_line> m_rendererlines;
+    std::vector<gfx_renderer::info_section> m_renderersections; // the data of the renderer, each part under a header of its own
     std::vector<text_line> m_uartlines;
 
 	double last_time = std::numeric_limits<double>::quiet_NaN();

rendering/opengl46/opengl46renderer.cpp

@@ -675,6 +675,7 @@ bool opengl46_renderer::Render()
 	}
 	// the context of the main view is current here, the one of the previous frame's end
 	m_gputimeline.begin("frame setup");
+	m_cputimeline.begin("frame setup");
 
 	// fetch simulation data
 	if (simulation::is_ready)
@@ -765,6 +766,7 @@ bool opengl46_renderer::Render()
 
 	m_current_viewport = &(*m_viewports.front());
 	m_gputimeline.end();
+	m_cputimeline.end();
 /*
 	m_debugtimestext += "cpu: " + to_string(Timer::subsystem.gfx_color.average(), 2) + " ms (" + std::to_string(m_cellqueue.size()) + " sectors)\n" +=
 	    "cpu swap: " + to_string(Timer::subsystem.gfx_swap.average(), 2) + " ms\n" += "uilayer: " + to_string(Timer::subsystem.gfx_gui.average(), 2) + "ms\n" +=
@@ -801,89 +803,151 @@ void opengl46_renderer::SwapBuffers()
 
 	Timer::subsystem.gfx_swap.stop();
 
-    m_debugtimestext.clear();
+    // the debug data, in sections for the panel. info_times() and info_stats() hold the same, joined
-    // the whole frame of the main loop and its parts: the update of the simulation, Render() with the ui drawn in it, the swap,
+    m_debugsections.clear();
-    // and what's left (input, terrain streaming, tasks, network), measured by none of them
+    // a line of a table of times: the name indented and padded to a column, then the time(s)
+    auto const timeline = []( int const Indent, std::string const &Name, std::string const &Values ) {
+        auto line { std::string( static_cast<std::size_t>( Indent ), ' ' ) + Name };
+        line.resize( std::max<std::size_t>( line.size() + 1, 34 ), ' ' );
+        return line + Values + "\n";
+    };
+    auto const ms = []( double const Value, int const Precision = 2 ) {
+        auto text { to_string( Value, Precision ) };
+        return std::string( std::max<int>( 0, 7 - static_cast<int>( text.size() ) ), ' ' ) + text;
+    };
+
+    // the whole frame of the main loop on the cpu and its parts, the simulation with its own; what's left is measured by none
     {
-        auto const mainloop { Timer::subsystem.mainloop_total.average() };
+        auto const &timers { Timer::subsystem };
-        auto const simulation { Timer::subsystem.sim_total.average() };
+        auto const mainloop { timers.mainloop_total.average() };
-        auto const render { Timer::subsystem.gfx_total.average() };
+        auto const simulation { timers.sim_total.average() };
-        auto const swap { Timer::subsystem.gfx_swap.average() };
+        auto const render { timers.gfx_total.average() };
-        m_debugtimestext =
+        auto const swap { timers.gfx_swap.average() };
-            "mainloop total: " + to_string( mainloop, 2 ) + " ms\n"
+        auto const simulationparts {
-            + " simulation: " + to_string( simulation, 2 ) + " ms\n"
+            timers.sim_scripting.average() + timers.sim_environment.average() + timers.sim_precipitation.average() + timers.sim_dynamics.average()
-            + " render: " + to_string( render, 2 ) + " ms (ui " + to_string( Timer::subsystem.gfx_gui.average(), 2 ) + " ms)\n"
+            + timers.sim_secondary.average() + timers.sim_trains.average() + timers.sim_events.average() + timers.sim_lights.average()
-            + " swap: " + to_string( swap, 2 ) + " ms\n"
+            + timers.sim_commands.average() + timers.sim_ui.average() + timers.sim_camera.average() };
-            + " other: " + to_string( mainloop - simulation - render - swap, 2 ) + " ms\n";
+        auto const loopparts {
+            timers.loop_input.average() + simulation + timers.loop_audio.average() + timers.loop_particles.average() + timers.loop_renderer_update.average()
+            + timers.loop_terrain.average() + timers.loop_tasks.average() + render + swap };
+        std::string text;
+        text += timeline( 0, "main loop", ms( mainloop ) + " ms (" + std::to_string( static_cast<int>( std::round( 1000.f / std::max( mainloop, 0.001f ) ) ) ) + " fps)" );
+        text += timeline( 1, "input, start of the ui frame", ms( timers.loop_input.average() ) );
+        text += timeline( 1, "simulation", ms( simulation ) );
+        text += timeline( 2, "clocks, scripting", ms( timers.sim_scripting.average() ) );
+        text += timeline( 2, "environment", ms( timers.sim_environment.average() + timers.sim_precipitation.average() ) );
+        text += timeline( 2, "vehicles (physics, ai)", ms( timers.sim_dynamics.average() ) );
+        text += timeline( 2, "secondary steps", ms( timers.sim_secondary.average() ) );
+        text += timeline( 2, "trains (cabs)", ms( timers.sim_trains.average() ) );
+        text += timeline( 2, "events", ms( timers.sim_events.average() ) );
+        text += timeline( 2, "lights", ms( timers.sim_lights.average() ) );
+        text += timeline( 2, "commands", ms( timers.sim_commands.average() ) );
+        text += timeline( 2, "ui panels, tooltips (50 Hz)", ms( timers.sim_ui.average() ) );
+        text += timeline( 2, "camera", ms( timers.sim_camera.average() ) );
+        text += timeline( 2, "rest", ms( simulation - simulationparts ) );
+        text += timeline( 1, "sounds", ms( timers.loop_audio.average() ) );
+        text += timeline( 1, "particles", ms( timers.loop_particles.average() ) );
+        text += timeline( 1, "renderer update", ms( timers.loop_renderer_update.average() ) );
+        text += timeline( 1, "terrain streaming", ms( timers.loop_terrain.average() ) );
+        text += timeline( 1, "tasks", ms( timers.loop_tasks.average() ) );
+        text += timeline( 1, "render", ms( render ) );
+        text += timeline( 1, "swap", ms( swap ) );
+        text += timeline( 1, "rest", ms( mainloop - loopparts ) );
+        m_debugsections.push_back( { "CPU: main loop", std::move( text ), true } );
     }
-    m_debugtimestext +=
+
-        "cpu frame total: " + to_string( Timer::subsystem.gfx_color.average() + Timer::subsystem.gfx_shadows.average() + ( Global.gfx_envmap_enabled ? Timer::subsystem.gfx_reflections.average() : 0.f ) + Timer::subsystem.gfx_swap.average(), 2 ) + " ms\n"
+    // the parts of the frame of the renderer, cpu and gpu side by side. the gpu ones follow one another and add up to the frame;
-        + " color: " + to_string( Timer::subsystem.gfx_color.average(), 2 ) + " ms (" + std::to_string( m_cellqueue.size() ) + " sectors)\n";
+    // while the gpu waits for the cpu, the wait goes to the part drawn next
-    if( Global.gfx_shadowmap_enabled ) {
+    {
-        m_debugtimestext +=
+        std::string text;
-            " shadows: " + to_string( Timer::subsystem.gfx_shadows.average(), 2 ) + " ms\n";
+        text += timeline( 0, "part", "    cpu      gpu  ms" );
-    }
+        auto const &gpuparts { m_gputimeline.result() };
-    if( Global.gfx_envmap_enabled ) {
+        auto cputotal { 0.f };
-        m_debugtimestext +=
+        for( auto const &part : m_cputimeline.parts ) {
-            " reflections: " + to_string( Timer::subsystem.gfx_reflections.average(), 2 ) + " ms\n";
+            cputotal += part.time;
-    }
+            std::string gpu { "        -" };
-    m_debugtimestext += " swap: " + to_string( Timer::subsystem.gfx_swap.average(), 2 ) + " ms\n";
+            for( auto const &gpupart : gpuparts ) {
-    if (m_gllasttime)
+                if( std::strcmp( gpupart.name, part.name ) == 0 ) {
-        m_debugtimestext += "gpu frame total: " + to_string((double)(m_gllasttime / 1000ULL) / 1000.0, 3) + " ms\n";
+                    gpu = "  " + ms( static_cast<double>( gpupart.time ) / 1000000.0, 3 );
-    // the parts follow one another and add up to the frame; the steps below are timed each on its own and can hold the tail
+                    break;
-    // of the work before them
+                }
-    if( auto const &gpuparts { m_gputimeline.result() }; false == gpuparts.empty() ) {
+            }
-        m_debugtimestext += "gpu frame parts: " + to_string( static_cast<double>( m_gputimeline.total() ) / 1000000.0, 3 ) + " ms\n";
+            text += timeline( 1, part.name, ms( part.time ) + gpu );
-        for( auto const &part : gpuparts ) {
-            m_debugtimestext += " " + std::string{ part.name } + ": " + to_string( static_cast<double>( part.time ) / 1000000.0, 3 ) + " ms\n";
         }
-        m_debugtimestext += "gpu steps:\n";
+        // parts the gpu measured and the cpu didn't, if any
-    }
+        for( auto const &gpupart : gpuparts ) {
-    if (auto const clusterstime = m_clusterstimer.result())
+            if( false == m_cputimeline.time( gpupart.name ).has_value() ) {
-        m_debugtimestext += " clusters: " + to_string(static_cast<double>(*clusterstime) / 1000000.0, 3) + " ms\n";
+                text += timeline( 1, gpupart.name, "      -  " + ms( static_cast<double>( gpupart.time ) / 1000000.0, 3 ) );
-    if (auto const culltime = m_cullstimer.result())
+            }
-        m_debugtimestext += " cull: " + to_string(static_cast<double>(*culltime) / 1000000.0, 3) + " ms\n";
-    m_debugtimestext += m_sky.info_times();
-    m_debugtimestext += m_weather.info_times();
-    m_debugtimestext += m_exposure.info_times();
-    m_debugtimestext += m_ao.info_times();
-    m_debugtimestext += m_instancecull.info_times();
-    // the cullings of the other passes; the environment map is drawn now and then, its numbers are of its last update
-    if( Global.gfx_gpucull_shadows ) {
-        for( std::size_t cascade = 0; cascade < m_shadowcull.size(); ++cascade ) {
-            m_debugtimestext += m_shadowcull[ cascade ].info_times( "instance cull shadows " + std::to_string( cascade + 1 ) );
         }
-    }
+        text += timeline(
-    if( Global.gfx_gpucull_reflections && m_reflectioncull.ran() ) {
+            0, "total",
-        m_debugtimestext += m_reflectioncull.info_times( "instance cull reflections, last face" );
+            ms( cputotal ) + "  " + ( gpuparts.empty() ? std::string{ "      -" } : ms( static_cast<double>( m_gputimeline.total() ) / 1000000.0, 3 ) ) );
-    }
+        text += "\n";
-    m_debugtimestext += Light_Shadow_Cull_Info( true );
+        text += timeline( 0, "cpu of the passes", "" );
-    if( Global.gfx_depthprepass_scene || m_contactshadowslast ) {
+        text += timeline( 1, "colour (" + std::to_string( m_cellqueue.size() ) + " sectors)", ms( Timer::subsystem.gfx_color.average() ) );
-        if( auto const scenedepthtime = m_scenedepthtimer.result() )
+        if( Global.gfx_shadowmap_enabled ) {
-            m_debugtimestext += " scene depth: " + to_string( static_cast<double>( *scenedepthtime ) / 1000000.0, 3 ) + " ms\n";
+            text += timeline( 1, "shadows", ms( Timer::subsystem.gfx_shadows.average() ) );
-    }
-    if( m_contactshadowslast ) {
-        if( auto const contacttime = m_contactshadowstimer.result() )
-            m_debugtimestext += " contact shadows depth: " + to_string( static_cast<double>( *contacttime ) / 1000000.0, 3 ) + " ms\n";
-    }
-    if( Global.gfx_gpucull == 1 ) {
-        auto const twophase { m_instancecull.two_phase() };
-        m_debugtimestext += m_hiz.info_times( twophase );
-        if( auto const prepasstime = m_prepasstimer.result() ) {
-            m_debugtimestext += " depth prepass: " + to_string( static_cast<double>( *prepasstime ) / 1000000.0, 3 ) + " ms";
-            auto const firsttime { m_prepassfirsttimer.result() };
-            if( twophase && firsttime )
-                m_debugtimestext += " (+" + to_string( static_cast<double>( *firsttime ) / 1000000.0, 3 ) + " ms of the instances drawn first)";
-            m_debugtimestext += "\n";
         }
+        if( Global.gfx_envmap_enabled ) {
+            text += timeline( 1, "reflections", ms( Timer::subsystem.gfx_reflections.average() ) );
+        }
+        text += timeline( 1, "ui", ms( Timer::subsystem.gfx_gui.average() ) );
+        if( m_gllasttime ) {
+            text += timeline( 0, "gpu frame (query)", ms( static_cast<double>( m_gllasttime / 1000ULL ) / 1000.0, 3 ) );
+        }
+        m_debugsections.push_back( { "Render: cpu / gpu by part", std::move( text ), true } );
+    }
+
+    // the steps below are timed each on its own on the gpu and can hold the tail of the work before them
+    {
+        std::string text;
+        if (auto const clusterstime = m_clusterstimer.result())
+            text += " clusters: " + to_string(static_cast<double>(*clusterstime) / 1000000.0, 3) + " ms\n";
+        if (auto const culltime = m_cullstimer.result())
+            text += " cull: " + to_string(static_cast<double>(*culltime) / 1000000.0, 3) + " ms\n";
+        text += m_sky.info_times();
+        text += m_weather.info_times();
+        text += m_exposure.info_times();
+        text += m_ao.info_times();
+        text += m_instancecull.info_times();
+        // the cullings of the other passes; the environment map is drawn now and then, its numbers are of its last update
+        if( Global.gfx_gpucull_shadows ) {
+            for( std::size_t cascade = 0; cascade < m_shadowcull.size(); ++cascade ) {
+                text += m_shadowcull[ cascade ].info_times( "instance cull shadows " + std::to_string( cascade + 1 ) );
+            }
+        }
+        if( Global.gfx_gpucull_reflections && m_reflectioncull.ran() ) {
+            text += m_reflectioncull.info_times( "instance cull reflections, last face" );
+        }
+        text += Light_Shadow_Cull_Info( true );
+        if( Global.gfx_depthprepass_scene || m_contactshadowslast ) {
+            if( auto const scenedepthtime = m_scenedepthtimer.result() )
+                text += " scene depth: " + to_string( static_cast<double>( *scenedepthtime ) / 1000000.0, 3 ) + " ms\n";
+        }
+        if( m_contactshadowslast ) {
+            if( auto const contacttime = m_contactshadowstimer.result() )
+                text += " contact shadows depth: " + to_string( static_cast<double>( *contacttime ) / 1000000.0, 3 ) + " ms\n";
+        }
+        if( Global.gfx_gpucull == 1 ) {
+            auto const twophase { m_instancecull.two_phase() };
+            text += m_hiz.info_times( twophase );
+            if( auto const prepasstime = m_prepasstimer.result() ) {
+                text += " depth prepass: " + to_string( static_cast<double>( *prepasstime ) / 1000000.0, 3 ) + " ms";
+                auto const firsttime { m_prepassfirsttimer.result() };
+                if( twophase && firsttime )
+                    text += " (+" + to_string( static_cast<double>( *firsttime ) / 1000000.0, 3 ) + " ms of the instances drawn first)";
+                text += "\n";
+            }
+        }
+        text += m_localshadows.info_times();
+        if( Global.gfx_shadow_sdsm )
+            text += m_shadowfit.info_times();
+        text += m_gpuparticles.info_times();
+        if( DebugModeFlag )
+            text += m_textures.info();
+        m_debugsections.push_back( { "GPU steps", std::move( text ), false } );
     }
-    m_debugtimestext += m_localshadows.info_times();
-    if( Global.gfx_shadow_sdsm )
-        m_debugtimestext += m_shadowfit.info_times();
-    m_debugtimestext += m_gpuparticles.info_times();
-    m_debugtimestext += "uilayer: " + to_string( Timer::subsystem.gfx_gui.average(), 2 ) + " ms\n";
-    if( DebugModeFlag )
-        m_debugtimestext += m_textures.info();
 
     debug_stats shadowstats;
     for( auto const &shadowpass : m_shadowpass ) {
@@ -920,7 +984,7 @@ void opengl46_renderer::SwapBuffers()
         shadowcascadestext += "\n";
     }
 
-    m_debugstatstext =
+    std::string statstext =
         "triangles: " + to_string( static_cast<int>(m_geometry.primitives_count()), 7 ) + "\n"
         + "vehicles:  " + to_string( m_colorpass.draw_stats.dynamics, 7 ) + " +" + to_string( shadowstats.dynamics, 7 )
         + " =" + to_string( m_colorpass.draw_stats.dynamics + shadowstats.dynamics, 7 ) + "\n"
@@ -980,26 +1044,91 @@ void opengl46_renderer::SwapBuffers()
         + ( Global.gfx_lights_clustered ? "clustered" : "first " + std::to_string( std::max( Global.DynamicLightCount, 0 ) ) )
         + "\n" + m_locallights.info()
         + m_localshadows.info()
-        + m_gpuparticles.info()
+        + m_gpuparticles.info();
-        + m_instancecull.info();
-    if( Global.gfx_gpucull_shadows ) {
-        for( std::size_t cascade = 0; cascade < m_shadowcull.size(); ++cascade ) {
-            if( false == m_shadowcull[ cascade ].ran() ) { continue; }
-            m_shadowcull[ cascade ].collect();
-            m_debugstatstext += m_shadowcull[ cascade ].info( "gpu cull shadows " + std::to_string( cascade + 1 ), false );
-        }
-    }
-    if( Global.gfx_gpucull_reflections && m_reflectioncull.ran() ) {
-        m_reflectioncull.collect();
-        m_debugstatstext += m_reflectioncull.info( "gpu cull reflections, last face", false );
-    }
-    m_debugstatstext += Light_Shadow_Cull_Info( false );
     if( auto const cullstats = ( m_viewports.empty() || !( Global.gfx_lights_clustered || Global.gfx_lights_clusterheatmap ) ? std::nullopt : m_viewports.front()->clusters->stats() ) ) {
-        m_debugstatstext +=
+        statstext +=
             "\ncluster lists: " + std::to_string( cullstats->index_count )
             + ", overflow " + std::to_string( cullstats->overflow_count )
             + " (peak " + std::to_string( cullstats->overflow_peak ) + ")";
     }
+    auto culltext { m_instancecull.info() };
+    if( Global.gfx_gpucull_shadows ) {
+        for( std::size_t cascade = 0; cascade < m_shadowcull.size(); ++cascade ) {
+            if( false == m_shadowcull[ cascade ].ran() ) { continue; }
+            m_shadowcull[ cascade ].collect();
+            culltext += m_shadowcull[ cascade ].info( "gpu cull shadows " + std::to_string( cascade + 1 ), false );
+        }
+    }
+    if( Global.gfx_gpucull_reflections && m_reflectioncull.ran() ) {
+        m_reflectioncull.collect();
+        culltext += m_reflectioncull.info( "gpu cull reflections, last face", false );
+    }
+    culltext += Light_Shadow_Cull_Info( false );
+    m_debugsections.push_back( { "Scene statistics", std::move( statstext ), false } );
+    m_debugsections.push_back( { "GPU culling", std::move( culltext ), false } );
+
+    // the parts of the sections start with a line break here and there, and end with one or not
+    for( auto &section : m_debugsections ) {
+        auto &text { section.text };
+        text.erase( 0, text.find_first_not_of( '\n' ) == std::string::npos ? text.size() : text.find_first_not_of( '\n' ) );
+        while( ( false == text.empty() ) && ( text.back() == '\n' ) ) { text.pop_back(); }
+    }
+    // the same joined, the first three sections times, the others statistics
+    m_debugtimestext.clear();
+    m_debugstatstext.clear();
+    for( std::size_t index = 0; index < m_debugsections.size(); ++index ) {
+        auto &target { index < 3 ? m_debugtimestext : m_debugstatstext };
+        target += ( target.empty() ? "" : "\n" ) + m_debugsections[ index ].title + ":\n" + m_debugsections[ index ].text;
+    }
+}
+
+void opengl46_renderer::cpu_timeline::begin( char const *Name )
+{
+	if( active ) { end(); }
+	active = true;
+	mark = std::chrono::steady_clock::now();
+	current = parts.size();
+	next( Name );
+}
+
+void opengl46_renderer::cpu_timeline::next( char const *Name )
+{
+	if( false == active ) { return; }
+	auto const now { std::chrono::steady_clock::now() };
+	if( current < parts.size() ) {
+		parts[ current ].frame += std::chrono::duration<float, std::milli>( now - mark ).count();
+	}
+	mark = now;
+	current = 0;
+	while( ( current < parts.size() ) && ( parts[ current ].name != Name ) && ( std::strcmp( parts[ current ].name, Name ) != 0 ) ) {
+		++current;
+	}
+	if( current == parts.size() ) {
+		parts.push_back( { Name } );
+	}
+}
+
+void opengl46_renderer::cpu_timeline::end()
+{
+	if( false == active ) { return; }
+	auto const now { std::chrono::steady_clock::now() };
+	if( current < parts.size() ) {
+		parts[ current ].frame += std::chrono::duration<float, std::milli>( now - mark ).count();
+	}
+	// the average of Timer::stopwatch: the last 20 frames or so. parts left out in the frame fade away
+	for( auto &part : parts ) {
+		part.time = 0.95f * part.time + 0.05f * part.frame;
+		part.frame = 0.f;
+	}
+	active = false;
+}
+
+std::optional<float> opengl46_renderer::cpu_timeline::time( char const *Name ) const
+{
+	for( auto const &part : parts ) {
+		if( ( part.name == Name ) || ( std::strcmp( part.name, Name ) == 0 ) ) { return part.time; }
+	}
+	return std::nullopt;
 }
 
 void opengl46_renderer::draw_debug_ui()
@@ -1216,7 +1345,10 @@ void opengl46_renderer::Render_pass(viewport_config &vp, rendermode const Mode)
 		// parts of the gpu time of the frame; the marks go through the main view only, in the context they were begun in
 		auto const gpupart = [this, &vp](char const *Name) {
 			if (vp.main)
+			{
 				m_gputimeline.next(Name);
+				m_cputimeline.next(Name);
+			}
 		};
 
 		scene_ubs.time = Timer::GetTime();
@@ -1723,6 +1855,7 @@ if (!Global.gfx_skippipeline)
             static char const *const gpuparts[] = { "sun shadows 1", "sun shadows 2", "sun shadows 3" };
             static_assert( std::size( gpuparts ) == std::tuple_size_v<decltype( m_shadowpass )> );
             m_gputimeline.next( gpuparts[ idx ] );
+            m_cputimeline.next( gpuparts[ idx ] );
 
             m_shadow_fb->attach( *m_shadow_tex, GL_DEPTH_ATTACHMENT, idx );
             m_shadow_fb->clear( GL_DEPTH_BUFFER_BIT );
@@ -8164,6 +8297,11 @@ std::string const &opengl46_renderer::info_times() const
 	return m_debugtimestext;
 }
 
+std::vector<gfx_renderer::info_section> const &opengl46_renderer::info_sections() const
+{
+	return m_debugsections;
+}
+
 std::string const &opengl46_renderer::info_stats() const
 {
 

rendering/opengl46/opengl46renderer.h

@@ -165,6 +165,8 @@ class opengl46_renderer : public gfx_renderer {
         info_times() const override;
     std::string const &
         info_stats() const override;
+    std::vector<info_section> const &
+        info_sections() const override;
 	  void MakeScreenshot() override;
     bool Render_Preview( TAnimModel *Instance, int const Size, int const Margin, bool const Shadows, std::vector<std::uint8_t> &Image ) override;
 
@@ -614,6 +616,7 @@ class opengl46_renderer : public gfx_renderer {
 	std::string m_pickdebuginfo;
 	//debug_stats m_debugstats;
 	std::string m_debugstatstext;
+	std::vector<info_section> m_debugsections; // the same data in sections, for the debug panel
     struct simulation_state {
         std::string weather;
         std::string season;
@@ -905,6 +908,27 @@ class opengl46_renderer : public gfx_renderer {
 	GLuint64 m_gllasttime = 0;
 	// gpu time of the parts of the frame, marks put one after another through the main view (the context of m_window)
 	gl::gpu_timeline m_gputimeline;
+	// cpu time of the same parts, marked at the same places: a part lasts from its mark to the next one, the parts of the same
+	// name are added up in a frame and averaged over the frames the way Timer::stopwatch averages
+	struct cpu_timeline {
+		struct part {
+			char const *name;
+			float time { 0.f }; // average, ms
+			float frame { 0.f }; // in the frame under way, ms
+		};
+		std::vector<part> parts; // in the order they came first
+		std::size_t current { 0 };
+		std::chrono::steady_clock::time_point mark;
+		bool active { false };
+		// starts the frame with its first part. the names are kept as pointers: string literals
+		void begin( char const *Name );
+		// ends the part under way and starts the next one
+		void next( char const *Name );
+		void end();
+		// average of the part of the name, or none
+		std::optional<float> time( char const *Name ) const;
+	};
+	cpu_timeline m_cputimeline;
 	// gpu time of the light cluster compute passes; the debug panel shows it once a pass measures it
 	gl::gpu_timer m_clusterstimer;
 	// gpu time of assigning the lights to the clusters, done every frame

rendering/renderer.h

@@ -165,6 +165,16 @@ public:
     // debug methods
     virtual auto info_times() const -> std::string const & = 0;
     virtual auto info_stats() const -> std::string const & = 0;
+    // the same data in sections, for the debug panel to show each under a header of its own, the ones marked open unfolded at
+    // first. none: the panel shows info_times() and info_stats() as they are
+    struct info_section {
+        std::string title;
+        std::string text;
+        bool open { false };
+    };
+    virtual auto info_sections() const -> std::vector<info_section> const & {
+        static std::vector<info_section> const none;
+        return none; }
     // imgui renderer
 	  virtual class imgui_renderer *GetImguiRenderer() = 0;
 	  virtual void MakeScreenshot() = 0;

utilities/Timer.h

@@ -63,7 +63,24 @@ struct subsystem_stopwatches {
     stopwatch sim_dynamics;
     stopwatch sim_events;
     stopwatch sim_ai;
+    // parts of sim_total for the debug panel, measured in driver_mode::update()
+    stopwatch sim_scripting; // clocks and the scripting interface
+    stopwatch sim_environment; // sky and weather
+    stopwatch sim_precipitation;
+    stopwatch sim_secondary; // secondary fixed step routines
+    stopwatch sim_trains; // cabs of the trains
+    stopwatch sim_lights;
+    stopwatch sim_commands;
+    stopwatch sim_ui; // 50 Hz routines: ui panels, tooltips
+    stopwatch sim_camera;
     stopwatch mainloop_total;
+    // parts of the main loop outside the simulation and Render(), for the debug panel
+    stopwatch loop_input; // events, head tracking, start of the ui frame
+    stopwatch loop_audio; // sounds of the scenery and the audio renderer
+    stopwatch loop_particles; // cpu particles
+    stopwatch loop_renderer_update; // gfx_renderer::Update()
+    stopwatch loop_terrain; // terrain streaming
+    stopwatch loop_tasks; // task queue
 };
 
 extern subsystem_stopwatches subsystem;