|
| 1 | +// |
| 2 | +// Copyright (c) 2019-2026 Angouri. |
| 3 | +// AngouriMath is licensed under MIT. |
| 4 | +// Details: https://github.com/asc-community/AngouriMath/blob/master/LICENSE.md. |
| 5 | +// Website: https://am.angouri.org. |
| 6 | +// |
| 7 | + |
| 8 | +using System; |
| 9 | +using System.Collections.Generic; |
| 10 | +using System.Diagnostics; |
| 11 | +using System.Globalization; |
| 12 | +using System.IO; |
| 13 | +using System.Linq; |
| 14 | +using System.Text.Encodings.Web; |
| 15 | +using System.Text.Json; |
| 16 | + |
| 17 | +namespace Utils |
| 18 | +{ |
| 19 | + /// <summary> |
| 20 | + /// How long CI takes, and whether that has changed. |
| 21 | + /// </summary> |
| 22 | + /// <remarks> |
| 23 | + /// <para> |
| 24 | + /// Run with <c>dotnet run CiTiming</c> from <c>Sources/Utils/Utils</c>. Requires the |
| 25 | + /// GitHub CLI (<c>gh</c>) to be installed and authenticated; it is the only thing here |
| 26 | + /// that knows how to talk to the API, and using it avoids a token in this repository. |
| 27 | + /// </para> |
| 28 | + /// <para> |
| 29 | + /// Two durations are reported per job and they answer different questions. <em>Exec</em> |
| 30 | + /// is from the moment a runner picks the job up to the moment it finishes, which is what |
| 31 | + /// changes when a test suite grows. <em>Queue</em> is from the run being created to a |
| 32 | + /// runner picking it up, which changes when several pull requests are in flight and says |
| 33 | + /// nothing about the code. Reporting only the sum of the two — which is what the web UI |
| 34 | + /// shows — makes a busy afternoon look like a performance regression. |
| 35 | + /// </para> |
| 36 | + /// <para> |
| 37 | + /// The baseline is committed rather than derived, because GitHub keeps run history for a |
| 38 | + /// bounded window and logs for ninety days. Without a file in the repository there is |
| 39 | + /// nothing left to compare against once that window passes, which is exactly the |
| 40 | + /// situation this was written in. |
| 41 | + /// </para> |
| 42 | + /// </remarks> |
| 43 | + public static class CiTiming |
| 44 | + { |
| 45 | + private const string Repo = "asc-community/AngouriMath"; |
| 46 | + |
| 47 | + /// <summary>How many runs to ask for. The API caps a page at a thousand.</summary> |
| 48 | + private const int RunsToFetch = 400; |
| 49 | + |
| 50 | + /// <summary>Runs per workflow to open up for per-job timings. Each costs a request.</summary> |
| 51 | + private const int JobSample = 10; |
| 52 | + |
| 53 | + /// <summary>Reported as a regression above this. Runner-to-runner noise is a few percent.</summary> |
| 54 | + private const double RegressionThreshold = 0.15; |
| 55 | + |
| 56 | + private static void Log(string msg) => Console.WriteLine("CiTiming: " + msg); |
| 57 | + |
| 58 | + public static void Do() |
| 59 | + { |
| 60 | + var baselinePath = Path.Join(Program.GetPathIntoSources(), "Utils", "ci-baseline.json"); |
| 61 | + var recording = Environment.GetEnvironmentVariable("CI_TIMING_RECORD") == "1"; |
| 62 | + |
| 63 | + Log($"asking {Repo} for the last {RunsToFetch} runs"); |
| 64 | + var runs = FetchRuns(); |
| 65 | + if (runs.Count is 0) |
| 66 | + { |
| 67 | + Log("no successful runs came back — is gh installed and authenticated?"); |
| 68 | + return; |
| 69 | + } |
| 70 | + Log($"{runs.Count} successful runs, " |
| 71 | + + $"{runs.Min(r => r.Created):yyyy-MM-dd} to {runs.Max(r => r.Created):yyyy-MM-dd}"); |
| 72 | + |
| 73 | + var measured = Measure(runs); |
| 74 | + var baseline = recording ? null : ReadBaseline(baselinePath); |
| 75 | + Report(measured, baseline); |
| 76 | + |
| 77 | + if (recording) |
| 78 | + { |
| 79 | + WriteBaseline(baselinePath, measured, runs); |
| 80 | + Log($"baseline written to {baselinePath}"); |
| 81 | + } |
| 82 | + } |
| 83 | + |
| 84 | + private readonly record struct Run(long Id, string Workflow, DateTimeOffset Created); |
| 85 | + |
| 86 | + private readonly record struct JobTiming(string Workflow, string Job, double Exec, double Queue); |
| 87 | + |
| 88 | + /// <summary>Median exec and queue seconds for one workflow job, over the sample.</summary> |
| 89 | + private sealed record Stat(string Workflow, string Job, double Exec, double Queue, int Samples); |
| 90 | + |
| 91 | + private static List<Run> FetchRuns() |
| 92 | + { |
| 93 | + var json = Gh($"run list --repo {Repo} --limit {RunsToFetch} " |
| 94 | + + "--json name,conclusion,createdAt,databaseId"); |
| 95 | + if (json is null) return new List<Run>(); |
| 96 | + |
| 97 | + var runs = new List<Run>(); |
| 98 | + foreach (var element in JsonDocument.Parse(json).RootElement.EnumerateArray()) |
| 99 | + { |
| 100 | + // Only successful runs: a run that failed stopped early, so its duration is |
| 101 | + // the duration of getting to the failure and not of the work. |
| 102 | + if (element.GetProperty("conclusion").GetString() != "success") continue; |
| 103 | + runs.Add(new Run( |
| 104 | + element.GetProperty("databaseId").GetInt64(), |
| 105 | + element.GetProperty("name").GetString() ?? "?", |
| 106 | + DateTimeOffset.Parse(element.GetProperty("createdAt").GetString()!, |
| 107 | + CultureInfo.InvariantCulture))); |
| 108 | + } |
| 109 | + return runs; |
| 110 | + } |
| 111 | + |
| 112 | + private static List<Stat> Measure(List<Run> runs) |
| 113 | + { |
| 114 | + var timings = new List<JobTiming>(); |
| 115 | + foreach (var workflow in runs.Select(r => r.Workflow).Distinct().OrderBy(n => n, StringComparer.Ordinal)) |
| 116 | + { |
| 117 | + // Newest first, so the answer is about the code as it stands. |
| 118 | + var sample = runs.Where(r => r.Workflow == workflow) |
| 119 | + .OrderByDescending(r => r.Created) |
| 120 | + .Take(JobSample) |
| 121 | + .ToList(); |
| 122 | + Log($" {workflow}: opening {sample.Count} runs"); |
| 123 | + foreach (var run in sample) |
| 124 | + timings.AddRange(JobsOf(run)); |
| 125 | + } |
| 126 | + |
| 127 | + return timings |
| 128 | + .GroupBy(t => (t.Workflow, t.Job)) |
| 129 | + .Select(g => new Stat(g.Key.Workflow, g.Key.Job, |
| 130 | + Median(g.Select(t => t.Exec)), Median(g.Select(t => t.Queue)), g.Count())) |
| 131 | + .OrderByDescending(s => s.Exec) |
| 132 | + .ToList(); |
| 133 | + } |
| 134 | + |
| 135 | + private static IEnumerable<JobTiming> JobsOf(Run run) |
| 136 | + { |
| 137 | + var json = Gh($"api /repos/{Repo}/actions/runs/{run.Id}/jobs?per_page=100"); |
| 138 | + if (json is null) yield break; |
| 139 | + |
| 140 | + JsonElement jobs; |
| 141 | + try |
| 142 | + { |
| 143 | + if (!JsonDocument.Parse(json).RootElement.TryGetProperty("jobs", out jobs)) yield break; |
| 144 | + } |
| 145 | + catch (JsonException) { yield break; } |
| 146 | + |
| 147 | + foreach (var job in jobs.EnumerateArray()) |
| 148 | + { |
| 149 | + var startedRaw = job.GetProperty("started_at").GetString(); |
| 150 | + var completedRaw = job.GetProperty("completed_at").GetString(); |
| 151 | + if (startedRaw is null || completedRaw is null) continue; |
| 152 | + |
| 153 | + var started = DateTimeOffset.Parse(startedRaw, CultureInfo.InvariantCulture); |
| 154 | + var completed = DateTimeOffset.Parse(completedRaw, CultureInfo.InvariantCulture); |
| 155 | + if (completed <= started) continue; |
| 156 | + |
| 157 | + yield return new JobTiming(run.Workflow, job.GetProperty("name").GetString() ?? "?", |
| 158 | + (completed - started).TotalSeconds, |
| 159 | + Math.Max(0, (started - run.Created).TotalSeconds)); |
| 160 | + } |
| 161 | + } |
| 162 | + |
| 163 | + private static void Report(List<Stat> measured, (Snapshot Latest, List<Snapshot> History)? baseline) |
| 164 | + { |
| 165 | + var latest = baseline?.Latest; |
| 166 | + // The oldest snapshot on file, so a slow drift over many small steps is visible. |
| 167 | + var oldest = baseline?.History.FirstOrDefault() ?? latest; |
| 168 | + |
| 169 | + Console.WriteLine(); |
| 170 | + var sinceHeader = oldest is null || oldest == latest ? "" : $"since {oldest.Recorded}"; |
| 171 | + Console.WriteLine($"{"workflow / job",-46}{"exec",8}{"queue",8}" |
| 172 | + + $"{(latest is null ? "" : latest.Recorded),12}{"change",9}{sinceHeader,17}"); |
| 173 | + Console.WriteLine(new string('-', 100)); |
| 174 | + |
| 175 | + var regressions = new List<string>(); |
| 176 | + foreach (var stat in measured) |
| 177 | + { |
| 178 | + var key = Key(stat); |
| 179 | + var line = $"{Truncate(key, 46),-46}{Minutes(stat.Exec),8}{Minutes(stat.Queue),8}"; |
| 180 | + |
| 181 | + if (latest is not null && latest.Jobs.TryGetValue(key, out var was) && was > 0) |
| 182 | + { |
| 183 | + var change = (stat.Exec - was) / was; |
| 184 | + line += $"{Minutes(was),12}{change,9:+0.0%;-0.0%;0.0%}"; |
| 185 | + if (change > RegressionThreshold) regressions.Add($"{key} {change:+0%}"); |
| 186 | + |
| 187 | + if (oldest is not null && oldest != latest |
| 188 | + && oldest.Jobs.TryGetValue(key, out var first) && first > 0) |
| 189 | + line += $"{(stat.Exec - first) / first,17:+0.0%;-0.0%;0.0%}"; |
| 190 | + } |
| 191 | + else if (latest is not null) |
| 192 | + line += $"{"new",12}"; |
| 193 | + |
| 194 | + Console.WriteLine(line); |
| 195 | + } |
| 196 | + |
| 197 | + Console.WriteLine(); |
| 198 | + // The jobs run in parallel, so what a contributor waits for is the slowest one, |
| 199 | + // not the sum. The sum is what the project costs the runner pool. |
| 200 | + if (measured.Count > 0) |
| 201 | + Log($"slowest job {Minutes(measured[0].Exec)} ({measured[0].Job} in {measured[0].Workflow}); " |
| 202 | + + $"{Minutes(measured.Sum(s => s.Exec))} of runner time per commit"); |
| 203 | + |
| 204 | + if (regressions.Count > 0) |
| 205 | + { |
| 206 | + Log($"{regressions.Count} job(s) above the {RegressionThreshold:P0} threshold since " |
| 207 | + + $"{latest!.Recorded}:"); |
| 208 | + foreach (var r in regressions) Log(" " + r); |
| 209 | + } |
| 210 | + else if (latest is not null) |
| 211 | + Log("nothing above the threshold"); |
| 212 | + } |
| 213 | + |
| 214 | + private static string Key(Stat s) => s.Workflow + " / " + s.Job; |
| 215 | + |
| 216 | + private static string Minutes(double seconds) => (seconds / 60).ToString("0.0", CultureInfo.InvariantCulture) + "m"; |
| 217 | + |
| 218 | + private static string Truncate(string s, int n) => s.Length <= n ? s : s[..(n - 1)] + "…"; |
| 219 | + |
| 220 | + private static double Median(IEnumerable<double> values) |
| 221 | + { |
| 222 | + var sorted = values.OrderBy(v => v).ToList(); |
| 223 | + if (sorted.Count is 0) return 0; |
| 224 | + return sorted.Count % 2 is 1 |
| 225 | + ? sorted[sorted.Count / 2] |
| 226 | + : (sorted[sorted.Count / 2 - 1] + sorted[sorted.Count / 2]) / 2; |
| 227 | + } |
| 228 | + |
| 229 | + /// <summary>One dated set of measurements: the current one, or an older one kept for history.</summary> |
| 230 | + private sealed record Snapshot(string Recorded, Dictionary<string, double> Jobs); |
| 231 | + |
| 232 | + private static (Snapshot Latest, List<Snapshot> History)? ReadBaseline(string path) |
| 233 | + { |
| 234 | + if (!File.Exists(path)) |
| 235 | + { |
| 236 | + Log($"no baseline at {path} — run with CI_TIMING_RECORD=1 to write one"); |
| 237 | + return null; |
| 238 | + } |
| 239 | + var root = JsonDocument.Parse(File.ReadAllText(path)).RootElement; |
| 240 | + var history = new List<Snapshot>(); |
| 241 | + if (root.TryGetProperty("history", out var past)) |
| 242 | + history.AddRange(past.EnumerateArray().Select(ReadSnapshot)); |
| 243 | + return (ReadSnapshot(root), history); |
| 244 | + } |
| 245 | + |
| 246 | + private static Snapshot ReadSnapshot(JsonElement element) |
| 247 | + => new(element.GetProperty("recorded").GetString() ?? "?", |
| 248 | + element.GetProperty("jobs").EnumerateObject() |
| 249 | + .ToDictionary(p => p.Name, p => p.Value.GetDouble())); |
| 250 | + |
| 251 | + /// <summary> |
| 252 | + /// Keeps every earlier snapshot. GitHub drops run history after a bounded window and |
| 253 | + /// logs after ninety days, so a measurement that is not written down here cannot be |
| 254 | + /// recovered later — which is how the January 2026 numbers were nearly lost. |
| 255 | + /// </summary> |
| 256 | + private static void WriteBaseline(string path, List<Stat> measured, List<Run> runs) |
| 257 | + { |
| 258 | + var previous = ReadBaseline(path); |
| 259 | + |
| 260 | + using var stream = File.Create(path); |
| 261 | + using var writer = new Utf8JsonWriter(stream, new JsonWriterOptions |
| 262 | + { |
| 263 | + Indented = true, |
| 264 | + Encoder = JavaScriptEncoder.UnsafeRelaxedJsonEscaping, // so "C++ Test" reads as itself |
| 265 | + }); |
| 266 | + writer.WriteStartObject(); |
| 267 | + writer.WriteString("comment", "Median seconds a CI job spends executing, queue time excluded. " |
| 268 | + + "Written by Sources/Utils/Utils/CiTiming.cs; see its remarks."); |
| 269 | + writer.WriteString("recorded", runs.Max(r => r.Created).ToString("yyyy-MM-dd")); |
| 270 | + WriteJobs(writer, measured.ToDictionary(Key, s => s.Exec)); |
| 271 | + |
| 272 | + writer.WriteStartArray("history"); |
| 273 | + if (previous is { } p) |
| 274 | + foreach (var snapshot in p.History.Append(p.Latest)) |
| 275 | + { |
| 276 | + writer.WriteStartObject(); |
| 277 | + writer.WriteString("recorded", snapshot.Recorded); |
| 278 | + WriteJobs(writer, snapshot.Jobs); |
| 279 | + writer.WriteEndObject(); |
| 280 | + } |
| 281 | + writer.WriteEndArray(); |
| 282 | + writer.WriteEndObject(); |
| 283 | + } |
| 284 | + |
| 285 | + private static void WriteJobs(Utf8JsonWriter writer, Dictionary<string, double> jobs) |
| 286 | + { |
| 287 | + writer.WriteStartObject("jobs"); |
| 288 | + foreach (var (key, seconds) in jobs.OrderBy(j => j.Key, StringComparer.Ordinal)) |
| 289 | + writer.WriteNumber(key, Math.Round(seconds, 1)); |
| 290 | + writer.WriteEndObject(); |
| 291 | + } |
| 292 | + |
| 293 | + /// <summary>Runs <c>gh</c> and hands back stdout, or null with a reason logged.</summary> |
| 294 | + private static string? Gh(string arguments) |
| 295 | + { |
| 296 | + try |
| 297 | + { |
| 298 | + using var process = Process.Start(new ProcessStartInfo("gh", arguments) |
| 299 | + { |
| 300 | + RedirectStandardOutput = true, |
| 301 | + RedirectStandardError = true, |
| 302 | + }); |
| 303 | + if (process is null) { Log("could not start gh"); return null; } |
| 304 | + |
| 305 | + var stdout = process.StandardOutput.ReadToEnd(); |
| 306 | + var stderr = process.StandardError.ReadToEnd(); |
| 307 | + process.WaitForExit(); |
| 308 | + if (process.ExitCode is not 0) |
| 309 | + { |
| 310 | + Log($"gh {arguments.Split(' ')[0]} exited {process.ExitCode}: {stderr.Trim()}"); |
| 311 | + return null; |
| 312 | + } |
| 313 | + return stdout; |
| 314 | + } |
| 315 | + catch (Exception e) |
| 316 | + { |
| 317 | + Log("gh could not be run: " + e.Message); |
| 318 | + return null; |
| 319 | + } |
| 320 | + } |
| 321 | + } |
| 322 | +} |
0 commit comments