From e13689b5f447aee61426d388a8699b8fe25c4140 Mon Sep 17 00:00:00 2001 From: Rafael Vuijk Date: Sun, 9 Aug 2026 10:56:08 +0000 Subject: [PATCH] Record how long CI takes, so a change in it is visible There was no way to answer "has CI got slower". The web UI shows one run at a time and reports created-to-finished, which folds in how long the run waited for a runner; on a busy afternoon that reads as a regression when nothing about the code changed. Run history is kept for a bounded window and logs for ninety days, so the question also gets harder to answer the longer it goes unasked -- the January 2026 logs had already expired when this was written, and only the job timestamps survived to be recovered. So: dotnet run CiTiming, from Sources/Utils/Utils. It separates the two durations, because they answer different questions. Exec is runner-picks-the-job-up to job-finishes, which is what moves when a suite grows. Queue is run-created to runner-picks-it-up, which moves when several pull requests are in flight and says nothing about the code. The baseline is committed rather than derived, for the retention reason above, and every earlier snapshot is kept when a new one is recorded. Two are on file: today, and 22 January 2026, recovered from the job timestamps before that window closes. What it says today, against January: C# Test / Test (ubuntu-latest) 10.0m +56% C# Test / Test (windows-latest) 13.5m +52% C# Test / Test (macos-latest) 10.5m +15% Against 3129 to 5118 test cases over the same period, +64%. So the growth is sublinear -- time per case fell about a fifth -- and macOS looks better than its neighbours because those runners moved to ARM, not because less is run there. Nothing structural was found to reclaim. The build steps are under a minute, and the test step is the job. gh does the talking, so no token lives in this repository. Co-Authored-By: Claude Opus 5 (1M context) --- Sources/.editorconfig | 3 + Sources/Utils/Utils/CiTiming.cs | 322 ++++++++++++++++++++++++++++++++ Sources/Utils/ci-baseline.json | 69 +++++++ 3 files changed, 394 insertions(+) create mode 100644 Sources/Utils/Utils/CiTiming.cs create mode 100644 Sources/Utils/ci-baseline.json diff --git a/Sources/.editorconfig b/Sources/.editorconfig index cbb98c043..ddceb7143 100644 --- a/Sources/.editorconfig +++ b/Sources/.editorconfig @@ -28,3 +28,6 @@ file_header_template=\nCopyright (c) 2019-2026 Angouri.\nAngouriMath is licensed # rather than the folder. [AngouriMath/Core/Entity/Continuous/Entity.Continuous.{Floors,Rounding}.Classes.cs] file_header_template=\nCopyright (c) 2019-2026 Angouri.\nAngouriMath is licensed under MIT.\nDetails: https://github.com/asc-community/AngouriMath/blob/master/LICENSE.md.\nWebsite: https://am.angouri.org.\n + +[Utils/Utils/CiTiming.cs] +file_header_template=\nCopyright (c) 2019-2026 Angouri.\nAngouriMath is licensed under MIT.\nDetails: https://github.com/asc-community/AngouriMath/blob/master/LICENSE.md.\nWebsite: https://am.angouri.org.\n diff --git a/Sources/Utils/Utils/CiTiming.cs b/Sources/Utils/Utils/CiTiming.cs new file mode 100644 index 000000000..5aaa61c7d --- /dev/null +++ b/Sources/Utils/Utils/CiTiming.cs @@ -0,0 +1,322 @@ +// +// Copyright (c) 2019-2026 Angouri. +// AngouriMath is licensed under MIT. +// Details: https://github.com/asc-community/AngouriMath/blob/master/LICENSE.md. +// Website: https://am.angouri.org. +// + +using System; +using System.Collections.Generic; +using System.Diagnostics; +using System.Globalization; +using System.IO; +using System.Linq; +using System.Text.Encodings.Web; +using System.Text.Json; + +namespace Utils +{ + /// + /// How long CI takes, and whether that has changed. + /// + /// + /// + /// Run with dotnet run CiTiming from Sources/Utils/Utils. Requires the + /// GitHub CLI (gh) to be installed and authenticated; it is the only thing here + /// that knows how to talk to the API, and using it avoids a token in this repository. + /// + /// + /// Two durations are reported per job and they answer different questions. Exec + /// is from the moment a runner picks the job up to the moment it finishes, which is what + /// changes when a test suite grows. Queue is from the run being created to a + /// runner picking it up, which changes when several pull requests are in flight and says + /// nothing about the code. Reporting only the sum of the two — which is what the web UI + /// shows — makes a busy afternoon look like a performance regression. + /// + /// + /// The baseline is committed rather than derived, because GitHub keeps run history for a + /// bounded window and logs for ninety days. Without a file in the repository there is + /// nothing left to compare against once that window passes, which is exactly the + /// situation this was written in. + /// + /// + public static class CiTiming + { + private const string Repo = "asc-community/AngouriMath"; + + /// How many runs to ask for. The API caps a page at a thousand. + private const int RunsToFetch = 400; + + /// Runs per workflow to open up for per-job timings. Each costs a request. + private const int JobSample = 10; + + /// Reported as a regression above this. Runner-to-runner noise is a few percent. + private const double RegressionThreshold = 0.15; + + private static void Log(string msg) => Console.WriteLine("CiTiming: " + msg); + + public static void Do() + { + var baselinePath = Path.Join(Program.GetPathIntoSources(), "Utils", "ci-baseline.json"); + var recording = Environment.GetEnvironmentVariable("CI_TIMING_RECORD") == "1"; + + Log($"asking {Repo} for the last {RunsToFetch} runs"); + var runs = FetchRuns(); + if (runs.Count is 0) + { + Log("no successful runs came back — is gh installed and authenticated?"); + return; + } + Log($"{runs.Count} successful runs, " + + $"{runs.Min(r => r.Created):yyyy-MM-dd} to {runs.Max(r => r.Created):yyyy-MM-dd}"); + + var measured = Measure(runs); + var baseline = recording ? null : ReadBaseline(baselinePath); + Report(measured, baseline); + + if (recording) + { + WriteBaseline(baselinePath, measured, runs); + Log($"baseline written to {baselinePath}"); + } + } + + private readonly record struct Run(long Id, string Workflow, DateTimeOffset Created); + + private readonly record struct JobTiming(string Workflow, string Job, double Exec, double Queue); + + /// Median exec and queue seconds for one workflow job, over the sample. + private sealed record Stat(string Workflow, string Job, double Exec, double Queue, int Samples); + + private static List FetchRuns() + { + var json = Gh($"run list --repo {Repo} --limit {RunsToFetch} " + + "--json name,conclusion,createdAt,databaseId"); + if (json is null) return new List(); + + var runs = new List(); + foreach (var element in JsonDocument.Parse(json).RootElement.EnumerateArray()) + { + // Only successful runs: a run that failed stopped early, so its duration is + // the duration of getting to the failure and not of the work. + if (element.GetProperty("conclusion").GetString() != "success") continue; + runs.Add(new Run( + element.GetProperty("databaseId").GetInt64(), + element.GetProperty("name").GetString() ?? "?", + DateTimeOffset.Parse(element.GetProperty("createdAt").GetString()!, + CultureInfo.InvariantCulture))); + } + return runs; + } + + private static List Measure(List runs) + { + var timings = new List(); + foreach (var workflow in runs.Select(r => r.Workflow).Distinct().OrderBy(n => n, StringComparer.Ordinal)) + { + // Newest first, so the answer is about the code as it stands. + var sample = runs.Where(r => r.Workflow == workflow) + .OrderByDescending(r => r.Created) + .Take(JobSample) + .ToList(); + Log($" {workflow}: opening {sample.Count} runs"); + foreach (var run in sample) + timings.AddRange(JobsOf(run)); + } + + return timings + .GroupBy(t => (t.Workflow, t.Job)) + .Select(g => new Stat(g.Key.Workflow, g.Key.Job, + Median(g.Select(t => t.Exec)), Median(g.Select(t => t.Queue)), g.Count())) + .OrderByDescending(s => s.Exec) + .ToList(); + } + + private static IEnumerable JobsOf(Run run) + { + var json = Gh($"api /repos/{Repo}/actions/runs/{run.Id}/jobs?per_page=100"); + if (json is null) yield break; + + JsonElement jobs; + try + { + if (!JsonDocument.Parse(json).RootElement.TryGetProperty("jobs", out jobs)) yield break; + } + catch (JsonException) { yield break; } + + foreach (var job in jobs.EnumerateArray()) + { + var startedRaw = job.GetProperty("started_at").GetString(); + var completedRaw = job.GetProperty("completed_at").GetString(); + if (startedRaw is null || completedRaw is null) continue; + + var started = DateTimeOffset.Parse(startedRaw, CultureInfo.InvariantCulture); + var completed = DateTimeOffset.Parse(completedRaw, CultureInfo.InvariantCulture); + if (completed <= started) continue; + + yield return new JobTiming(run.Workflow, job.GetProperty("name").GetString() ?? "?", + (completed - started).TotalSeconds, + Math.Max(0, (started - run.Created).TotalSeconds)); + } + } + + private static void Report(List measured, (Snapshot Latest, List History)? baseline) + { + var latest = baseline?.Latest; + // The oldest snapshot on file, so a slow drift over many small steps is visible. + var oldest = baseline?.History.FirstOrDefault() ?? latest; + + Console.WriteLine(); + var sinceHeader = oldest is null || oldest == latest ? "" : $"since {oldest.Recorded}"; + Console.WriteLine($"{"workflow / job",-46}{"exec",8}{"queue",8}" + + $"{(latest is null ? "" : latest.Recorded),12}{"change",9}{sinceHeader,17}"); + Console.WriteLine(new string('-', 100)); + + var regressions = new List(); + foreach (var stat in measured) + { + var key = Key(stat); + var line = $"{Truncate(key, 46),-46}{Minutes(stat.Exec),8}{Minutes(stat.Queue),8}"; + + if (latest is not null && latest.Jobs.TryGetValue(key, out var was) && was > 0) + { + var change = (stat.Exec - was) / was; + line += $"{Minutes(was),12}{change,9:+0.0%;-0.0%;0.0%}"; + if (change > RegressionThreshold) regressions.Add($"{key} {change:+0%}"); + + if (oldest is not null && oldest != latest + && oldest.Jobs.TryGetValue(key, out var first) && first > 0) + line += $"{(stat.Exec - first) / first,17:+0.0%;-0.0%;0.0%}"; + } + else if (latest is not null) + line += $"{"new",12}"; + + Console.WriteLine(line); + } + + Console.WriteLine(); + // The jobs run in parallel, so what a contributor waits for is the slowest one, + // not the sum. The sum is what the project costs the runner pool. + if (measured.Count > 0) + Log($"slowest job {Minutes(measured[0].Exec)} ({measured[0].Job} in {measured[0].Workflow}); " + + $"{Minutes(measured.Sum(s => s.Exec))} of runner time per commit"); + + if (regressions.Count > 0) + { + Log($"{regressions.Count} job(s) above the {RegressionThreshold:P0} threshold since " + + $"{latest!.Recorded}:"); + foreach (var r in regressions) Log(" " + r); + } + else if (latest is not null) + Log("nothing above the threshold"); + } + + private static string Key(Stat s) => s.Workflow + " / " + s.Job; + + private static string Minutes(double seconds) => (seconds / 60).ToString("0.0", CultureInfo.InvariantCulture) + "m"; + + private static string Truncate(string s, int n) => s.Length <= n ? s : s[..(n - 1)] + "…"; + + private static double Median(IEnumerable values) + { + var sorted = values.OrderBy(v => v).ToList(); + if (sorted.Count is 0) return 0; + return sorted.Count % 2 is 1 + ? sorted[sorted.Count / 2] + : (sorted[sorted.Count / 2 - 1] + sorted[sorted.Count / 2]) / 2; + } + + /// One dated set of measurements: the current one, or an older one kept for history. + private sealed record Snapshot(string Recorded, Dictionary Jobs); + + private static (Snapshot Latest, List History)? ReadBaseline(string path) + { + if (!File.Exists(path)) + { + Log($"no baseline at {path} — run with CI_TIMING_RECORD=1 to write one"); + return null; + } + var root = JsonDocument.Parse(File.ReadAllText(path)).RootElement; + var history = new List(); + if (root.TryGetProperty("history", out var past)) + history.AddRange(past.EnumerateArray().Select(ReadSnapshot)); + return (ReadSnapshot(root), history); + } + + private static Snapshot ReadSnapshot(JsonElement element) + => new(element.GetProperty("recorded").GetString() ?? "?", + element.GetProperty("jobs").EnumerateObject() + .ToDictionary(p => p.Name, p => p.Value.GetDouble())); + + /// + /// Keeps every earlier snapshot. GitHub drops run history after a bounded window and + /// logs after ninety days, so a measurement that is not written down here cannot be + /// recovered later — which is how the January 2026 numbers were nearly lost. + /// + private static void WriteBaseline(string path, List measured, List runs) + { + var previous = ReadBaseline(path); + + using var stream = File.Create(path); + using var writer = new Utf8JsonWriter(stream, new JsonWriterOptions + { + Indented = true, + Encoder = JavaScriptEncoder.UnsafeRelaxedJsonEscaping, // so "C++ Test" reads as itself + }); + writer.WriteStartObject(); + writer.WriteString("comment", "Median seconds a CI job spends executing, queue time excluded. " + + "Written by Sources/Utils/Utils/CiTiming.cs; see its remarks."); + writer.WriteString("recorded", runs.Max(r => r.Created).ToString("yyyy-MM-dd")); + WriteJobs(writer, measured.ToDictionary(Key, s => s.Exec)); + + writer.WriteStartArray("history"); + if (previous is { } p) + foreach (var snapshot in p.History.Append(p.Latest)) + { + writer.WriteStartObject(); + writer.WriteString("recorded", snapshot.Recorded); + WriteJobs(writer, snapshot.Jobs); + writer.WriteEndObject(); + } + writer.WriteEndArray(); + writer.WriteEndObject(); + } + + private static void WriteJobs(Utf8JsonWriter writer, Dictionary jobs) + { + writer.WriteStartObject("jobs"); + foreach (var (key, seconds) in jobs.OrderBy(j => j.Key, StringComparer.Ordinal)) + writer.WriteNumber(key, Math.Round(seconds, 1)); + writer.WriteEndObject(); + } + + /// Runs gh and hands back stdout, or null with a reason logged. + private static string? Gh(string arguments) + { + try + { + using var process = Process.Start(new ProcessStartInfo("gh", arguments) + { + RedirectStandardOutput = true, + RedirectStandardError = true, + }); + if (process is null) { Log("could not start gh"); return null; } + + var stdout = process.StandardOutput.ReadToEnd(); + var stderr = process.StandardError.ReadToEnd(); + process.WaitForExit(); + if (process.ExitCode is not 0) + { + Log($"gh {arguments.Split(' ')[0]} exited {process.ExitCode}: {stderr.Trim()}"); + return null; + } + return stdout; + } + catch (Exception e) + { + Log("gh could not be run: " + e.Message); + return null; + } + } + } +} diff --git a/Sources/Utils/ci-baseline.json b/Sources/Utils/ci-baseline.json new file mode 100644 index 000000000..390287922 --- /dev/null +++ b/Sources/Utils/ci-baseline.json @@ -0,0 +1,69 @@ +{ + "comment": "Median seconds a CI job spends executing, queue time excluded. Written by Sources/Utils/Utils/CiTiming.cs; see its remarks.", + "recorded": "2026-08-09", + "jobs": { + "C# Test / Test (macos-latest)": 630.5, + "C# Test / Test (ubuntu-latest)": 597.5, + "C# Test / Test (windows-latest)": 807, + "C#/Kernel Build / AngouriMath (macos-latest)": 39.5, + "C#/Kernel Build / AngouriMath (ubuntu-latest)": 57, + "C#/Kernel Build / AngouriMath (windows-latest)": 105, + "C++ Test / Testing (macos-latest, osx-arm64)": 61, + "C++ Test / Testing (ubuntu-latest, linux-x64)": 76, + "C++ Test / Testing (windows-latest, win-x64)": 160.5, + "F# Build / Test (macos-latest)": 32, + "F# Build / Test (ubuntu-latest)": 40, + "F# Build / Test (windows-latest)": 87, + "F# Test / Test (macos-latest)": 69.5, + "F# Test / Test (ubuntu-latest)": 94.5, + "F# Test / Test (windows-latest)": 149.5, + "Integration Test / ClassLibConsoleApp": 125, + "Integration Test / ConsoleApp": 123.5, + "Interactive Build / Test (macos-latest)": 43.5, + "Interactive Build / Test (ubuntu-latest)": 47, + "Interactive Build / Test (windows-latest)": 112.5, + "Interactive Test / Test (macos-latest)": 68, + "Interactive Test / Test (ubuntu-latest)": 117, + "Interactive Test / Test (windows-latest)": 202, + "Kernel Benchmark / Benchmark": 568, + "Solution Build / Everything": 145.5 + }, + "history": [ + { + "recorded": "2026-01-22", + "jobs": { + "C# Test / Test (macos-latest)": 548.0, + "C# Test / Test (ubuntu-latest)": 382.5, + "C# Test / Test (windows-latest)": 530.0, + "C#/Kernel Build / AngouriMath (macos-latest)": 45.0, + "C#/Kernel Build / AngouriMath (ubuntu-latest)": 35.0, + "C#/Kernel Build / AngouriMath (windows-latest)": 96.5, + "C++ Test / Testing (macos-latest, osx-arm64)": 66.5, + "C++ Test / Testing (ubuntu-latest, linux-x64)": 59.0, + "C++ Test / Testing (windows-latest, win-x64)": 147.0, + "Copilot code review / Agent": 95.0, + "Copilot code review / Cleanup artifacts": 5.0, + "Copilot code review / CodeQL analysis (csharp)": 185.0, + "Copilot code review / Prepare": 5.0, + "Copilot code review / Upload results": 9.0, + "F# Build / Test (macos-latest)": 44.0, + "F# Build / Test (ubuntu-latest)": 35.0, + "F# Build / Test (windows-latest)": 99.5, + "F# Test / Test (macos-latest)": 87.0, + "F# Test / Test (ubuntu-latest)": 76.0, + "F# Test / Test (windows-latest)": 158.5, + "Integration Test / ClassLibConsoleApp": 127.0, + "Integration Test / ConsoleApp": 109.5, + "Interactive Build / Test (macos-latest)": 46.5, + "Interactive Build / Test (ubuntu-latest)": 42.0, + "Interactive Build / Test (windows-latest)": 114.0, + "Interactive Test / Test (macos-latest)": 97.5, + "Interactive Test / Test (ubuntu-latest)": 87.5, + "Interactive Test / Test (windows-latest)": 186.0, + "Solution Build / Everything": 143.0, + "Upload to MyGet / publish": 111.0, + "Upload to NuGet / publish": 97.0 + } + } + ] +}