Add controller performance metrics

.gitignore

@@ -23,5 +23,8 @@ installfilesdev
 
 .uptodate
 
+# vscode settings
+.vscode
+
 # allocator compiled plugin
 kubectl-gameserver

cmd/nodeagent/nodeagentmanager.go

@@ -220,6 +220,7 @@ func (n *NodeAgentManager) gameServerCreatedOrUpdated(obj *unstructured.Unstruct
 		// or that the NodeAgent crashed and we're having a new instance
 		// in any case, we're adding the details to the map
 		logger.Infof("GameServer %s/%s does not exist in cache, we're creating it", gameServerNamespace, gameServerName)
+
 		gsdi = &GameServerInfo{
 			GameServerNamespace: gameServerNamespace,
 			Mutex:               &sync.RWMutex{},
@@ -452,8 +453,12 @@ func (n *NodeAgentManager) updateHealthAndStateIfNeeded(ctx context.Context, hb
 			now := metav1.Time{Time: n.nowFunc()}
 			if hb.CurrentGameState == GameStateInitializing {
 				status.ReachedInitializingOn = &now
+				timeDif := time.Now().UnixMilli() - gsd.CreationTime
+				GameServerReachedInitializingDuration.WithLabelValues(gsd.BuildName).Set(float64(timeDif))
 			} else if hb.CurrentGameState == GameStateStandingBy {
 				status.ReachedStandingByOn = &now
+				timeDif := time.Now().UnixMilli() - gsd.CreationTime
+				GameServerReachedStandingByDuration.WithLabelValues(gsd.BuildName).Set(float64(timeDif))
 			}
 		}
 

cmd/nodeagent/types.go

@@ -58,6 +58,24 @@ var (
 		Name:      "connected_players",
 		Help:      "Number of connected players per GameServer",
 	}, []string{"namespace", "ServerName", "BuildName"})
+
+	GameServerReachedStandingByDuration = promauto.NewGaugeVec(
+		prometheus.GaugeOpts{
+			Namespace: "thundernetes",
+			Name:      "gameserver_standing_by_duration",
+			Help:      "Time taken for a GameServer to reach StandingBy",
+		},
+		[]string{"BuildName"},
+	)
+
+	GameServerReachedInitializingDuration = promauto.NewGaugeVec(
+		prometheus.GaugeOpts{
+			Namespace: "thundernetes",
+			Name:      "gameserver_initialization_duration",
+			Help:      "Time taken for a GameServer to reach initialization",
+		},
+		[]string{"BuildName"},
+	)
 )
 
 // HeartbeatRequest contains data for the heartbeat request coming from the GSDK running alongside GameServer

docs/howtos/monitoring.md

@@ -84,8 +84,11 @@ There is a custom Grafana dashboard example that visualizes some of this data in
 | --- | --- | --- |
 | gameserver_states | Gauge | nodeagent |
 | connected_players | Gauge | nodeagent |
+| gameserver_initialization_duration | Gauge | nodeagent |
+| gameserver_standing_by_duration | Gauge | nodeagent |
 | gameservers_current_state_per_build | Gauge | controller-manager |
 | gameservers_created_total | Counter | controller-manager |
+| gameservers_reconcile_standby_duration | Gauge | controller-manager | 
 | gameservers_sessionended_total | Counter | controller-manager |
 | gameservers_crashed_total | Counter | controller-manager |
 | gameservers_deleted_total | Counter | controller-manager |

pkg/operator/controllers/gameserverbuild_controller.go

@@ -23,6 +23,7 @@ import (
 	"runtime"
 	"sort"
 	"sync"
+	"time"
 
 	mpsv1alpha1 "github.com/playfab/thundernetes/pkg/operator/api/v1alpha1"
 	corev1 "k8s.io/api/core/v1"
@@ -140,6 +141,7 @@ func (r *GameServerBuildReconciler) Reconcile(ctx context.Context, req ctrl.Requ
 
 	// calculate counts by state so we can update .status accordingly
 	var activeCount, standingByCount, crashesCount, initializingCount, pendingCount int
+
 	for i := 0; i < len(gameServers.Items); i++ {
 		gs := gameServers.Items[i]
 
@@ -156,6 +158,7 @@ func (r *GameServerBuildReconciler) Reconcile(ctx context.Context, req ctrl.Requ
 			if err := r.Delete(ctx, &gs); err != nil {
 				return ctrl.Result{}, err
 			}
+
 			GameServersSessionEndedCounter.WithLabelValues(gsb.Name).Inc()
 			r.expectations.addGameServerToUnderDeletionMap(gsb.Name, gs.Name)
 			r.Recorder.Eventf(&gsb, corev1.EventTypeNormal, "Exited", "GameServer %s session completed", gs.Name)
@@ -183,19 +186,19 @@ func (r *GameServerBuildReconciler) Reconcile(ctx context.Context, req ctrl.Requ
 	// calculate the total amount of servers not in the active state
 	nonActiveGameServersCount := standingByCount + initializingCount + pendingCount
 
+	// Evaluate desired number of servers against actual
+	var totalNumberOfGameServersToDelete int = 0
+
 	// user has decreased standingBy numbers
 	if nonActiveGameServersCount > gsb.Spec.StandingBy {
-		totalNumberOfGameServersToDelete := int(math.Min(float64(nonActiveGameServersCount-gsb.Spec.StandingBy), maxNumberOfGameServersToDelete))
-		err := r.deleteNonActiveGameServers(ctx, &gsb, &gameServers, totalNumberOfGameServersToDelete)
-		if err != nil {
-			return ctrl.Result{}, err
-		}
+		totalNumberOfGameServersToDelete += int(math.Min(float64(nonActiveGameServersCount-gsb.Spec.StandingBy), maxNumberOfGameServersToDelete))
 	}
-
-	// we need to check if we are above the max
+	// we also need to check if we are above the max
 	// this can happen if the user modifies the spec.Max during the GameServerBuild's lifetime
 	if nonActiveGameServersCount+activeCount > gsb.Spec.Max {
-		totalNumberOfGameServersToDelete := int(math.Min(float64(nonActiveGameServersCount+activeCount-gsb.Spec.Max), maxNumberOfGameServersToDelete))
+		totalNumberOfGameServersToDelete += int(math.Min(float64(totalNumberOfGameServersToDelete+(nonActiveGameServersCount+activeCount-gsb.Spec.Max)), maxNumberOfGameServersToDelete))
+	}
+	if totalNumberOfGameServersToDelete > 0 {
 		err := r.deleteNonActiveGameServers(ctx, &gsb, &gameServers, totalNumberOfGameServersToDelete)
 		if err != nil {
 			return ctrl.Result{}, err
@@ -207,13 +210,16 @@ func (r *GameServerBuildReconciler) Reconcile(ctx context.Context, req ctrl.Requ
 	// we attempt to create the missing number of game servers, but we don't want to create more than the max
 	// an error channel for the go routines to write errors
 	errCh := make(chan error, maxNumberOfGameServersToAdd)
+
+	// Time how long it takes to trigger new standby gameservers
+	standByReconcileStartTime := time.Now()
 	// a waitgroup for async create calls
 	var wg sync.WaitGroup
 	for i := 0; i < gsb.Spec.StandingBy-nonActiveGameServersCount &&
 		i+nonActiveGameServersCount+activeCount < gsb.Spec.Max &&
 		i < maxNumberOfGameServersToAdd; i++ {
 		wg.Add(1)
-		go func() {
+		go func(standByStartTime time.Time) {
 			defer wg.Done()
 			newgs, err := NewGameServerForGameServerBuild(&gsb, r.PortRegistry)
 			if err != nil {
@@ -227,9 +233,11 @@ func (r *GameServerBuildReconciler) Reconcile(ctx context.Context, req ctrl.Requ
 			r.expectations.addGameServerToUnderCreationMap(gsb.Name, newgs.Name)
 			GameServersCreatedCounter.WithLabelValues(gsb.Name).Inc()
 			r.Recorder.Eventf(&gsb, corev1.EventTypeNormal, "Creating", "Creating GameServer %s", newgs.Name)
-		}()
+			GameServersStandByReconcileDuration.WithLabelValues(gsb.Name).Set(float64(time.Since(standByStartTime).Milliseconds()))
+		}(standByReconcileStartTime)
 	}
 	wg.Wait()
+
 	if len(errCh) > 0 {
 		return ctrl.Result{}, <-errCh
 	}
@@ -325,6 +333,7 @@ func (r *GameServerBuildReconciler) deleteNonActiveGameServers(ctx context.Conte
 	// a waitgroup for async deletion calls
 	var wg sync.WaitGroup
 	deletionCalls := 0
+
 	// we sort the GameServers by state so that we can delete the ones that are empty state or Initializing before we delete the StandingBy ones (if needed)
 	// this is to make sure we don't fall below the desired number of StandingBy during scaling down
 	sort.Sort(ByState(gameServers.Items))

pkg/operator/controllers/metrics.go

@@ -24,6 +24,14 @@ var (
 		},
 		[]string{"BuildName"},
 	)
+	GameServersStandByReconcileDuration = registry.NewGaugeVec(
+		prometheus.GaugeOpts{
+			Namespace: "thundernetes",
+			Name:      "gameservers_reconcile_standby_duration",
+			Help:      "Time it took to begin initialization for all new GameServers",
+		},
+		[]string{"BuildName"},
+	)
 	GameServersSessionEndedCounter = registry.NewCounterVec(
 		prometheus.CounterOpts{
 			Namespace: "thundernetes",