From 1678f922e7f553a4763d749d0019562bcd310f48 Mon Sep 17 00:00:00 2001
From: Elias Naur <mail@eliasnaur.com>
Date: Fri, 8 Nov 2019 13:29:35 +0100
Subject: [PATCH] app: make CPU timings more useful

Record the time for generating a frame and submitting it as well
as the time for issuing the frame to the GPU and swapping buffers.

Signed-off-by: Elias Naur <mail@eliasnaur.com>
---
 app/internal/gpu/gpu.go |  4 +++-
 app/window.go           | 25 ++++++++-----------------
 2 files changed, 11 insertions(+), 18 deletions(-)

diff --git a/app/internal/gpu/gpu.go b/app/internal/gpu/gpu.go
index 3c8e86cd..abbc2934 100644
--- a/app/internal/gpu/gpu.go
+++ b/app/internal/gpu/gpu.go
@@ -291,6 +291,7 @@ func (g *GPU) renderLoop(glctx gl.Context) error {
 				g.refreshErr <- glctx.MakeCurrent()
 			case frame := <-g.frames:
 				glctx.Lock()
+				frameStart := time.Now()
 				if frame.collectStats && timers == nil && ctx.caps.EXT_disjoint_timer_query {
 					timers = newTimers(ctx)
 					zopsTimer = timers.newTimer()
@@ -348,8 +349,9 @@ func (g *GPU) renderLoop(glctx gl.Context) error {
 					ft := zt + st + covt + cleant
 					q := 100 * time.Microsecond
 					zt, st, covt = zt.Round(q), st.Round(q), covt.Round(q)
+					frameDur := time.Since(frameStart).Round(q)
 					ft = ft.Round(q)
-					res.summary = fmt.Sprintf("f:%7s zt:%7s st:%7s cov:%7s", ft, zt, st, covt)
+					res.summary = fmt.Sprintf("draw:%7s gpu:%7s zt:%7s st:%7s cov:%7s", frameDur, ft, zt, st, covt)
 				}
 				res.err = err
 				glctx.Unlock()
diff --git a/app/window.go b/app/window.go
index 2d21d3b0..31a7cfeb 100644
--- a/app/window.go
+++ b/app/window.go
@@ -26,10 +26,8 @@ type Option func(opts *window.Options)
 
 // Window represents an operating system window.
 type Window struct {
-	driver    window.Driver
-	lastFrame time.Time
-	drawStart time.Time
-	gpu       *gpu.GPU
+	driver window.Driver
+	gpu    *gpu.GPU
 
 	out         chan event.Event
 	in          chan event.Event
@@ -123,27 +121,20 @@ func (w *Window) update(frame *op.Ops) {
 	<-w.frameAck
 }
 
-func (w *Window) draw(size image.Point, frame *op.Ops) {
-	var drawDur time.Duration
-	if !w.drawStart.IsZero() {
-		drawDur = time.Since(w.drawStart)
-		w.drawStart = time.Time{}
-	}
+func (w *Window) draw(frameStart time.Time, size image.Point, frame *op.Ops) {
 	w.gpu.Draw(w.queue.q.Profiling(), size, frame)
 	w.queue.q.Frame(frame)
-	now := time.Now()
 	switch w.queue.q.TextInputState() {
 	case input.TextInputOpen:
 		w.driver.ShowTextInput(true)
 	case input.TextInputClose:
 		w.driver.ShowTextInput(false)
 	}
-	frameDur := now.Sub(w.lastFrame)
-	frameDur = frameDur.Truncate(100 * time.Microsecond)
-	w.lastFrame = now
 	if w.queue.q.Profiling() {
+		frameDur := time.Since(frameStart)
+		frameDur = frameDur.Truncate(100 * time.Microsecond)
 		q := 100 * time.Microsecond
-		timings := fmt.Sprintf("tot:%7s cpu:%7s %s", frameDur.Round(q), drawDur.Round(q), w.gpu.Timings())
+		timings := fmt.Sprintf("tot:%7s %s", frameDur.Round(q), w.gpu.Timings())
 		w.queue.q.AddProfile(profile.Event{Timings: timings})
 	}
 	if t, ok := w.queue.q.WakeupTime(); ok {
@@ -260,7 +251,7 @@ func (w *Window) run(opts *window.Options) {
 					// No drawing if not visible.
 					break
 				}
-				w.drawStart = time.Now()
+				frameStart := time.Now()
 				w.hasNextFrame = false
 				e2.Frame = w.update
 				w.out <- e2.FrameEvent
@@ -297,8 +288,8 @@ func (w *Window) run(opts *window.Options) {
 					w.destroy(err)
 					return
 				}
+				w.draw(frameStart, e2.Size, frame)
 				if gotFrame {
-					w.draw(e2.Size, frame)
 					// We're done with frame, let the client continue.
 					w.frameAck <- struct{}{}
 				}