diff --git a/application/application.cpp b/application/application.cpp index dfe373ca..f3dc7544 100644 --- a/application/application.cpp +++ b/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()) diff --git a/application/drivermode.cpp b/application/drivermode.cpp index b55d09c2..e27c7c76 100644 --- a/application/drivermode.cpp +++ b/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"; diff --git a/application/driveruipanels.cpp b/application/driveruipanels.cpp index 017e518d..8525ffcf 100644 --- a/application/driveruipanels.cpp +++ b/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 &Output ) const { } void -debug_panel::update_section_renderer( std::vector &Output ) const { +debug_panel::update_section_renderer( std::vector &Output ) { // gfx renderer data auto textline = @@ -1471,9 +1471,12 @@ debug_panel::update_section_renderer( std::vector &Output ) const { Output.emplace_back( textline, Global.UITextColor ); - // renderer stats - Output.emplace_back( GfxRenderer->info_times(), Global.UITextColor ); - Output.emplace_back( GfxRenderer->info_stats(), Global.UITextColor ); + // renderer stats, in sections when the renderer has them (render_section_renderer()) + m_renderersections = GfxRenderer->info_sections(); + 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 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 §ion : 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 const &Lines ) const { diff --git a/application/driveruipanels.h b/application/driveruipanels.h index 96b9ac1c..dd43275c 100644 --- a/application/driveruipanels.h +++ b/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 &Output ); void update_section_powergrid( std::vector &Output ) const; void update_section_camera( std::vector &Output ) const; - void update_section_renderer( std::vector &Output ) const; + void update_section_renderer( std::vector &Output ); #ifdef WITH_UART void update_section_uart( std::vector &Output ) const; #endif @@ -99,6 +100,7 @@ private: bool render_section( std::vector 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 m_eventqueuelines; std::vector m_powergridlines; std::vector m_rendererlines; + std::vector m_renderersections; // the data of the renderer, each part under a header of its own std::vector m_uartlines; double last_time = std::numeric_limits::quiet_NaN(); diff --git a/rendering/opengl46/opengl46renderer.cpp b/rendering/opengl46/opengl46renderer.cpp index e8500a9a..1cd93fcd 100644 --- a/rendering/opengl46/opengl46renderer.cpp +++ b/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 whole frame of the main loop and its parts: the update of the simulation, Render() with the ui drawn in it, the swap, - // and what's left (input, terrain streaming, tasks, network), measured by none of them + // the debug data, in sections for the panel. info_times() and info_stats() hold the same, joined + m_debugsections.clear(); + // 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( Indent ), ' ' ) + Name }; + line.resize( std::max( 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( 0, 7 - static_cast( 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 simulation { Timer::subsystem.sim_total.average() }; - auto const render { Timer::subsystem.gfx_total.average() }; - auto const swap { Timer::subsystem.gfx_swap.average() }; - m_debugtimestext = - "mainloop total: " + to_string( mainloop, 2 ) + " ms\n" - + " simulation: " + to_string( simulation, 2 ) + " ms\n" - + " render: " + to_string( render, 2 ) + " ms (ui " + to_string( Timer::subsystem.gfx_gui.average(), 2 ) + " ms)\n" - + " swap: " + to_string( swap, 2 ) + " ms\n" - + " other: " + to_string( mainloop - simulation - render - swap, 2 ) + " ms\n"; + auto const &timers { Timer::subsystem }; + auto const mainloop { timers.mainloop_total.average() }; + auto const simulation { timers.sim_total.average() }; + auto const render { timers.gfx_total.average() }; + auto const swap { timers.gfx_swap.average() }; + auto const simulationparts { + timers.sim_scripting.average() + timers.sim_environment.average() + timers.sim_precipitation.average() + timers.sim_dynamics.average() + + timers.sim_secondary.average() + timers.sim_trains.average() + timers.sim_events.average() + timers.sim_lights.average() + + timers.sim_commands.average() + timers.sim_ui.average() + timers.sim_camera.average() }; + 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( 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" - + " color: " + to_string( Timer::subsystem.gfx_color.average(), 2 ) + " ms (" + std::to_string( m_cellqueue.size() ) + " sectors)\n"; - if( Global.gfx_shadowmap_enabled ) { - m_debugtimestext += - " shadows: " + to_string( Timer::subsystem.gfx_shadows.average(), 2 ) + " ms\n"; - } - if( Global.gfx_envmap_enabled ) { - m_debugtimestext += - " reflections: " + to_string( Timer::subsystem.gfx_reflections.average(), 2 ) + " ms\n"; - } - m_debugtimestext += " swap: " + to_string( Timer::subsystem.gfx_swap.average(), 2 ) + " ms\n"; - if (m_gllasttime) - m_debugtimestext += "gpu frame total: " + to_string((double)(m_gllasttime / 1000ULL) / 1000.0, 3) + " ms\n"; - // 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 - // of the work before them - if( auto const &gpuparts { m_gputimeline.result() }; false == gpuparts.empty() ) { - m_debugtimestext += "gpu frame parts: " + to_string( static_cast( m_gputimeline.total() ) / 1000000.0, 3 ) + " ms\n"; - for( auto const &part : gpuparts ) { - m_debugtimestext += " " + std::string{ part.name } + ": " + to_string( static_cast( part.time ) / 1000000.0, 3 ) + " 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; + // while the gpu waits for the cpu, the wait goes to the part drawn next + { + std::string text; + text += timeline( 0, "part", " cpu gpu ms" ); + auto const &gpuparts { m_gputimeline.result() }; + auto cputotal { 0.f }; + for( auto const &part : m_cputimeline.parts ) { + cputotal += part.time; + std::string gpu { " -" }; + for( auto const &gpupart : gpuparts ) { + if( std::strcmp( gpupart.name, part.name ) == 0 ) { + gpu = " " + ms( static_cast( gpupart.time ) / 1000000.0, 3 ); + break; + } + } + text += timeline( 1, part.name, ms( part.time ) + gpu ); } - m_debugtimestext += "gpu steps:\n"; - } - if (auto const clusterstime = m_clusterstimer.result()) - m_debugtimestext += " clusters: " + to_string(static_cast(*clusterstime) / 1000000.0, 3) + " ms\n"; - if (auto const culltime = m_cullstimer.result()) - m_debugtimestext += " cull: " + to_string(static_cast(*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 ) ); + // parts the gpu measured and the cpu didn't, if any + for( auto const &gpupart : gpuparts ) { + if( false == m_cputimeline.time( gpupart.name ).has_value() ) { + text += timeline( 1, gpupart.name, " - " + ms( static_cast( gpupart.time ) / 1000000.0, 3 ) ); + } } - } - if( Global.gfx_gpucull_reflections && m_reflectioncull.ran() ) { - m_debugtimestext += m_reflectioncull.info_times( "instance cull reflections, last face" ); - } - m_debugtimestext += Light_Shadow_Cull_Info( true ); - if( Global.gfx_depthprepass_scene || m_contactshadowslast ) { - if( auto const scenedepthtime = m_scenedepthtimer.result() ) - m_debugtimestext += " scene depth: " + to_string( static_cast( *scenedepthtime ) / 1000000.0, 3 ) + " ms\n"; - } - if( m_contactshadowslast ) { - if( auto const contacttime = m_contactshadowstimer.result() ) - m_debugtimestext += " contact shadows depth: " + to_string( static_cast( *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( *prepasstime ) / 1000000.0, 3 ) + " ms"; - auto const firsttime { m_prepassfirsttimer.result() }; - if( twophase && firsttime ) - m_debugtimestext += " (+" + to_string( static_cast( *firsttime ) / 1000000.0, 3 ) + " ms of the instances drawn first)"; - m_debugtimestext += "\n"; + text += timeline( + 0, "total", + ms( cputotal ) + " " + ( gpuparts.empty() ? std::string{ " -" } : ms( static_cast( m_gputimeline.total() ) / 1000000.0, 3 ) ) ); + text += "\n"; + text += timeline( 0, "cpu of the passes", "" ); + text += timeline( 1, "colour (" + std::to_string( m_cellqueue.size() ) + " sectors)", ms( Timer::subsystem.gfx_color.average() ) ); + if( Global.gfx_shadowmap_enabled ) { + text += timeline( 1, "shadows", ms( Timer::subsystem.gfx_shadows.average() ) ); } + 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( 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(*clusterstime) / 1000000.0, 3) + " ms\n"; + if (auto const culltime = m_cullstimer.result()) + text += " cull: " + to_string(static_cast(*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( *scenedepthtime ) / 1000000.0, 3 ) + " ms\n"; + } + if( m_contactshadowslast ) { + if( auto const contacttime = m_contactshadowstimer.result() ) + text += " contact shadows depth: " + to_string( static_cast( *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( *prepasstime ) / 1000000.0, 3 ) + " ms"; + auto const firsttime { m_prepassfirsttimer.result() }; + if( twophase && firsttime ) + text += " (+" + to_string( static_cast( *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(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_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 ); + + m_gpuparticles.info(); 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 §ion : 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( 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( 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 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 ); 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 const &opengl46_renderer::info_sections() const +{ + return m_debugsections; +} + std::string const &opengl46_renderer::info_stats() const { diff --git a/rendering/opengl46/opengl46renderer.h b/rendering/opengl46/opengl46renderer.h index 00843fbb..20f90777 100644 --- a/rendering/opengl46/opengl46renderer.h +++ b/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 const & + info_sections() const override; void MakeScreenshot() override; bool Render_Preview( TAnimModel *Instance, int const Size, int const Margin, bool const Shadows, std::vector &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 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 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 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 diff --git a/rendering/renderer.h b/rendering/renderer.h index a9cf6edf..5b3041d1 100644 --- a/rendering/renderer.h +++ b/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 const & { + static std::vector const none; + return none; } // imgui renderer virtual class imgui_renderer *GetImguiRenderer() = 0; virtual void MakeScreenshot() = 0; diff --git a/utilities/Timer.h b/utilities/Timer.h index 32e170a4..dbee4ccd 100644 --- a/utilities/Timer.h +++ b/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;