From fcf121f7b7653442d4ff8be11152b7174e60769b Mon Sep 17 00:00:00 2001 From: win gutmann Date: Sun, 26 Jul 2026 14:54:31 -0400 Subject: [PATCH] feat(observability): plugin-side OTel metrics instrumentation Adds OTLP metrics export (PluginMetricsTelemetry) covering DataUpdate tick interval/Hz, WS broadcast duration and skip reasons, send errors, action dispatch duration, incident-detection duration (live + replay sweep), and replay index build duration/completion + live progress %. Enabled via OTEL_EXPORTER_OTLP_ENDPOINT / SIMSTEWARD_OTLP_ENDPOINT, same pattern as the existing host/process resource sampler. Co-Authored-By: Claude Sonnet 5 --- .../PluginMetricsTelemetry.cs | 167 +++++++++++++++++- ...mStewardPlugin.ReplayIncidentIndexBuild.cs | 22 +++ src/SimSteward.Plugin/SimStewardPlugin.cs | 50 +++++- 3 files changed, 235 insertions(+), 4 deletions(-) diff --git a/src/SimSteward.Plugin/PluginMetricsTelemetry.cs b/src/SimSteward.Plugin/PluginMetricsTelemetry.cs index db3e612..f572d8c 100644 --- a/src/SimSteward.Plugin/PluginMetricsTelemetry.cs +++ b/src/SimSteward.Plugin/PluginMetricsTelemetry.cs @@ -18,18 +18,39 @@ public sealed class PluginMetricsTelemetry : IDisposable private readonly MeterProvider _meterProvider; private readonly Meter _meter; private readonly Func _getSample; + private readonly Func _getDataUpdateHz; + private readonly Func _getClientCount; + private readonly Func _getReplayBuildProgressPct; private readonly KeyValuePair[] _baseTags; + private readonly Histogram _dataUpdateTickIntervalMs; + private readonly Counter _broadcastsSent; + private readonly Counter _broadcastsSkippedThrottle; + private readonly Counter _broadcastsSkippedNoClients; + private readonly Histogram _broadcastDurationMs; + private readonly Counter _sendErrors; + private readonly Histogram _incidentDetectionDurationMs; + private readonly Histogram _actionDurationMs; + private readonly Histogram _replayIndexBuildDurationMs; + private readonly Counter _replayIndexBuildsTotal; + private PluginMetricsTelemetry( MeterProvider meterProvider, Meter meter, Func getSample, + Func getDataUpdateHz, + Func getClientCount, + Func getReplayBuildProgressPct, KeyValuePair[] baseTags) { _meterProvider = meterProvider; _meter = meter; _getSample = getSample; + _getDataUpdateHz = getDataUpdateHz; + _getClientCount = getClientCount; + _getReplayBuildProgressPct = getReplayBuildProgressPct; _baseTags = baseTags; + _meter.CreateObservableGauge( "simsteward.plugin.ready", ObserveReady, @@ -45,12 +66,80 @@ private PluginMetricsTelemetry( ObserveWs, unit: "MiBy", description: "SimHub process working set."); + + // --- DataUpdate loop health (real achieved tick rate vs. the ~60Hz game-tick target) --- + _meter.CreateObservableGauge( + "simsteward.dataupdate.hz", + ObserveDataUpdateHz, + unit: "Hz", + description: "Achieved DataUpdate() tick rate (EMA), vs. the ~60Hz game-tick target."); + _dataUpdateTickIntervalMs = _meter.CreateHistogram( + "simsteward.dataupdate.tick_interval_ms", + unit: "ms", + description: "Distribution of inter-tick intervals for DataUpdate() — jitter/stall detection."); + + // --- WebSocket dashboard broadcast path --- + _meter.CreateObservableGauge( + "simsteward.ws.clients", + ObserveClientCount, + unit: "1", + description: "Connected dashboard WebSocket clients."); + _broadcastsSent = _meter.CreateCounter( + "simsteward.ws.broadcasts_sent", + unit: "1", + description: "State broadcasts successfully sent to dashboard clients."); + _broadcastsSkippedThrottle = _meter.CreateCounter( + "simsteward.ws.broadcasts_skipped_throttle", + unit: "1", + description: "DataUpdate ticks where a broadcast was skipped due to the 200ms/5Hz throttle."); + _broadcastsSkippedNoClients = _meter.CreateCounter( + "simsteward.ws.broadcasts_skipped_no_clients", + unit: "1", + description: "Broadcasts skipped because no dashboard client was connected."); + _broadcastDurationMs = _meter.CreateHistogram( + "simsteward.ws.broadcast_duration_ms", + unit: "ms", + description: "Wall-clock time to build the state snapshot and send it to all connected clients."); + _sendErrors = _meter.CreateCounter( + "simsteward.ws.send_errors", + unit: "1", + description: "Per-client WebSocket send failures."); + + // --- Incident detection --- + _incidentDetectionDurationMs = _meter.CreateHistogram( + "simsteward.incident_detection.duration_ms", + unit: "ms", + description: "Duration of a single incident-detection pass, tagged by path (live | replay_sweep)."); + + // --- Dashboard action dispatch --- + _actionDurationMs = _meter.CreateHistogram( + "simsteward.action.duration_ms", + unit: "ms", + description: "Duration of a dispatched dashboard action, tagged by action name."); + + // --- Replay incident index build (the >2s long-running operation) --- + _meter.CreateObservableGauge( + "simsteward.replay_index_build.progress_pct", + ObserveReplayBuildProgress, + unit: "%", + description: "Current replay-index fast-forward sweep completion percentage (0 when idle)."); + _replayIndexBuildDurationMs = _meter.CreateHistogram( + "simsteward.replay_index_build.duration_ms", + unit: "ms", + description: "Total wall-clock duration of a replay incident index build, tagged by completion_reason."); + _replayIndexBuildsTotal = _meter.CreateCounter( + "simsteward.replay_index_build.builds_total", + unit: "1", + description: "Replay incident index builds completed, tagged by completion_reason."); } /// Returns null if OTLP is not configured (no endpoint env vars). public static PluginMetricsTelemetry TryCreate( PluginLogger logger, - Func getSample) + Func getSample, + Func getDataUpdateHz = null, + Func getClientCount = null, + Func getReplayBuildProgressPct = null) { var endpoint = FirstNonEmpty( Environment.GetEnvironmentVariable("OTEL_EXPORTER_OTLP_ENDPOINT"), @@ -95,7 +184,12 @@ public static PluginMetricsTelemetry TryCreate( }) .Build(); - var telemetry = new PluginMetricsTelemetry(provider, meter, getSample, baseTags); + var telemetry = new PluginMetricsTelemetry( + provider, meter, getSample, + getDataUpdateHz ?? (() => 0), + getClientCount ?? (() => 0), + getReplayBuildProgressPct ?? (() => 0), + baseTags); logger?.Structured("INFO", "simhub-plugin", "otel_metrics_started", "OTLP metrics export enabled (OpenTelemetry → collector).", @@ -137,6 +231,75 @@ private IEnumerable> ObserveWs() yield return new Measurement(v, _baseTags); } + private IEnumerable> ObserveDataUpdateHz() + { + yield return new Measurement(_getDataUpdateHz(), _baseTags); + } + + private IEnumerable> ObserveClientCount() + { + yield return new Measurement(_getClientCount(), _baseTags); + } + + private IEnumerable> ObserveReplayBuildProgress() + { + yield return new Measurement(_getReplayBuildProgressPct(), _baseTags); + } + + // --- Imperative recording (histograms/counters, called from the hot paths that measure them) --- + + public void RecordDataUpdateTickIntervalMs(double ms) => + _dataUpdateTickIntervalMs.Record(ms, _baseTags); + + public void RecordBroadcastSent(double durationMs) + { + _broadcastsSent.Add(1, _baseTags); + _broadcastDurationMs.Record(durationMs, _baseTags); + } + + public void RecordBroadcastSkippedThrottle() => + _broadcastsSkippedThrottle.Add(1, _baseTags); + + public void RecordBroadcastSkippedNoClients() => + _broadcastsSkippedNoClients.Add(1, _baseTags); + + public void RecordSendError() => + _sendErrors.Add(1, _baseTags); + + /// Bounded label: "live" or "replay_sweep". + public void RecordIncidentDetectionDuration(string path, double ms) + { + var tags = new[] + { + _baseTags[0], + new KeyValuePair("path", path ?? "unknown"), + }; + _incidentDetectionDurationMs.Record(ms, tags); + } + + /// Bounded label: dashboard action name (~24 distinct values). + public void RecordActionDuration(string action, double ms) + { + var tags = new[] + { + _baseTags[0], + new KeyValuePair("action", action ?? "unknown"), + }; + _actionDurationMs.Record(ms, tags); + } + + /// Bounded label: "success" | "cancelled" | "error" etc. + public void RecordReplayIndexBuildCompleted(string completionReason, double durationMs) + { + var tags = new[] + { + _baseTags[0], + new KeyValuePair("completion_reason", completionReason ?? "unknown"), + }; + _replayIndexBuildDurationMs.Record(durationMs, tags); + _replayIndexBuildsTotal.Add(1, tags); + } + public void Dispose() { try diff --git a/src/SimSteward.Plugin/SimStewardPlugin.ReplayIncidentIndexBuild.cs b/src/SimSteward.Plugin/SimStewardPlugin.ReplayIncidentIndexBuild.cs index 1a7dac7..fd45658 100644 --- a/src/SimSteward.Plugin/SimStewardPlugin.ReplayIncidentIndexBuild.cs +++ b/src/SimSteward.Plugin/SimStewardPlugin.ReplayIncidentIndexBuild.cs @@ -80,7 +80,10 @@ private void OnIrsdkTelemetryDataForReplayIndex() try { + var __sw = System.Diagnostics.Stopwatch.StartNew(); ProcessReplayIncidentIndexBuildTelemetry(); + __sw.Stop(); + _metricsTelemetry?.RecordIncidentDetectionDuration("replay_sweep", __sw.Elapsed.TotalMilliseconds); } catch (Exception ex) { @@ -98,7 +101,10 @@ private void OnIrsdkTelemetryDataForReplayIndex() try { + var __sw = System.Diagnostics.Stopwatch.StartNew(); ProcessLiveIncidentDetectionTick(); + __sw.Stop(); + _metricsTelemetry?.RecordIncidentDetectionDuration("live", __sw.Elapsed.TotalMilliseconds); } catch (Exception ex) { @@ -709,6 +715,19 @@ private void ProcessYamlIncidentDiffLocked(double replaySessionTimeSec, int repl /// private void BroadcastReplaySweepProgressIfDueLocked(int replayFrame, double replaySessionTimeSec) { + // Progress % feeds the simsteward.replay_index_build.progress_pct gauge unconditionally — + // independent of whether a dashboard client happens to be connected (the WS broadcast below is gated + // on client count, but the metrics gauge must reflect real build progress regardless). + { + int frameEndForMetrics = _replayIndexReplayFrameNumEndSnapshot > 0 + ? _replayIndexReplayFrameNumEndSnapshot + : SafeGetInt("ReplayFrameNumEnd"); + double pctForMetrics = frameEndForMetrics > 0 ? (100.0 * replayFrame / frameEndForMetrics) : 0.0; + if (pctForMetrics < 0) pctForMetrics = 0; + if (pctForMetrics > 100) pctForMetrics = 100; + _replayIndexBuildProgressPctForMetrics = pctForMetrics; + } + if (_bridge == null || _bridge.ClientCount <= 0) return; var nowUtc = DateTime.UtcNow; if ((nowUtc - _lastSweepProgressTickAt).TotalMilliseconds < 1000) @@ -989,6 +1008,9 @@ private void ProcessFastForwardingLocked() _logger.Structured("INFO", "simhub-plugin", ReplayIncidentIndexBuild.EventFastForwardComplete, "Replay incident index: fast-forward complete (TR-010/011).", done, "lifecycle", null); + _metricsTelemetry?.RecordReplayIndexBuildCompleted(reason, wallMs); + _replayIndexBuildProgressPctForMetrics = 0; + _replayIndexFfWallClock = null; _replayIndexLastValidationBlock = BuildReplayIndexValidationBlockLocked(_replayIndexIncidentSamples); FinalizeReplayIndexBuildLocked(); diff --git a/src/SimSteward.Plugin/SimStewardPlugin.cs b/src/SimSteward.Plugin/SimStewardPlugin.cs index 57e2ffd..e28e057 100644 --- a/src/SimSteward.Plugin/SimStewardPlugin.cs +++ b/src/SimSteward.Plugin/SimStewardPlugin.cs @@ -68,6 +68,9 @@ public partial class SimStewardPlugin private int _resourceSampleIntervalSec = 60; private SystemMetricsSample _lastResourceSample; private PluginMetricsTelemetry _metricsTelemetry; + private DateTime _lastDataUpdateTickUtc = DateTime.MinValue; + private double _dataUpdateEmaHz; + private double _replayIndexBuildProgressPctForMetrics; #if SIMHUB_SDK private IRacingSdk _irsdk; @@ -754,6 +757,20 @@ private System.Collections.Generic.Dictionary BuildCaptureIncide } private (bool success, string result, string error) DispatchAction(string action, string arg, string correlationId) + { + var __actionSw = System.Diagnostics.Stopwatch.StartNew(); + try + { + return DispatchActionCore(action, arg, correlationId); + } + finally + { + __actionSw.Stop(); + _metricsTelemetry?.RecordActionDuration(action, __actionSw.Elapsed.TotalMilliseconds); + } + } + + private (bool success, string result, string error) DispatchActionCore(string action, string arg, string correlationId) { if (string.IsNullOrEmpty(action)) return (false, null, "missing_action"); @@ -1751,9 +1768,14 @@ public void Init(PluginManager pluginManager) OnLog, _logger, OnDashboardStructuredLog, - onSendError: (ex, payloadType) => WriteBroadcastError("Send:" + payloadType, ex), + onSendError: (ex, payloadType) => + { + _metricsTelemetry?.RecordSendError(); + WriteBroadcastError("Send:" + payloadType, ex); + }, onNoClients: () => { + _metricsTelemetry?.RecordBroadcastSkippedNoClients(); var n = DateTime.UtcNow; lock (_broadcastErrorLock) { @@ -1840,7 +1862,12 @@ public void Init(PluginManager pluginManager) try { - _metricsTelemetry = PluginMetricsTelemetry.TryCreate(_logger, () => _lastResourceSample); + _metricsTelemetry = PluginMetricsTelemetry.TryCreate( + _logger, + () => _lastResourceSample, + () => _dataUpdateEmaHz, + () => _bridge != null ? _bridge.ClientCount : 0, + () => _replayIndexBuildProgressPctForMetrics); } catch (Exception ex) { @@ -1860,6 +1887,19 @@ public void DataUpdate(PluginManager pluginManager, ref GameData data) { try { + var __tickNowUtc = DateTime.UtcNow; + if (_lastDataUpdateTickUtc != DateTime.MinValue) + { + double __intervalMs = (__tickNowUtc - _lastDataUpdateTickUtc).TotalMilliseconds; + _metricsTelemetry?.RecordDataUpdateTickIntervalMs(__intervalMs); + if (__intervalMs > 0) + { + double __instHz = 1000.0 / __intervalMs; + _dataUpdateEmaHz = _dataUpdateEmaHz <= 0 ? __instHz : (_dataUpdateEmaHz * 0.9 + __instHz * 0.1); + } + } + _lastDataUpdateTickUtc = __tickNowUtc; + _dataUpdateTick++; if (_dataUpdateTick % DependencyCheckIntervalTicks == 0) RefreshDependencyChecks(); @@ -2004,11 +2044,17 @@ public void DataUpdate(PluginManager pluginManager, ref GameData data) var now = DateTime.UtcNow; if ((now - _lastBroadcastAt).TotalMilliseconds < BroadcastThrottleMs) + { + _metricsTelemetry?.RecordBroadcastSkippedThrottle(); return; + } _lastBroadcastAt = now; + var __broadcastSw = System.Diagnostics.Stopwatch.StartNew(); var snapshot = BuildPluginSnapshot(); _bridge.BroadcastState(BuildStateJson(snapshot)); + __broadcastSw.Stop(); + _metricsTelemetry?.RecordBroadcastSent(__broadcastSw.Elapsed.TotalMilliseconds); } catch (Exception ex) {