From a9089799407d417850e39e75d53623b9281e1913 Mon Sep 17 00:00:00 2001
From: Vinzenz Schroeter <vinzenz.f.s@gmail.com>
Date: Tue, 30 Apr 2024 11:16:26 +0200
Subject: [PATCH] improve ups counter output

---
 .../TanksServer/GameLogic/GameTickWorker.cs   |  4 +++-
 .../GameLogic/UpdatesPerSecondCounter.cs      | 24 ++++++++++++-------
 2 files changed, 19 insertions(+), 9 deletions(-)

diff --git a/tanks-backend/TanksServer/GameLogic/GameTickWorker.cs b/tanks-backend/TanksServer/GameLogic/GameTickWorker.cs
index 8dd20f7..a529889 100644
--- a/tanks-backend/TanksServer/GameLogic/GameTickWorker.cs
+++ b/tanks-backend/TanksServer/GameLogic/GameTickWorker.cs
@@ -33,12 +33,14 @@ internal sealed class GameTickWorker(
 
     private async Task RunAsync()
     {
+        // the first tick is really short (< 0.01ms) if this line is directly above the while
+        var sw = Stopwatch.StartNew();
+
         // do not block in StartAsync
         await Task.Delay(1).ConfigureAwait(false);
 
         try
         {
-            var sw = new Stopwatch();
             while (!_cancellation.IsCancellationRequested)
             {
                 var delta = sw.Elapsed;
diff --git a/tanks-backend/TanksServer/GameLogic/UpdatesPerSecondCounter.cs b/tanks-backend/TanksServer/GameLogic/UpdatesPerSecondCounter.cs
index adfdc9b..71a9818 100644
--- a/tanks-backend/TanksServer/GameLogic/UpdatesPerSecondCounter.cs
+++ b/tanks-backend/TanksServer/GameLogic/UpdatesPerSecondCounter.cs
@@ -4,6 +4,9 @@ namespace TanksServer.GameLogic;
 
 internal sealed class UpdatesPerSecondCounter(ILogger<UpdatesPerSecondCounter> logger) : ITickStep
 {
+    private static readonly TimeSpan LongTime = TimeSpan.FromSeconds(5);
+    private static readonly TimeSpan CriticalUpdateTime = TimeSpan.FromMilliseconds(50);
+
     private readonly Stopwatch _long = Stopwatch.StartNew();
     private ulong _updatesSinceLongReset;
     private TimeSpan _minFrameTime = TimeSpan.MaxValue;
@@ -13,8 +16,12 @@ internal sealed class UpdatesPerSecondCounter(ILogger<UpdatesPerSecondCounter> l
     {
         if (logger.IsEnabled(LogLevel.Trace))
             logger.LogTrace("time since last update: {}", delta);
-        if (delta.TotalSeconds > 1)
-            logger.LogCritical("single update took {}", delta);
+
+        if (delta > CriticalUpdateTime)
+        {
+            logger.LogCritical("a single update took {}, which is longer than the allowed {}",
+                delta, CriticalUpdateTime);
+        }
 
         if (_minFrameTime > delta)
             _minFrameTime = delta;
@@ -23,7 +30,7 @@ internal sealed class UpdatesPerSecondCounter(ILogger<UpdatesPerSecondCounter> l
 
         _updatesSinceLongReset++;
 
-        if (_long.Elapsed.TotalSeconds < 10)
+        if (_long.Elapsed < LongTime)
             return ValueTask.CompletedTask;
 
         LogCounters();
@@ -37,11 +44,12 @@ internal sealed class UpdatesPerSecondCounter(ILogger<UpdatesPerSecondCounter> l
             return;
 
         var time = _long.Elapsed;
-        var average = Math.Round(_updatesSinceLongReset / time.TotalSeconds);
-        var min = Math.Round(1 / _maxFrameTime.TotalSeconds);
-        var max = Math.Round(1 / _minFrameTime.TotalSeconds);
-        logger.LogDebug("UPS stats for {} updates in {}: avg={}, min={}, max={}",
-            _updatesSinceLongReset, time, average, min, max);
+        var averageTime = Math.Round(time.TotalMilliseconds / _updatesSinceLongReset, 2);
+        var averageUps = Math.Round(_updatesSinceLongReset / time.TotalSeconds, 2);
+        var min = Math.Round(_minFrameTime.TotalMilliseconds, 2);
+        var max = Math.Round(_maxFrameTime.TotalMilliseconds, 2);
+        logger.LogDebug("count={}, time={}, avg={}ms, ups={}, min={}ms, max={}ms",
+            _updatesSinceLongReset, time, averageTime, averageUps, min, max);
     }
 
     private void ResetCounters()