fix: replace per-hub update loop warnings with a metric

LiveControlGateway/LifetimeManager/HubLifetime.cs

@@ -10,6 +10,7 @@
 using OpenShock.Common.Services.RedisPubSub;
 using OpenShock.Common.Utils;
 using OpenShock.LiveControlGateway.Controllers;
+using OpenShock.LiveControlGateway.Metrics;
 using OpenShock.LiveControlGateway.Mappers;
 using OpenShock.Serialization.Gateway;
 using Redis.OM.Contracts;
@@ -50,6 +51,7 @@ public sealed class HubLifetime : IAsyncDisposable
     private readonly IDbContextFactory<OpenShockContext> _dbContextFactory;
     private readonly IRedisConnectionProvider _redisConnectionProvider;
     private readonly IRedisPubService _redisPubService;
+    private readonly GatewayMetrics _metrics;
 
     private readonly RedisChannel _deviceMsgChannel;
     private readonly ISubscriber _subscriber;
@@ -74,6 +76,15 @@ public sealed class HubLifetime : IAsyncDisposable
     /// </summary>
     private static readonly TimeSpan BehindWarningInterval = TimeSpan.FromSeconds(5);
 
+    private static readonly TimeSpan SevereLagThreshold = TimeSpan.FromSeconds(1);
+
+    /// <summary>
+    /// Severe lag is a gateway-wide stall, so the error is rate limited across all lifetimes, not per hub
+    /// </summary>
+    private static readonly TimeSpan SevereLagErrorInterval = TimeSpan.FromSeconds(30);
+
+    private static long _lastSevereLagError;
+
     /// <summary>
     /// DI Constructor
     /// </summary>
@@ -83,19 +94,22 @@ public sealed class HubLifetime : IAsyncDisposable
     /// <param name="connectionMultiplexer"></param>
     /// <param name="redisConnectionProvider"></param>
     /// <param name="redisPubService"></param>
+    /// <param name="metrics"></param>
     /// <param name="logger"></param>
     public HubLifetime([Range(1, 10)] byte tps, IHubController hubController,
         IDbContextFactory<OpenShockContext> dbContextFactory,
         IConnectionMultiplexer connectionMultiplexer,
         IRedisConnectionProvider redisConnectionProvider,
         IRedisPubService redisPubService,
+        GatewayMetrics metrics,
         ILogger<HubLifetime> logger)
     {
         HubController = hubController;
         _cancellationSource = new CancellationTokenSource();
         _dbContextFactory = dbContextFactory;
         _redisConnectionProvider = redisConnectionProvider;
         _redisPubService = redisPubService;
+        _metrics = metrics;
         _logger = logger;
 
         _waitBetweenTicks = TimeSpan.FromMilliseconds(1000.0 / tps);
@@ -336,13 +350,26 @@ private async Task UpdateLoop()
             // PeriodicTimer drops missed ticks, so a gap of two or more periods
             // means Update() couldn't keep up and tick(s) were skipped.
             var dropped = (int)(sinceLastTick.Ticks / _waitBetweenTicks.Ticks) - 1;
-            if (dropped >= 1 && (lastBehindWarning is null ||
-                                 Stopwatch.GetElapsedTime(lastBehindWarning.Value, now) >= BehindWarningInterval))
+            if (dropped >= 1)
             {
-                lastBehindWarning = now;
-                _logger.LogWarning(
-                    "Update loop behind for device [{DeviceId}]: ~{Dropped} tick(s) dropped, {LateMs:F1}ms late",
-                    HubController.Id, dropped, (sinceLastTick - _waitBetweenTicks).TotalMilliseconds);
+                _metrics.UpdateTicksDropped(dropped);
+
+                var late = sinceLastTick - _waitBetweenTicks;
+                if (late >= SevereLagThreshold && TryClaimSevereLagError(now))
+                {
+                    _logger.LogError(
+                        "Update loop severely behind, gateway likely stalled: device [{DeviceId}] {LateMs:F1}ms late, ~{Dropped} tick(s) dropped",
+                        HubController.Id, late.TotalMilliseconds, dropped);
+                }
+
+                if (lastBehindWarning is null ||
+                    Stopwatch.GetElapsedTime(lastBehindWarning.Value, now) >= BehindWarningInterval)
+                {
+                    lastBehindWarning = now;
+                    _logger.LogDebug(
+                        "Update loop behind for device [{DeviceId}]: ~{Dropped} tick(s) dropped, {LateMs:F1}ms late",
+                        HubController.Id, dropped, late.TotalMilliseconds);
+                }
             }
 
             try
@@ -356,6 +383,13 @@ private async Task UpdateLoop()
         }
     }
 
+    private static bool TryClaimSevereLagError(long now)
+    {
+        var last = Interlocked.Read(ref _lastSevereLagError);
+        if (last != 0 && Stopwatch.GetElapsedTime(last, now) < SevereLagErrorInterval) return false;
+        return Interlocked.CompareExchange(ref _lastSevereLagError, now, last) == last;
+    }
+
     private async Task Update()
     {
         var now = DateTimeOffset.UtcNow;

LiveControlGateway/LifetimeManager/HubLifetimeManager.cs

@@ -201,6 +201,7 @@ private HubLifetime CreateNewLifetime(byte tps, IHubController hubController)
             _connectionMultiplexer,
             _redisConnectionProvider,
             _redisPubService,
+            _metrics,
             _loggerFactory.CreateLogger<HubLifetime>());
 
         return deviceLifetime;

LiveControlGateway/Metrics/GatewayMetrics.cs

@@ -91,6 +91,7 @@ public static class FrameOutcome
     private readonly Histogram<int> _liveControlLatency;
     private readonly Histogram<int> _hubLatency;
     private readonly Counter<long> _frames;
+    private readonly Counter<long> _updateTicksDropped;
 
     /// <summary>
     /// DI constructor
@@ -132,6 +133,10 @@ public GatewayMetrics(LcgOptions lcgOptions, [FromKeyedServices("OpenShock.Gatew
         // these count ticks of a held control, not discrete presses.
         _frames = meter.CreateCounter<long>("openshock_live_frames", "frames",
             "Live control frames processed by outcome and control type, counted per frame (a bulk frame counts once per frame it carries).");
+
+        // Not tagged per hub: when the loop falls behind it is the gateway stalling, so every hub drops at once.
+        _updateTicksDropped = meter.CreateCounter<long>("openshock_hub_update_ticks_dropped", "ticks",
+            "Hub update loop ticks skipped because the loop fell behind.");
     }
 
     /// <summary>
@@ -159,6 +164,12 @@ public void HubLatency(int latencyMs, IHubController hub) =>
         _hubLatency.Record(latencyMs, _gatewayFqdn, AsnTag(hub.IpInfo), AsnOrgTag(hub.IpInfo),
             CountryTag(hub.IpInfo));
 
+    /// <summary>
+    /// Record hub update loop ticks that were skipped.
+    /// </summary>
+    /// <param name="dropped"></param>
+    public void UpdateTicksDropped(int dropped) => _updateTicksDropped.Add(dropped, _gatewayFqdn);
+
     /// <summary>
     /// The <c>asn</c> tag for a hub's network.
     /// </summary>