From 5c3ee8565e04fd298ea8dbdda7205067fa9002b2 Mon Sep 17 00:00:00 2001 From: LucHeart Date: Sat, 14 Nov 2026 04:16:37 +0100 Subject: [PATCH] fix: replace per-hub update loop warnings with a metric A gateway stall made every connected hub log a warning at once. Dropped ticks now feed openshock_hub_update_ticks_dropped, the per-hub message is demoted to debug, and severe lag (>=1s) logs a single error at most every 30s gateway-wide. --- .../LifetimeManager/HubLifetime.cs | 46 ++++++++++++++++--- .../LifetimeManager/HubLifetimeManager.cs | 1 + LiveControlGateway/Metrics/GatewayMetrics.cs | 11 +++++ 3 files changed, 52 insertions(+), 6 deletions(-) diff --git a/LiveControlGateway/LifetimeManager/HubLifetime.cs b/LiveControlGateway/LifetimeManager/HubLifetime.cs index 576d0f1ec..bed30494c 100644 --- a/LiveControlGateway/LifetimeManager/HubLifetime.cs +++ b/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 _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 /// private static readonly TimeSpan BehindWarningInterval = TimeSpan.FromSeconds(5); + private static readonly TimeSpan SevereLagThreshold = TimeSpan.FromSeconds(1); + + /// + /// Severe lag is a gateway-wide stall, so the error is rate limited across all lifetimes, not per hub + /// + private static readonly TimeSpan SevereLagErrorInterval = TimeSpan.FromSeconds(30); + + private static long _lastSevereLagError; + /// /// DI Constructor /// @@ -83,12 +94,14 @@ public sealed class HubLifetime : IAsyncDisposable /// /// /// + /// /// public HubLifetime([Range(1, 10)] byte tps, IHubController hubController, IDbContextFactory dbContextFactory, IConnectionMultiplexer connectionMultiplexer, IRedisConnectionProvider redisConnectionProvider, IRedisPubService redisPubService, + GatewayMetrics metrics, ILogger logger) { HubController = hubController; @@ -96,6 +109,7 @@ public HubLifetime([Range(1, 10)] byte tps, IHubController hubController, _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; diff --git a/LiveControlGateway/LifetimeManager/HubLifetimeManager.cs b/LiveControlGateway/LifetimeManager/HubLifetimeManager.cs index 614d6e537..8b5fa7c93 100644 --- a/LiveControlGateway/LifetimeManager/HubLifetimeManager.cs +++ b/LiveControlGateway/LifetimeManager/HubLifetimeManager.cs @@ -201,6 +201,7 @@ private HubLifetime CreateNewLifetime(byte tps, IHubController hubController) _connectionMultiplexer, _redisConnectionProvider, _redisPubService, + _metrics, _loggerFactory.CreateLogger()); return deviceLifetime; diff --git a/LiveControlGateway/Metrics/GatewayMetrics.cs b/LiveControlGateway/Metrics/GatewayMetrics.cs index 18351b9c2..823766809 100644 --- a/LiveControlGateway/Metrics/GatewayMetrics.cs +++ b/LiveControlGateway/Metrics/GatewayMetrics.cs @@ -91,6 +91,7 @@ public static class FrameOutcome private readonly Histogram _liveControlLatency; private readonly Histogram _hubLatency; private readonly Counter _frames; + private readonly Counter _updateTicksDropped; /// /// 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("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("openshock_hub_update_ticks_dropped", "ticks", + "Hub update loop ticks skipped because the loop fell behind."); } /// @@ -159,6 +164,12 @@ public void HubLatency(int latencyMs, IHubController hub) => _hubLatency.Record(latencyMs, _gatewayFqdn, AsnTag(hub.IpInfo), AsnOrgTag(hub.IpInfo), CountryTag(hub.IpInfo)); + /// + /// Record hub update loop ticks that were skipped. + /// + /// + public void UpdateTicksDropped(int dropped) => _updateTicksDropped.Add(dropped, _gatewayFqdn); + /// /// The asn tag for a hub's network. ///