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/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/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/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/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..4632f26 --- /dev/null +++ b/docs/METRICS.md @@ -0,0 +1,235 @@ +# 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) + - [Baseline: a fast synchronous consumer](#baseline-a-fast-synchronous-consumer) + - [When the consumer is too slow](#when-the-consumer-is-too-slow) + +## 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 | + +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 + +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.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: + +| 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` 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`. + +## 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. + +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: + +```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 + +### 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 | +|----------|---------------------|-------------------|---------------|------------------------------------------------| +| 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