refactor debug info, measure render times

internal/game/imgui.go

@@ -52,13 +52,17 @@ func (g *Game) initImgui(win *glfw.Window) {
 }
 
 func (g *Game) imgui() {
+
+	io.Diagnostics.CgoCalls = runtime.NumCgoCall() - g.gui.lastframeCgoCalls
+	g.gui.lastframeCgoCalls = runtime.NumCgoCall()
+
 	if io.ShowDebugInfo {
 		imgui.SetNextWindowPosV(imgui.Vec2{}, imgui.ConditionAlways, imgui.Vec2{})
 		imgui.SetNextWindowSize(imgui.Vec2{X: float32(io.DisplaySize[0]), Y: float32(io.DisplaySize[1])})
 		if igwrap.Begin("F3", nil, igwrap.WindowFlagsOverlay) {
 			igwrap.TextBackground("Gl01 compiled by %s/%s [%s/%s] (120AVG) %.1f FPS (%.3f frame)", runtime.Compiler, runtime.Version(), runtime.GOOS, runtime.GOARCH, imgui.CurrentIO().Framerate(), 1000/imgui.CurrentIO().Framerate())
 			igwrap.TextBackground("GLFW %s, Dear ImGUI %s", glfw.GetVersionString(), imgui.Version())
-			igwrap.TextBackground("CgoCalls:%d (%d lastframe), Goroutines:%d", runtime.NumCgoCall(), runtime.NumCgoCall()-g.gui.lastframeCgoCalls, runtime.NumGoroutine())
+			igwrap.TextBackground("CgoCalls:%d (%d lastframe), Goroutines:%d", g.gui.lastframeCgoCalls, io.Diagnostics.CgoCalls, runtime.NumGoroutine())
 			igwrap.TextBlank()
 
 			pos := g.player.Position()
@@ -66,7 +70,6 @@ func (g *Game) imgui() {
 			imgui.End()
 		}
 	}
-	g.gui.lastframeCgoCalls = runtime.NumCgoCall()
 
 	if imgui.BeginV("Player", nil, imgui.WindowFlagsAlwaysAutoResize) {
 		pos := g.player.Position()

internal/game/logic.go

@@ -9,6 +9,7 @@ import (
 	"edgaru089.ml/go/gl01/internal/igwrap/backend"
 	"edgaru089.ml/go/gl01/internal/io"
 	"edgaru089.ml/go/gl01/internal/render"
+	"edgaru089.ml/go/gl01/internal/util"
 	"edgaru089.ml/go/gl01/internal/util/itype"
 	"edgaru089.ml/go/gl01/internal/world"
 	"edgaru089.ml/go/gl01/internal/world/worldgen"
@@ -174,7 +175,8 @@ const airAccel = 0.1
 // Update updates the game state, not necessarily in the main thread.
 func (g *Game) Update(win *glfw.Window, delta time.Duration) {
 	backend.NewFrame()
-	imgui.ShowDemoWindow(nil)
+
+	clock := util.NewClock()
 
 	if !g.paused {
 
@@ -242,7 +244,12 @@ func (g *Game) Update(win *glfw.Window, delta time.Duration) {
 		g.player.SetSpeed(itype.Vec3d{})
 	}
 
+	io.Diagnostics.Times.Logic = clock.Restart()
+
+	imgui.ShowDemoWindow(nil)
 	g.imgui()
+
+	io.Diagnostics.Times.GUI = clock.Restart()
 }
 
 // Render, called with a OpenGL context, renders the game.

internal/io/io.go

@@ -1,6 +1,10 @@
 package io
 
-import "edgaru089.ml/go/gl01/internal/util/itype"
+import (
+	"time"
+
+	"edgaru089.ml/go/gl01/internal/util/itype"
+)
 
 var (
 	DisplaySize itype.Vec2i // Size of the window viewport in pixels.
@@ -13,4 +17,19 @@ var (
 	RenderPos, RenderDir itype.Vec3d // Position and Direction of view for the current render pass. Might be different for e.g. lighting passes
 
 	ShowDebugInfo bool // Show debug info (F3 screen)?
+
+	// Per-Frame Diagnostics information
+	Diagnostics struct {
+		CgoCalls int64    // Cgo calls in the last frame
+		Times    struct { // Times spent
+			GUI, Logic, Render time.Duration
+			RenderPasses       struct {
+				Depthmap,
+				Geometry,
+				SSAO,
+				Lighting,
+				Postfx time.Duration
+			}
+		}
+	}
 )

internal/render/render_world.go

@@ -2,7 +2,6 @@ package render
 
 import (
 	"errors"
-	"math"
 	"math/rand"
 	"time"
 	"unsafe"
@@ -305,6 +304,9 @@ var (
 )
 
 func (r *WorldRenderer) Render(world *world.World, view *View) {
+	allclock := util.NewClock()
+	lastclock := util.NewClock()
+
 	io.RenderPos = io.ViewPos
 	io.RenderDir = io.ViewDir
 
@@ -337,6 +339,8 @@ func (r *WorldRenderer) Render(world *world.World, view *View) {
 	gl.Enable(gl.DEPTH_TEST)
 	gl.DepthFunc(gl.LESS)
 
+	lastclock.Restart()
+
 	// 1. Render to depth map
 	gl.Viewport(0, 0, int32(ShadowmapSize[0]), int32(ShadowmapSize[1]))
 	gl.BindFramebuffer(gl.FRAMEBUFFER, r.depthmap.fbo)
@@ -356,6 +360,8 @@ func (r *WorldRenderer) Render(world *world.World, view *View) {
 	world.Render()
 	world.RenderWater()
 
+	io.Diagnostics.Times.RenderPasses.Depthmap = lastclock.Restart()
+
 	// 2. Geometry pass, render to G-buffer
 	io.RenderPos = io.ViewPos
 	io.RenderDir = io.ViewDir
@@ -376,6 +382,8 @@ func (r *WorldRenderer) Render(world *world.World, view *View) {
 
 	world.Render()
 
+	io.Diagnostics.Times.RenderPasses.Geometry = lastclock.Restart()
+
 	// 3/1. SSAO pass
 	gl.BindFramebuffer(gl.FRAMEBUFFER, r.ssao.fbo)
 	gl.ClearColor(1, 1, 1, 1)
@@ -386,7 +394,6 @@ func (r *WorldRenderer) Render(world *world.World, view *View) {
 	r.ssao.shader.SetUniformMat4("view", view.View())
 	r.ssao.shader.SetUniformMat4("projection", view.Perspective())
 	r.ssao.shader.SetUniformVec3f("viewPos", view.EyePos)
-	r.ssao.shader.SetUniformFloat("time", float32(time.Since(r.startTime).Seconds()))
 
 	DrawScreenQuad()
 
@@ -398,6 +405,8 @@ func (r *WorldRenderer) Render(world *world.World, view *View) {
 
 	DrawScreenQuad()
 
+	io.Diagnostics.Times.RenderPasses.SSAO = lastclock.Restart()
+
 	// 4. Render the actual output with deferred lighting
 	gl.BindFramebuffer(gl.FRAMEBUFFER, r.output.fbo)
 	gl.ClearColor(0, 0, 0, 0)
@@ -412,6 +421,8 @@ func (r *WorldRenderer) Render(world *world.World, view *View) {
 
 	DrawScreenQuad()
 
+	io.Diagnostics.Times.RenderPasses.Lighting = lastclock.Restart()
+
 	// 5. Render water
 	gl.Enable(gl.DEPTH_TEST)
 	gl.DepthFunc(gl.LESS)
@@ -445,46 +456,11 @@ func (r *WorldRenderer) Render(world *world.World, view *View) {
 
 	DrawScreenQuad()
 
-	// Show G-buffers?
+	io.Diagnostics.Times.RenderPasses.Postfx = lastclock.Restart()
+	io.Diagnostics.Times.Render = allclock.Elapsed()
+
+	// Show Information?
 	if io.ShowDebugInfo {
-		imgui.SetNextWindowPosV(imgui.Vec2{X: float32(r.lastDisplaySize[0]), Y: 0}, imgui.ConditionAlways, imgui.Vec2{X: 1, Y: 0})
+		r.renderDebugInfo()
-		if igwrap.Begin("Renderer Textures/Outputs", nil, igwrap.WindowFlagsOverlay) {
-			imgui.PushStyleVarVec2(imgui.StyleVarItemSpacing, imgui.Vec2{})
-
-			imageSize := r.lastDisplaySize.ToFloat32().Multiply(0.25)
-			imageSize[1] -= imgui.CurrentStyle().WindowPadding().Y / 2
-			imageSize[0] = imageSize[1] / float32(r.lastDisplaySize[1]) * float32(r.lastDisplaySize[0])
-
-			igwrap.Image(r.gbuffer.pos, imageSize, itype.Rectf{0, 0, 1, 1})
-			igwrap.Image(r.gbuffer.norm, imageSize, itype.Rectf{0, 0, 1, 1})
-			igwrap.Image(r.gbuffer.color, imageSize, itype.Rectf{0, 0, 1, 1})
-			igwrap.Image(r.ssao.ambient, imageSize, itype.Rectf{0, 0, 1, 1})
-
-			imgui.PopStyleVar()
-			imgui.End()
-		}
-
-		if igwrap.Begin("F3", nil, 0) {
-			imgui.PushStyleColor(imgui.StyleColorButton, imgui.Vec4{0, 0, 0, 0.5})
-			imgui.PushStyleColor(imgui.StyleColorButtonHovered, imgui.Vec4{0, 0, 0, 0.6})
-			imgui.PushStyleColor(imgui.StyleColorButtonActive, imgui.Vec4{0, 0, 0, 0.8})
-			igwrap.TextBlank()
-			isize := asset.WorldTextureAtlas.ImageSize
-			igwrap.TextBackground("Texture Atlas Size: (%dx%d)", isize[0], isize[1])
-			imgui.SameLine()
-			igwrap.TextBackground("[Hover]")
-			if imgui.IsItemHoveredV(imgui.HoveredFlagsAllowWhenDisabled) {
-				_, wheely := imgui.CurrentIO().MouseWheel()
-				if math.Abs(float64(wheely)) > 1e-3 {
-					atlasScale = util.Maxf(1, atlasScale+wheely)
-				}
-				imgui.BeginTooltip()
-				igwrap.Image(r.texture.Handle(), isize.ToFloat32().Multiply(atlasScale), itype.Rectf{0, 0, 1, 1})
-				imgui.EndTooltip()
-			}
-
-			imgui.PopStyleColorV(3)
-			imgui.End()
-		}
 	}
 }

internal/render/render_world_debuginfo.go

@@ -0,0 +1,56 @@
+package render
+
+import (
+	"math"
+	"time"
+
+	"edgaru089.ml/go/gl01/internal/asset"
+	"edgaru089.ml/go/gl01/internal/igwrap"
+	"edgaru089.ml/go/gl01/internal/io"
+	"edgaru089.ml/go/gl01/internal/util"
+	"edgaru089.ml/go/gl01/internal/util/itype"
+	"github.com/inkyblackness/imgui-go/v4"
+)
+
+func (r *WorldRenderer) renderDebugInfo() {
+	// Render information
+	if igwrap.Begin("F3", nil, 0) {
+		igwrap.TextBlank()
+
+		igwrap.TextBackground("WorldRender: lastframe %.3fms", float64(io.Diagnostics.Times.Render.Nanoseconds())/float64(time.Millisecond))
+
+		isize := asset.WorldTextureAtlas.ImageSize
+		igwrap.TextBackground("Texture Atlas Size: (%dx%d)", isize[0], isize[1])
+		imgui.SameLine()
+		igwrap.TextBackground("[Hover]")
+		if imgui.IsItemHoveredV(imgui.HoveredFlagsAllowWhenDisabled) {
+			_, wheely := imgui.CurrentIO().MouseWheel()
+			if math.Abs(float64(wheely)) > 1e-3 {
+				atlasScale = util.Maxf(1, atlasScale+wheely)
+			}
+			imgui.BeginTooltip()
+			igwrap.Image(r.texture.Handle(), isize.ToFloat32().Multiply(atlasScale), itype.Rectf{0, 0, 1, 1})
+			imgui.EndTooltip()
+		}
+
+		imgui.End()
+	}
+
+	imgui.SetNextWindowPosV(imgui.Vec2{X: float32(r.lastDisplaySize[0]), Y: 0}, imgui.ConditionAlways, imgui.Vec2{X: 1, Y: 0})
+	if igwrap.Begin("Renderer Textures/Outputs", nil, igwrap.WindowFlagsOverlay) {
+		imgui.PushStyleVarVec2(imgui.StyleVarItemSpacing, imgui.Vec2{})
+
+		imageSize := r.lastDisplaySize.ToFloat32().Multiply(0.25)
+		imageSize[1] -= imgui.CurrentStyle().WindowPadding().Y / 2
+		imageSize[0] = imageSize[1] / float32(r.lastDisplaySize[1]) * float32(r.lastDisplaySize[0])
+
+		igwrap.Image(r.gbuffer.pos, imageSize, itype.Rectf{0, 0, 1, 1})
+		igwrap.Image(r.gbuffer.norm, imageSize, itype.Rectf{0, 0, 1, 1})
+		igwrap.Image(r.gbuffer.color, imageSize, itype.Rectf{0, 0, 1, 1})
+		igwrap.Image(r.ssao.ambient, imageSize, itype.Rectf{0, 0, 1, 1})
+
+		imgui.PopStyleVar()
+		imgui.End()
+	}
+
+}

internal/util/clock.go

@@ -0,0 +1,28 @@
+package util
+
+import "time"
+
+// Clock is a clock to measure elapsed time.
+// It is a shorthand for the time.Since() and time.Now() combo.
+type Clock struct {
+	t time.Time
+}
+
+// NewClock returns a new clock.
+// It also starts it.
+func NewClock() (c *Clock) {
+	return &Clock{t: time.Now()}
+}
+
+// Restart resets the start time.
+// It also returns the elapsed time.
+func (c *Clock) Restart() (t time.Duration) {
+	t = time.Since(c.t)
+	c.t = time.Now()
+	return
+}
+
+// Elapsed returns the elapsed time.
+func (c *Clock) Elapsed() time.Duration {
+	return time.Since(c.t)
+}