From ab5cdc84b51dfed49c58c0017ee0c05d5e695294 Mon Sep 17 00:00:00 2001 From: Scott Velez <162245270+SVappsLAB@users.noreply.github.com> Date: Sun, 13 Sep 2026 19:01:55 -0700 Subject: [PATCH 1/2] improveMetrics --- .github/workflows/ci.yaml | 15 +- .gitignore | 2 + NUGET.md | 1 + README.md | 8 +- .../DumpVariables_DumpSessionInfo.csproj | 2 +- .../LocationAndWarnings.csproj | 2 +- .../MinimalExampleAsync.csproj | 2 +- .../MinimalExampleSync.csproj | 2 +- Samples/SimControl/SimControl.csproj | 2 +- Samples/SpeedRPMGear/SpeedRPMGear.csproj | 2 +- Sdk/SVappsLAB.iRacingTelemetrySDK.slnx | 5 +- .../DataProviders/IBTDataProvider.cs | 89 +++- .../DataProviders/LiveDataProvider.cs | 9 +- .../IBTPlayback/Governor.cs | 18 +- .../Metrics/MetricsService.cs | 381 +++++++++++++++--- .../Metrics/ScopeTimeSpanTimer.cs | 35 -- .../SVappsLAB.iRacingTelemetrySDK.csproj | 2 +- .../ScopeLambda.cs => StampedSample.cs} | 27 +- .../TelemetryClient.cs | 117 ++++-- .../{Constants.cs => TelemetryMetrics.cs} | 16 +- .../UnitTests/Metrics/MetricsServiceTests.cs | 292 ++++++++++++++ .../Metrics/TelemetryPipelineMetricsTests.cs | 296 ++++++++++++++ Sdk/tests/UnitTests/PlaybackLagTests.cs | 66 +++ Sdk/tests/UnitTests/UnitTests.csproj | 9 + docs/ARCHITECTURE.md | 65 +-- docs/METRICS.md | 202 ++++++++++ 26 files changed, 1438 insertions(+), 229 deletions(-) delete mode 100644 Sdk/SVappsLAB.iRacingTelemetrySDK/Metrics/ScopeTimeSpanTimer.cs rename Sdk/SVappsLAB.iRacingTelemetrySDK/{Metrics/ScopeLambda.cs => StampedSample.cs} (54%) rename Sdk/SVappsLAB.iRacingTelemetrySDK/{Constants.cs => TelemetryMetrics.cs} (65%) create mode 100644 Sdk/tests/UnitTests/Metrics/MetricsServiceTests.cs create mode 100644 Sdk/tests/UnitTests/Metrics/TelemetryPipelineMetricsTests.cs create mode 100644 Sdk/tests/UnitTests/PlaybackLagTests.cs create mode 100644 docs/METRICS.md diff --git a/.github/workflows/ci.yaml b/.github/workflows/ci.yaml index 78ddfa2..9c3f2aa 100644 --- a/.github/workflows/ci.yaml +++ b/.github/workflows/ci.yaml @@ -9,7 +9,13 @@ jobs: run: working-directory: Sdk steps: - - uses: actions/checkout@v2 + # not 'lfs: true' - that pulls every lfs object at HEAD (~319MB) + - uses: actions/checkout@v4 + + # the unit tests play back a real ibt file + - name: fetch ibt test data + working-directory: ${{ github.workspace }} + run: git lfs pull --include "Sdk/tests/SmokeTests/data/ibt/raygr22_roadatlanta full 2025-07-15.ibt" - name: setup uses: actions/setup-dotnet@v4 @@ -23,7 +29,8 @@ jobs: - name: unit tests run: dotnet run --no-restore -c release --project ./tests/UnitTests/UnitTests.csproj - # can't run IBT tests with github runers - because we don't have - # access to memory mapped files on the host + # the ibt smoke tests are not run here. they do pass headlessly on a runner (they + # only read ibt files - no iRacing needed), but the 3 files they sweep are ~191MB + # of lfs data per run. to enable, fetch them above and add: # - name: ibt tests - # run: dotnet test --no-restore -c release --filter IBT_Tests + # run: dotnet run --no-restore -c release --no-launch-profile --project ./tests/SmokeTests/SmokeTests.csproj -- --filter-trait "Category=ibt" diff --git a/.gitignore b/.gitignore index 628d3a2..f35adb3 100644 --- a/.gitignore +++ b/.gitignore @@ -1,7 +1,9 @@ *.user .vs +TestResults/ artifacts/ bin/ dist/ obj/ + diff --git a/NUGET.md b/NUGET.md index 694aadf..e8fbeff 100644 --- a/NUGET.md +++ b/NUGET.md @@ -6,6 +6,7 @@ High-performance .NET SDK for accessing **live telemetry data** from iRacing sim - **Type Safety**: Enum-based telemetry variables with IntelliSense/Copilot support and compile-time validation - **High Performance**: Processes 600,000+ telemetry records/second with lock-free data streaming architecture +- **Low Per-Frame Overhead**: Under 0.01 ms of SDK work per telemetry update - leaving over 99.9% of iRacing's 16.67 ms (60 Hz) frame budget to your code - **Background Processing**: Dedicated threads for telemetry collection and processing - your app's processing speed never blocks the streaming telemetry data - **Modern Async API**: Async data streams with async/await patterns, bounded buffering, and automatic overload handling - **Dynamic Variable Lookup**: Look up any telemetry variable by name at runtime with `GetValue(string)` - no compile-time struct required diff --git a/README.md b/README.md index d089bf1..76c4b76 100644 --- a/README.md +++ b/README.md @@ -19,6 +19,7 @@ Perfect for building **real-time dashboards**, **data analysis tools**, **race e - [Samples](#samples) - [Advanced Usage](./docs/ADVANCED.md) - [Architecture and Design](./docs/ARCHITECTURE.md) +- [Metrics and Diagnostics](./docs/METRICS.md) - [Documentation](#documentation) - [AI-Assisted Development](#ai-assisted-development) - [Building from Source](#building-from-source) @@ -28,6 +29,7 @@ Perfect for building **real-time dashboards**, **data analysis tools**, **race e - **Type Safety**: Enum-based telemetry variables with IntelliSense support and compile-time validation - **High Performance**: Processes 600,000+ telemetry records/second with lock-free data streaming architecture +- **Low Per-Frame Overhead**: Under 0.01 ms of SDK work per telemetry update - leaving over 99.9% of iRacing's 16.67 ms (60 Hz) frame budget to your code - **Background Processing**: Dedicated threads for telemetry collection and processing - your app's processing speed never blocks the streaming telemetry data - **Live Telemetry**: Real-time access to 200+ variables including speed, RPM, tire data during iRacing sessions - **IBT File Playback**: Analyze historical telemetry using the same API as live data @@ -65,7 +67,7 @@ This SDK takes a different approach. It treats telemetry as a **typed, high-thro - **Minimal-allocation reads** — each sample is copied once into a reused buffer (guarding against iRacing overwriting it mid-read), then decoded field-by-field via `ReadOnlySpan` with no further allocations, keeping steady-state GC pressure near zero - **Independent background tasks** mean CPU-intensive session-info YAML parsing never stalls the 60Hz telemetry path -Full details, including the threading model, buffering semantics, and built-in metrics: **[Architecture and Design](./docs/ARCHITECTURE.md)** +Full details on the threading model and buffering semantics: **[Architecture and Design](./docs/ARCHITECTURE.md)**. For the built-in metrics and how to collect them: **[Metrics and Diagnostics](./docs/METRICS.md)** ## Requirements @@ -319,13 +321,15 @@ sim.Camera.SwitchToCar("001", cameraGroup: 1, camera: 1); See [Samples Directory](./Samples/README.md) for ready-to-run example projects including: - Basic telemetry monitoring - IBT file analysis +- Collecting the SDK's built-in metrics - Simulator control, including cameras, replay, pit service, and broadcast commands - Data export utilities - Track analysis tools ## Documentation -- **[Architecture and Design](./docs/ARCHITECTURE.md)** - Threading model, data streaming and buffering, performance characteristics, and built-in metrics +- **[Architecture and Design](./docs/ARCHITECTURE.md)** - Threading model, data streaming and buffering, and performance characteristics +- **[Metrics and Diagnostics](./docs/METRICS.md)** - Instrument reference, OpenTelemetry and DI setup, collection, and interpretation - **[Advanced Usage](./docs/ADVANCED.md)** - Direct stream access, multiple consumers, and cancellation behavior - **[Migration Guide](./docs/MIGRATION_GUIDE.md)** - Upgrading from early pre-1.0 releases diff --git a/Samples/DumpVariables_DumpSessionInfo/DumpVariables_DumpSessionInfo.csproj b/Samples/DumpVariables_DumpSessionInfo/DumpVariables_DumpSessionInfo.csproj index 2f3f14e..70dd805 100644 --- a/Samples/DumpVariables_DumpSessionInfo/DumpVariables_DumpSessionInfo.csproj +++ b/Samples/DumpVariables_DumpSessionInfo/DumpVariables_DumpSessionInfo.csproj @@ -9,7 +9,7 @@ - + diff --git a/Samples/LocationAndWarnings/LocationAndWarnings.csproj b/Samples/LocationAndWarnings/LocationAndWarnings.csproj index 2f3f14e..70dd805 100644 --- a/Samples/LocationAndWarnings/LocationAndWarnings.csproj +++ b/Samples/LocationAndWarnings/LocationAndWarnings.csproj @@ -9,7 +9,7 @@ - + diff --git a/Samples/MinimalExampleAsync/MinimalExampleAsync.csproj b/Samples/MinimalExampleAsync/MinimalExampleAsync.csproj index 2f3f14e..70dd805 100644 --- a/Samples/MinimalExampleAsync/MinimalExampleAsync.csproj +++ b/Samples/MinimalExampleAsync/MinimalExampleAsync.csproj @@ -9,7 +9,7 @@ - + diff --git a/Samples/MinimalExampleSync/MinimalExampleSync.csproj b/Samples/MinimalExampleSync/MinimalExampleSync.csproj index b8d826c..ed8b4d3 100644 --- a/Samples/MinimalExampleSync/MinimalExampleSync.csproj +++ b/Samples/MinimalExampleSync/MinimalExampleSync.csproj @@ -9,7 +9,7 @@ - + diff --git a/Samples/SimControl/SimControl.csproj b/Samples/SimControl/SimControl.csproj index c029faf..44f68f2 100644 --- a/Samples/SimControl/SimControl.csproj +++ b/Samples/SimControl/SimControl.csproj @@ -9,6 +9,6 @@ - + diff --git a/Samples/SpeedRPMGear/SpeedRPMGear.csproj b/Samples/SpeedRPMGear/SpeedRPMGear.csproj index cc43274..d942af3 100644 --- a/Samples/SpeedRPMGear/SpeedRPMGear.csproj +++ b/Samples/SpeedRPMGear/SpeedRPMGear.csproj @@ -11,7 +11,7 @@ - + diff --git a/Sdk/SVappsLAB.iRacingTelemetrySDK.slnx b/Sdk/SVappsLAB.iRacingTelemetrySDK.slnx index 3890314..72c647b 100644 --- a/Sdk/SVappsLAB.iRacingTelemetrySDK.slnx +++ b/Sdk/SVappsLAB.iRacingTelemetrySDK.slnx @@ -1,6 +1,8 @@ + + @@ -10,9 +12,6 @@ - - - diff --git a/Sdk/SVappsLAB.iRacingTelemetrySDK/DataProviders/IBTDataProvider.cs b/Sdk/SVappsLAB.iRacingTelemetrySDK/DataProviders/IBTDataProvider.cs index f9959e4..0bf5bfb 100644 --- a/Sdk/SVappsLAB.iRacingTelemetrySDK/DataProviders/IBTDataProvider.cs +++ b/Sdk/SVappsLAB.iRacingTelemetrySDK/DataProviders/IBTDataProvider.cs @@ -14,26 +14,28 @@ * limitations under the License. **/ -using System; -using System.IO; -using System.IO.MemoryMappedFiles; -using System.Runtime.InteropServices; -using System.Threading; -using System.Threading.Tasks; using Microsoft.Extensions.Logging; using SVappsLAB.iRacingTelemetrySDK.IBTPlayback; using SVappsLAB.iRacingTelemetrySDK.irSDKDefines; +using System.IO.MemoryMappedFiles; +using System.Runtime.InteropServices; namespace SVappsLAB.iRacingTelemetrySDK.DataProviders; internal unsafe class IBTDataProvider : DataProviderBase, IDataProvider { + // the irsdk header version has been 1 or 2 forever. + // anything far outside is garbage + const int MAX_SANE_HEADER_VER = 3; + readonly IBTOptions _ibtOptions; readonly IPlaybackGovernor _governor; int _numRecords = 0; int _currentRecord = 0; - public IBTDataProvider(ILogger logger, IBTOptions ibtOptions) : base(logger) + // onPlaybackLag is called for each record of a paced playback with how far behind its + // scheduled time the record is being read + public IBTDataProvider(ILogger logger, IBTOptions ibtOptions, Action? onPlaybackLag = null) : base(logger) { if (!File.Exists(ibtOptions.IbtFilePath)) @@ -45,20 +47,25 @@ public IBTDataProvider(ILogger logger, IBTOptions ibtOptions) : base(logger) throw new ArgumentException($"File [{ibtOptions.IbtFilePath}] is not an IBT file", ibtOptions.IbtFilePath); } _ibtOptions = ibtOptions; - _governor = new SimpleGovernor(_logger, _ibtOptions!.PlayBackSpeedMultiplier); + _governor = new SimpleGovernor(_logger, _ibtOptions!.PlayBackSpeedMultiplier, onPlaybackLag); } public override void OpenDataSource() { + var fileLength = new FileInfo(_ibtOptions.IbtFilePath).Length; + // open in shared mode so multiple processes (or tests) can access the same file _mmFile = MemoryMappedFile.CreateFromFile(_ibtOptions.IbtFilePath, FileMode.Open, null, 0, MemoryMappedFileAccess.Read); _viewAccessor = _mmFile.CreateViewAccessor(0, 0, MemoryMappedFileAccess.Read); _viewAccessor!.SafeMemoryMappedViewHandle.AcquirePointer(ref _dataPtr); + // validate before the first read + ValidateHeader(fileLength); + // read header _header = GetHeader(); - _numRecords = GetNumRecordsInIBTFile(); + _numRecords = GetNumRecordsInIBTFile(fileLength); if (_logger.IsEnabled(LogLevel.Debug)) LogIBTFileLayout(); @@ -66,6 +73,50 @@ public override void OpenDataSource() _governor.StartPlayback(); } + // validate + void ValidateHeader(long fileLength) + { + var minLength = sizeof(irsdk_header) + sizeof(irsdk_diskSubHeader); + if (fileLength < minLength) + throw Invalid($"file is {fileLength} bytes, too small to hold the {minLength} byte header"); + + // read the raw header rather than calling GetHeader(), which would go on to read the + // var headers + var header = MemoryMarshal.AsRef(new ReadOnlySpan(_dataPtr, sizeof(irsdk_header))); + + // a sanity band + if (header.ver < 1 || header.ver > MAX_SANE_HEADER_VER) + throw Invalid($"header version {header.ver} is not a valid irsdk version"); + if (header.ver != Constants.IRSDK_VER) + _logger.LogWarning("IBT file [{file}] has header version {ver}, expected {expectedVer}. attempting to read it anyway", + _ibtOptions.IbtFilePath, header.ver, Constants.IRSDK_VER); + + if (header.numVars <= 0) + throw Invalid($"numVars is {header.numVars}"); + if (header.bufLen <= 0) + throw Invalid($"bufLen is {header.bufLen}"); + if (header.numBuf < 1 || header.numBuf > Constants.IRSDK_MAX_BUFS) + throw Invalid($"numBuf is {header.numBuf}"); + + // the var header array must sit past the header, and end inside the file + var varHeaderEnd = (long)header.varHeaderOffset + (long)header.numVars * sizeof(irsdk_varHeader); + if (header.varHeaderOffset < sizeof(irsdk_header) || varHeaderEnd > fileLength) + throw Invalid($"the {header.numVars} var headers at offset {header.varHeaderOffset} end at {varHeaderEnd}, past the end of the {fileLength} byte file"); + + // session info yaml + var sessionInfoEnd = (long)header.sessionInfoOffset + header.sessionInfoLen; + if (header.sessionInfoOffset < sizeof(irsdk_header) || header.sessionInfoLen < 0 || sessionInfoEnd > fileLength) + throw Invalid($"session info at offset {header.sessionInfoOffset} with length {header.sessionInfoLen} ends at {sessionInfoEnd}, past the end of the {fileLength} byte file"); + + // the record region starts at the first (only) buffer. one full record has to fit + var firstRecordOffset = header.GetVarBuf(0).bufOffset; + if (firstRecordOffset < sizeof(irsdk_header) || (long)firstRecordOffset + header.bufLen > fileLength) + throw Invalid($"the first {header.bufLen} byte record at offset {firstRecordOffset} runs past the end of the {fileLength} byte file"); + } + + InvalidDataException Invalid(string reason) => + new($"IBT file [{_ibtOptions.IbtFilePath}] is not valid: {reason}"); + // the base class logs the regions common to live and IBT data. // add the the disk sub header, and the record region till end of the file void LogIBTFileLayout() @@ -91,10 +142,21 @@ void LogIBTFileLayout() computedFileLength, actualFileLength, computedFileLength == actualFileLength); } - public int GetNumRecordsInIBTFile() + public int GetNumRecordsInIBTFile(long fileLength) { - var numRecs = GetDiskSubHeader().sessionRecordCount; - return numRecs; + var claimedRecs = GetDiskSubHeader().sessionRecordCount; + + var firstRecordOffset = _header.GetVarBuf(0).bufOffset; + var availableRecs = (int)Math.Min((fileLength - firstRecordOffset) / _header.bufLen, int.MaxValue); + + if (claimedRecs > availableRecs) + { + _logger.LogWarning("IBT file [{file}] claims {claimedRecs} records, but only {availableRecs} fit in its {fileLength} bytes. the file looks truncated - playing back what is there", + _ibtOptions.IbtFilePath, claimedRecs, availableRecs, fileLength); + return availableRecs; + } + + return claimedRecs; } // wait for iRacing to signal there is new data @@ -138,6 +200,9 @@ public static async Task WaitForDataReady(IPlaybackGovernor governor, int // throttle playback speed await governor.GovernSpeed(currentRecord).ConfigureAwait(false); + // measured after the wait, so any delay in the read loop shows up as lag + governor.RecordLag(currentRecord); + return provider.ProcessNextRecord(); } } diff --git a/Sdk/SVappsLAB.iRacingTelemetrySDK/DataProviders/LiveDataProvider.cs b/Sdk/SVappsLAB.iRacingTelemetrySDK/DataProviders/LiveDataProvider.cs index 9dee829..038ec0a 100644 --- a/Sdk/SVappsLAB.iRacingTelemetrySDK/DataProviders/LiveDataProvider.cs +++ b/Sdk/SVappsLAB.iRacingTelemetrySDK/DataProviders/LiveDataProvider.cs @@ -30,10 +30,14 @@ internal unsafe class LiveDataProvider : DataProviderBase, IDataProvider int _dataDropCount = 0; int _lastTickCount = 0; // latest tick count iRacing wrote to + readonly Action? _onMissedTicks; AutoResetEvent? _dataReadyEvent; - public LiveDataProvider(ILogger logger) : base(logger) + // onMissedTicks is called with the number of ticks iRacing wrote that were never read, + // each time a gap is detected + public LiveDataProvider(ILogger logger, Action? onMissedTicks = null) : base(logger) { + _onMissedTicks = onMissedTicks; } public override void OpenDataSource() @@ -67,13 +71,14 @@ internal bool ProcessNewData() return false; } - // if we missed any telemetry data, log that it happened + // if we missed any telemetry data, log and count it if (latestTickCount > _lastTickCount) { var tickDiff = latestTickCount - _lastTickCount - 1; if (_lastTickCount != 0 && tickDiff > 0) { _dataDropCount += tickDiff; + _onMissedTicks?.Invoke(tickDiff); _logger.LogWarning("dropped {count} data records. a total of {total} missed so far. last tick: {lastTick}, current tick: {currentTick}", tickDiff, _dataDropCount, _lastTickCount, latestTickCount); } } diff --git a/Sdk/SVappsLAB.iRacingTelemetrySDK/IBTPlayback/Governor.cs b/Sdk/SVappsLAB.iRacingTelemetrySDK/IBTPlayback/Governor.cs index 9701b4a..1f1523a 100644 --- a/Sdk/SVappsLAB.iRacingTelemetrySDK/IBTPlayback/Governor.cs +++ b/Sdk/SVappsLAB.iRacingTelemetrySDK/IBTPlayback/Governor.cs @@ -27,6 +27,7 @@ internal interface IPlaybackGovernor { public void StartPlayback(); public Task GovernSpeed(int recNum); + public void RecordLag(int recNum); public GovernorStats GetStats(); } @@ -40,11 +41,14 @@ internal class SimpleGovernor : IPlaybackGovernor TimeSpan _delayTimeSpan; // current delay amount Stopwatch _stopwatch = new Stopwatch(); GovernorStats? _governorStats; + readonly Action? _onPlaybackLag; - public SimpleGovernor(ILogger logger, int playbackSpeedMultiplier) + // onPlaybackLag is called from RecordLag with how far behind its scheduled time a record is being read + public SimpleGovernor(ILogger logger, int playbackSpeedMultiplier, Action? onPlaybackLag = null) { _logger = logger; _playbackSpeedMultiplier = playbackSpeedMultiplier; + _onPlaybackLag = onPlaybackLag; _adjustmentAmountInMs = STANDARD_MS_PER_RECORD / _playbackSpeedMultiplier / 5; // make delay +- changes in 5% increments } @@ -82,6 +86,18 @@ public Task GovernSpeed(int recNum) return Task.Delay(_delayTimeSpan); } + // reports how far behind its scheduled time a record is being read, zero when on time. + // nothing is reported at max speed, where there is no schedule + public void RecordLag(int recNum) + { + if (_onPlaybackLag == null || _playbackSpeedMultiplier == int.MaxValue) + return; + + var dueMs = recNum * STANDARD_MS_PER_RECORD / _playbackSpeedMultiplier; + var lagMs = Math.Max(0, _stopwatch.Elapsed.TotalMilliseconds - dueMs); + _onPlaybackLag(TimeSpan.FromMilliseconds(lagMs)); + } + void CalculateGoverningDelay(int currentRecNum) { var elapsed = _stopwatch.ElapsedMilliseconds; diff --git a/Sdk/SVappsLAB.iRacingTelemetrySDK/Metrics/MetricsService.cs b/Sdk/SVappsLAB.iRacingTelemetrySDK/Metrics/MetricsService.cs index 1d155a6..1525952 100644 --- a/Sdk/SVappsLAB.iRacingTelemetrySDK/Metrics/MetricsService.cs +++ b/Sdk/SVappsLAB.iRacingTelemetrySDK/Metrics/MetricsService.cs @@ -1,12 +1,12 @@ /** * Copyright (C) 2024-2026 Scott Velez - * + * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at - * + * * http://www.apache.org/licenses/LICENSE-2.0 - * + * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. @@ -16,60 +16,356 @@ using System; using System.Collections.Generic; +using System.Diagnostics; using System.Diagnostics.Metrics; using System.Threading.Tasks; namespace SVappsLAB.iRacingTelemetrySDK.Metrics; +// use opentelemetry naming conventions: +// lowercase, dot-namespaced, no unit or '_total' suffix in the name (exporters add those) +internal static class MetricNames +{ + const string Prefix = "svappslab.iracingsdk."; + + public const string TelemetryRecordsProcessed = Prefix + "telemetry.records.processed"; + public const string TelemetryRecordsDropped = Prefix + "telemetry.records.dropped"; + + // latency names: sdk + handler = total. 'decode' is the SDK-side + public const string TelemetryDecodeDuration = Prefix + "telemetry.decode.duration"; + public const string TelemetrySdkDuration = Prefix + "telemetry.sdk.duration"; + public const string TelemetryHandlerDuration = Prefix + "telemetry.handler.duration"; + public const string TelemetryTotalDuration = Prefix + "telemetry.total.duration"; + public const string TelemetrySampleInterval = Prefix + "telemetry.sample.interval"; + + public const string SessionInfoRecordsProcessed = Prefix + "session_info.records.processed"; + public const string SessionInfoProcessDuration = Prefix + "session_info.process.duration"; + public const string SessionInfoRecordsDropped = Prefix + "session_info.records.dropped"; + public const string SessionInfoSize = Prefix + "session_info.size"; + public const string SessionInfoParseAttempts = Prefix + "session_info.parse.attempts"; + + public const string PlaybackLag = Prefix + "playback.lag"; + + // attributes + public const string DataSource = Prefix + "data_source"; + public const string DropReason = Prefix + "drop.reason"; + public const string SessionInfoStream = Prefix + "session_info.stream"; + public const string ErrorType = "error.type"; // opentelemetry semantic convention +} + +internal static class MetricTags +{ + // set only when an operation fails, with the exception's full type name - per + // opentelemetry error.type convention. + public static KeyValuePair ErrorType(Exception ex) => + new(MetricNames.ErrorType, ex.GetType().FullName); +} + internal class TelemetryMeters { + // sentinel start value to denote "duration is not being collected" + internal const long NotTiming = 0; + + // preallocated tags keep recording allocation-free + static readonly KeyValuePair MissedTickTag = new(MetricNames.DropReason, "missed_tick"); + static readonly KeyValuePair ConsumerOverflowTag = new(MetricNames.DropReason, "consumer_overflow"); + + // decoding one record: p50 2.2us, p99 7.4us, p99.9 16.5us, rare millisecond outliers + // when the machine stalls. microsecond resolution up to 100us is where the signal is. + static readonly InstrumentAdvice DecodeAdvice = new() + { + HistogramBucketBoundaries = [0.000001, 0.0000025, 0.000005, 0.00001, 0.000025, 0.00005, 0.0001, 0.00025, 0.0005, 0.001, 0.005, 0.025] + }; + + // sdk and total latency share boundaries so the two can be compared bucket for bucket - + // the difference between them is what the consumer's handler cost. + // + // 0.01667s is one frame at 60Hz: anything above it is older than the next record iRacing has already written. + static readonly InstrumentAdvice LatencyAdvice = new() + { + HistogramBucketBoundaries = [0.000002, 0.000005, 0.00001, 0.000025, 0.00005, 0.0001, 0.00025, 0.001, 0.0025, 0.01, 0.01667, 0.03333, 0.1, 0.5] + }; + + // the consumer's own code, need wide range as some users handlers take a while. + // + // 0.01667s matters most here: a handler slower than one frame cannot sustain 60Hz. Sustained + // overload can cause consumer_overflow in async delivery or missed_tick drops in live synchronous delivery. + static readonly InstrumentAdvice HandlerAdvice = new() + { + HistogramBucketBoundaries = [0.000001, 0.0000025, 0.000005, 0.00001, 0.000025, 0.0001, 0.00025, 0.001, 0.0025, 0.01, 0.01667, 0.03333, 0.1, 1] + }; + + // live intervals cluster hard at one frame: in the fitted session 99.99% of records + // arrived exactly one tick apart and 0.01% two ticks apart. + // + // the cluster is bracketed rather than split - (0.015, 0.0185] is "on time" - but with a + // boundary on 0.01667 inside it, so early and late frames separate without losing the + // single-bucket health check. + // + // (0.025, 0.04] brackets the two-frame cluster: exactly one missed frame. the buckets + // below 0.005 are where max-speed ibt playback fits. + static readonly InstrumentAdvice IntervalAdvice = new() + { + HistogramBucketBoundaries = [0.00001, 0.0001, 0.001, 0.005, 0.0125, 0.015, 0.01667, 0.0185, 0.025, 0.04, 0.0667, 0.1, 0.25, 1] + }; + + // previous acquisition timestamp, for the sample interval. only touched by the read loop + long _lastAcquiredTimestamp = NotTiming; + public TelemetryMeters(Meter meter) { Processed = meter.CreateCounter( - "telemetry_records_processed_total", - description: "Total number of telemetry records processed"); + MetricNames.TelemetryRecordsProcessed, + unit: "{record}", + description: "Number of telemetry records processed. Failed records carry the error.type attribute."); + // missed_tick: iRacing wrote ticks the sdk never read (live only - the read loop fell + // behind). consumer_overflow: records were read but evicted from the async delivery + // buffer because the consumer's handler could not keep up Dropped = meter.CreateCounter( - "telemetry_records_dropped_total", - description: "Total number of telemetry records dropped"); + MetricNames.TelemetryRecordsDropped, + unit: "{record}", + description: "Number of telemetry records lost before reaching the consumer."); - Duration = meter.CreateHistogram( - "telemetry_processing_duration_microseconds", - unit: "us", - description: "Time spent processing individual telemetry records"); + Decode = meter.CreateHistogram( + MetricNames.TelemetryDecodeDuration, + unit: "s", + description: "SDK time decoding one telemetry record into a typed sample.", + tags: null, + advice: DecodeAdvice); + + // the pipeline instruments all measure from the same origin: the instant the data provider + // reported new data, before decoding. iRacing does not timestamp its samples, so nothing + // upstream of that is measurable - the missed_tick drop count is the proxy for it + SdkLatency = meter.CreateHistogram( + MetricNames.TelemetrySdkDuration, + unit: "s", + description: "SDK time: acquiring a telemetry record until the consumer's handler received it.", + tags: null, + advice: LatencyAdvice); + + Handler = meter.CreateHistogram( + MetricNames.TelemetryHandlerDuration, + unit: "s", + description: "Consumer time: the handler's own work on one telemetry record.", + tags: null, + advice: HandlerAdvice); + + Total = meter.CreateHistogram( + MetricNames.TelemetryTotalDuration, + unit: "s", + description: "End to end: acquisition until the handler finished, including SDK and handler time.", + tags: null, + advice: LatencyAdvice); + + SampleInterval = meter.CreateHistogram( + MetricNames.TelemetrySampleInterval, + unit: "s", + description: "Elapsed-time gap between consecutive telemetry record acquisitions.", + tags: null, + advice: IntervalAdvice); } public Counter Processed { get; private set; } public Counter Dropped { get; private set; } - public Histogram Duration { get; private set; } + public Histogram Decode { get; private set; } + public Histogram SdkLatency { get; private set; } + public Histogram Handler { get; private set; } + public Histogram Total { get; private set; } + public Histogram SampleInterval { get; private set; } + + // this runs for every telemetry record, so only read the clock when a listener + // is collecting the duration histogram. counter adds are near-free without a listener + internal long StartTiming() => Decode.Enabled ? Stopwatch.GetTimestamp() : NotTiming; + + internal void RecordProcessed(long startTimestamp) + { + Processed.Add(1); + + if (startTimestamp != NotTiming) + Decode.Record(Stopwatch.GetElapsedTime(startTimestamp).TotalSeconds); + } + + internal void RecordFailed(long startTimestamp, Exception ex) + { + var errorType = MetricTags.ErrorType(ex); + Processed.Add(1, errorType); + + if (startTimestamp != NotTiming) + Decode.Record(Stopwatch.GetElapsedTime(startTimestamp).TotalSeconds, errorType); + } + + internal void TicksMissed(long count) => Dropped.Add(count, MissedTickTag); + internal void ConsumerOverflow(long count) => Dropped.Add(count, ConsumerOverflowTag); + + // like StartTiming, the pipeline clock is only read while a listener collects. + // returns the acquisition timestamp every later pipeline measurement starts from + internal long MarkAcquired() + { + if (!(SdkLatency.Enabled || Total.Enabled || SampleInterval.Enabled)) + { + // forget the previous acquisition, so re-enabling can't report the idle gap as one interval + _lastAcquiredTimestamp = NotTiming; + return NotTiming; + } + + var now = Stopwatch.GetTimestamp(); + if (_lastAcquiredTimestamp != NotTiming && SampleInterval.Enabled) + SampleInterval.Record(Stopwatch.GetElapsedTime(_lastAcquiredTimestamp, now).TotalSeconds); + _lastAcquiredTimestamp = now; + + return now; + } + + // the consumer is about to receive the record. returns the timestamp the handler duration starts from + internal long RecordHandoff(long acquiredTimestamp) + { + if (acquiredTimestamp != NotTiming && SdkLatency.Enabled) + SdkLatency.Record(Stopwatch.GetElapsedTime(acquiredTimestamp).TotalSeconds); + + return Handler.Enabled ? Stopwatch.GetTimestamp() : NotTiming; + } + + // the consumer has finished with the record + internal void RecordConsumed(long acquiredTimestamp, long handlerStartTimestamp) + { + var total = acquiredTimestamp != NotTiming && Total.Enabled; + if (!total && handlerStartTimestamp == NotTiming) + return; - internal void RecordsProcessed(long count) => Processed.Add(count); - internal void RecordsDropped(long count) => Dropped.Add(count); - internal void ProcessingDuration(TimeSpan ts) => Duration.Record(ts.TotalMicroseconds); + var now = Stopwatch.GetTimestamp(); + if (handlerStartTimestamp != NotTiming) + Handler.Record(Stopwatch.GetElapsedTime(handlerStartTimestamp, now).TotalSeconds); + if (total) + Total.Record(Stopwatch.GetElapsedTime(acquiredTimestamp, now).TotalSeconds); + } } + internal class SessionInfoMeters { + // parsing session info yaml takes milliseconds, occasionally longer for large sessions + static readonly InstrumentAdvice DurationAdvice = new() + { + HistogramBucketBoundaries = [0.001, 0.0025, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5] + }; + + // session info yaml runs from a few kilobytes for a test session to hundreds for a full field + static readonly InstrumentAdvice SizeAdvice = new() + { + HistogramBucketBoundaries = [4_096, 16_384, 32_768, 65_536, 131_072, 262_144, 524_288, 1_048_576] + }; + + // one bucket per parse strategy - anything above 1 means the yaml needed repairing first + static readonly InstrumentAdvice AttemptsAdvice = new() + { + HistogramBucketBoundaries = [1, 2, 3] + }; + + static readonly KeyValuePair ParseBacklogTag = new(MetricNames.DropReason, "parse_backlog"); + static readonly KeyValuePair ConsumerOverflowTag = new(MetricNames.DropReason, "consumer_overflow"); + static readonly KeyValuePair SessionDataStreamTag = new(MetricNames.SessionInfoStream, "session_data"); + static readonly KeyValuePair SessionDataYamlStreamTag = new(MetricNames.SessionInfoStream, "session_data_yaml"); + public SessionInfoMeters(Meter meter) { Processed = meter.CreateCounter( - "sessioninfo_records_processed_total", - description: "Total number of session info records processed"); + MetricNames.SessionInfoRecordsProcessed, + unit: "{record}", + description: "Number of session info records processed. Failed records carry the error.type attribute."); Duration = meter.CreateHistogram( - "sessioninfo_processing_duration_milliseconds", - unit: "ms", - description: "Time spent processing individual session info records"); + MetricNames.SessionInfoProcessDuration, + unit: "s", + description: "Time spent parsing each session info record.", + tags: null, + advice: DurationAdvice); + + // parse_backlog: updates arrived faster than they could be parsed and were evicted from the + // internal queue unparsed. consumer_overflow: parsed updates were evicted from a public stream + // because nobody read them in time - tagged with which stream + Dropped = meter.CreateCounter( + MetricNames.SessionInfoRecordsDropped, + unit: "{record}", + description: "Number of session info records lost before reaching the consumer."); + + Size = meter.CreateHistogram( + MetricNames.SessionInfoSize, + unit: "By", + description: "UTF-8 encoded size of each session info record.", + tags: null, + advice: SizeAdvice); + + ParseAttempts = meter.CreateHistogram( + MetricNames.SessionInfoParseAttempts, + unit: "{attempt}", + description: "Parse attempts each successfully parsed session info record needed.", + tags: null, + advice: AttemptsAdvice); } public Counter Processed { get; private set; } public Histogram Duration { get; private set; } + public Counter Dropped { get; private set; } + public Histogram Size { get; private set; } + public Histogram ParseAttempts { get; private set; } + + // session info updates are infrequent, so the caller always measures elapsed time + internal void RecordProcessed(TimeSpan elapsed, int sizeBytes, int parseAttempts) + { + Processed.Add(1); + Duration.Record(elapsed.TotalSeconds); + Size.Record(sizeBytes); + ParseAttempts.Record(parseAttempts); + } + + // a failure means every parse strategy was exhausted, so there is no attempt count to add + internal void RecordFailed(TimeSpan elapsed, int sizeBytes, Exception ex) + { + var errorType = MetricTags.ErrorType(ex); + Processed.Add(1, errorType); + Duration.Record(elapsed.TotalSeconds, errorType); + Size.Record(sizeBytes, errorType); + } - internal void RecordsProcessed(long count) => Processed.Add(count); - internal void ProcessingDuration(TimeSpan ts) => Duration.Record(ts.TotalMilliseconds); + internal void ParseBacklogOverflow(long count) => Dropped.Add(count, ParseBacklogTag); + internal void SessionDataOverflow(long count) => Dropped.Add(count, ConsumerOverflowTag, SessionDataStreamTag); + internal void SessionDataYamlOverflow(long count) => Dropped.Add(count, ConsumerOverflowTag, SessionDataYamlStreamTag); +} + +internal class PlaybackMeters +{ + // lag ranges from zero when on time to many seconds when playback falls far behind + // measured over a 1x replay of an 8 minute live recording: p50 7.0ms, p90 13.2ms, + // p99 14.7ms, p99.9 91.7ms, max 297.6ms. + // + // 0.01667s is the threshold that matters - a record read less than one frame behind + // schedule is effectively on time. the old tail ran to 60s, which is well past the point + // where a replay has stopped being a replay; 30s is kept only so a hang lands somewhere. + static readonly InstrumentAdvice LagAdvice = new() + { + HistogramBucketBoundaries = [0.0005, 0.001, 0.0025, 0.005, 0.01, 0.01667, 0.03333, 0.0667, 0.1, 0.25, 0.5, 1, 5, 30] + }; + + public PlaybackMeters(Meter meter) + { + // recorded for every record of a paced ibt playback, zero when on time. a healthy playback + // sits near zero; a rising tail means the consumer or the machine cannot keep up with the + // requested speed. max-speed playback has no schedule and records nothing + Lag = meter.CreateHistogram( + MetricNames.PlaybackLag, + unit: "s", + description: "How far behind its scheduled time each paced IBT playback record was read.", + tags: null, + advice: LagAdvice); + } + public Histogram Lag { get; private set; } + + internal void RecordLag(TimeSpan lag) => Lag.Record(lag.TotalSeconds); } internal interface IMetricsService : IAsyncDisposable { TelemetryMeters Telemetry { get; } SessionInfoMeters SessionInfo { get; } + PlaybackMeters Playback { get; } } internal class MetricsService : IMetricsService @@ -77,48 +373,25 @@ internal class MetricsService : IMetricsService private readonly Meter _meter; public TelemetryMeters Telemetry { get; private set; } public SessionInfoMeters SessionInfo { get; private set; } + public PlaybackMeters Playback { get; private set; } - public MetricsService(IMeterFactory? meterFactory, string dataSourceType) + public MetricsService(IMeterFactory? meterFactory, string dataSource) { var tags = new List> { - new("data_source", dataSourceType) + new(MetricNames.DataSource, dataSource) }; + // the version lets metrics backends tell instrumentation revisions apart + var version = typeof(MetricsService).Assembly.GetName().Version?.ToString(); + _meter = meterFactory != null ? - meterFactory.Create(Constants.SDK_NAME, null, tags) : - new Meter(Constants.SDK_NAME, null, tags); + meterFactory.Create(TelemetryMetrics.MeterName, version, tags) : + new Meter(TelemetryMetrics.MeterName, version, tags); Telemetry = new TelemetryMeters(_meter); SessionInfo = new SessionInfoMeters(_meter); - - //// Connection metrics - //_connectionsTotal = _meter.CreateCounter( - // "telemetry_connections_total", - // description: "Total number of telemetry connections established"); - - //_disconnectionsTotal = _meter.CreateCounter( - // "telemetry_disconnections_total", - // description: "Total number of telemetry disconnections"); - - //_connectionStatus = _meter.CreateGauge( - // "telemetry_connection_status", - // description: "Current connection status (1 = connected, 0 = disconnected)"); - - //_connectionDuration = _meter.CreateHistogram( - // "telemetry_connection_duration_seconds", - // unit: "s", - // description: "Duration of telemetry connections", - // advice: new InstrumentAdvice { HistogramBucketBoundaries = [1, 5, 10, 30, 60, 300, 600, 1800, 3600] }); - - - //// Observable metrics for current state - //_meter.CreateObservableGauge( - // "telemetry_connection_uptime_seconds", - // () => _isConnected && _connectionStartTime.HasValue ? - // (DateTime.UtcNow - _connectionStartTime.Value).TotalSeconds : 0.0, - // unit: "s", - // description: "Current connection uptime in seconds"); + Playback = new PlaybackMeters(_meter); } public ValueTask DisposeAsync() diff --git a/Sdk/SVappsLAB.iRacingTelemetrySDK/Metrics/ScopeTimeSpanTimer.cs b/Sdk/SVappsLAB.iRacingTelemetrySDK/Metrics/ScopeTimeSpanTimer.cs deleted file mode 100644 index 68b95eb..0000000 --- a/Sdk/SVappsLAB.iRacingTelemetrySDK/Metrics/ScopeTimeSpanTimer.cs +++ /dev/null @@ -1,35 +0,0 @@ -/** - * Copyright (C) 2024-2026 Scott Velez - * - * Licensed under the Apache License, Version 2.0 (the "License"); - * you may not use this file except in compliance with the License. - * You may obtain a copy of the License at - * - * http://www.apache.org/licenses/LICENSE-2.0 - * - * Unless required by applicable law or agreed to in writing, software - * distributed under the License is distributed on an "AS IS" BASIS, - * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. - * See the License for the specific language governing permissions and - * limitations under the License. -**/ - -using System; - -namespace SVappsLAB.iRacingTelemetrySDK.Metrics; - -internal class ScopeTimeSpanTimer : IDisposable -{ - long _timeStamp; - readonly Action _lambda; - public ScopeTimeSpanTimer(Action lambda) - { - _lambda = lambda; - _timeStamp = TimeProvider.System.GetTimestamp(); - } - public void Dispose() - { - var elapsed = TimeProvider.System.GetElapsedTime(_timeStamp); - _lambda(elapsed); - } -} diff --git a/Sdk/SVappsLAB.iRacingTelemetrySDK/SVappsLAB.iRacingTelemetrySDK.csproj b/Sdk/SVappsLAB.iRacingTelemetrySDK/SVappsLAB.iRacingTelemetrySDK.csproj index 914e80d..b1c8d78 100644 --- a/Sdk/SVappsLAB.iRacingTelemetrySDK/SVappsLAB.iRacingTelemetrySDK.csproj +++ b/Sdk/SVappsLAB.iRacingTelemetrySDK/SVappsLAB.iRacingTelemetrySDK.csproj @@ -43,7 +43,7 @@ iRacing iRacingSDK irsdk IBT telemetry SDK API sim-control replay broadcast NUGET.md LICENSE - 2.4.0 + 2.5.0 Scott Velez SVappsLAB Copyright (c) 2026 SVappsLAB diff --git a/Sdk/SVappsLAB.iRacingTelemetrySDK/Metrics/ScopeLambda.cs b/Sdk/SVappsLAB.iRacingTelemetrySDK/StampedSample.cs similarity index 54% rename from Sdk/SVappsLAB.iRacingTelemetrySDK/Metrics/ScopeLambda.cs rename to Sdk/SVappsLAB.iRacingTelemetrySDK/StampedSample.cs index 9691cfc..adea775 100644 --- a/Sdk/SVappsLAB.iRacingTelemetrySDK/Metrics/ScopeLambda.cs +++ b/Sdk/SVappsLAB.iRacingTelemetrySDK/StampedSample.cs @@ -1,12 +1,12 @@ /** * Copyright (C) 2024-2026 Scott Velez - * + * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at - * + * * http://www.apache.org/licenses/LICENSE-2.0 - * + * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. @@ -14,19 +14,10 @@ * limitations under the License. **/ -using System; +namespace SVappsLAB.iRacingTelemetrySDK; -namespace SVappsLAB.iRacingTelemetrySDK.Metrics; - -internal class ScopeLambda : IDisposable -{ - readonly Action _lambda; - public ScopeLambda(Action lambda) - { - _lambda = lambda; - } - public void Dispose() - { - _lambda(); - } -} +// what travels through the internal telemetry channel: one record plus when it was acquired. +// TData is the caller's source-generated struct. the timestamp rides with it and is +// unwrapped before delivery - the public stream still yields plain TData. +// AcquiredTimestamp is TelemetryMeters.NotTiming when no pipeline instrument is being collected +internal readonly record struct StampedSample(TData Sample, long AcquiredTimestamp); diff --git a/Sdk/SVappsLAB.iRacingTelemetrySDK/TelemetryClient.cs b/Sdk/SVappsLAB.iRacingTelemetrySDK/TelemetryClient.cs index 775c8ff..701779e 100644 --- a/Sdk/SVappsLAB.iRacingTelemetrySDK/TelemetryClient.cs +++ b/Sdk/SVappsLAB.iRacingTelemetrySDK/TelemetryClient.cs @@ -164,7 +164,7 @@ public class TelemetryClient : ITelemetryClient, IAsyncDisposable where T readonly Channel _errorChannel; readonly Channel _rawSessionDataChannel; readonly Channel _sessionDataChannel; - readonly Channel _telemetryDataChannel; + readonly Channel> _telemetryDataChannel; readonly Channel _internalSessionInfoChannel; IMetricsService? _metricsService; Task? _dataProcessingTask; @@ -255,8 +255,31 @@ private async IAsyncEnumerable GetSessionDataEnumerable([E private async IAsyncEnumerable GetTelemetryDataEnumerable([EnumeratorCancellation] CancellationToken cancellationToken = default) { - await foreach (var item in _telemetryDataChannel.Reader.ReadAllAsync(cancellationToken)) - yield return item; + await foreach (var stamped in GetStampedTelemetryDataEnumerable(cancellationToken)) + yield return stamped.Sample; + } + + // the metered side of the telemetry stream. both async paths read through here - the handler + // loop and the public TelemetryData stream - so they report the same measurements + private async IAsyncEnumerable> GetStampedTelemetryDataEnumerable([EnumeratorCancellation] CancellationToken cancellationToken = default) + { + await foreach (var stamped in _telemetryDataChannel.Reader.ReadAllAsync(cancellationToken)) + { + var meters = _metricsService?.Telemetry; + var handlerStart = meters?.RecordHandoff(stamped.AcquiredTimestamp) ?? TelemetryMeters.NotTiming; + + // an iterator only resumes past its yield when the consumer asks for the next record. + // this span is exactly the consumer's work duration. + // the finally covers a consumer breaking out of its loop, which disposes the enumerator instead of resuming it + try + { + yield return stamped; + } + finally + { + meters?.RecordConsumed(stamped.AcquiredTimestamp, handlerStart); + } + } } /// @@ -320,9 +343,13 @@ private TelemetryClient(ILogger logger, ClientOptions? clientOptions = null, IBT }; _connectStateChannel = Channel.CreateBounded(boundedChannelOptions); _errorChannel = Channel.CreateBounded(boundedChannelOptions); - _rawSessionDataChannel = Channel.CreateBounded(boundedChannelOptions); - _sessionDataChannel = Channel.CreateBounded(boundedChannelOptions); - _telemetryDataChannel = Channel.CreateBounded(boundedChannelOptions); + _rawSessionDataChannel = Channel.CreateBounded( + boundedChannelOptions, _ => _metricsService?.SessionInfo.SessionDataYamlOverflow(1)); + _sessionDataChannel = Channel.CreateBounded( + boundedChannelOptions, _ => _metricsService?.SessionInfo.SessionDataOverflow(1)); + // a slow async consumer loses the oldest records rather than stalling the producer - count them + _telemetryDataChannel = Channel.CreateBounded>( + boundedChannelOptions, _ => _metricsService?.Telemetry.ConsumerOverflow(1)); // Internal session info processing channel var sessionInfoChannelOptions = new BoundedChannelOptions(10) @@ -331,12 +358,14 @@ private TelemetryClient(ILogger logger, ClientOptions? clientOptions = null, IBT SingleReader = true, SingleWriter = false // Both Live and IBT can write }; - _internalSessionInfoChannel = Channel.CreateBounded(sessionInfoChannelOptions); + // updates arriving faster than they can be parsed are evicted unparsed - count them + _internalSessionInfoChannel = Channel.CreateBounded( + sessionInfoChannelOptions, _ => _metricsService?.SessionInfo.ParseBacklogOverflow(1)); // initialize data provider - _dataProvider = _ibtOptions == null ? new LiveDataProvider(_logger) : new IBTDataProvider(_logger, _ibtOptions); + _dataProvider = _ibtOptions == null ? new LiveDataProvider(_logger, RecordMissedTicks) : new IBTDataProvider(_logger, _ibtOptions, RecordPlaybackLag); - _metricsService = new MetricsService(clientOptions?.MeterFactory, _ibtOptions == null ? "Live" : "IBT"); + _metricsService = new MetricsService(clientOptions?.MeterFactory, _ibtOptions == null ? "live" : "ibt"); _telemetryAccessor = new TelemetryDataAccessor(_logger); _sessionInfoParser = new YamlParser(_logger); @@ -528,9 +557,9 @@ private async Task WaitForHandlersToComplete(Task subscriptionTask) private async Task HandleTelemetryData(Func handler) { - await foreach (var data in TelemetryData.ConfigureAwait(false)) + await foreach (var stamped in GetStampedTelemetryDataEnumerable().ConfigureAwait(false)) { - await handler(data).ConfigureAwait(false); + await handler(stamped.Sample).ConfigureAwait(false); } } @@ -842,6 +871,12 @@ private void CompleteAllChannels(Exception? exception = null) } private bool IsOnlineMode => _ibtOptions == null; + private void RecordMissedTicks(long count) => _metricsService?.Telemetry.TicksMissed(count); + + private void RecordPlaybackLag(TimeSpan lag) => _metricsService?.Playback.RecordLag(lag); + + private long MarkAcquired() => _metricsService?.Telemetry.MarkAcquired() ?? TelemetryMeters.NotTiming; + private async Task ProcessSessionInfoChannel(CancellationToken ct) { _logger.LogDebug("Session info processor started"); @@ -885,20 +920,22 @@ private async Task ProcessSessionInfoChannel(CancellationToken ct) private TelemetrySessionInfo? ParseSessionInfo(string rawSessionInfoYaml) { - using var timer = new ScopeTimeSpanTimer(elapsed => _metricsService?.SessionInfo.ProcessingDuration(elapsed)); - using var counter = new ScopeLambda(() => _metricsService?.SessionInfo.RecordsProcessed(1)); - TelemetrySessionInfo? sessionInfo = null; + // a full pass over the yaml, but it's trivial + var sizeBytes = System.Text.Encoding.UTF8.GetByteCount(rawSessionInfoYaml); + var startTimestamp = Stopwatch.GetTimestamp(); try { - Stopwatch sw = Stopwatch.StartNew(); - var parseResult = _sessionInfoParser.Parse(rawSessionInfoYaml); sessionInfo = parseResult.Model; - _logger.LogDebug("sessionInfo deserialize complete. required {attempts} attempts. ({ScopeTimeSpanTimer}ms)", parseResult.ParseAttemptsRequired, sw.ElapsedMilliseconds); + + var elapsed = Stopwatch.GetElapsedTime(startTimestamp); + _metricsService?.SessionInfo.RecordProcessed(elapsed, sizeBytes, parseResult.ParseAttemptsRequired); + _logger.LogDebug("sessionInfo deserialize complete. required {attempts} attempts. ({elapsedMs}ms)", parseResult.ParseAttemptsRequired, (long)elapsed.TotalMilliseconds); } catch (Exception e) { + _metricsService?.SessionInfo.RecordFailed(Stopwatch.GetElapsedTime(startTimestamp), sizeBytes, e); _logger.LogError(e, "error deserializing or sending sessionTelemetryInfo event"); _errorChannel.Writer.TryWrite(e); } @@ -1018,10 +1055,13 @@ private async Task WaitForData(CancellationToken ct) return false; } + // taken before decoding, so decode cost lands inside every pipeline measurement + var acquiredTimestamp = MarkAcquired(); + // suppress events if paused or disposed if (!IsPaused) { - await DeliverTelemetryData(GetTelemetryDataSample()).ConfigureAwait(false); + await DeliverTelemetryData(new(GetTelemetryDataSample(), acquiredTimestamp)).ConfigureAwait(false); } return true; // data processed @@ -1029,32 +1069,48 @@ private async Task WaitForData(CancellationToken ct) private T GetTelemetryDataSample() { - using var elapsedTimer = new ScopeTimeSpanTimer(elapsed => _metricsService?.Telemetry.ProcessingDuration(elapsed)); - using var counter = new ScopeLambda(() => _metricsService?.Telemetry.RecordsProcessed(1)); + // hot path + var meters = _metricsService?.Telemetry; + var startTimestamp = meters?.StartTiming() ?? TelemetryMeters.NotTiming; + + T val; + try + { + val = _telemetryAccessor.CreateTelemetryDataSample(_dataProvider); + } + catch (Exception ex) + { + meters?.RecordFailed(startTimestamp, ex); + throw; + } - T val = _telemetryAccessor.CreateTelemetryDataSample(_dataProvider); + meters?.RecordProcessed(startTimestamp); return val; } // keep this method synchronous to avoid building an async - private Task DeliverTelemetryData(T telemetryData) + private Task DeliverTelemetryData(StampedSample stamped) { if (_deliveryMode == TelemetryDeliveryMode.Synchronous) { return _syncTelemetryHandler != null - ? InvokeSyncTelemetryHandler(telemetryData) + ? InvokeSyncTelemetryHandler(stamped) : Task.CompletedTask; } - _telemetryDataChannel.Writer.TryWrite(telemetryData); + _telemetryDataChannel.Writer.TryWrite(stamped); return Task.CompletedTask; } - private async Task InvokeSyncTelemetryHandler(T telemetryData) + private async Task InvokeSyncTelemetryHandler(StampedSample stamped) { + // no queue in synchronous mode, so sdk latency is only decode cost. recorded anyway, + // so the sync/async tradeoff shows up in the data instead of having to be inferred + var meters = _metricsService?.Telemetry; + var handlerStart = meters?.RecordHandoff(stamped.AcquiredTimestamp) ?? TelemetryMeters.NotTiming; try { - await _syncTelemetryHandler!(telemetryData).ConfigureAwait(false); + await _syncTelemetryHandler!(stamped.Sample).ConfigureAwait(false); } catch (Exception ex) { @@ -1062,6 +1118,10 @@ private async Task InvokeSyncTelemetryHandler(T telemetryData) // catch blocks fault Monitor() instead of treating it as a retryable error routed to OnError throw new SyncHandlerFaultException(ex); } + finally + { + meters?.RecordConsumed(stamped.AcquiredTimestamp, handlerStart); + } } private async Task ProcessIbtData(CancellationToken token) { @@ -1103,10 +1163,13 @@ private async Task ProcessIbtData(CancellationToken token) break; } + // taken before decoding, so decode cost lands inside pipeline measurement + var acquiredTimestamp = MarkAcquired(); + // suppress events if paused or disposed if (!IsPaused) { - await DeliverTelemetryData(GetTelemetryDataSample()).ConfigureAwait(false); + await DeliverTelemetryData(new(GetTelemetryDataSample(), acquiredTimestamp)).ConfigureAwait(false); } // Apply playback speed delay if configured diff --git a/Sdk/SVappsLAB.iRacingTelemetrySDK/Constants.cs b/Sdk/SVappsLAB.iRacingTelemetrySDK/TelemetryMetrics.cs similarity index 65% rename from Sdk/SVappsLAB.iRacingTelemetrySDK/Constants.cs rename to Sdk/SVappsLAB.iRacingTelemetrySDK/TelemetryMetrics.cs index 9930588..ede8228 100644 --- a/Sdk/SVappsLAB.iRacingTelemetrySDK/Constants.cs +++ b/Sdk/SVappsLAB.iRacingTelemetrySDK/TelemetryMetrics.cs @@ -1,12 +1,12 @@ /** * Copyright (C) 2024-2026 Scott Velez - * + * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at - * + * * http://www.apache.org/licenses/LICENSE-2.0 - * + * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. @@ -16,7 +16,13 @@ namespace SVappsLAB.iRacingTelemetrySDK; -internal static class Constants +/// +/// Identifies the diagnostic metrics published by the SDK. +/// +public static class TelemetryMetrics { - public const string SDK_NAME = "SVappsLAB.iRacingTelemetrySDK"; + /// + /// The name of the that publishes SDK metrics. + /// + public const string MeterName = "SVappsLAB.iRacingTelemetrySDK"; } diff --git a/Sdk/tests/UnitTests/Metrics/MetricsServiceTests.cs b/Sdk/tests/UnitTests/Metrics/MetricsServiceTests.cs new file mode 100644 index 0000000..f279f69 --- /dev/null +++ b/Sdk/tests/UnitTests/Metrics/MetricsServiceTests.cs @@ -0,0 +1,292 @@ +/** + * Copyright (C) 2024-2026 Scott Velez + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. +**/ + +using SVappsLAB.iRacingTelemetrySDK; +using SVappsLAB.iRacingTelemetrySDK.Metrics; +using System.Diagnostics.Metrics; + +namespace UnitTests.Metrics; + +public class MetricsServiceTests +{ + record Measurement(double Value, Dictionary Tags); + + // listens only to instruments whose meter carries this test's unique data source, + // so tests running in parallel never see each other's measurements + sealed class Recorder : IDisposable + { + readonly MeterListener _listener = new(); + readonly List<(string Name, Measurement Measurement)> _measurements = []; + readonly Dictionary _instruments = []; + + public Recorder(string dataSource, params string[] instrumentNames) + { + _listener.InstrumentPublished = (instrument, listener) => + { + var ours = instrument.Meter.Tags?.Any(t => t.Key == MetricNames.DataSource && Equals(t.Value, dataSource)) == true; + if (!ours) + return; + + lock (_instruments) + _instruments[instrument.Name] = instrument; + + if (instrumentNames.Contains(instrument.Name)) + listener.EnableMeasurementEvents(instrument); + }; + _listener.SetMeasurementEventCallback((instrument, value, tags, _) => Add(instrument.Name, value, tags)); + _listener.SetMeasurementEventCallback((instrument, value, tags, _) => Add(instrument.Name, value, tags)); + _listener.Start(); + } + + void Add(string name, double value, ReadOnlySpan> tags) + { + var measurement = new Measurement(value, tags.ToArray().ToDictionary(t => t.Key, t => t.Value)); + lock (_measurements) + _measurements.Add((name, measurement)); + } + + public Measurement[] For(string name) + { + lock (_measurements) + return _measurements.Where(m => m.Name == name).Select(m => m.Measurement).ToArray(); + } + + public Instrument Instrument(string name) + { + lock (_instruments) + return _instruments[name]; + } + + public void Dispose() => _listener.Dispose(); + } + + static string UniqueDataSource() => $"test-{Guid.NewGuid():N}"; + + [Fact] + public async Task TelemetryRecordProcessed_RecordsCountAndDurationInSeconds() + { + var dataSource = UniqueDataSource(); + await using var service = new MetricsService(null, dataSource); + using var recorder = new Recorder(dataSource, MetricNames.TelemetryRecordsProcessed, MetricNames.TelemetryDecodeDuration); + + var start = service.Telemetry.StartTiming(); + service.Telemetry.RecordProcessed(start); + + Assert.NotEqual(TelemetryMeters.NotTiming, start); + var processed = Assert.Single(recorder.For(MetricNames.TelemetryRecordsProcessed)); + Assert.Equal(1, processed.Value); + Assert.Empty(processed.Tags); + + var duration = Assert.Single(recorder.For(MetricNames.TelemetryDecodeDuration)); + Assert.InRange(duration.Value, 0, 1); + } + + [Fact] + public async Task TelemetryStartTiming_SkipsClock_WhenDurationIsNotCollected() + { + var dataSource = UniqueDataSource(); + await using var service = new MetricsService(null, dataSource); + using var recorder = new Recorder(dataSource, MetricNames.TelemetryRecordsProcessed); + + var start = service.Telemetry.StartTiming(); + service.Telemetry.RecordProcessed(start); + + Assert.Equal(TelemetryMeters.NotTiming, start); + Assert.Single(recorder.For(MetricNames.TelemetryRecordsProcessed)); + Assert.Empty(recorder.For(MetricNames.TelemetryDecodeDuration)); + } + + [Fact] + public async Task TelemetryRecordFailed_TagsCountAndDurationWithErrorType() + { + var dataSource = UniqueDataSource(); + await using var service = new MetricsService(null, dataSource); + using var recorder = new Recorder(dataSource, MetricNames.TelemetryRecordsProcessed, MetricNames.TelemetryDecodeDuration); + + service.Telemetry.RecordFailed(service.Telemetry.StartTiming(), new InvalidOperationException()); + + var processed = Assert.Single(recorder.For(MetricNames.TelemetryRecordsProcessed)); + Assert.Equal("System.InvalidOperationException", processed.Tags[MetricNames.ErrorType]); + var duration = Assert.Single(recorder.For(MetricNames.TelemetryDecodeDuration)); + Assert.Equal("System.InvalidOperationException", duration.Tags[MetricNames.ErrorType]); + } + + [Fact] + public async Task TelemetryDropped_IsTaggedWithReason() + { + var dataSource = UniqueDataSource(); + await using var service = new MetricsService(null, dataSource); + using var recorder = new Recorder(dataSource, MetricNames.TelemetryRecordsDropped); + + service.Telemetry.TicksMissed(3); + service.Telemetry.ConsumerOverflow(1); + + var dropped = recorder.For(MetricNames.TelemetryRecordsDropped); + Assert.Equal(2, dropped.Length); + Assert.Equal((3d, "missed_tick"), (dropped[0].Value, dropped[0].Tags[MetricNames.DropReason])); + Assert.Equal((1d, "consumer_overflow"), (dropped[1].Value, dropped[1].Tags[MetricNames.DropReason])); + } + + [Fact] + public async Task SessionInfo_RecordsSuccessAndFailureOnOneCounter() + { + var dataSource = UniqueDataSource(); + await using var service = new MetricsService(null, dataSource); + using var recorder = new Recorder(dataSource, MetricNames.SessionInfoRecordsProcessed, MetricNames.SessionInfoProcessDuration); + + service.SessionInfo.RecordProcessed(TimeSpan.FromMilliseconds(5), 40_000, 1); + service.SessionInfo.RecordFailed(TimeSpan.FromMilliseconds(20), 50_000, new FormatException()); + + var processed = recorder.For(MetricNames.SessionInfoRecordsProcessed); + Assert.Equal(2, processed.Length); + Assert.Empty(processed[0].Tags); + Assert.Equal("System.FormatException", processed[1].Tags[MetricNames.ErrorType]); + + var durations = recorder.For(MetricNames.SessionInfoProcessDuration); + Assert.Equal([0.005, 0.02], durations.Select(d => d.Value)); + } + + [Fact] + public async Task SessionInfo_RecordsSizeAndParseAttempts() + { + var dataSource = UniqueDataSource(); + await using var service = new MetricsService(null, dataSource); + using var recorder = new Recorder(dataSource, MetricNames.SessionInfoSize, MetricNames.SessionInfoParseAttempts); + + service.SessionInfo.RecordProcessed(TimeSpan.FromMilliseconds(5), 40_000, 2); + service.SessionInfo.RecordFailed(TimeSpan.FromMilliseconds(20), 50_000, new FormatException()); + + var sizes = recorder.For(MetricNames.SessionInfoSize); + Assert.Equal([40_000d, 50_000d], sizes.Select(s => s.Value)); + Assert.Empty(sizes[0].Tags); + Assert.Equal("System.FormatException", sizes[1].Tags[MetricNames.ErrorType]); + + // a failed parse exhausted every strategy, so only the successful record has an attempt count + var attempts = Assert.Single(recorder.For(MetricNames.SessionInfoParseAttempts)); + Assert.Equal(2, attempts.Value); + } + + [Fact] + public async Task SessionInfoDropped_IsTaggedWithReasonAndStream() + { + var dataSource = UniqueDataSource(); + await using var service = new MetricsService(null, dataSource); + using var recorder = new Recorder(dataSource, MetricNames.SessionInfoRecordsDropped); + + service.SessionInfo.ParseBacklogOverflow(1); + service.SessionInfo.SessionDataOverflow(1); + service.SessionInfo.SessionDataYamlOverflow(1); + + var dropped = recorder.For(MetricNames.SessionInfoRecordsDropped); + Assert.Equal(3, dropped.Length); + + Assert.Equal("parse_backlog", dropped[0].Tags[MetricNames.DropReason]); + Assert.False(dropped[0].Tags.ContainsKey(MetricNames.SessionInfoStream)); + + Assert.Equal(("consumer_overflow", "session_data"), (dropped[1].Tags[MetricNames.DropReason], dropped[1].Tags[MetricNames.SessionInfoStream])); + Assert.Equal(("consumer_overflow", "session_data_yaml"), (dropped[2].Tags[MetricNames.DropReason], dropped[2].Tags[MetricNames.SessionInfoStream])); + } + + [Fact] + public async Task TelemetryPipeline_RecordsEveryStageInSeconds() + { + var dataSource = UniqueDataSource(); + await using var service = new MetricsService(null, dataSource); + using var recorder = new Recorder(dataSource, + MetricNames.TelemetrySdkDuration, MetricNames.TelemetryHandlerDuration, + MetricNames.TelemetryTotalDuration, MetricNames.TelemetrySampleInterval); + + var first = service.Telemetry.MarkAcquired(); + var acquired = service.Telemetry.MarkAcquired(); + var handlerStart = service.Telemetry.RecordHandoff(acquired); + await Task.Delay(20, TestContext.Current.CancellationToken); + service.Telemetry.RecordConsumed(acquired, handlerStart); + + Assert.NotEqual(TelemetryMeters.NotTiming, first); + Assert.NotEqual(TelemetryMeters.NotTiming, handlerStart); + + // the first acquisition has nothing to measure an interval against + Assert.InRange(Assert.Single(recorder.For(MetricNames.TelemetrySampleInterval)).Value, 0, 1); + Assert.InRange(Assert.Single(recorder.For(MetricNames.TelemetrySdkDuration)).Value, 0, 0.015); + + var handler = Assert.Single(recorder.For(MetricNames.TelemetryHandlerDuration)).Value; + var endToEnd = Assert.Single(recorder.For(MetricNames.TelemetryTotalDuration)).Value; + Assert.InRange(handler, 0.015, 1); + Assert.True(endToEnd >= handler, $"end-to-end {endToEnd}s is below handler {handler}s"); + } + + [Fact] + public async Task TelemetryPipeline_SkipsClock_WhenNotCollected() + { + var dataSource = UniqueDataSource(); + await using var service = new MetricsService(null, dataSource); + using var recorder = new Recorder(dataSource); + + var acquired = service.Telemetry.MarkAcquired(); + var handlerStart = service.Telemetry.RecordHandoff(acquired); + service.Telemetry.RecordConsumed(acquired, handlerStart); + + Assert.Equal(TelemetryMeters.NotTiming, acquired); + Assert.Equal(TelemetryMeters.NotTiming, handlerStart); + } + + [Fact] + public async Task PlaybackLag_RecordsInSeconds() + { + var dataSource = UniqueDataSource(); + await using var service = new MetricsService(null, dataSource); + using var recorder = new Recorder(dataSource, MetricNames.PlaybackLag); + + service.Playback.RecordLag(TimeSpan.Zero); + service.Playback.RecordLag(TimeSpan.FromMilliseconds(250)); + + Assert.Equal([0d, 0.25], recorder.For(MetricNames.PlaybackLag).Select(m => m.Value)); + } + + [Fact] + public async Task Instruments_FollowNamingAndUnitConventions() + { + var dataSource = UniqueDataSource(); + await using var service = new MetricsService(null, dataSource); + using var recorder = new Recorder(dataSource); + + var expectedUnits = new Dictionary + { + [MetricNames.TelemetryRecordsProcessed] = "{record}", + [MetricNames.TelemetryRecordsDropped] = "{record}", + [MetricNames.TelemetryDecodeDuration] = "s", + [MetricNames.TelemetrySdkDuration] = "s", + [MetricNames.TelemetryHandlerDuration] = "s", + [MetricNames.TelemetryTotalDuration] = "s", + [MetricNames.TelemetrySampleInterval] = "s", + [MetricNames.SessionInfoRecordsProcessed] = "{record}", + [MetricNames.SessionInfoRecordsDropped] = "{record}", + [MetricNames.SessionInfoProcessDuration] = "s", + [MetricNames.SessionInfoSize] = "By", + [MetricNames.SessionInfoParseAttempts] = "{attempt}", + [MetricNames.PlaybackLag] = "s", + }; + + foreach (var (name, expectedUnit) in expectedUnits) + { + var instrument = recorder.Instrument(name); + Assert.Matches("^svappslab\\.iracingsdk\\.[a-z_.]+$", instrument.Name); + Assert.Equal(TelemetryMetrics.MeterName, instrument.Meter.Name); + Assert.False(string.IsNullOrEmpty(instrument.Meter.Version)); + Assert.Equal(expectedUnit, instrument.Unit); + } + } +} diff --git a/Sdk/tests/UnitTests/Metrics/TelemetryPipelineMetricsTests.cs b/Sdk/tests/UnitTests/Metrics/TelemetryPipelineMetricsTests.cs new file mode 100644 index 0000000..bac917e --- /dev/null +++ b/Sdk/tests/UnitTests/Metrics/TelemetryPipelineMetricsTests.cs @@ -0,0 +1,296 @@ +/** + * Copyright (C) 2024-2026 Scott Velez + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. +**/ + +using Microsoft.Extensions.Logging.Abstractions; +using SVappsLAB.iRacingTelemetrySDK; +using SVappsLAB.iRacingTelemetrySDK.Metrics; +using System.Diagnostics.Metrics; + +namespace UnitTests.Metrics; + +// hand written rather than source generated - the accessor binds by public property name at +// runtime, so this exercises a realistic decode without running the generator in this project +public struct PipelineTelemetryData +{ + public float Speed { get; set; } + public float RPM { get; set; } + public int Gear { get; set; } +} + +// runs a real ibt file through every delivery path and checks the pipeline instruments +public class TelemetryPipelineMetricsTests +{ + const string DroppedOverflow = MetricNames.TelemetryRecordsDropped + "|consumer_overflow"; + const string DroppedMissedTick = MetricNames.TelemetryRecordsDropped + "|missed_tick"; + + // a few hundred records - more than the 60-record delivery buffer, so a slow consumer is + // guaranteed to fall far enough behind for records to be evicted + static string IbtFile => Path.Combine(AppContext.BaseDirectory, "data", "ibt", "metrics-playback.ibt"); + + // hands out a meter per client and remembers which ones it made, so the collector picks out + // exactly one client's instruments while other tests using the "ibt" data source run in parallel + sealed class TestMeterFactory : IMeterFactory + { + readonly List _meters = []; + + public Meter Create(MeterOptions options) + { + var meter = new Meter(options); + lock (_meters) + _meters.Add(meter); + return meter; + } + + public bool Owns(Meter meter) + { + lock (_meters) + return _meters.Any(m => ReferenceEquals(m, meter)); + } + + public void Dispose() + { + lock (_meters) + { + foreach (var meter in _meters) + meter.Dispose(); + _meters.Clear(); + } + } + } + + // keyed by instrument name, plus the drop reason when present so the two drop kinds stay separate + sealed class Collector : IDisposable + { + readonly MeterListener _listener = new(); + readonly Dictionary> _values = []; + + public Collector(TestMeterFactory factory) + { + _listener.InstrumentPublished = (instrument, listener) => + { + if (factory.Owns(instrument.Meter)) + listener.EnableMeasurementEvents(instrument); + }; + _listener.SetMeasurementEventCallback((instrument, value, tags, _) => Add(Key(instrument, tags), value)); + _listener.SetMeasurementEventCallback((instrument, value, tags, _) => Add(Key(instrument, tags), value)); + _listener.Start(); + } + + static string Key(Instrument instrument, ReadOnlySpan> tags) + { + foreach (var tag in tags) + { + if (tag.Key == MetricNames.DropReason) + return $"{instrument.Name}|{tag.Value}"; + } + return instrument.Name; + } + + void Add(string key, double value) + { + lock (_values) + { + if (!_values.TryGetValue(key, out var list)) + _values[key] = list = []; + list.Add(value); + } + } + + double[] Values(string key) + { + lock (_values) + return _values.TryGetValue(key, out var list) ? list.ToArray() : []; + } + + // for a histogram, how many records it measured + public int Count(string key) => Values(key).Length; + + // for a counter, its total + public long Sum(string key) => (long)Values(key).Sum(); + + public double Median(string key) + { + var values = Values(key); + if (values.Length == 0) + return 0; + Array.Sort(values); + return values[values.Length / 2]; + } + + public string Describe() + { + lock (_values) + return string.Join(", ", _values.OrderBy(kv => kv.Key).Select(kv => $"{kv.Key}={kv.Value.Count}")); + } + + public void Dispose() => _listener.Dispose(); + } + + static ITelemetryClient CreateClient(TestMeterFactory factory, TelemetryDeliveryMode mode = TelemetryDeliveryMode.Async) => + TelemetryClient.Create( + NullLogger.Instance, + new IBTOptions(IbtFile), + new ClientOptions { MeterFactory = factory, DeliveryMode = mode }); + + [Fact] + public async Task AsyncHandler_MeasuresEveryPipelineStage() + { + using var factory = new TestMeterFactory(); + await using var client = CreateClient(factory); + using var collector = new Collector(factory); + + var received = 0; + await client.Monitor(new TelemetryHandlers + { + OnTelemetryUpdate = _ => + { + received++; + return Task.CompletedTask; + } + }, TestContext.Current.CancellationToken); + + Assert.True(received > 0, $"no telemetry reached the handler. instruments: {collector.Describe()}"); + + var processed = collector.Sum(MetricNames.TelemetryRecordsProcessed); + Assert.Equal(processed, collector.Count(MetricNames.TelemetryDecodeDuration)); + + // one interval per acquisition, minus the first which has nothing to measure against + Assert.Equal(processed - 1, collector.Count(MetricNames.TelemetrySampleInterval)); + + // the consumer-side stages fire once per record that reached the handler + Assert.Equal(received, collector.Count(MetricNames.TelemetrySdkDuration)); + Assert.Equal(received, collector.Count(MetricNames.TelemetryHandlerDuration)); + Assert.Equal(received, collector.Count(MetricNames.TelemetryTotalDuration)); + + // every acquired record either reached the consumer or was counted as evicted + Assert.Equal(processed, received + collector.Sum(DroppedOverflow)); + + // ibt playback cannot skip records + Assert.Equal(0, collector.Sum(DroppedMissedTick)); + } + + [Fact] + public async Task SlowAsyncHandler_ShowsUpAsHandlerTimeAndConsumerOverflow() + { + using var factory = new TestMeterFactory(); + await using var client = CreateClient(factory); + using var collector = new Collector(factory); + + await client.Monitor(new TelemetryHandlers + { + // blocking rather than awaiting a timer keeps the delay predictable + OnTelemetryUpdate = _ => + { + Thread.Sleep(2); + return Task.CompletedTask; + } + }, TestContext.Current.CancellationToken); + + Assert.True(collector.Sum(DroppedOverflow) > 0, + $"expected the slow consumer to lose records to eviction. instruments: {collector.Describe()}"); + + // the cost of the callback is attributed to the handler + Assert.True(collector.Median(MetricNames.TelemetryHandlerDuration) >= 0.001, + $"expected a ~2ms handler to measure at least 1ms, got {collector.Median(MetricNames.TelemetryHandlerDuration)}s"); + + // and waiting in the buffer behind that handler shows up as sdk latency + Assert.True(collector.Median(MetricNames.TelemetrySdkDuration) >= 0.001, + $"expected records to wait behind the slow handler, got a median sdk latency of {collector.Median(MetricNames.TelemetrySdkDuration)}s"); + } + + [Fact] + public async Task SyncHandler_MeasuresEveryRecordWithNoQueueWait() + { + using var factory = new TestMeterFactory(); + await using var client = CreateClient(factory, TelemetryDeliveryMode.Synchronous); + using var collector = new Collector(factory); + + await client.Monitor(new TelemetryHandlers + { + OnTelemetryUpdate = _ => Task.CompletedTask + }, TestContext.Current.CancellationToken); + + var processed = collector.Sum(MetricNames.TelemetryRecordsProcessed); + Assert.True(processed > 0, $"nothing was processed. instruments: {collector.Describe()}"); + + // the handler runs inline, so every acquired record is measured + Assert.Equal(processed, collector.Count(MetricNames.TelemetrySdkDuration)); + Assert.Equal(processed, collector.Count(MetricNames.TelemetryHandlerDuration)); + Assert.Equal(processed, collector.Count(MetricNames.TelemetryTotalDuration)); + + // no buffer to evict from + Assert.Equal(0, collector.Sum(DroppedOverflow)); + + // sdk latency collapses to the decode cost + Assert.True(collector.Median(MetricNames.TelemetrySdkDuration) < 0.001, + $"synchronous sdk latency should be near zero, got a median of {collector.Median(MetricNames.TelemetrySdkDuration)}s"); + } + + [Fact] + public async Task SessionInfo_RecordsSizeAndParseAttemptsForEachParse() + { + using var factory = new TestMeterFactory(); + await using var client = CreateClient(factory); + using var collector = new Collector(factory); + + await client.Monitor(new TelemetryHandlers + { + OnTelemetryUpdate = _ => Task.CompletedTask + }, TestContext.Current.CancellationToken); + + var processed = collector.Sum(MetricNames.SessionInfoRecordsProcessed); + Assert.True(processed > 0, $"no session info was parsed. instruments: {collector.Describe()}"); + + Assert.Equal(processed, collector.Count(MetricNames.SessionInfoSize)); + Assert.Equal(processed, collector.Count(MetricNames.SessionInfoParseAttempts)); + + // a real session info yaml is kilobytes, not a handful of bytes + Assert.True(collector.Median(MetricNames.SessionInfoSize) > 1024, + $"session info size looks wrong: {collector.Median(MetricNames.SessionInfoSize)} bytes"); + Assert.InRange(collector.Median(MetricNames.SessionInfoParseAttempts), 1, 2); + } + + [Fact] + public async Task StreamConsumer_IsMeasuredLikeTheHandlerPath() + { + using var factory = new TestMeterFactory(); + await using var client = CreateClient(factory); + using var collector = new Collector(factory); + + var received = 0; + var reader = Task.Run(async () => + { + await foreach (var _ in client.TelemetryData) + { + // slow on purpose, so the assertion below proves the loop body is what gets measured + Thread.Sleep(2); + received++; + } + }, TestContext.Current.CancellationToken); + + await client.Monitor(TestContext.Current.CancellationToken); + await reader; + + Assert.True(received > 0, $"no telemetry reached the stream. instruments: {collector.Describe()}"); + + Assert.Equal(received, collector.Count(MetricNames.TelemetrySdkDuration)); + Assert.Equal(received, collector.Count(MetricNames.TelemetryHandlerDuration)); + Assert.Equal(received, collector.Count(MetricNames.TelemetryTotalDuration)); + + Assert.True(collector.Median(MetricNames.TelemetryHandlerDuration) >= 0.001, + $"expected a ~2ms foreach body to measure at least 1ms, got {collector.Median(MetricNames.TelemetryHandlerDuration)}s"); + } +} diff --git a/Sdk/tests/UnitTests/PlaybackLagTests.cs b/Sdk/tests/UnitTests/PlaybackLagTests.cs new file mode 100644 index 0000000..df03538 --- /dev/null +++ b/Sdk/tests/UnitTests/PlaybackLagTests.cs @@ -0,0 +1,66 @@ +/** + * Copyright (C) 2024-2026 Scott Velez + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. +**/ + +using System; +using System.Collections.Generic; +using System.Threading.Tasks; +using Microsoft.Extensions.Logging.Abstractions; +using SVappsLAB.iRacingTelemetrySDK.IBTPlayback; + +namespace UnitTests; + +public class PlaybackLagTests +{ + [Fact] + public void RecordLag_IsZero_WhenRecordIsAheadOfSchedule() + { + var lags = new List(); + var governor = new SimpleGovernor(NullLogger.Instance, 1, lags.Add); + governor.StartPlayback(); + + // record 6000 is due 100 seconds into a 1x playback + governor.RecordLag(6000); + + Assert.Equal([TimeSpan.Zero], lags); + } + + [Fact] + public async Task RecordLag_ReportsTimePastSchedule_WhenRecordIsLate() + { + var lags = new List(); + var governor = new SimpleGovernor(NullLogger.Instance, 1, lags.Add); + governor.StartPlayback(); + + // record 0 is due immediately, so everything waited here is lag + await Task.Delay(100, TestContext.Current.CancellationToken); + governor.RecordLag(0); + + var lag = Assert.Single(lags); + Assert.True(lag >= TimeSpan.FromMilliseconds(90), $"lag was {lag.TotalMilliseconds}ms"); + } + + [Fact] + public void RecordLag_ReportsNothing_AtMaxSpeed() + { + var lags = new List(); + var governor = new SimpleGovernor(NullLogger.Instance, int.MaxValue, lags.Add); + governor.StartPlayback(); + + governor.RecordLag(0); + + Assert.Empty(lags); + } +} diff --git a/Sdk/tests/UnitTests/UnitTests.csproj b/Sdk/tests/UnitTests/UnitTests.csproj index 5372e49..06326f3 100644 --- a/Sdk/tests/UnitTests/UnitTests.csproj +++ b/Sdk/tests/UnitTests/UnitTests.csproj @@ -25,6 +25,15 @@ + + + + data\ibt\metrics-playback.ibt + PreserveNewest + + + diff --git a/docs/ARCHITECTURE.md b/docs/ARCHITECTURE.md index eeb31f5..75a4178 100644 --- a/docs/ARCHITECTURE.md +++ b/docs/ARCHITECTURE.md @@ -1,8 +1,8 @@ # Architecture and Design -This document describes the SDK's threading model, data pipeline, memory layout, buffering policy, and performance instrumentation. +This document describes the SDK's threading model, data pipeline, memory layout, and buffering policy. -For installation and everyday usage, see the [README](../README.md). For direct stream access and multi-consumer patterns, see [Advanced Usage](./ADVANCED.md). +For installation and everyday usage, see the [README](../README.md). For direct stream access and multi-consumer patterns, see [Advanced Usage](./ADVANCED.md). For the runtime instrumentation the SDK publishes, see [Metrics and Diagnostics](./METRICS.md). ## Table of Contents @@ -12,7 +12,7 @@ For installation and everyday usage, see the [README](../README.md). For direct - [Compile-Time Code Generation](#compile-time-code-generation) - [Data Streaming and Buffering](#data-streaming-and-buffering) - [Performance Characteristics](#performance-characteristics) -- [Performance Monitoring](#performance-monitoring) +- [Metrics and Diagnostics](#metrics-and-diagnostics) ## Design Principles @@ -249,63 +249,10 @@ Async mode supports handler-based consumption through `Monitor(handlers, ct)` an Actual throughput depends on the requested schema, consumer work, storage, and host hardware. -## Performance Monitoring +## Metrics and Diagnostics -The SDK publishes runtime instrumentation through `System.Diagnostics.Metrics`. - -### Available Metrics - -Available instruments: - -- `telemetry_records_processed_total`: processed telemetry records -- `telemetry_processing_duration_microseconds`: telemetry processing duration -- `sessioninfo_records_processed_total`: processed session-info updates -- `sessioninfo_processing_duration_milliseconds`: session-info processing duration - -### Enabling Metrics with Dependency Injection - -```csharp -using Microsoft.Extensions.DependencyInjection; -using Microsoft.Extensions.Hosting; -using Microsoft.Extensions.Logging; - -[RequiredTelemetryVars([TelemetryVar.Speed, TelemetryVar.RPM])] -public class Program -{ - public static async Task Main(string[] args) - { - var host = Host.CreateDefaultBuilder(args) - .ConfigureServices((context, services) => - { - services.AddMetrics(); - services.AddLogging(logging => logging.AddConsole()); - }) - .Build(); - - var logger = host.Services.GetRequiredService>(); - var meterFactory = host.Services.GetRequiredService(); - - var clientOptions = new ClientOptions { MeterFactory = meterFactory }; - await using var client = TelemetryClient.Create(logger, null, clientOptions); - } -} -``` - -### Monitoring with dotnet-counters - -Any `System.Diagnostics.Metrics` consumer can collect these instruments. For example, `dotnet-counters` can attach to a running process: - -```bash -# Monitor all SDK metrics for a running application named "YourApp" -dotnet-counters monitor --name "YourApp" --counters SVappsLAB.iRacingTelemetrySDK - -# Sample output: -# [SVappsLAB.iRacingTelemetrySDK] -# telemetry_records_processed_total 45,231 -# sessioninfo_records_processed_total 12 -``` - -Processing rates, latency distributions, and dropped-record counts identify whether the producer or a downstream consumer is the limiting stage. +The SDK publishes runtime instrumentation through `System.Diagnostics.Metrics`. See +[Metrics and Diagnostics](./METRICS.md) for the metric reference, OpenTelemetry and dependency-injection setup, `dotnet-counters` commands, and interpretation guidance. ## Related Documentation diff --git a/docs/METRICS.md b/docs/METRICS.md new file mode 100644 index 0000000..85ed838 --- /dev/null +++ b/docs/METRICS.md @@ -0,0 +1,202 @@ +# Metrics and Diagnostics + +The SDK publishes runtime instrumentation through `System.Diagnostics.Metrics`. The meter is named `SVappsLAB.iRacingTelemetrySDK`, carries the SDK assembly version, and follows [OpenTelemetry metric naming conventions](https://opentelemetry.io/docs/specs/semconv/general/metrics/). + +For the threading model and buffering policy these instruments measure, see [Architecture and Design](./ARCHITECTURE.md). + +## Table of Contents + +- [Available Metrics](#available-metrics) +- [Metric Attributes](#metric-attributes) +- [Telemetry Pipeline Latency](#telemetry-pipeline-latency) + - [Latency versus cadence](#latency-versus-cadence) +- [OpenTelemetry](#opentelemetry) +- [Dependency Injection](#dependency-injection) +- [Monitoring with dotnet-counters](#monitoring-with-dotnet-counters) +- [Live-Session Example](#live-session-example) + +## Available Metrics + +| Instrument | Type | Unit | Description | +|------------|------|------|-------------| +| `svappslab.iracingsdk.telemetry.records.processed` | Counter | `{record}` | Telemetry records processed | +| `svappslab.iracingsdk.telemetry.records.dropped` | Counter | `{record}` | Telemetry records lost before reaching the consumer | +| `svappslab.iracingsdk.telemetry.decode.duration` | Histogram | `s` | SDK time decoding one telemetry record into a typed sample | +| `svappslab.iracingsdk.telemetry.sdk.duration` | Histogram | `s` | SDK time from acquisition until the consumer's handler received the record | +| `svappslab.iracingsdk.telemetry.handler.duration` | Histogram | `s` | Consumer time: the handler's own work on one telemetry record | +| `svappslab.iracingsdk.telemetry.total.duration` | Histogram | `s` | End to end: Latency of one record, from acquisition until the handler finished; equals SDK plus handler time | +| `svappslab.iracingsdk.telemetry.sample.interval` | Histogram | `s` | Cadence between records: the previous record's acquisition until this one's. Not a latency - see [Latency versus cadence](#latency-versus-cadence) | +| `svappslab.iracingsdk.session_info.records.processed` | Counter | `{record}` | Session-info records processed | +| `svappslab.iracingsdk.session_info.process.duration` | Histogram | `s` | Time spent parsing each session-info record | +| `svappslab.iracingsdk.session_info.records.dropped` | Counter | `{record}` | Session-info records lost before reaching the consumer | +| `svappslab.iracingsdk.session_info.size` | Histogram | `By` | UTF-8 encoded size of each session-info record | +| `svappslab.iracingsdk.session_info.parse.attempts` | Histogram | `{attempt}` | Parse attempts required by each successfully parsed session-info record | +| `svappslab.iracingsdk.playback.lag` | Histogram | `s` | How far behind its scheduled time each paced IBT playback record was read | + +## Metric Attributes + +- `svappslab.iracingsdk.data_source`: `live` or `ibt`. Set on the meter, so it appears on every measurement. +- `error.type` (the two processed counters, `telemetry.decode.duration`, `session_info.process.duration`, and `session_info.size`): the exception's full type name. It is present only for failed records. The remaining histograms - `telemetry.sdk.duration`, `telemetry.handler.duration`, `telemetry.total.duration`, `telemetry.sample.interval`, `session_info.parse.attempts`, and `playback.lag` - never carry it. +- `svappslab.iracingsdk.drop.reason` (telemetry dropped counter): + - `missed_tick`: live only. iRacing wrote ticks the SDK never read because its read loop fell behind, for example behind a slow synchronous handler. + - `consumer_overflow`: async delivery only. Records were read but evicted from the 60-record delivery buffer because the `OnTelemetryUpdate` handler could not keep up. +- `svappslab.iracingsdk.drop.reason` (session-info dropped counter): + - `parse_backlog`: updates arrived faster than they could be parsed and were evicted unparsed from the 10-record internal queue. + - `consumer_overflow`: records were evicted from a 60-record public stream because nobody read them in time. Also carries `svappslab.iracingsdk.session_info.stream`: `session_data` (`SessionData` / `OnSessionInfoUpdate`) or `session_data_yaml` (`SessionDataYaml` / `OnRawSessionInfoUpdate`). Both streams are filled on every update, so a stream the application never reads starts counting drops after 60 updates; filter on the stream you consume. + +`svappslab.iracingsdk.session_info.parse.attempts` is 1 when the YAML parsed as-is and 2 when it had to be repaired first. A parse that fails records no attempt count; it appears as `error.type` on the processed counter instead. A rising attempt count explains slower parse durations. + +`svappslab.iracingsdk.playback.lag` is recorded only for IBT playback with a `playBackSpeedMultiplier` set. It is zero when a record is read on time. A rising tail means the consumer or machine cannot keep up with the requested speed. Max-speed playback has no schedule and records nothing. + +Each histogram provides bucket boundaries suited to what it measures, so exporters report useful resolution without extra view configuration. The telemetry boundaries were fitted to a real 8-minute, 19,915-record live session replayed through the pipeline: + +| Instrument | Measured (1x replay, async delivery) | Range covered | +|---|---|---| +| `telemetry.decode.duration` | p50 7.8 µs, p99 37 µs, max 1.7 ms | 1 µs to 25 ms | +| `telemetry.sdk.duration` | p50 23 µs, p99 80 µs, max 2.6 ms | 2 µs to 500 ms | +| `telemetry.handler.duration` | p50 1.3 µs, p99 5.1 µs, max 287 µs | 1 µs to 1 s | +| `telemetry.total.duration` | p50 26 µs, p99 85 µs, max 2.9 ms | 2 µs to 500 ms | +| `telemetry.sample.interval` | p50 15.5 ms, p99 31 ms | 10 µs to 1 s | +| `playback.lag` | p50 7.0 ms, p99 15 ms, max 298 ms | 500 µs to 30 s | + +`sdk.duration` and `total.duration` share boundaries so they can be compared bucket for bucket; their difference is the consumer's handler cost. The telemetry clocks are read only while a listener collects a histogram that needs them, so the hot path costs nothing extra when metrics are not collected. + +## Telemetry Pipeline Latency + +The pipeline instruments follow each record from acquisition to the consumer. Acquisition is when the live data-ready event fires or the next IBT record is read. iRacing does not timestamp its samples, so nothing before acquisition is measurable; the `missed_tick` drop count stands in for it. + +``` +within one record - latency + +acquire ──► decode record ──► [ delivery buffer ] ──► handler start ──► handler end + │ └ decode.duration ┘ │ │ + ├────────────── sdk.duration ───────────────────────►│ │ + │ ├ handler.duration ► + └──────────────────────── total.duration ───────────────────────────────► + +between records - cadence + +acquire(n-1) ────── sample.interval ──────► acquire(n) ────── sample.interval ──────► acquire(n+1) +``` + +- **`sdk.duration`** — the SDK's share, everything before the consumer sees the record. +- **`handler.duration`** — the consumer's share. +- **`total.duration`** — the two together: `sdk + handler = total`. +- **`sample.interval`** — how often records arrive, measured from the previous record's acquisition to this one's. + +`decode.duration` is the SDK-side detail inside `sdk.duration`: the cost of turning the raw buffer into a typed sample, with no queueing. `sdk.duration` minus `decode.duration` is delivery-buffer wait time. + +### Latency versus cadence + +`total.duration` and `sample.interval` both start from an acquisition, but measure different axes: + +- **`total.duration` is a latency.** It lives entirely inside one record: that record's acquisition until the handler returned for that same record. It answers *how long did this record take to process*. +- **`sample.interval` is a cadence.** It spans two records and ignores what happened to either one. It answers *how often are records arriving*. A consumer whose handler does nothing at all still records the same intervals. + +In a healthy live session the two differ by roughly three orders of magnitude - about 0.02 ms of work inside each 15.5 ms frame. That ratio, rather than either number on its own, is the processing headroom. + +Reading them together isolates the slow stage: + +| What you see | What it means | +|---|---| +| `total.duration` rises, `sample.interval` flat | Per-record work got slower, but records still arrive on schedule. Split it with `handler.duration` to see whether the consumer or the SDK is responsible. | +| `sample.interval` rises, `total.duration` flat | Records are arriving less often; nothing in the pipeline got slower. The source stalled, or ticks were missed - check `missed_tick` drops. | +| Both rise | Typically live synchronous delivery, where a slow handler blocks the read loop, so per-record latency drags the arrival gap out with it. | + + +The consumer's work is measured consistently on every delivery path: + +| Delivery path | What `telemetry.handler.duration` measures | +|---------------|--------------------------------------------| +| `OnTelemetryUpdate`, `Async` mode | The callback, entry to exit | +| `await foreach` over `TelemetryData` | The caller's loop body, up to asking for the next record | +| `OnTelemetryUpdate`, `Synchronous` mode | The callback, entry to exit, including `GetValue()` calls inside it | + +Interpret the values as follows: + +- **Live**: `telemetry.sample.interval` should sit near 0.01667 s (60 Hz). A distribution split between one and two frames means ticks are being missed, which also appears as `missed_tick` drops. `telemetry.total.duration` says nothing about this; it stays flat while frames are being dropped. +- **Async delivery**: a rising `telemetry.sdk.duration` means records are waiting in the delivery buffer behind the consumer. If the consumer stays behind, `consumer_overflow` drops follow. +- **Synchronous delivery**: there is no buffer, so `sdk.duration` collapses to decode cost and `total.duration` is roughly decode plus handler. A slow handler shows up as handler time and `missed_tick` drops rather than SDK time. +- **IBT at max speed** (the default `PlayBackSpeedMultiplier`): there is no schedule to keep, so `sample.interval` measures how fast the file is being consumed rather than a 60 Hz cadence; it and `sdk.duration` describe throughput, not real-time latency. At a paced speed both behave like live. +- **Async delivery with no consumer**: a client that neither sets `OnTelemetryUpdate` nor enumerates `TelemetryData` never records `sdk.duration`, `handler.duration`, or `total.duration`. + +## OpenTelemetry + +Subscribe to the SDK meter by name in the application's OpenTelemetry configuration: + +```csharp +services.AddOpenTelemetry() + .WithMetrics(metrics => metrics.AddMeter(TelemetryMetrics.MeterName)); +``` + +Configure the exporter appropriate to the application separately. The SDK publishes metrics; it does not configure an OpenTelemetry exporter or collector. + +## Dependency Injection + +Pass the application's `IMeterFactory` to the client so the SDK creates its meter through the DI container: + +```csharp +using System.Diagnostics.Metrics; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Hosting; +using Microsoft.Extensions.Logging; + +[RequiredTelemetryVars([TelemetryVar.Speed, TelemetryVar.RPM])] +public class Program +{ + public static async Task Main(string[] args) + { + var host = Host.CreateDefaultBuilder(args) + .ConfigureServices((context, services) => + { + services.AddMetrics(); + services.AddLogging(logging => logging.AddConsole()); + }) + .Build(); + + var logger = host.Services.GetRequiredService>(); + var meterFactory = host.Services.GetRequiredService(); + var clientOptions = new ClientOptions { MeterFactory = meterFactory }; + + await using var client = TelemetryClient.Create(logger, null, clientOptions); + } +} +``` + +## Monitoring with dotnet-counters + +Any `System.Diagnostics.Metrics` consumer can collect these instruments. The [MeterListener sample](../Samples/Metrics/MeterListener/) does it in-process with a `MeterListener` and no extra packages. To attach to a running application: + +```bash +dotnet-counters monitor --name "YourApp" --counters SVappsLAB.iRacingTelemetrySDK +``` + +To capture from application startup, including the initial session-info parse: + +```bash +dotnet-counters collect --counters SVappsLAB.iRacingTelemetrySDK --format csv -o metrics.csv -- YourApp.exe +``` + +## Live-Session Example + +The following one-second snapshots are from the same live iRacing session, consumed three ways. Slow handlers wait 50 ms per record, so they can handle about 16 records per second against iRacing's 60 Hz. + +| Consumer | `records.processed` | `records.dropped` | `drop.reason` | `telemetry.decode.duration` p50 / p95 / p99 | +|----------|---------------------|-------------------|---------------|------------------------------------------------| +| Async, fast handler | 61/s | 0/s | | 6.8 µs / 9.2 µs / 16.6 µs | +| Async, slow handler | 60/s | 44/s | `consumer_overflow` | 6.1 µs / 8.6 µs / 12.6 µs | +| Synchronous, slow handler | 15/s | 46/s | `missed_tick` | 8.0 µs / 22.1 µs / 22.1 µs | + +- **Async, slow handler**: the SDK still reads every tick (60/s processed), but the handler falls behind and the 60-record buffer evicts the difference as `consumer_overflow`. Only the consumer is too slow. +- **Synchronous, slow handler**: the handler blocks the read loop, so processed falls to the handler's pace and unread ticks surface as `missed_tick`. Processed plus dropped still accounts for iRacing's 60 Hz. +- Creating a telemetry record takes single-digit microseconds either way, so record decoding is not the limiting stage. +- Each run parsed the session-info YAML once at startup, taking 71–73 ms. + +Processing rates, latency distributions, and dropped-record counts identify whether the producer or a downstream consumer is the limiting stage. + +## Related Documentation + +- **[README](../README.md)** - Installation, quick start, and telemetry variables +- **[Architecture and Design](./ARCHITECTURE.md)** - Threading model, data streaming and buffering, and performance characteristics +- **[Advanced Usage](./ADVANCED.md)** - Direct stream access, multiple consumers, and cancellation behavior +- **[SDK reference for agents](./ai/SDK_REFERENCE.md)** - Advanced stream, DI, and troubleshooting patterns From 010754d90314a88b4c565eff01b6a79bb2abfe8f Mon Sep 17 00:00:00 2001 From: Scott Velez <162245270+SVappsLAB@users.noreply.github.com> Date: Mon, 21 Sep 2026 11:47:34 -0700 Subject: [PATCH 2/2] add metric sample --- .../MeterListener/MeterListener.csproj | 15 ++ .../Metrics/MeterListener/MetricsCollector.cs | 133 ++++++++++++++++++ Samples/Metrics/MeterListener/Program.cs | 72 ++++++++++ .../Properties/launchSettings.json | 8 ++ .../OpenTelemetry/OpenTelemetry.csproj | 23 +++ Samples/Metrics/OpenTelemetry/Program.cs | 81 +++++++++++ .../Properties/launchSettings.json | 8 ++ Samples/Metrics/README.md | 105 ++++++++++++++ Samples/README.md | 15 ++ Samples/Samples.slnx | 5 + docs/METRICS.md | 39 ++++- 11 files changed, 501 insertions(+), 3 deletions(-) create mode 100644 Samples/Metrics/MeterListener/MeterListener.csproj create mode 100644 Samples/Metrics/MeterListener/MetricsCollector.cs create mode 100644 Samples/Metrics/MeterListener/Program.cs create mode 100644 Samples/Metrics/MeterListener/Properties/launchSettings.json create mode 100644 Samples/Metrics/OpenTelemetry/OpenTelemetry.csproj create mode 100644 Samples/Metrics/OpenTelemetry/Program.cs create mode 100644 Samples/Metrics/OpenTelemetry/Properties/launchSettings.json create mode 100644 Samples/Metrics/README.md diff --git a/Samples/Metrics/MeterListener/MeterListener.csproj b/Samples/Metrics/MeterListener/MeterListener.csproj new file mode 100644 index 0000000..ed8b4d3 --- /dev/null +++ b/Samples/Metrics/MeterListener/MeterListener.csproj @@ -0,0 +1,15 @@ + + + + Exe + net8.0 + enable + enable + + + + + + + + diff --git a/Samples/Metrics/MeterListener/MetricsCollector.cs b/Samples/Metrics/MeterListener/MetricsCollector.cs new file mode 100644 index 0000000..da1c75b --- /dev/null +++ b/Samples/Metrics/MeterListener/MetricsCollector.cs @@ -0,0 +1,133 @@ +/** + * Copyright (C) 2024-2026 Scott Velez + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + **/ + +using SVappsLAB.iRacingTelemetrySDK; +using System.Collections.Concurrent; +using System.Diagnostics.Metrics; + +namespace MeterListenerSample; + +/// +/// Collects the SDK's metrics with a , +/// which is built into the runtime and needs no packages. +/// +/// A MeterListener hands you raw measurements - one callback per recorded value - and stops +/// there, so everything below is the aggregation OpenTelemetry would otherwise do for you: +/// the dictionary keyed by instrument-plus-tags, the rows, the reporting +/// timer, and the printing. It is all here rather than in Program.cs so the sample's client +/// setup reads the same as the OpenTelemetry sample's. +/// +internal sealed class MetricsCollector : IDisposable +{ + // one row per instrument, per set of tags - so the drop reasons stay apart + readonly ConcurrentDictionary _stats = new(); + readonly object _consoleLock = new(); + readonly MeterListener _listener; + readonly Timer _timer; + + /// + /// Starts listening. Measurements are printed every , + /// and whenever is called. + /// + public MetricsCollector(TimeSpan reportInterval) + { + // subscribe to the SDK's meter by name; the SDK creates the meter itself, so + // nothing has to be passed to the client + _listener = new MeterListener + { + InstrumentPublished = (instrument, theListener) => + { + if (instrument.Meter.Name == TelemetryMetrics.MeterName) + theListener.EnableMeasurementEvents(instrument); + } + }; + + // raw measurements arrive one at a time, and we aggregate them ourselves. + // the SDK's counters are long, its histograms are double + _listener.SetMeasurementEventCallback((instrument, value, tags, _) => Record(instrument, value, tags)); + _listener.SetMeasurementEventCallback((instrument, value, tags, _) => Record(instrument, value, tags)); + _listener.Start(); + + _timer = new Timer(_ => Print("metrics"), null, reportInterval, reportInterval); + } + + public void Dispose() + { + _timer.Dispose(); + _listener.Dispose(); + } + + void Record(Instrument instrument, double value, ReadOnlySpan> tags) + { + // the meter-level 'data_source' tag is not repeated here; these are the per-measurement + // tags - drop.reason, error.type, session_info.stream - and each combination gets its own row + var key = instrument.Name; + foreach (var tag in tags) + key += $" [{tag.Key}={tag.Value}]"; + + _stats.GetOrAdd(key, _ => new Stat(instrument.Unit, instrument is Counter)).Add(value); + } + + public void Print(string title) + { + lock (_consoleLock) + { + Console.WriteLine($"{Environment.NewLine}--- {title} ---"); + + foreach (var (name, stat) in _stats.OrderBy(kvp => kvp.Key)) + { + var value = stat switch + { + // counters are totals + { IsCounter: true } => $"{stat.Sum,10:N0} {stat.Unit}", + // durations read better scaled than in raw seconds + { Unit: "s" } => $"{stat.Count,10:N0} recorded avg {Duration(stat.Sum / stat.Count)} max {Duration(stat.Max)}", + // everything else - byte sizes, parse attempts + _ => $"{stat.Count,10:N0} recorded avg {stat.Sum / stat.Count,10:N0} {stat.Unit} max {stat.Max,10:N0} {stat.Unit}" + }; + + // trim the meter prefix the instruments all share + Console.WriteLine($" {name.Replace("svappslab.iracingsdk.", ""),-62} {value}"); + } + } + } + + // most of these land in microseconds, so scale rather than print a row of zeros + static string Duration(double seconds) => + seconds < 0.001 ? $"{seconds * 1_000_000,8:N1} us" : $"{seconds * 1_000,8:N3} ms"; + + // count/sum/max is all a MeterListener gives you without writing a bucketing histogram + // yourself - no percentiles, and the SDK's bucket 'advice' is not applied + class Stat(string? unit, bool isCounter) + { + public string? Unit => unit; + public bool IsCounter => isCounter; + public long Count { get; private set; } + public double Sum { get; private set; } + public double Max { get; private set; } + + public void Add(double value) + { + // measurements arrive on the SDK's threads + lock (this) + { + Count++; + Sum += value; + Max = Math.Max(Max, value); + } + } + } +} diff --git a/Samples/Metrics/MeterListener/Program.cs b/Samples/Metrics/MeterListener/Program.cs new file mode 100644 index 0000000..2e08791 --- /dev/null +++ b/Samples/Metrics/MeterListener/Program.cs @@ -0,0 +1,72 @@ +/** + * Copyright (C) 2024-2026 Scott Velez + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + **/ + +using Microsoft.Extensions.Logging; +using SVappsLAB.iRacingTelemetrySDK; + +namespace MeterListenerSample; + +[RequiredTelemetryVars([TelemetryVar.Speed, TelemetryVar.RPM])] +internal class Program +{ + public static async Task Main(string[] args) + { + // === collection - the only part that differs from the OpenTelemetry sample === + + // MetricsCollector (MetricsCollector.cs) is the MeterListener half of this sample. + using var metrics = new MetricsCollector(reportInterval: TimeSpan.FromSeconds(5)); + + // === client setup - identical in both samples === + + var logger = LoggerFactory.Create(builder => builder.AddConsole()) + .CreateLogger("MeterListener"); + + // no argument for live telemetry, an IBT filepath to replay a file. an optional second + // argument is the playback speed - '1' replays at the speed it was recorded, which is the + // only way playback.lag gets recorded. the default is max speed, which has no schedule + IBTOptions? ibtOptions = args.Length switch + { + 0 => null, + 1 => new IBTOptions(args[0]), + _ => new IBTOptions(args[0], int.Parse(args[1])) + }; + + var clientOptions = new ClientOptions { DeliveryMode = TelemetryDeliveryMode.Synchronous }; + await using var client = TelemetryClient.Create(logger, ibtOptions, clientOptions); + + using var cts = new CancellationTokenSource(); + Console.CancelKeyPress += (_, e) => { e.Cancel = true; cts.Cancel(); }; + + // synchronous delivery runs this handler inline, so its cost is the consumer's cost. + // give it some work - await Task.Delay(50) - and watch handler.duration climb; + // live telemetry will then report missed_tick as the read loop falls behind + var handlers = new TelemetryHandlers + { + OnTelemetryUpdate = _ => + { + client.GetValue("Speed"); + client.GetValue("RPM"); + return Task.CompletedTask; + } + }; + + Console.WriteLine("press Ctrl-C to exit..."); + await client.Monitor(handlers, cts.Token); + + // one last report, for the run as a whole + metrics.Print("final metrics"); + } +} diff --git a/Samples/Metrics/MeterListener/Properties/launchSettings.json b/Samples/Metrics/MeterListener/Properties/launchSettings.json new file mode 100644 index 0000000..f5a3522 --- /dev/null +++ b/Samples/Metrics/MeterListener/Properties/launchSettings.json @@ -0,0 +1,8 @@ +{ + "profiles": { + "MeterListener": { + "commandName": "Project", + "commandLineArgs": "\"..\\..\\..\\..\\..\\data\\formulair04_tsukuba 2kfull 2024-01-09 17-26-10.ibt\"" + } + } +} diff --git a/Samples/Metrics/OpenTelemetry/OpenTelemetry.csproj b/Samples/Metrics/OpenTelemetry/OpenTelemetry.csproj new file mode 100644 index 0000000..f07dcfd --- /dev/null +++ b/Samples/Metrics/OpenTelemetry/OpenTelemetry.csproj @@ -0,0 +1,23 @@ + + + + Exe + net8.0 + enable + enable + + OpenTelemetrySample + OpenTelemetrySample + OpenTelemetrySample + + + + + + + + + + diff --git a/Samples/Metrics/OpenTelemetry/Program.cs b/Samples/Metrics/OpenTelemetry/Program.cs new file mode 100644 index 0000000..280237e --- /dev/null +++ b/Samples/Metrics/OpenTelemetry/Program.cs @@ -0,0 +1,81 @@ +/** + * Copyright (C) 2024-2026 Scott Velez + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + **/ + +using Microsoft.Extensions.Logging; +using OpenTelemetry; +using OpenTelemetry.Metrics; +using SVappsLAB.iRacingTelemetrySDK; + +namespace OpenTelemetrySample; + +[RequiredTelemetryVars([TelemetryVar.Speed, TelemetryVar.RPM])] +internal class Program +{ + public static async Task Main(string[] args) + { + // === collection - the only part that differs from the MeterListener sample === + + // subscribe to the SDK's meter by name; the SDK creates the meter itself, so + // nothing has to be passed to the client. OpenTelemetry does the aggregating - + // counters become sums and histograms become bucket distributions, using the + // bucket boundaries the SDK advises for each instrument. + // + using var meterProvider = Sdk.CreateMeterProviderBuilder() + .AddMeter(TelemetryMetrics.MeterName) + // the console exporter keeps the sample self-contained. swap in + // .AddOtlpExporter() to ship to a collector, Prometheus, or Grafana instead + .AddConsoleExporter((_, metricReader) => + metricReader.PeriodicExportingMetricReaderOptions.ExportIntervalMilliseconds = 5000) + .Build(); + + // === client setup - identical in both samples === + + var logger = LoggerFactory.Create(builder => builder.AddConsole()) + .CreateLogger("OpenTelemetry"); + + // no argument for live telemetry, an IBT filepath to replay a file. an optional second + // argument is the playback speed - '1' replays at the speed it was recorded, which is the + // only way playback.lag gets recorded. the default is max speed, which has no schedule + IBTOptions? ibtOptions = args.Length switch + { + 0 => null, + 1 => new IBTOptions(args[0]), + _ => new IBTOptions(args[0], int.Parse(args[1])) + }; + + var clientOptions = new ClientOptions { DeliveryMode = TelemetryDeliveryMode.Synchronous }; + await using var client = TelemetryClient.Create(logger, ibtOptions, clientOptions); + + using var cts = new CancellationTokenSource(); + Console.CancelKeyPress += (_, e) => { e.Cancel = true; cts.Cancel(); }; + + // synchronous delivery runs this handler inline, so its cost is the consumer's cost. + // give it some work - await Task.Delay(50) - and watch handler.duration climb; + // live telemetry will then report missed_tick as the read loop falls behind + var handlers = new TelemetryHandlers + { + OnTelemetryUpdate = _ => + { + client.GetValue("Speed"); + client.GetValue("RPM"); + return Task.CompletedTask; + } + }; + + Console.WriteLine("press Ctrl-C to exit..."); + await client.Monitor(handlers, cts.Token); + } +} diff --git a/Samples/Metrics/OpenTelemetry/Properties/launchSettings.json b/Samples/Metrics/OpenTelemetry/Properties/launchSettings.json new file mode 100644 index 0000000..513bf44 --- /dev/null +++ b/Samples/Metrics/OpenTelemetry/Properties/launchSettings.json @@ -0,0 +1,8 @@ +{ + "profiles": { + "OpenTelemetry": { + "commandName": "Project", + "commandLineArgs": "\"..\\..\\..\\..\\..\\data\\formulair04_tsukuba 2kfull 2024-01-09 17-26-10.ibt\"" + } + } +} diff --git a/Samples/Metrics/README.md b/Samples/Metrics/README.md new file mode 100644 index 0000000..739e266 --- /dev/null +++ b/Samples/Metrics/README.md @@ -0,0 +1,105 @@ +# Metrics Samples + +Two samples that collect the SDK's built-in diagnostic metrics. + +| Sample | Collected with | Extra packages | +|--------|----------------|----------------| +| [MeterListener](./MeterListener/) | `System.Diagnostics.Metrics.MeterListener` | none - it is built into .NET | +| [OpenTelemetry](./OpenTelemetry/) | OpenTelemetry `MeterProvider` + console exporter | `OpenTelemetry`, `OpenTelemetry.Exporter.Console` | + +The two programs are deliberately identical apart from collection. Both request the same telemetry variables, and both read them the same way inside the handler - so the metrics they produce are directly comparable. + +## Running + +```bash +cd MeterListener # or OpenTelemetry + +dotnet run # live iRacing session +dotnet run # replay an IBT file at max speed +dotnet run 1 # replay at recorded speed, so playback.lag is recorded too +``` + +Ctrl-C ends a live run. Both samples report every 5 seconds and once more for the whole run. + +To see the pipeline under stress, give the handler some work - `await Task.Delay(50)` - and watch `handler.duration` climb while `records.dropped` starts counting `missed_tick`. + +## What is being collected + +Neither sample creates instruments or passes anything to `TelemetryClient`. The SDK always publishes a meter named `SVappsLAB.iRacingTelemetrySDK` (the `TelemetryMetrics.MeterName` constant), and both samples subscribe to it *by name*. If nothing is listening, the SDK skips reading its clocks, so the instrumentation costs nothing when unused. + +Thirteen instruments arrive, in three groups: + +**Telemetry pipeline** - one record's journey from acquisition to your handler + +| Instrument | Type | Measures | +|---|---|---| +| `telemetry.records.processed` | Counter | records that made it through | +| `telemetry.records.dropped` | Counter | records lost, tagged with `drop.reason` | +| `telemetry.decode.duration` | Histogram | turning the raw buffer into a typed sample | +| `telemetry.sdk.duration` | Histogram | acquisition until your handler was called | +| `telemetry.handler.duration` | Histogram | your handler's own work | +| `telemetry.total.duration` | Histogram | `sdk + handler`, end to end | +| `telemetry.sample.interval` | Histogram | gap *between* records - cadence, not latency | + +**Session info** - the YAML block iRacing publishes alongside telemetry + +| Instrument | Type | Measures | +|---|---|---| +| `session_info.records.processed` | Counter | session-info updates parsed | +| `session_info.records.dropped` | Counter | updates lost, tagged with `drop.reason` | +| `session_info.process.duration` | Histogram | time to parse one update | +| `session_info.size` | Histogram | UTF-8 size of one update | +| `session_info.parse.attempts` | Histogram | 1 if the YAML parsed as-is, 2 if it had to be repaired | + +**Playback** + +| Instrument | Type | Measures | +|---|---|---| +| `playback.lag` | Histogram | how far behind schedule a paced IBT record was read - only recorded when a playback speed is set | + +All names carry the `svappslab.iracingsdk.` prefix. Measurements are tagged with `data_source` (`live` or `ibt`) on the meter, plus `drop.reason`, `error.type`, and `session_info.stream` per measurement where they apply. + +See [Metrics and Diagnostics](../../docs/METRICS.md) for details. + +## MeterListener vs. OpenTelemetry + +The samples differ in one thing - **who aggregates**. + +`MeterListener` sample hands you raw measurements, one callback per recorded value. You must aggregate and calculate the stats yourself. +OpenTelemetry sample aggregates into sums and bucketed histograms and hands the result to an exporter. Great for Grafana dashboards. + +| | MeterListener | OpenTelemetry | +|---|---|---| +| Dependencies | none | the OpenTelemetry SDK + an exporter | +| Subscribe | `InstrumentPublished` + a callback per measurement type | `.AddMeter(TelemetryMetrics.MeterName)` | +| Aggregation | yours to write | built in | +| Histograms | whatever you compute - count/sum/max here. The SDK's bucket `advice` is **not** applied, so no percentiles | full bucket distributions using the boundaries the SDK advises, so p50/p95/p99 come out of the backend | +| Tags | a raw `ReadOnlySpan` you fold into a key yourself; the meter-level `data_source` tag is not included | handled as dimensions, with meter-level tags reported alongside | +| Output | whatever you print | any exporter - console here, or `.AddOtlpExporter()` to a collector, Prometheus, or Grafana | +| Cost | a few allocations and your own locking on the SDK's threads | a metrics pipeline and an export thread | + + +## Sample output + +**MeterListener** - single stats sample, grabbed from console output: + +``` +--- final metrics --- + session_info.parse.attempts 1 recorded avg 1 {attempt} max 1 {attempt} + session_info.process.duration 1 recorded avg 62.944 ms max 62.944 ms + session_info.records.processed 1 {record} + session_info.size 1 recorded avg 26,463 By max 26,463 By + telemetry.decode.duration 123,936 recorded avg 0.5 us max 1.696 ms + telemetry.handler.duration 123,936 recorded avg 0.2 us max 206.7 us + telemetry.records.processed 123,936 {record} + telemetry.sample.interval 123,935 recorded avg 2.3 us max 3.349 ms + telemetry.sdk.duration 123,936 recorded avg 0.8 us max 2.536 ms + telemetry.total.duration 123,936 recorded avg 1.2 us max 2.715 ms +``` + + +## Related Documentation + +- **[Metrics and Diagnostics](../../docs/METRICS.md)** - reference, attributes, bucket boundaries, interpretation +- **[Architecture and Design](../../docs/ARCHITECTURE.md)** - the threading model and buffering policy these metrics measure +- **[Samples](../README.md)** - the rest of the example projects diff --git a/Samples/README.md b/Samples/README.md index 1451a4c..741b9d5 100644 --- a/Samples/README.md +++ b/Samples/README.md @@ -15,6 +15,21 @@ All samples define a `TelemetryHandlers` variable and pass it to Same shape as MinimalExampleAsync, but looks up telemetry variables dynamically with `GetValue("")` instead of a strongly-typed property. Synchronous mode allows you to query for any variable, at runtime, at the cost of throughput. See [SDK_REFERENCE.md](../docs/ai/SDK_REFERENCE.md#telemetry-delivery-mode) for details on the tradeoffs. +* [Metrics](./Metrics/) + + Two samples that collect the SDK's built-in metrics, one for each of the common ways to consume them. They are identical apart from collection. + + * [MeterListener](./Metrics/MeterListener/) - subscribes to the SDK meter by name and aggregates every measurement itself. No DI, no OpenTelemetry, no extra packages. + * [OpenTelemetry](./Metrics/OpenTelemetry/) - subscribes and uses a console exporter to print real bucketed histograms. Swap in `.AddOtlpExporter()` for a collector, Prometheus, or Grafana. + + ```bash + dotnet run # live + dotnet run # replay, max speed + dotnet run 1 # replay at recorded speed, so playback.lag is recorded too + ``` + + See the [Metrics README](./Metrics/) for what is collected, what each instrument means and how to interpret it. + * [DumpVariables_DumpSessionInfo](./DumpVariables_DumpSessionInfo/) Connects to a session (live or IBT file) diff --git a/Samples/Samples.slnx b/Samples/Samples.slnx index 6795240..c8cf5a0 100644 --- a/Samples/Samples.slnx +++ b/Samples/Samples.slnx @@ -2,6 +2,11 @@ + + + + + diff --git a/docs/METRICS.md b/docs/METRICS.md index 85ed838..4632f26 100644 --- a/docs/METRICS.md +++ b/docs/METRICS.md @@ -14,6 +14,8 @@ For the threading model and buffering policy these instruments measure, see [Arc - [Dependency Injection](#dependency-injection) - [Monitoring with dotnet-counters](#monitoring-with-dotnet-counters) - [Live-Session Example](#live-session-example) + - [Baseline: a fast synchronous consumer](#baseline-a-fast-synchronous-consumer) + - [When the consumer is too slow](#when-the-consumer-is-too-slow) ## Available Metrics @@ -59,6 +61,8 @@ Each histogram provides bucket boundaries suited to what it measures, so exporte | `telemetry.sample.interval` | p50 15.5 ms, p99 31 ms | 10 µs to 1 s | | `playback.lag` | p50 7.0 ms, p99 15 ms, max 298 ms | 500 µs to 30 s | +A later live run - the one in [Live-Session Example](#baseline-a-fast-synchronous-consumer) - stayed inside every one of these ranges, its widest outliers being a 4.879 ms `total.duration` and a 65.178 ms `sample.interval`. + `sdk.duration` and `total.duration` share boundaries so they can be compared bucket for bucket; their difference is the consumer's handler cost. The telemetry clocks are read only while a listener collects a histogram that needs them, so the hot path costs nothing extra when metrics are not collected. ## Telemetry Pipeline Latency @@ -93,7 +97,7 @@ acquire(n-1) ────── sample.interval ──────► acquire(n) - **`total.duration` is a latency.** It lives entirely inside one record: that record's acquisition until the handler returned for that same record. It answers *how long did this record take to process*. - **`sample.interval` is a cadence.** It spans two records and ignores what happened to either one. It answers *how often are records arriving*. A consumer whose handler does nothing at all still records the same intervals. -In a healthy live session the two differ by roughly three orders of magnitude - about 0.02 ms of work inside each 15.5 ms frame. That ratio, rather than either number on its own, is the processing headroom. +In a healthy live session the two differ by roughly three orders of magnitude - about 0.008 ms of work inside each 16.7 ms frame, [measured below](#baseline-a-fast-synchronous-consumer). That ratio, rather than either number on its own, is the processing headroom. Reading them together isolates the slow stage: @@ -116,7 +120,7 @@ Interpret the values as follows: - **Live**: `telemetry.sample.interval` should sit near 0.01667 s (60 Hz). A distribution split between one and two frames means ticks are being missed, which also appears as `missed_tick` drops. `telemetry.total.duration` says nothing about this; it stays flat while frames are being dropped. - **Async delivery**: a rising `telemetry.sdk.duration` means records are waiting in the delivery buffer behind the consumer. If the consumer stays behind, `consumer_overflow` drops follow. -- **Synchronous delivery**: there is no buffer, so `sdk.duration` collapses to decode cost and `total.duration` is roughly decode plus handler. A slow handler shows up as handler time and `missed_tick` drops rather than SDK time. +- **Synchronous delivery**: there is no buffer, so `sdk.duration` falls to decode cost plus the handoff itself - measured at roughly twice decode - and `total.duration` is roughly decode plus handler. A slow handler shows up as handler time and `missed_tick` drops rather than SDK time. - **IBT at max speed** (the default `PlayBackSpeedMultiplier`): there is no schedule to keep, so `sample.interval` measures how fast the file is being consumed rather than a 60 Hz cadence; it and `sdk.duration` describe throughput, not real-time latency. At a paced speed both behave like live. - **Async delivery with no consumer**: a client that neither sets `OnTelemetryUpdate` nor enumerates `TelemetryData` never records `sdk.duration`, `handler.duration`, or `total.duration`. @@ -131,6 +135,8 @@ services.AddOpenTelemetry() Configure the exporter appropriate to the application separately. The SDK publishes metrics; it does not configure an OpenTelemetry exporter or collector. +The [OpenTelemetry sample](../Samples/Metrics/OpenTelemetry/) is a runnable version of this, using a console exporter so it needs no collector. Subscribing by meter name needs neither DI nor an `IMeterFactory`. + ## Dependency Injection Pass the application's `IMeterFactory` to the client so the SDK creates its meter through the DI container: @@ -179,7 +185,34 @@ dotnet-counters collect --counters SVappsLAB.iRacingTelemetrySDK --format csv -o ## Live-Session Example -The following one-second snapshots are from the same live iRacing session, consumed three ways. Slow handlers wait 50 ms per record, so they can handle about 16 records per second against iRacing's 60 Hz. +### Baseline: a fast synchronous consumer + +A report from the [MeterListener sample](../Samples/Metrics/MeterListener/) against a live iRacing session: synchronous delivery, and a handler that does two `GetValue()` calls. The run covered 12,704 records, about three and a half minutes. + +``` +--- metrics --- + session_info.parse.attempts 26 recorded avg 1 {attempt} max 1 {attempt} + session_info.process.duration 26 recorded avg 9.283 ms max 60.118 ms + session_info.records.processed 26 {record} + session_info.size 26 recorded avg 54,772 By max 56,027 By + telemetry.decode.duration 12,704 recorded avg 3.2 us max 1.380 ms + telemetry.handler.duration 12,704 recorded avg 0.8 us max 253.5 us + telemetry.records.processed 12,704 {record} + telemetry.sample.interval 12,703 recorded avg 16.680 ms max 65.178 ms + telemetry.sdk.duration 12,704 recorded avg 6.2 us max 2.362 ms + telemetry.total.duration 12,704 recorded avg 7.6 us max 4.879 ms +``` + +- **Cadence**: `telemetry.sample.interval` averaged 16.680 ms - 59.95 Hz, iRacing's 60 Hz. Consecutive five-second reports each added exactly 300 records. +- **Headroom**: 7.6 µs of end-to-end work inside a 16.68 ms frame is about 0.05% of the frame; the rest is the consumer's to spend. +- **Where the time goes**: `sdk.duration` 6.2 µs, of which `decode.duration` is 3.2 µs, and the handler's two `GetValue()` calls 0.8 µs. Synchronous delivery has no buffer, so the SDK's remaining share is handoff rather than queueing. The 0.6 µs by which `sdk` plus `handler` falls short of `total` is the cost of recording `sdk.duration` itself, which lands between the two clock reads - the price of collecting, not of the pipeline. +- **Nothing was dropped**: neither `records.dropped` counter appears at all. A `MeterListener` prints only instruments that recorded something, so an absent row is a zero. +- **The outliers are the source, not the pipeline**: the widest `sample.interval` was 65.178 ms, about four frames, yet no `missed_tick` drops were counted. Missed ticks come from iRacing's own tick counter, so zero means the sim wrote nothing during that gap rather than the read loop falling behind. +- **Session info**: 26 updates, roughly one every eight seconds, averaging 53 KiB and 9.283 ms to parse. Parsing runs off the telemetry path, so even the 60.118 ms outlier costs the telemetry pipeline nothing. `parse.attempts` never exceeded 1, so no YAML needed repairing. + +### When the consumer is too slow + +The following one-second snapshots are from a live iRacing session, consumed three ways. Slow handlers wait 50 ms per record, so they can handle about 16 records per second against iRacing's 60 Hz. | Consumer | `records.processed` | `records.dropped` | `drop.reason` | `telemetry.decode.duration` p50 / p95 / p99 | |----------|---------------------|-------------------|---------------|------------------------------------------------|