utils: Added logger helper to log time

Added this to all the dispatchers and Client Draw/Update methods.

This will help to track why sometimes things go really slow on bouth sides

client/action.go

@@ -42,12 +42,9 @@ func NewActionDispatcher(d *flux.Dispatcher, s *store.Store, l *slog.Logger, opt
 // This should only be used from the WS Handler to forward server actions directly
 func (ac *ActionDispatcher) Dispatch(a *action.Action) {
 	b := time.Now()
+	defer utils.LogTime(ac.logger, b, "action dispatched", "action", a.Type)
+
 	ac.dispatcher.Dispatch(a)
-	d := time.Now().Sub(b)
-	if d > time.Millisecond {
-		ac.logger.Info("action dispatched", "type", a.Type, "time", d)
-	}
-	ac.logger.Debug("action dispatched", "type", a.Type, "time", d)
 }
 
 // CursorMove dispatches an action of moving the Cursor

client/camera.go

@@ -1,6 +1,9 @@
 package client
 
 import (
+	"log/slog"
+	"time"
+
 	"github.com/hajimehoshi/ebiten/v2"
 	"github.com/xescugc/go-flux"
 	"github.com/xescugc/maze-wars/action"
@@ -16,6 +19,8 @@ type CameraStore struct {
 
 	Store *store.Store
 
+	logger *slog.Logger
+
 	cameraSpeed float64
 }
 
@@ -36,9 +41,10 @@ const (
 // NewCameraStore creates a new CameraState linked to the Dispatcher d
 // with the Game g and with width w and height h which is the size of
 // the viewport
-func NewCameraStore(d *flux.Dispatcher, s *store.Store, w, h int) *CameraStore {
+func NewCameraStore(d *flux.Dispatcher, s *store.Store, l *slog.Logger, w, h int) *CameraStore {
 	cs := &CameraStore{
 		Store:       s,
+		logger:      l,
 		cameraSpeed: 10,
 	}
 
@@ -54,6 +60,9 @@ func NewCameraStore(d *flux.Dispatcher, s *store.Store, w, h int) *CameraStore {
 }
 
 func (cs *CameraStore) Update() error {
+	b := time.Now()
+	defer utils.LogTime(cs.logger, b, "camera update")
+
 	// TODO: https://github.com/xescugc/maze-wars/issues/4
 	//s := cs.GetState().(CameraState)
 	//if _, wy := ebiten.Wheel(); wy != 0 {
@@ -66,7 +75,10 @@ func (cs *CameraStore) Update() error {
 	return nil
 }
 
-func (cs *CameraStore) Draw(screen *ebiten.Image) {}
+func (cs *CameraStore) Draw(screen *ebiten.Image) {
+	b := time.Now()
+	defer utils.LogTime(cs.logger, b, "camera draw")
+}
 
 func (cs *CameraStore) Reduce(state, a interface{}) interface{} {
 	act, ok := a.(*action.Action)

client/game.go

@@ -1,8 +1,12 @@
 package client
 
 import (
+	"log/slog"
+	"time"
+
 	"github.com/hajimehoshi/ebiten/v2"
 	"github.com/xescugc/maze-wars/store"
+	"github.com/xescugc/maze-wars/utils"
 )
 
 // Game is the main struct that is the initializer
@@ -18,9 +22,21 @@ type Game struct {
 	Towers *Towers
 
 	Map *Map
+
+	Logger *slog.Logger
+}
+
+func NewGame(s *store.Store, l *slog.Logger) *Game {
+	return &Game{
+		Store:  s,
+		Logger: l,
+	}
 }
 
 func (g *Game) Update() error {
+	b := time.Now()
+	defer utils.LogTime(g.Logger, b, "game update")
+
 	g.Map.Update()
 	g.Camera.Update()
 	g.Units.Update()
@@ -33,6 +49,9 @@ func (g *Game) Update() error {
 }
 
 func (g *Game) Draw(screen *ebiten.Image) {
+	b := time.Now()
+	defer utils.LogTime(g.Logger, b, "game draw")
+
 	g.Map.Draw(screen)
 	g.Camera.Draw(screen)
 	g.HUD.Draw(screen)

client/hud.go

@@ -7,6 +7,7 @@ import (
 	"sort"
 	"strconv"
 	"strings"
+	"time"
 
 	"github.com/ebitenui/ebitenui"
 	"github.com/ebitenui/ebitenui/image"
@@ -95,6 +96,9 @@ func NewHUDStore(d *flux.Dispatcher, g *Game) (*HUDStore, error) {
 }
 
 func (hs *HUDStore) Update() error {
+	b := time.Now()
+	defer utils.LogTime(hs.game.Logger, b, "hud update")
+
 	hs.ui.Update()
 
 	cs := hs.game.Camera.GetState().(CameraState)
@@ -269,6 +273,8 @@ func (hs *HUDStore) Update() error {
 }
 
 func (hs *HUDStore) Draw(screen *ebiten.Image) {
+	b := time.Now()
+	defer utils.LogTime(hs.game.Logger, b, "hud draw")
 
 	hst := hs.GetState().(HUDState)
 	cs := hs.game.Camera.GetState().(CameraState)

client/lobby.go

@@ -3,13 +3,16 @@ package client
 import (
 	"fmt"
 	"image/color"
+	"log/slog"
+	"time"
 
 	"github.com/ebitenui/ebitenui"
 	"github.com/ebitenui/ebitenui/image"
 	"github.com/ebitenui/ebitenui/widget"
 	"github.com/hajimehoshi/ebiten/v2"
 	"github.com/xescugc/go-flux"
 	"github.com/xescugc/maze-wars/action"
+	"github.com/xescugc/maze-wars/utils"
 )
 
 var (
@@ -19,7 +22,8 @@ var (
 type LobbyStore struct {
 	*flux.ReduceStore
 
-	Store *Store
+	Store  *Store
+	Logger *slog.Logger
 
 	ui           *ebitenui.UI
 	textPlayersW *widget.Text
@@ -29,9 +33,10 @@ type LobbyState struct {
 	TotalUsers int
 }
 
-func NewLobbyStore(d *flux.Dispatcher, s *Store) (*LobbyStore, error) {
+func NewLobbyStore(d *flux.Dispatcher, s *Store, l *slog.Logger) (*LobbyStore, error) {
 	ls := &LobbyStore{
-		Store: s,
+		Store:  s,
+		Logger: l,
 	}
 	ls.ReduceStore = flux.NewReduceStore(d, ls.Reduce, LobbyState{})
 
@@ -41,11 +46,17 @@ func NewLobbyStore(d *flux.Dispatcher, s *Store) (*LobbyStore, error) {
 }
 
 func (ls *LobbyStore) Update() error {
+	b := time.Now()
+	defer utils.LogTime(ls.Logger, b, "lobby update")
+
 	ls.ui.Update()
 	return nil
 }
 
 func (ls *LobbyStore) Draw(screen *ebiten.Image) {
+	b := time.Now()
+	defer utils.LogTime(ls.Logger, b, "lobby draw")
+
 	lstate := ls.GetState().(LobbyState)
 	ls.textPlayersW.Label = fmt.Sprintf("Users online: %d", lstate.TotalUsers)
 	ls.ui.Draw(screen)

client/map.go

@@ -2,9 +2,11 @@ package client
 
 import (
 	"image"
+	"time"
 
 	"github.com/hajimehoshi/ebiten/v2"
 	"github.com/xescugc/maze-wars/store"
+	"github.com/xescugc/maze-wars/utils"
 )
 
 type Map struct {
@@ -20,10 +22,16 @@ func NewMap(g *Game) *Map {
 }
 
 func (m *Map) Update() error {
+	b := time.Now()
+	defer utils.LogTime(m.game.Logger, b, "map update")
+
 	return nil
 }
 
 func (m *Map) Draw(screen *ebiten.Image) {
+	b := time.Now()
+	defer utils.LogTime(m.game.Logger, b, "map draw")
+
 	// Draw will draw just a partial image of the map based on the viewport, so it does not render everything but just the
 	// part that it's seen by the user
 	// If we want to render everything and just move the viewport around we need o render the full image and change the

client/router.go

@@ -1,9 +1,13 @@
 package client
 
 import (
+	"log/slog"
+	"time"
+
 	"github.com/hajimehoshi/ebiten/v2"
 	"github.com/xescugc/go-flux"
 	"github.com/xescugc/maze-wars/action"
+	"github.com/xescugc/maze-wars/utils"
 )
 
 const (
@@ -20,18 +24,20 @@ type RouterStore struct {
 	lobby       *LobbyStore
 	signUp      *SignUpStore
 	waitingRoom *WaitingRoomStore
+	logger      *slog.Logger
 }
 
 type RouterState struct {
 	Route string
 }
 
-func NewRouterStore(d *flux.Dispatcher, su *SignUpStore, l *LobbyStore, wr *WaitingRoomStore, g *Game) *RouterStore {
+func NewRouterStore(d *flux.Dispatcher, su *SignUpStore, ls *LobbyStore, wr *WaitingRoomStore, g *Game, l *slog.Logger) *RouterStore {
 	rs := &RouterStore{
 		game:        g,
-		lobby:       l,
+		lobby:       ls,
 		signUp:      su,
 		waitingRoom: wr,
+		logger:      l,
 	}
 
 	rs.ReduceStore = flux.NewReduceStore(d, rs.Reduce, RouterState{
@@ -43,6 +49,9 @@ func NewRouterStore(d *flux.Dispatcher, su *SignUpStore, l *LobbyStore, wr *Wait
 }
 
 func (rs *RouterStore) Update() error {
+	b := time.Now()
+	defer utils.LogTime(rs.logger, b, "router update")
+
 	rstate := rs.GetState().(RouterState)
 	switch rstate.Route {
 	case SignUpRoute:
@@ -58,6 +67,9 @@ func (rs *RouterStore) Update() error {
 }
 
 func (rs *RouterStore) Draw(screen *ebiten.Image) {
+	b := time.Now()
+	defer utils.LogTime(rs.logger, b, "router draw")
+
 	rstate := rs.GetState().(RouterState)
 	switch rstate.Route {
 	case SignUpRoute:

client/sign_up.go

@@ -3,6 +3,8 @@ package client
 import (
 	"image"
 	"image/color"
+	"log/slog"
+	"time"
 
 	"github.com/ebitenui/ebitenui"
 	euiimage "github.com/ebitenui/ebitenui/image"
@@ -13,6 +15,7 @@ import (
 	"github.com/xescugc/go-flux"
 	"github.com/xescugc/maze-wars/action"
 	"github.com/xescugc/maze-wars/store"
+	"github.com/xescugc/maze-wars/utils"
 )
 
 var (
@@ -22,7 +25,8 @@ var (
 type SignUpStore struct {
 	*flux.ReduceStore
 
-	Store *store.Store
+	Store  *store.Store
+	Logger *slog.Logger
 
 	Camera *CameraStore
 
@@ -34,9 +38,10 @@ type SignUpState struct {
 	Error string
 }
 
-func NewSignUpStore(d *flux.Dispatcher, s *store.Store) (*SignUpStore, error) {
+func NewSignUpStore(d *flux.Dispatcher, s *store.Store, l *slog.Logger) (*SignUpStore, error) {
 	su := &SignUpStore{
-		Store: s,
+		Store:  s,
+		Logger: l,
 	}
 	su.ReduceStore = flux.NewReduceStore(d, su.Reduce, SignUpState{})
 
@@ -46,11 +51,17 @@ func NewSignUpStore(d *flux.Dispatcher, s *store.Store) (*SignUpStore, error) {
 }
 
 func (su *SignUpStore) Update() error {
+	b := time.Now()
+	defer utils.LogTime(su.Logger, b, "sign_up update")
+
 	su.ui.Update()
 	return nil
 }
 
 func (su *SignUpStore) Draw(screen *ebiten.Image) {
+	b := time.Now()
+	defer utils.LogTime(su.Logger, b, "sign_up draw")
+
 	sutate := su.GetState().(SignUpState)
 	if sutate.Error != "" {
 		su.inputErrorW.GetWidget().Visibility = widget.Visibility_Show

client/towers.go

@@ -3,11 +3,13 @@ package client
 import (
 	"bytes"
 	"image"
+	"time"
 
 	"github.com/hajimehoshi/ebiten/v2"
 	"github.com/xescugc/maze-wars/assets"
 	"github.com/xescugc/maze-wars/store"
 	"github.com/xescugc/maze-wars/tower"
+	"github.com/xescugc/maze-wars/utils"
 )
 
 type Towers struct {
@@ -31,6 +33,9 @@ func NewTowers(g *Game) (*Towers, error) {
 }
 
 func (ts *Towers) Update() error {
+	b := time.Now()
+	defer utils.LogTime(ts.game.Logger, b, "towers update")
+
 	uts := ts.game.Store.Units.List()
 	tws := ts.game.Store.Towers.List()
 	cp := ts.game.Store.Players.FindCurrent()
@@ -66,6 +71,9 @@ func (ts *Towers) Update() error {
 }
 
 func (ts *Towers) Draw(screen *ebiten.Image) {
+	b := time.Now()
+	defer utils.LogTime(ts.game.Logger, b, "towers draw")
+
 	for _, t := range ts.game.Store.Towers.List() {
 		ts.DrawTower(screen, ts.game.Camera, t)
 	}