Add controller performance metrics

.gitignore

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

cmd/nodeagent/nodeagentmanager.go

@@ -220,11 +220,15 @@ 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)
+		// save actual gameserver creation time
+		creationTimeStamp := obj.GetCreationTimestamp()
+
 		gsdi = &GameServerInfo{
 			GameServerNamespace: gameServerNamespace,
 			Mutex:               &sync.RWMutex{},
 			GsUid:               obj.GetUID(),
 			CreationTime:        n.nowFunc().UnixMilli(),
+			CreationTimeStamp:   &creationTimeStamp,
 			BuildName:           gameServerBuildName,
 			MarkedUnhealthy:     false,
 			// we're not adding details about health/state since the NodeAgent might have crashed
@@ -454,6 +458,7 @@ func (n *NodeAgentManager) updateHealthAndStateIfNeeded(ctx context.Context, hb
 				status.ReachedInitializingOn = &now
 			} else if hb.CurrentGameState == GameStateStandingBy {
 				status.ReachedStandingByOn = &now
+				GameServerCreateDuration.WithLabelValues(gsd.BuildName).Set(getStateDuration(status.ReachedStandingByOn, gsd.CreationTimeStamp))
 			}
 		}
 

cmd/nodeagent/types.go

@@ -5,6 +5,7 @@ import (
 
 	"github.com/prometheus/client_golang/prometheus"
 	"github.com/prometheus/client_golang/prometheus/promauto"
+	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/apimachinery/pkg/runtime/schema"
 	"k8s.io/apimachinery/pkg/types"
 )
@@ -58,6 +59,15 @@ var (
 		Name:      "connected_players",
 		Help:      "Number of connected players per GameServer",
 	}, []string{"namespace", "ServerName", "BuildName"})
+
+	GameServerCreateDuration = promauto.NewGaugeVec(
+		prometheus.GaugeOpts{
+			Namespace: "thundernetes",
+			Name:      "gameserver_create_duration",
+			Help:      "Time taken to create a GameServers",
+		},
+		[]string{"BuildName"},
+	)
 )
 
 // HeartbeatRequest contains data for the heartbeat request coming from the GSDK running alongside GameServer
@@ -101,9 +111,10 @@ type GameServerInfo struct {
 	GameServerNamespace   string
 	ConnectedPlayersCount int
 	Mutex                 *sync.RWMutex
-	GsUid                 types.UID // UID of the GameServer object
-	CreationTime          int64     // time when this GameServerInfo was created in the nodeagent
-	LastHeartbeatTime     int64     // time since the nodeagent received a heartbeat from this GameServer
-	MarkedUnhealthy       bool      // if the GameServer was marked unhealthy by a heartbeat condition, used to avoid repeating the patch
-	BuildName             string    // the name of the GameServerBuild that this GameServer belongs to
+	GsUid                 types.UID    // UID of the GameServer object
+	CreationTime          int64        // time when this GameServerInfo was created in the nodeagent
+	CreationTimeStamp     *metav1.Time // time when the GameServer was created
+	LastHeartbeatTime     int64        // time since the nodeagent received a heartbeat from this GameServer
+	MarkedUnhealthy       bool         // if the GameServer was marked unhealthy by a heartbeat condition, used to avoid repeating the patch
+	BuildName             string       // the name of the GameServerBuild that this GameServer belongs to
 }

cmd/nodeagent/utilities.go

@@ -3,12 +3,15 @@ package main
 import (
 	"errors"
 	"fmt"
+	"math"
 	"net/http"
 	"os"
 	"strconv"
 	"strings"
+	"time"
 
 	log "github.com/sirupsen/logrus"
+	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/apimachinery/pkg/apis/meta/v1/unstructured"
 	"k8s.io/client-go/dynamic"
 	"k8s.io/client-go/rest"
@@ -104,6 +107,15 @@ func getLogger(gameServerName, gameServerNamespace string) *log.Entry {
 	return log.WithFields(log.Fields{"GameServerName": gameServerName, "GameServerNamespace": gameServerNamespace})
 }
 
+// getStateDuration determine whether to use an existing saved time variables or the current time for state duration
+func getStateDuration(endTime *metav1.Time, startTime *metav1.Time) float64 {
+	// If the end time state is missing, use the current time
+	if endTime == nil {
+		return math.Abs(float64(time.Since(startTime.Time).Milliseconds()))
+	}
+	return math.Abs(float64(endTime.Time.Sub(startTime.Time).Milliseconds()))
+}
+
 // sanitize removes new line characters from the string
 // https://codeql.github.com/codeql-query-help/go/go-log-injection/
 func sanitize(s string) string {

docs/howtos/monitoring.md

@@ -86,9 +86,13 @@ There is a custom Grafana dashboard example that visualizes some of this data in
 | connected_players | Gauge | nodeagent |
 | gameservers_current_state_per_build | Gauge | controller-manager |
 | gameservers_created_total | Counter | controller-manager |
+| gameservers_create_duration | Gauge | 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 |
+| gameservers_end_duration | Gauge | controller-manager |
+| gameservers_clean_up_duration | Gauge | controller-manager |
 | allocations_total | Counter | controller-manager |
 
 ## More pictures

pkg/operator/api/v1alpha1/gameserver_types.go

@@ -80,6 +80,8 @@ type GameServerStatus struct {
 	Health GameServerHealth `json:"health,omitempty"`
 	// State defines the state of the game server (Initializing, StandingBy, Active etc.)
 	State GameServerState `json:"state,omitempty"`
+	// The Previously known manually set state
+	PrevState GameServerState `json:"prevState,omitempty"`
 	// PublicIP is the PublicIP of the game server
 	PublicIP string `json:"publicIP,omitempty"`
 	// Ports is a concatenated list of the ports this game server listens to

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",