Draw the recorded instance draws with the variant seed they were recorded with

docs/opengl46-renderer.md

@@ -405,6 +405,16 @@ editor goes through the first `dynamiclights` headlights, the reflections throug
   writing to it (`waits`, should stay at 0) and how many times a buffer had to grow (`grown`, a few times after the start).
   With `gfx.gpucull yes` and `gfx.gpucull.multidraw yes` the `multi draw blocks:` row shows the same for the data of the
   parts of models drawn with multi draws (one block per draw, written once a frame).
+- Shift+F12 shows below `gpu frame total:` the `gpu frame parts:` of the main view: marks of time put one after another
+  through the frame, so each part lasts until the next one begins and the parts add up to the frame with nothing left out
+  (`frame setup`, `sun shadows 1` to `3` — 1 the nearest, with the culling of the cascade —, `reflections`, `lamp and
+  headlight shadows`, `clear, clusters, lights`, `clouds, fog volume`, `sky`, `scene depth` and `contact shadows depth` when
+  drawn, `colour, opaque` — with the culling, the occlusion depth and the depth prepass of the instances —,
+  `colour, translucent and cab`, `resolve, ambient occlusion, motion blur`, `exposure, bloom`, `tonemapping, output`, `ui`,
+  and `other viewports` when there are more of them; only those in the context of the main window are counted). The timings
+  under `gpu steps:` are measured each from its own pair of marks, and the first mark of a pair can be put while the graphics
+  card still works on what came before, so a short step right after a heavy one may show some of that work; the parts don't.
+  Like the other timings, they are of a frame a few frames back.
 - `gfx.gldebug yes` turns on the OpenGL debug output (`KHR_debug`); messages go to the log.
 
 ## Building

gl/query.cpp

@@ -2,6 +2,8 @@
 #include "query.h"
 #include "utilities/Globals.h"
 
+#include <cstring>
+
 gl::query::query(targets target)
     : target(target)
 {
@@ -122,3 +124,111 @@ void gl::gpu_timer::collect()
 		m_pending[slot] = false;
 	}
 }
+
+gl::gpu_timeline::~gpu_timeline()
+{
+	for (auto &frame : m_frames)
+	{
+		if (frame.queries[0] != 0)
+			glDeleteQueries(static_cast<GLsizei>(frame.queries.size()), frame.queries.data());
+	}
+}
+
+void gl::gpu_timeline::begin(char const *Name)
+{
+	if (m_active)
+		end();
+
+	collect();
+	auto &frame = m_frames[m_slot];
+	m_active = !frame.pending;
+	if (!m_active)
+		return;
+
+	if (frame.queries[0] == 0)
+		glCreateQueries(GL_TIMESTAMP, static_cast<GLsizei>(frame.queries.size()), frame.queries.data());
+	frame.count = 0;
+	next(Name);
+}
+
+void gl::gpu_timeline::next(char const *Name)
+{
+	if (!m_active)
+		return;
+
+	auto &frame = m_frames[m_slot];
+	// the last mark is kept for end(); past the limit the part under way goes on
+	if (frame.count + 1 >= MARKS)
+		return;
+
+	glQueryCounter(frame.queries[frame.count], GL_TIMESTAMP);
+	frame.names[frame.count] = Name;
+	++frame.count;
+}
+
+void gl::gpu_timeline::end()
+{
+	if (!m_active)
+		return;
+
+	auto &frame = m_frames[m_slot];
+	glQueryCounter(frame.queries[frame.count], GL_TIMESTAMP);
+	frame.names[frame.count] = nullptr;
+	++frame.count;
+	frame.pending = true;
+	m_slot = (m_slot + 1) % SLOTS;
+	m_active = false;
+}
+
+std::vector<gl::gpu_timeline::part> const &gl::gpu_timeline::result()
+{
+	collect();
+	return m_last;
+}
+
+void gl::gpu_timeline::collect()
+{
+	// frames finish in the order they were issued, oldest first
+	for (size_t i = 0; i < SLOTS; ++i)
+	{
+		auto &frame = m_frames[(m_slot + i) % SLOTS];
+		if (!frame.pending)
+			continue;
+
+		auto ready = true;
+		for (size_t mark = 0; (mark < frame.count) && ready; ++mark)
+		{
+			GLint available = GL_FALSE;
+			glGetQueryObjectiv(frame.queries[mark], GL_QUERY_RESULT_AVAILABLE, &available);
+			ready = (available != GL_FALSE);
+		}
+		if (!ready)
+			break;
+
+		m_last.clear();
+		GLuint64 first = 0;
+		GLuint64 previous = 0;
+		for (size_t mark = 0; mark < frame.count; ++mark)
+		{
+			GLuint64 time = 0;
+			glGetQueryObjectui64v(frame.queries[mark], GL_QUERY_RESULT, &time);
+			if (mark == 0)
+				first = time;
+			else
+			{
+				auto const length = (time >= previous ? time - previous : 0);
+				auto const *name = frame.names[mark - 1];
+				auto lookup = m_last.begin();
+				while ((lookup != m_last.end()) && (std::strcmp(lookup->name, name) != 0))
+					++lookup;
+				if (lookup != m_last.end())
+					lookup->time += length;
+				else
+					m_last.push_back({name, length});
+			}
+			previous = time;
+		}
+		m_total = (previous >= first ? previous - first : 0);
+		frame.pending = false;
+	}
+}

gl/query.h

@@ -2,6 +2,7 @@
 
 #include <array>
 #include <optional>
+#include <vector>
 
 #include "object.h"
 
@@ -65,4 +66,60 @@ class gpu_timer
 	bool m_active = false;
 	std::optional<uint64_t> m_last;
 };
+
+// gpu time of the parts of a frame, from GL_TIMESTAMP queries put one after another: a part lasts from its mark to the next
+// one, so the parts add up to the time from the first mark to the last, with nothing left out and nothing counted twice.
+// the first mark of a gpu_timer is put while the gpu may still be busy with what came before, so its time can hold the tail
+// of that work; in the run of marks that time goes to the part it belongs to. results are read a few frames later without
+// stalling; if the gpu falls further behind, the frame is skipped
+class gpu_timeline
+{
+  public:
+	struct part
+	{
+		char const *name;
+		uint64_t time; // nanoseconds
+	};
+
+	gpu_timeline() = default;
+	~gpu_timeline();
+	gpu_timeline(const gpu_timeline &) = delete;
+	gpu_timeline &operator=(const gpu_timeline &) = delete;
+
+	// 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();
+	bool active() const
+	{
+		return m_active;
+	}
+	// parts of the most recent finished frame in the order they came first, the time of parts of the same name added up
+	std::vector<part> const &result();
+	// from the first mark of that frame to the last
+	uint64_t total() const
+	{
+		return m_total;
+	}
+
+  private:
+	void collect();
+
+	static constexpr size_t SLOTS = 4;
+	static constexpr size_t MARKS = 32; // per frame, the last one included
+	struct frame
+	{
+		std::array<GLuint, MARKS> queries{};
+		std::array<char const *, MARKS> names{};
+		size_t count = 0; // marks put
+		bool pending = false;
+	};
+	std::array<frame, SLOTS> m_frames;
+	// slot written by the next begin(), also the oldest one still pending
+	size_t m_slot = 0;
+	bool m_active = false;
+	std::vector<part> m_last;
+	uint64_t m_total = 0;
+};
 }

rendering/opengl46/opengl46renderer.cpp

@@ -652,6 +652,8 @@ bool opengl46_renderer::Render()
 		m_gllasttime = *result;
 		m_timequery->begin();
 	}
+	// the context of the main view is current here, the one of the previous frame's end
+	m_gputimeline.begin("frame setup");
 
 	// fetch simulation data
 	if (simulation::is_ready)
@@ -729,6 +731,7 @@ bool opengl46_renderer::Render()
 	gl::framebuffer::unbind();
 
 	m_current_viewport = &(*m_viewports.front());
+	m_gputimeline.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" +=
@@ -780,6 +783,15 @@ void opengl46_renderer::SwapBuffers()
     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<double>( m_gputimeline.total() ) / 1000000.0, 3 ) + " ms\n";
+        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";
+    }
     if (auto const clusterstime = m_clusterstimer.result())
         m_debugtimestext += " clusters: " + to_string(static_cast<double>(*clusterstime) / 1000000.0, 3) + " ms\n";
     if (auto const culltime = m_cullstimer.result())
@@ -1063,6 +1075,11 @@ void opengl46_renderer::Render_pass(viewport_config &vp, rendermode const Mode)
 		}
 
         m_colorpass = m_renderpass; // cache pass data
+		// 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);
+		};
 
 		scene_ubs.time = Timer::GetTime();
 		{
@@ -1135,6 +1152,7 @@ void opengl46_renderer::Render_pass(viewport_config &vp, rendermode const Mode)
 
 		if (Global.gfx_envmap_enabled && vp.main)
 		{
+			gpupart("reflections");
 			// potentially update environmental cube map
             m_renderpass.draw_stats = {};
 			Timer::subsystem.gfx_reflections.start();
@@ -1149,11 +1167,13 @@ void opengl46_renderer::Render_pass(viewport_config &vp, rendermode const Mode)
 
 		if (vp.main)
 		{
+			gpupart("lamp and headlight shadows");
 			Render_local_shadows();
 			Render_lamp_shadows();
 			Render_headlight_shadows();
 		}
 
+		gpupart("clear, clusters, lights");
 		glClearColor(0.0f, 0.0f, 0.0f, 0.0f);
 
 		setup_drawing(false);
@@ -1231,6 +1251,7 @@ void opengl46_renderer::Render_pass(viewport_config &vp, rendermode const Mode)
         }
 
         // the clouds of the view and the fog volume, which take the lights of the clusters and the shadow map of the pass
+        gpupart("clouds, fog volume");
         {
             auto const fogtarget{ Global.gfx_skippipeline ? target_size : glm::ivec2{ vp.width, vp.height } };
             if( vp.main ) {
@@ -1244,6 +1265,7 @@ void opengl46_renderer::Render_pass(viewport_config &vp, rendermode const Mode)
         }
 
 		glDebug("render environment");
+		gpupart("sky");
 
 		scene_ubs.projection = OpenGLMatrices.data(GL_PROJECTION);
 		// back to the rotation of the camera after the faces of the environment map, which are drawn with their own
@@ -1261,14 +1283,19 @@ void opengl46_renderer::Render_pass(viewport_config &vp, rendermode const Mode)
 		if ((Global.gfx_depthprepass_scene || contactshadows) && vp.main && (false == Global.bWireFrame))
 		{
 			glDebug("render scene depth");
+			gpupart("scene depth");
 			Render_Scene_Depth(future);
 			if (contactshadows)
+			{
+				gpupart("contact shadows depth");
 				Setup_Contact_Shadows(vp);
+			}
 		}
 		if (vp.main)
 			m_contactshadowslast = m_contactshadows;
 
 		// opaque parts...
+		gpupart("colour, opaque");
 		setup_drawing(false);
 
 		// without rain/snow we can render the cab early to limit the overdraw
@@ -1299,6 +1326,7 @@ void opengl46_renderer::Render_pass(viewport_config &vp, rendermode const Mode)
 
 		// ...translucent parts
 		glDebug("render translucent region");
+		gpupart("colour, translucent and cab");
 		setup_drawing(true);
 		Render_Alpha(simulation::Region);
 		Render_editor_overlay();
@@ -1359,6 +1387,7 @@ void opengl46_renderer::Render_pass(viewport_config &vp, rendermode const Mode)
 
 if (!Global.gfx_skippipeline)
 		{
+			gpupart("resolve, ambient occlusion, motion blur");
 			// the targets of the ambient occlusion are there only when it was on at the start
 			auto const aomode{(vp.ssao_tex != nullptr) ? Global.gfx_postfx_ao : 0};
 			if (Global.gfx_postfx_motionblur_enabled)
@@ -1389,6 +1418,7 @@ if (!Global.gfx_skippipeline)
 				}
 			}
 
+			gpupart("exposure, bloom");
 			// the exposure follows the main view; the other viewports use it too
 			if (Global.gfx_postfx_autoexposure && vp.main)
 				m_exposure.measure(*vp.main2_tex, Timer::GetDeltaRenderTime());
@@ -1407,6 +1437,7 @@ if (!Global.gfx_skippipeline)
 			if (bloomtexture != nullptr)
 				tonemapinput.push_back(bloomtexture);
 
+			gpupart("tonemapping, output");
 			if (!Global.gfx_shadergamma)
 				glEnable(GL_FRAMEBUFFER_SRGB);
 
@@ -1459,6 +1490,7 @@ if (!Global.gfx_skippipeline)
 			glDisable(GL_FRAMEBUFFER_SRGB);
 
 		glDebug("uilayer render");
+		gpupart("ui");
 		Timer::subsystem.gfx_gui.start();
 
         if (vp.main) {
@@ -1470,6 +1502,10 @@ if (!Global.gfx_skippipeline)
 
         Timer::subsystem.gfx_gui.stop();
 
+		// viewports drawn after this one in the same context (vr) land in the last part; others aren't measured
+		if (m_viewports.size() > 1)
+			gpupart("other viewports");
+
 		// restore binding
 		scene_ubo->bind_uniform();
 
@@ -1502,6 +1538,11 @@ if (!Global.gfx_skippipeline)
 
         for( auto idx = 0; idx < m_shadowpass.size(); ++idx ) {
 
+            // the pass is drawn for the main view only
+            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_shadow_fb->attach( *m_shadow_tex, GL_DEPTH_ATTACHMENT, idx );
             m_shadow_fb->clear( GL_DEPTH_BUFFER_BIT );
 
@@ -4195,6 +4236,9 @@ opengl46_renderer::indirect_counts opengl46_renderer::Render_Instances_Indirect_
 
 opengl46_renderer::indirect_counts opengl46_renderer::Render_Instances_Indirect_Depth( opengl46_instance_cull::command_set const Set )
 {
+	// the draws were recorded with the seed of scenery models and sleepers, 0 (TAnimModel::RaPrepare()); vehicles drawn since
+	// leave their own, which would pick other texture variants than those the draws were recorded and ordered with
+	TSubModel::iVariantSeed = 0;
 	indirect_counts counts;
 	auto const count { m_indirectdraws.size() };
 	// whether the prepass of the class draws the draw, and with which diffuse texture (class 2)
@@ -4283,6 +4327,8 @@ opengl46_renderer::indirect_counts opengl46_renderer::Render_Instances_Indirect_
 
 opengl46_renderer::indirect_counts opengl46_renderer::Render_Instances_Indirect_Colour( opengl46_instance_cull::command_set const Set )
 {
+	// as in Render_Instances_Indirect_Depth(): the seed the draws were recorded with
+	TSubModel::iVariantSeed = 0;
 	indirect_counts counts;
 	auto const count { m_indirectdraws.size() };
 	for( std::size_t index = 0; index < count; ) {

rendering/opengl46/opengl46renderer.h

@@ -702,6 +702,8 @@ class opengl46_renderer : public gfx_renderer {
 
 	std::optional<gl::query> m_timequery;
 	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;
 	// 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