diff --git a/.github/workflows/gc-profile.yaml b/.github/workflows/gc-profile.yaml new file mode 100644 index 00000000..8c15aed7 --- /dev/null +++ b/.github/workflows/gc-profile.yaml @@ -0,0 +1,144 @@ +# Sustained-load GC / allocation profiling (#212). +# +# Runs the library through a 10-minute in-memory extract -> transform -> load loop +# under `dotnet-counters`, so we can measure gen0/1/2 promotion, LOH pressure, +# finalizer-queue depth, and thread-pool starvation under a real streaming ETL +# pattern rather than the micro-scale BDN benchmarks. +# +# Gate mode: INFORMATIONAL. Reports upload as artifacts and get summarised in the +# Step Summary; no regression gate yet — that requires a stable baseline the first +# several runs need to establish (same "land the tool informational, harden later" +# pattern as reproducible-build / semgrep / stryker). See docs/GC-PROFILE.md. + +name: GC / allocation profile + +on: + workflow_dispatch: + inputs: + duration_seconds: + description: "Wall-clock seconds to run the workload" + required: false + default: "600" + type: string + schedule: + # Weekly Sunday 07:00 UTC — after the Stryker run at 06:00, so they don't fight + # for the same GitHub-hosted runner pool. + - cron: '0 7 * * 0' + +permissions: + contents: read + +jobs: + profile: + name: Profile ETL workload (Linux x64) + runs-on: ubuntu-latest + # 10 min workload + slack for build / trace processing + safety margin. + timeout-minutes: 30 + steps: + - name: Checkout code + uses: actions/checkout@3d3c42e5aac5ba805825da76410c181273ba90b1 # v7 + with: + persist-credentials: false + + # Guard so the scheduled run no-ops when the workload project isn't on the + # checked-out ref (it lands via vNext before it reaches main). + - name: Detect GcProfileWorkload + id: check + shell: bash + run: | + if [ -f tools/GcProfileWorkload/GcProfileWorkload.csproj ]; then + echo "found=true" >> "$GITHUB_OUTPUT" + else + echo "::notice::GcProfileWorkload project not present on this ref — skipping GC profile. Merge vNext to main to enable." + echo "found=false" >> "$GITHUB_OUTPUT" + fi + + - name: Setup .NET + if: steps.check.outputs.found == 'true' + uses: actions/setup-dotnet@a98b56852c35b8e3190ac28c8c2271da59106c68 # v6 + with: + dotnet-version: '10.0.x' + + - name: Install dotnet-counters + dotnet-trace + if: steps.check.outputs.found == 'true' + run: | + dotnet tool install --global dotnet-counters + dotnet tool install --global dotnet-trace + + - name: Restore + Build workload (Release) + if: steps.check.outputs.found == 'true' + run: | + dotnet restore tools/GcProfileWorkload/GcProfileWorkload.csproj + dotnet build tools/GcProfileWorkload/GcProfileWorkload.csproj \ + --no-restore \ + --configuration Release + + - name: Run workload + capture counters + id: profile + if: steps.check.outputs.found == 'true' + env: + GC_WORKLOAD_SECONDS: ${{ inputs.duration_seconds || '600' }} + run: | + set -uo pipefail + mkdir -p reports + + # Launch the workload in the background so dotnet-counters can attach by + # PID; its stdout goes to reports/workload.log for offline inspection. + dotnet run --no-build --project tools/GcProfileWorkload \ + --configuration Release \ + > reports/workload.log 2>&1 & + workload_pid=$! + echo "Workload PID: $workload_pid" + + # Give it a moment to spin up. + sleep 5 + + # Capture CLR runtime counters continuously to a CSV; kill it explicitly + # at the end so the CSV is finalised. + dotnet-counters collect \ + --process-id "$workload_pid" \ + --refresh-interval 5 \ + --format csv \ + --output reports/counters.csv \ + --counters System.Runtime & + counters_pid=$! + + wait "$workload_pid" || echo "Workload exit code: $?" + echo "Workload done, stopping counters" + kill "$counters_pid" 2>/dev/null || true + wait "$counters_pid" 2>/dev/null || true + + - name: Summarise into Step Summary + if: always() && steps.check.outputs.found == 'true' + # Pass the duration through env (not inline expansion) so a dispatch input + # can't inject into this script. + env: + DURATION_SECONDS: ${{ inputs.duration_seconds || '600' }} + run: | + { + echo "## GC / allocation profile" + echo "" + echo "Duration: **${DURATION_SECONDS}s**" + echo "" + echo "### Workload progress (last 20 lines)" + echo "" + echo '```' + tail -n 20 reports/workload.log 2>/dev/null || echo "(no workload log)" + echo '```' + echo "" + echo "### Runtime counter head (System.Runtime)" + echo "" + echo '```' + head -n 30 reports/counters.csv 2>/dev/null || echo "(no counter CSV)" + echo '```' + echo "" + echo "Gate mode: informational. See docs/GC-PROFILE.md for how to read the full report." + } >> "$GITHUB_STEP_SUMMARY" + + - name: Upload reports + if: always() && steps.check.outputs.found == 'true' + uses: actions/upload-artifact@043fb46d1a93c77aae656e7c1c64a875d1fc6a0a # v7 + with: + name: gc-profile-reports + path: reports/ + retention-days: 30 diff --git a/docs/GC-PROFILE.md b/docs/GC-PROFILE.md new file mode 100644 index 00000000..65fd1dda --- /dev/null +++ b/docs/GC-PROFILE.md @@ -0,0 +1,83 @@ +# GC / allocation profile + +BDN benchmarks (see [`benchmarks/`](../benchmarks/)) measure single-method +micro-perf. This workflow measures the **sustained-load** metrics — the ones that +only surface after minutes of continuous ETL traffic: + +- gen0 → gen1 → gen2 promotion rates +- Large Object Heap (LOH) growth and pinning +- Finalizer queue depth +- Thread-pool starvation events +- Working-set growth vs allocated bytes + +## What runs + +[`.github/workflows/gc-profile.yaml`](../.github/workflows/gc-profile.yaml) runs on +**workflow_dispatch** and on a weekly Sunday 07:00 UTC schedule (Stryker runs at +06:00, so the two don't fight for the same GitHub-hosted runner pool). + +The workload — [`tools/GcProfileWorkload/`](../tools/GcProfileWorkload/) — runs an +in-memory extract → transform → load `Pipeline` (base-class `ExtractorBase` → +`TransformerBase` → `LoaderBase`, with per-stage progress and stage disposal) in a +loop for 10 minutes (configurable via the `duration_seconds` input). ServerGC + +concurrent GC are enabled to match a realistic long-running ETL host. +`dotnet-counters` attaches by PID and samples the `System.Runtime` counter set +every 5 seconds; results write to a CSV artifact. + +## Gate mode: informational + +Every run uploads: + +- `reports/workload.log` — the workload's stdout (per-cycle `gen0`/`gen1`/`gen2` + counts, allocated MB, heap MB, and a final summary). +- `reports/counters.csv` — every sampled `System.Runtime` counter (heap size per + generation, GC count per gen, working set, thread-pool queue depth, + exceptions/sec, …). + +**No regression gate today.** A meaningful gate needs a stable baseline, which the +first several runs establish (GC metrics vary more run-to-run than BDN benchmarks — +differently-timed collections dominate short samples). Follow-up: once ~10 baseline +runs exist, add a threshold gate (e.g. "gen2 collections/minute > 2× rolling median +→ fail + open a maintenance issue"). + +## Baseline (first local run, 2026-07-22) + +For reference, an 8-second local run processed **~90M records** through the +pipeline with only **2 gen0 collections, 0 gen1, 0 gen2**, ~6 MB total allocated, +~1 MB steady heap — i.e. the streaming pipeline is near-zero-alloc per record +(consistent with the allocation-free hot-path tests, #217). The sustained profile +should stay in that shape; a linear heap climb or rising gen2 is the regression to +catch. + +## Reading a report + +The counter CSV has columns like: + +``` +Timestamp,Metadata,Provider,Name,Value +2026-07-19T07:00:15Z,,System.Runtime,gc-heap-size,1.1 +2026-07-19T07:00:15Z,,System.Runtime,gen-0-gc-count,2.0 +... +``` + +Metrics worth watching: + +- **`gc-heap-size`** — total heap MB. Should stabilise, not grow linearly. Linear + growth = leak. +- **`gen-2-gc-count` / `loh-size`** — high gen2 or LOH growth = large-object + pinning or long-lived allocations. For a streaming ETL library we expect + near-zero gen2. +- **`threadpool-queue-length`** — should stay near zero. A rising queue = the + workload is blocking a thread-pool thread somewhere. +- **`allocation-rate`** — MB/sec allocated. Cross-reference the workload log's + per-cycle line for allocations-per-record instead. + +## Ratchet policy + +Same shape as [`mutation-testing.md`](mutation-testing.md)'s ratchet: + +- Baseline: whatever the first stable run gives. +- Improvement: tighter thresholds. +- Regression: never quietly relaxed — flag in review. + +Refs #212. diff --git a/tools/GcProfileWorkload/GcProfileWorkload.csproj b/tools/GcProfileWorkload/GcProfileWorkload.csproj new file mode 100644 index 00000000..9c9af149 --- /dev/null +++ b/tools/GcProfileWorkload/GcProfileWorkload.csproj @@ -0,0 +1,27 @@ + + + + Exe + net10.0 + latest + enable + enable + false + + + true + true + + + $(NoWarn);CA2007;MA0004;MA0048;S3903;VSTHRD200 + + + + + + + diff --git a/tools/GcProfileWorkload/Program.cs b/tools/GcProfileWorkload/Program.cs new file mode 100644 index 00000000..1ff38511 --- /dev/null +++ b/tools/GcProfileWorkload/Program.cs @@ -0,0 +1,145 @@ +// Sustained-load workload for GC / allocation profiling (#212). +// +// Runs an in-memory extract -> transform -> load pipeline in a loop for a +// wall-clock duration (env GC_WORKLOAD_SECONDS or argv[0], default 600), so +// `dotnet-counters` / `dotnet-trace` can characterise gen0/1/2 promotion rates, +// LOH pressure, finalizer-queue depth, and thread-pool starvation under a real +// streaming ETL pattern rather than the micro-scale BDN benchmarks. +// +// Not a benchmark — the scale / cycle counts are arbitrary. Meaningful metrics +// come from the EventPipe trace the outer workflow captures, not the wall time +// this process reports. +// +// Refs #212. + +using System.Diagnostics; +using System.Runtime; +using System.Runtime.CompilerServices; +using Wolfgang.Etl.Abstractions; + +const int recordsPerCycle = 50_000; +var durationSeconds = ParseDuration(args); + +Console.WriteLine($"[gc-workload] Version : {typeof(Report).Assembly.GetName().Version}"); +Console.WriteLine($"[gc-workload] Runtime : {Environment.Version}"); +Console.WriteLine($"[gc-workload] ServerGC : {GCSettings.IsServerGC}"); +Console.WriteLine($"[gc-workload] Duration : {durationSeconds}s"); +Console.WriteLine($"[gc-workload] Records : {recordsPerCycle:N0} / cycle"); +Console.WriteLine($"[gc-workload] PID : {Environment.ProcessId}"); + +// Progress callbacks are part of the hot path (the base classes fire a timer and +// allocate a Report per tick); a no-op sink keeps that path live. +var progress = new Progress(_ => { }); +var stopwatch = Stopwatch.StartNew(); +long cycles = 0; +long totalRecords = 0; + +while (stopwatch.Elapsed.TotalSeconds < durationSeconds) +{ + var loader = new CountingLoader(); + + await Pipeline + .Extract(new RangeExtractor(recordsPerCycle)) + .WithProgress(progress) + .Transform(new DoublingTransformer()) + .Load(loader) + .WithProgress(progress) + .WithName("gc-profile") + .DisposeStagesOnCompletion() + .RunAsync(CancellationToken.None); + + cycles++; + totalRecords += loader.Count; + + if (cycles % 10 == 0) + { + Console.WriteLine( + $"[gc-workload] cycle={cycles} records={totalRecords:N0} " + + $"gen0={GC.CollectionCount(0)} gen1={GC.CollectionCount(1)} gen2={GC.CollectionCount(2)} " + + $"alloc={GC.GetTotalAllocatedBytes(precise: true) / 1048576.0:F1}MB " + + $"heap={GC.GetTotalMemory(forceFullCollection: false) / (1024 * 1024)}MB"); + } +} + +stopwatch.Stop(); +Console.WriteLine( + $"[gc-workload] DONE cycles={cycles} records={totalRecords:N0} elapsed={stopwatch.Elapsed.TotalSeconds:F1}s"); +Console.WriteLine( + $"[gc-workload] FINAL gen0={GC.CollectionCount(0)} gen1={GC.CollectionCount(1)} gen2={GC.CollectionCount(2)} " + + $"alloc={GC.GetTotalAllocatedBytes(precise: true) / 1048576.0:F1}MB"); + +return 0; + + +static int ParseDuration(string[] args) +{ + var env = Environment.GetEnvironmentVariable("GC_WORKLOAD_SECONDS"); + if (int.TryParse(env, out var fromEnv) && fromEnv > 0) + { + return fromEnv; + } + + if (args.Length > 0 && int.TryParse(args[0], out var fromArg) && fromArg > 0) + { + return fromArg; + } + + return 600; +} + + +// Base-class stages so the workload exercises the real hot paths — async +// iteration, the Interlocked item counters, per-tick Report allocation, the +// progress timer, and stage disposal. +internal sealed class RangeExtractor(int count) : ExtractorBase +{ + protected override async IAsyncEnumerable ExtractWorkerAsync( + [EnumeratorCancellation] CancellationToken token) + { + for (var i = 0; i < count; i++) + { + IncrementCurrentItemCount(); + yield return i; + if ((i & 4095) == 0) + { + await Task.Yield(); + } + } + } + + protected override Report CreateProgressReport() => new(CurrentItemCount); +} + + +internal sealed class DoublingTransformer : TransformerBase +{ + protected override async IAsyncEnumerable TransformWorkerAsync( + IAsyncEnumerable items, + [EnumeratorCancellation] CancellationToken token) + { + await foreach (var item in items.WithCancellation(token)) + { + yield return item * 2; + } + } + + protected override Report CreateProgressReport() => new(CurrentItemCount); +} + + +internal sealed class CountingLoader : LoaderBase +{ + public long Count { get; private set; } + + protected override async Task LoadWorkerAsync(IAsyncEnumerable items, CancellationToken token) + { + await foreach (var item in items.WithCancellation(token)) + { + IncrementCurrentItemCount(); + _ = item; + Count++; + } + } + + protected override Report CreateProgressReport() => new(CurrentItemCount); +}