diff --git a/.github/workflows/tests.yml b/.github/workflows/tests.yml index d266c125d..65e7c6d65 100644 --- a/.github/workflows/tests.yml +++ b/.github/workflows/tests.yml @@ -89,69 +89,16 @@ jobs: - CIAotSmoke # NOTE: CISlowTests is deliberately NOT here. It is wall-clock bound by design and blew # through the 20 minute cap on its first run; it lives in slow-tests.yml as a manual job. - include: - # This sampler was added after CIMarten was twice killed outright by the runner ~15 minutes - # in ("The runner has received a shutdown signal"), on unrelated diffs, at almost exactly - # the same elapsed time both times -- read at the time as the VM running out of memory. - # See #3771. - # - # IT IS NOT OOM. The sampler caught the recurrence on 2026-08-24 (run 32683981250, job - # 97305549745) and disproved that reading outright: the last several minutes of samples are - # BYTE-IDENTICAL every 15 seconds -- ~13.7GB available, swap_used=0, the MartenTests process - # pinned at 1160MB and not growing. Nothing was starved. The process was idle and making no - # progress, and the job hit this workflow's 20 minute cap at 20m16s. - # - # Two things that cost real time to re-derive, so do not re-derive them: - # * The job's API conclusion is `cancelled`, NOT `failure`, and no step is marked failed. - # `gh pr checks` renders a cancelled job as `fail`, which reads as a test failure and is - # not one. Confirm with - # `gh api repos/JasperFx/wolverine/actions/jobs/ --jq '"\(.status) \(.conclusion)"'`. - # * A capped job uploads NO ledger and prints no summary, so the flakiness roll-up reports - # it as unmeasured rather than as clean. - # - # So the sampler now also carries a stall watchdog (see build/ci-memory-sampler.sh): flat - # memory alone was never actionable, because Bobcat 0.6.1 reports per-test results only when - # a batch finishes and a batch that never finishes prints nothing. The watchdog captures the - # wedged process's async stacks itself, before the cap can take them. Tracked in #4083. - # - # THE SAMPLER NOW RUNS ON EVERY TARGET, so there is no per-target flag here any more. It - # costs a `free`/`ps` pair every 15 seconds and installs nothing unless it actually fires. - # It was widened because #4089 -- MartenTests retains ~35MB per test and a GREEN CIMarten - # ends with 243MB free on a 16GB runner -- cannot be answered for the other suites without - # measuring them, and the suites that hold the most memory are not necessarily the ones - # that take the longest. - # - # What IS per-target is the watchdog's unconditional deadline, and it has to be, because - # the honest runtime of the heaviest suites already runs past it. Measured over 12 green - # `main` runs (max of 12): - # - # CIRabbitMQ 859s CIEfCore 821s CISqlServer 810s CIPersistence 807s - # CIPubsub 779s CIAzureServiceBus 775s CIRedis 629s CIKafka 625s - # - # ...against a 780s default. On these there is no daylight between "healthy" and "about to - # be capped" for a time trigger to sit in, and a spurious capture costs ~2 minutes inside a - # 20 minute cap on a job already at 14 -- it would turn a green job red. So they set the - # deadline to 0 and run the idle detector alone, which does not care how long a suite - # takes: a healthy suite is never idle for five minutes. - # - # Re-measure before trusting these numbers; they are a snapshot of 2026-08-24. Anything - # whose green max climbs past ~620s belongs on this list. - - target: CIRabbitMQ - stall_deadline: 0 - - target: CIEfCore - stall_deadline: 0 - - target: CISqlServer - stall_deadline: 0 - - target: CIPersistence - stall_deadline: 0 - - target: CIPubsub - stall_deadline: 0 - - target: CIAzureServiceBus - stall_deadline: 0 - - target: CIRedis - stall_deadline: 0 - - target: CIKafka - stall_deadline: 0 + # HISTORY: from 2026-08 to 2026-08-24 an `include:` block here carried per-target + # stall_deadline overrides for build/ci-memory-sampler.sh — a shell watchdog that sampled + # RSS from outside the process, guessed which pid was the test host, inferred stalls from + # flat memory + idle CPU, and captured async stacks before the cap could take them + # (#3771, #4083, #4089). Retired when Bobcat 0.8.0 moved all of it inside the supervisor + # (JasperFx/bobcat#145-#150), which states as facts what the watchdog inferred: the TEST + # in flight past its budget (named at +5 minutes, per test — no per-target deadline table + # to maintain), a 30s progress heartbeat, per-test RSS attribution, the pre-kill dump + # seam, and a partial ledger written on cancellation so a capped job is no longer + # unmeasured. See build/SupervisedTests.cs and build/StallCapture.cs. steps: - name: Checkout @@ -166,21 +113,10 @@ jobs: - name: Run Tests env: - # Empty for every target that does not override it, which the sampler reads as its default. - STALL_DEADLINE_SECONDS: ${{ matrix.stall_deadline }} # Names this job in the retry ledger (build/RetryLedger.cs). GITHUB_JOB is the matrix's # job id -- the same string, "test", for all thirty of these -- so it cannot be used. CI_JOB_NAME: ${{ matrix.target }} - run: | - # The sampler has to live inside this step: when the runner is killed, later steps are - # skipped, so only what has already been streamed to this step's log survives. See #3771. - # It must also be backgrounded from THIS shell -- it picks the process to watch out of its - # own parent's process tree, which is how it tells the test host from a service container. - ./build/ci-memory-sampler.sh & - sampler_pid=$! - trap 'kill "${sampler_pid}" 2>/dev/null || true' EXIT - - ./build.sh ${{ matrix.target }} --framework net9.0 + run: ./build.sh ${{ matrix.target }} --framework net9.0 # Only reachable when the runner itself survived. If the OOM killer took a *test* process # rather than the runner service, the kill is recorded here and nowhere else. diff --git a/Directory.Packages.props b/Directory.Packages.props index 4189d56af..a76c37148 100644 --- a/Directory.Packages.props +++ b/Directory.Packages.props @@ -39,8 +39,10 @@ - + honest retry reporting, and — since 0.8.0 — stall detection, heartbeats, RSS sampling, + the pre-kill dump seam and partial results on cancellation (build/StallCapture.cs). + Referenced ONLY by the build project. --> + diff --git a/build/RetryLedger.cs b/build/RetryLedger.cs index c7c516d4b..0ad99df92 100644 --- a/build/RetryLedger.cs +++ b/build/RetryLedger.cs @@ -69,7 +69,16 @@ void recordLedger(string projectName, string framework, SupervisorResults result // Bounded by the budget itself: the point of the list is to name the suspects, not to // reproduce the log. FlakyTests = results.PassedOnRetry.Select(x => x.DisplayName).Take(MaxRetriesPerRun).ToArray(), - FlakyFailures = results.PassedOnRetry.Take(MaxRetriesPerRun).Select(firstFailure).ToArray() + FlakyFailures = results.PassedOnRetry.Take(MaxRetriesPerRun).Select(firstFailure).ToArray(), + // The observability cluster's facts (Bobcat 0.8.0). IsPartial marks a ledger written + // by the cancellation handler — the run so far, not a verdict; StalledTests carries + // the names a capped job's log used to take to its grave (GH-4083); PeakWorkerRssMb + // is the GH-4089 figure, per job instead of per shell-sampler scrape. + IsPartial = results.IsPartial, + Stalled = results.StalledTests.Count, + StalledTests = results.StalledTests.Select(x => x.DisplayName).Distinct() + .Take(MaxRetriesPerRun).ToArray(), + PeakWorkerRssMb = RunResources.For(results).PeakBytes is { } peak ? peak / (1024 * 1024) : null }; writeLedgerFile(entry); @@ -320,6 +329,22 @@ static void appendStepSummary(LedgerEntry entry) builder.AppendLine($"> **ABORTED** — {entry.AbortReason}"); } + if (entry.IsPartial) + { + builder.AppendLine(); + builder.AppendLine( + "> **PARTIAL** — the job was cancelled mid-run. These counts are the run so far; " + + "tests without a verdict are counted Indeterminate, not failed."); + } + + if (entry.StalledTests.Length > 0) + { + builder.AppendLine(); + builder.AppendLine( + "> **Stalled (in flight past the 5-minute threshold):** " + + string.Join(", ", entry.StalledTests.Select(t => $"`{t}`"))); + } + if (entry.FlakyTests.Length > 0) { builder.AppendLine(); @@ -366,18 +391,37 @@ static void appendStepSummary(LedgerEntry entry) static void annotate(LedgerEntry entry) { if (Environment.GetEnvironmentVariable("GITHUB_ACTIONS") != "true") return; - if (entry.RetriesPerformed == 0) return; - var suspects = entry.FlakyTests.Length > 0 - ? $" First flaky test: {entry.FlakyTests[0]}." - : ""; + // Workflow commands are newline-delimited, so every message has to be a single line. - // Workflow commands are newline-delimited, so the message has to be a single line. - Console.WriteLine( - $"::warning title={entry.Job}: {entry.RetriesPerformed} retries::" + - $"{entry.Project} ({entry.Framework}) spent {entry.RetriesPerformed} of its " + - $"{MaxRetriesPerRun}-retry budget; " + - $"{entry.PassedOnRetry} test(s) passed only on a retry.{suspects}"); + if (entry.RetriesPerformed > 0) + { + var suspects = entry.FlakyTests.Length > 0 + ? $" First flaky test: {entry.FlakyTests[0]}." + : ""; + + Console.WriteLine( + $"::warning title={entry.Job}: {entry.RetriesPerformed} retries::" + + $"{entry.Project} ({entry.Framework}) spent {entry.RetriesPerformed} of its " + + $"{MaxRetriesPerRun}-retry budget; " + + $"{entry.PassedOnRetry} test(s) passed only on a retry.{suspects}"); + } + + if (entry.Stalled > 0) + { + Console.WriteLine( + $"::warning title={entry.Job}: {entry.Stalled} stalled test(s)::" + + $"{entry.Project} ({entry.Framework}) had test(s) in flight past the 5-minute " + + $"stall threshold. First: {entry.StalledTests[0]}."); + } + + if (entry.IsPartial) + { + Console.WriteLine( + $"::warning title={entry.Job}: partial results::" + + $"{entry.Project} ({entry.Framework}) was cancelled mid-run; the uploaded ledger " + + "holds the run so far, with unverdicted tests counted Indeterminate."); + } } static readonly JsonSerializerOptions LedgerJson = new() { WriteIndented = true }; @@ -417,6 +461,27 @@ class LedgerEntry /// ledger written before the field existed. See GH-3855. /// public ServiceRestart[] ServiceRestarts { get; init; } = []; + + // The Bobcat 0.8.0 observability fields. All additive and defaulted — the roll-up's jq + // reads them with `// 0` / `// false` / `// []` for the same baseline reason as above. + + /// + /// True when this ledger came from the cancellation handler's Supervisor.Snapshot() — + /// the run so far, not a verdict. A partial ledger's counts are honest but incomplete, + /// and its Indeterminate column includes every test the run never got to. + /// + public bool IsPartial { get; init; } + + /// Tests reported in flight past the stall threshold, whether or not they finished. + public int Stalled { get; init; } + + public string[] StalledTests { get; init; } = []; + + /// + /// The highest worker RSS the supervisor sampled, in MB. Null when unmeasured — never + /// zero, so "no memory data" can never read as "used no memory". + /// + public long? PeakWorkerRssMb { get; init; } } /// diff --git a/build/StallCapture.cs b/build/StallCapture.cs new file mode 100644 index 000000000..eb74b5bb3 --- /dev/null +++ b/build/StallCapture.cs @@ -0,0 +1,221 @@ +using System; +using System.Diagnostics; +using System.IO; +using System.Runtime.InteropServices; +using System.Threading; +using System.Threading.Tasks; +using Bobcat.Supervisor; +using Serilog; + +// The successor to build/ci-memory-sampler.sh (GH-4083/GH-4089), retired when Bobcat 0.8.0 moved +// stall detection, RSS sampling and the pre-kill diagnostic seam inside the supervisor +// (JasperFx/bobcat#145-#150). What the shell watchdog had to approximate from outside the process +// — guessing which pid was the test host, inferring a stall from flat RSS and idle CPU — the +// supervisor now states as facts: which TEST is in flight past its budget, in which lane, in which +// pid. What stays here is the part Bobcat deliberately does not ship: the dotnet-dump capture +// (the consumer knows what it wants to capture and how long it can afford), and the cancellation +// handler that writes the partial ledger a capped job used to take to its grave. +// +// Output contract carried over from the sampler: diagnostics go to STDOUT prefixed `[stall]`, +// never inside a ::group:: — a cancelled job skips later steps, and an unclosed group hides its +// contents. Retrieval: `gh run view --log | grep '\[stall\]'`. +partial class Build +{ + /// + /// Invoked by the supervisor with a live worker immediately before it is forcibly killed — + /// a worker that would not exit when asked, or one that never became usable. The useful + /// artifact for a hung .NET process is the async "stack" on its GC heap, not any thread's + /// stack: `dumpasync --coalesce` is what diagnosed the wedged Pulsar producers in GH-4100. + /// + static Task captureBeforeKill(WorkerKillContext context) + { + if (context.ProcessId is { } pid) + { + Console.WriteLine( + $"[stall] a live worker (pid {pid}) is about to be killed — {context.Reason}. " + + "Capturing its async stacks first."); + captureAsyncStacks(pid); + } + + return Task.CompletedTask; + } + + /// + /// GH-4098 / JasperFx/bobcat#150: a job killed at the 20-minute cap used to report nothing — + /// Bobcat printed its summary only at the end, GitHub discards a cancelled job's logs, and + /// the flakiness roll-up called the job "unmeasured". Registers SIGTERM/SIGINT handlers for + /// the duration of one supervised run: snapshot → partial ledger → name the stalled tests → + /// best-effort async stacks → exit 2. The ledger write comes first because it is fast and + /// must land inside whatever grace the runner grants; the dumps are gravy that may be cut + /// short by the hard kill. + /// + IDisposable registerCancellationCapture(Supervisor supervisor, string projectName, string framework) + { + // Only under Actions: locally Ctrl-C should stay an ordinary Ctrl-C. + if (Environment.GetEnvironmentVariable("GITHUB_ACTIONS") != "true") return null; + + var fired = 0; + + void handle(PosixSignalContext context) + { + context.Cancel = true; + if (Interlocked.Exchange(ref fired, 1) != 0) return; + + Console.WriteLine( + "[stall] cancellation signal received — writing the partial ledger before the runner " + + "discards the run"); + + try + { + var snapshot = supervisor.Snapshot(); + recordLedger(projectName, framework, snapshot); + Log.Warning("=== {Project}: {Summary} ===", projectName, snapshot.Summarize()); + + foreach (var stalled in snapshot.StalledTests) + { + Console.WriteLine( + $"[stall] stalled at cancellation: {stalled.DisplayName} " + + $"({(int)stalled.InFlight.TotalSeconds}s in flight, lane {stalled.Worker.Lane}, " + + $"pid {stalled.Worker.ProcessId?.ToString() ?? "unknown"})"); + } + + foreach (var stalled in snapshot.StalledTests) + { + if (stalled.Worker.ProcessId is { } pid) captureAsyncStacks(pid); + } + } + catch (Exception e) + { + Console.WriteLine($"[stall] cancellation capture failed: {e.Message}"); + } + + Environment.Exit(2); + } + + return new SignalRegistrations( + PosixSignalRegistration.Create(PosixSignal.SIGTERM, handle), + PosixSignalRegistration.Create(PosixSignal.SIGINT, handle)); + } + + sealed class SignalRegistrations(params IDisposable[] registrations) : IDisposable + { + public void Dispose() + { + foreach (var registration in registrations) registration.Dispose(); + } + } + + // ─── The dotnet-dump pipeline, ported from the sampler's async_stacks() ─── + + /// Lines of `dumpasync --coalesce` output kept — same bound the sampler used. + const int StallDumpLines = 400; + + static void captureAsyncStacks(int pid) + { + try + { + var tool = ensureDotnetDump(); + if (tool is null) + { + Console.WriteLine("[stall] dotnet-dump is unavailable and could not be installed — no capture"); + return; + } + + var dump = Path.Combine(Path.GetTempPath(), $"wolverine-stall-{pid}.dmp"); + + if (!runTool(tool, $"collect -p {pid} -o {dump}", input: null, + TimeSpan.FromSeconds(240), out var collectOutput)) + { + Console.WriteLine($"[stall] dotnet-dump collect failed for pid {pid}: {condense(collectOutput)}"); + return; + } + + if (!runTool(tool, $"analyze {dump}", input: "dumpasync --coalesce\nexit\n", + TimeSpan.FromSeconds(300), out var stacks)) + { + Console.WriteLine($"[stall] dumpasync failed for pid {pid}: {condense(stacks)}"); + } + else + { + Console.WriteLine($"[stall] === async stacks of pid {pid} (dumpasync --coalesce) ==="); + var lines = stacks.Split('\n'); + foreach (var line in lines.AsSpan(0, Math.Min(lines.Length, StallDumpLines))) + { + Console.WriteLine($"[stall] {line.TrimEnd()}"); + } + + if (lines.Length > StallDumpLines) + Console.WriteLine($"[stall] … {lines.Length - StallDumpLines} more line(s) elided"); + } + + try { File.Delete(dump); } catch { /* tmp cleanup only */ } + } + catch (Exception e) + { + Console.WriteLine($"[stall] async-stack capture for pid {pid} failed: {e.Message}"); + } + } + + /// + /// Finds dotnet-dump, installing it as a global tool on first use — the sampler did the + /// same, lazily, so a run that never wedges never pays for it. + /// + static string ensureDotnetDump() + { + if (runTool("dotnet-dump", "--version", null, TimeSpan.FromSeconds(10), out _)) return "dotnet-dump"; + + runTool("dotnet", "tool install -g dotnet-dump", null, TimeSpan.FromSeconds(120), out _); + + if (runTool("dotnet-dump", "--version", null, TimeSpan.FromSeconds(10), out _)) return "dotnet-dump"; + + // Fresh installs land in ~/.dotnet/tools, which may not be on this process's PATH. + var installed = Path.Combine( + Environment.GetFolderPath(Environment.SpecialFolder.UserProfile), ".dotnet", "tools", + OperatingSystem.IsWindows() ? "dotnet-dump.exe" : "dotnet-dump"); + + return File.Exists(installed) ? installed : null; + } + + /// Runs one bounded external command; overrunning the budget kills the tree. + static bool runTool(string fileName, string arguments, string input, TimeSpan budget, out string output) + { + output = ""; + try + { + using var process = new Process(); + process.StartInfo = new ProcessStartInfo(fileName, arguments) + { + RedirectStandardOutput = true, + RedirectStandardError = true, + RedirectStandardInput = input is not null, + UseShellExecute = false + }; + + if (!process.Start()) return false; + + if (input is not null) + { + process.StandardInput.Write(input); + process.StandardInput.Close(); + } + + var stdout = process.StandardOutput.ReadToEndAsync(); + var stderr = process.StandardError.ReadToEndAsync(); + + if (!process.WaitForExit((int)budget.TotalMilliseconds)) + { + try { process.Kill(entireProcessTree: true); } catch { } + output = "timed out"; + return false; + } + + output = stdout.GetAwaiter().GetResult() + stderr.GetAwaiter().GetResult(); + return process.ExitCode == 0; + } + catch (Exception e) + { + output = e.Message; + return false; + } + } +} diff --git a/build/SupervisedTests.cs b/build/SupervisedTests.cs index e764f9017..5a4b3d010 100644 --- a/build/SupervisedTests.cs +++ b/build/SupervisedTests.cs @@ -137,7 +137,13 @@ bool runSupervised(string projectPath, string framework, Func var factory = new MtpWorkerFactory(executable) { - EnvironmentFor = laneEnvironment(workers, postgresDatabasePerLane, sqlServerDatabasePerLane) + EnvironmentFor = laneEnvironment(workers, postgresDatabasePerLane, sqlServerDatabasePerLane), + // A wedged worker's state stops existing the moment it is killed (GH-4100): this + // hook gets the live pid first, and the dumpasync capture is the diagnosis. Only + // ever invoked for a live process that refused to exit — a healthy worker never + // pays for it. The budget covers dotnet-dump collect + analyze. + OnBeforeKill = captureBeforeKill, + BeforeKillTimeout = TimeSpan.FromMinutes(10) }; var supervisor = new Supervisor(factory) @@ -151,7 +157,24 @@ bool runSupervised(string projectPath, string framework, Func // released before they run: without this, workers+1 test hosts sit resident at once, // which OOM-killed 16GB GitHub runners twice — both times during a retry. ReleaseIdleLanes = true, - Log = message => Log.Information(" {Message}", message) + Log = message => Log.Information(" {Message}", message), + + // The observability the retired shell watchdog (build/ci-memory-sampler.sh, + // GH-4083/GH-4089) approximated from outside the process, now the supervisor's own + // facts (Bobcat 0.8.0, JasperFx/bobcat#145-#150). All report-only — none of these + // ever fails or kills anything: + // - a TEST in flight past five minutes is named immediately. Five minutes is the + // watchdog's own calibration ("a healthy suite is never idle for five minutes"), + // and per-test in-flight time replaces both its idle heuristic and the per-target + // deadline table that heavy suites kept having to opt out of. + // - a one-line progress heartbeat every 30s, so a wedged run's log shows where it + // stopped and how far it got — the summary a capped job never reaches. + // - worker RSS sampled on the watchdog's own 15s cadence, attributed per test + // (GH-4089: a GREEN CIMarten grew its host 375MB -> 9334MB and nothing could say + // which tests grew it). + StallThreshold = TimeSpan.FromMinutes(5), + HeartbeatInterval = TimeSpan.FromSeconds(30), + ResourceSampleInterval = TimeSpan.FromSeconds(15) }; if (!DisableTestRetry) supervisor.AddFailurePolicy(new RetryFailuresInFreshProcess()); @@ -162,6 +185,11 @@ bool runSupervised(string projectPath, string framework, Func if (Environment.GetEnvironmentVariable("GITHUB_ACTIONS") == "true") supervisor.AddObserver(new NarrateTestsAsTheyStart()); + // GH-4098: a job cancelled at the cap used to report nothing at all. The registration + // snapshots the run, writes the partial ledger and names the stalled tests inside the + // runner's grace window — see build/StallCapture.cs. + using var cancellation = registerCancellationCapture(supervisor, projectName, framework); + var results = supervisor.Run().GetAwaiter().GetResult(); return report(projectName, framework, results, shardFilter is not null); @@ -197,9 +225,10 @@ public Disposition Decide(AttemptContext attempt) /// The supervisor reports per-test results when a batch FINISHES. A batch that wedges never /// finishes, so it reports nothing at all: on JasperFx/wolverine#4083 a CIMarten job's last /// line was "275 test(s): 275 batched, 0 isolated", printed 18m33s before the 20 minute cap - /// cancelled the job, and the log could not name the test that hung. This is the cheap half of - /// the fix — the sampler's stack dump (build/ci-memory-sampler.sh) is the evidence, this is the - /// bookmark that says where to look. + /// cancelled the job, and the log could not name the test that hung. Since Bobcat 0.8.0 the + /// supervisor's own stall reporting and heartbeat carry the run-level view (STALLED lines and + /// the progress line arrive through Log above); this narration stays as the per-test bookmark + /// that says exactly what each lane picked up, in order. /// /// /// In-progress updates only. The terminal update carries the same verdict the end-of-run @@ -249,6 +278,23 @@ bool report(string projectName, string framework, SupervisorResults results, boo foreach (var fault in results.WorkerFaults) Log.Error(" [WORKER FAULT] {Fault}", fault); + // Report-only, like everything else the stall threshold does: a test that exceeded five + // minutes and then passed is still worth a line — a green run is exactly where a + // creeping slowdown would otherwise go unnoticed. + foreach (var stalled in results.StalledTests) + Log.Warning(" [STALLED] {Test} — {Seconds}s in flight on lane {Lane}", + stalled.DisplayName, (int)stalled.InFlight.TotalSeconds, stalled.Worker.Lane); + + var memory = RunResources.For(results); + if (memory.IsMeasured) + { + Log.Information(" peak worker RSS {Peak}; top retainer: {Retainer}", + RunResources.Humanize(memory.PeakBytes!.Value), + memory.TopRetainers(1) is [{ } top] + ? $"{RunResources.Delta(top.RetainedBytes!.Value)} {top.DisplayName}" + : "(none attributed)"); + } + foreach (var test in results.Indeterminate) Log.Error(" [INDETERMINATE] {Test} — {Error}", test.DisplayName, test.Final.Outcome.ErrorMessage); diff --git a/build/ci-memory-sampler.sh b/build/ci-memory-sampler.sh deleted file mode 100755 index 1f40cfe25..000000000 --- a/build/ci-memory-sampler.sh +++ /dev/null @@ -1,242 +0,0 @@ -#!/usr/bin/env bash -# -# Samples memory pressure to stdout while a CI test target runs, and -- when the target stops -# making progress -- captures the async stacks of the wedged process before the 20 minute job cap -# kills the runner and takes the evidence with it. -# -# Why stdout and not a file: the failures this exists to diagnose are ones where every later step -# is skipped -- the runner killed outright (GH-3771), or the job cancelled at the workflow's -# timeout-minutes cap (GH-4083) -- so an artifact upload or an `if: failure()` dmesg dump never -# executes. Anything already streamed to the live job log, on the other hand, survives. So this has -# to run in the background of the step being diagnosed and print as it goes, and nothing here may -# use ::group:: -- a group left unclosed by a cancellation hides everything inside it. -# -# Each line is prefixed [mem] or [stall] so the curve and the diagnostic can be pulled out of a -# noisy log with a single grep: -# -# gh run view --log | grep -E '\[mem\]|\[stall\]' -# -# THE MEMORY CURVE reads as: if MemAvailable trends toward zero and swap fills just before the -# kill, this is the OOM killer taking the runner service and the fix is footprint (lane count, -# per-lane hosts). If memory is flat at the moment of death, it is not OOM and lane tuning would be -# treating the wrong thing. -# -# THE STALL WATCHDOG exists because "memory is flat" turned out to be the answer, and on its own it -# is not actionable. On the GH-4083 occurrence the samples were byte-identical for the last several -# minutes -- 13.7GB available, no swap, the test host pinned at 1160MB -- which says the process was -# idle, not starved, but says nothing about WHICH test was wedged. Bobcat 0.6.1 reports per-test -# results only when a batch finishes, so a batch that never finishes prints nothing at all: the last -# line of that job was "275 test(s): 275 batched, 0 isolated", 18m33s before the cap. The watchdog -# closes that gap by dumping the async stacks itself. Per the repo's convention, that means -# dotnet-dump + `dumpasync`, NOT dotnet-stack: the wedge is an await living on the GC heap, and a -# thread report just shows pool workers parked on a semaphore. -# -# Sizing is measured, per target, over 12 green `main` runs -- see the note on `stall_deadline` -# below. The idle threshold is safe for every suite regardless of how long it takes (a healthy suite -# is never idle for five minutes); the deadline is not, and is turned off for the targets whose -# honest runtime is already close to the cap. -# -# This runs on EVERY target, not just the Marten shards it was written for. The suites that hold the -# most memory are not necessarily the ones that take the longest, and #4089 asks a question -- does -# any other suite retain the way MartenTests does -- that can only be answered by measuring rather -# than by guessing which ones to instrument. - -set -uo pipefail - -interval="${MEMORY_SAMPLE_INTERVAL:-15}" - -# Consecutive seconds of a genuinely idle watched process before the watchdog fires. -stall_after="${STALL_AFTER_SECONDS:-300}" - -# Don't watch for stalls until the build/restore phase is behind us. VBCSCompiler is the largest -# process on the box while a project compiles and idles between compilations, which is not a stall. -stall_arm_after="${STALL_ARM_AFTER_SECONDS:-240}" - -# Unconditional backstop: fire this many seconds in whatever the CPU says, because a wedge with a -# live poller in it (a durability agent, a Marten daemon) burns enough CPU to never look idle. Set -# below the workflow's timeout-minutes cap with room for the capture itself to finish and print. -# -# **0 disables it**, and several targets need that. Measured over 12 green `main` runs, the heaviest -# suites legitimately run PAST this: CIRabbitMQ 859s, CIEfCore 821s, CISqlServer 810s, CIPersistence -# 807s, CIPubsub 779s, CIAzureServiceBus 775s. There is not enough daylight between "healthy" and -# "about to be capped" on those for an unconditional time trigger to mean anything, and a spurious -# capture costs ~2 minutes inside a 20 minute cap on a job already at 14 -- it would turn a green job -# red. Those targets run the idle detector alone, which does not care how long a suite takes. -stall_deadline="${STALL_DEADLINE_SECONDS:-780}" - -# A watched process using less than this share of one core across a whole interval is idle. -stall_cpu_percent="${STALL_CPU_PERCENT:-2}" - -# The async stack of a wedged test host is worth having; all 40,000 lines of it are not. -stall_dump_lines="${STALL_DUMP_LINES:-400}" - -clock_tick="$(getconf CLK_TCK 2>/dev/null || echo 100)" -idle_jiffy_floor=$(( clock_tick * interval * stall_cpu_percent / 100 )) - -# The shell that backgrounded this sampler. Everything the step runs descends from it; the service -# containers do not. See the watched-process selection in the loop. -step_root="${PPID}" - -started="${SECONDS}" -fired=0 -prev_pid="" -prev_rss="" -prev_cpu="" -idle_for=0 - -echo "[mem] sampling every ${interval}s -- total/used/free/available in MB, plus the largest RSS consumers" -if [ "${stall_deadline}" -gt 0 ]; then - echo "[stall] watchdog armed at +${stall_arm_after}s: dumps async stacks after ${stall_after}s idle, or at +${stall_deadline}s regardless" -else - echo "[stall] watchdog armed at +${stall_arm_after}s: dumps async stacks after ${stall_after}s idle (deadline trigger disabled for this target)" -fi - -# Everything the kernel will tell us for free, printed before anything slow is attempted so that a -# capture truncated by the cap still leaves the cheap half behind. -cheap_evidence() { - local pid="$1" - - echo "[stall] --- process tree ---" - ps -eo pid,ppid,stat,wchan:24,etime,time,rss,comm --sort=-rss | head -15 | sed 's/^/[stall] /' - - if [ -r "/proc/${pid}/status" ]; then - echo "[stall] --- /proc/${pid} ---" - grep -E '^(Name|State|Threads|VmRSS|voluntary_ctxt_switches|nonvoluntary_ctxt_switches):' \ - "/proc/${pid}/status" 2>/dev/null | sed 's/^/[stall] /' - echo "[stall] open fds: $(ls "/proc/${pid}/fd" 2>/dev/null | wc -l)" - - # A thread histogram separates "every thread parked" (the await wedge this is looking for) - # from "one thread spinning" (a livelock, which needs a different tool). - echo -n "[stall] thread states: " - for t in "/proc/${pid}"/task/*/stat; do - rest="$(cat "$t" 2>/dev/null)"; rest="${rest#*) }" - echo "${rest%% *}" - done | sort | uniq -c | tr '\n' ' ' - echo - fi - - # Which sockets it is holding is often the whole answer: a test host parked on a connection to - # Postgres is a very different bug from one parked on nothing at all. - echo "[stall] --- sockets ---" - ss -tnp 2>/dev/null | grep -E "pid=${pid}[,)]" | head -20 | sed 's/^/[stall] /' \ - || echo "[stall] (no sockets attributed to ${pid})" - - echo "[stall] --- memory ---" - free -m | sed 's/^/[stall] /' -} - -# dotnet-dump + dumpasync. Installed lazily: a healthy run must not pay ~20s to install a tool it -# will never use. Every stage is bounded by `timeout` so a capture that goes wrong cannot itself be -# the thing that eats the remaining budget. -async_stacks() { - local pid="$1" - local dump="${RUNNER_TEMP:-/tmp}/stall-${pid}.dmp" - - export PATH="${PATH}:${HOME}/.dotnet/tools" - if ! command -v dotnet-dump >/dev/null 2>&1; then - echo "[stall] installing dotnet-dump..." - timeout 120 dotnet tool install -g dotnet-dump >/dev/null 2>&1 \ - || { echo "[stall] dotnet-dump install FAILED -- cheap evidence above is all there is"; return 1; } - fi - - echo "[stall] collecting a dump of pid ${pid}..." - timeout 240 dotnet-dump collect -p "${pid}" -o "${dump}" >/dev/null 2>&1 \ - || { echo "[stall] dotnet-dump collect FAILED"; rm -f "${dump}"; return 1; } - - echo "[stall] --- dumpasync --coalesce (first ${stall_dump_lines} lines) ---" - # Long-form flag only: `printf` with the short forms gets mangled into "Unrecognized argument". - printf 'dumpasync --coalesce\nexit\n' \ - | timeout 300 dotnet-dump analyze "${dump}" 2>&1 \ - | head -n "${stall_dump_lines}" \ - || true - echo "[stall] --- end dumpasync ---" - - rm -f "${dump}" -} - -fire() { - local pid="$1" why="$2" - fired=1 - - echo "[stall] ================================================================" - echo "[stall] NO PROGRESS: ${why} (pid ${pid}, $(( SECONDS - started ))s into this step)" - echo "[stall] ================================================================" - - cheap_evidence "${pid}" - async_stacks "${pid}" - - echo "[stall] capture complete; sampling continues" -} - -while true; do - # `free -m` line 2 is the physical memory row; column 7 is "available", which is the number that - # actually predicts an OOM kill (unlike "free", which excludes reclaimable page cache). - read -r _ total used free _ _ available <<<"$(free -m | awk 'NR==2')" - swap_used="$(free -m | awk 'NR==3 {print $3}')" - - # Top three processes by RSS, so a spike can be attributed to a test host / Postgres / the runner - # rather than just observed in aggregate. - top="$(ps -eo rss=,comm= --sort=-rss | head -3 | awk '{printf "%s=%dMB ", $2, $1/1024}')" - - # The largest process IN THIS STEP'S OWN TREE -- deliberately not the largest on the box. - # `ps -e` on a runner also sees the service containers, and several of them are both huge and - # idle: sqlservr alone holds multiple GB and can sit still for minutes while the test host is - # working perfectly well. Watching it would report a stall that is not happening, on exactly the - # suites (CISqlServer, CIPersistence, CIPolecat) this was turned on for. Everything the step - # actually runs -- Nuke's `build`, the MTP test host -- descends from the shell that backgrounded - # this sampler, and no container process does. - read -r pid rss watched <<<"$(ps -eo pid=,ppid=,rss=,comm= | awk -v root="${step_root}" ' - { ppid[$1] = $2; rss[$1] = $3; comm[$1] = $4; seen[NR] = $1 } - END { - for (i = 1; i <= NR; i++) { - p = seen[i]; cur = p; hops = 0 - while (cur != "" && cur != "1" && hops < 64) { - if (cur == root) break - cur = ppid[cur]; hops++ - } - if (cur == root && rss[p] > best) { best = rss[p]; bp = p; bc = comm[p] } - } - if (bp != "") print bp, best, bc - }')" - - cpu="" - # The pid guard is not paranoia: "/proc/${pid}/stat" with an empty pid collapses to the - # system-wide /proc/stat, whose twelfth field is the string "cpu0" -- which bash then evaluates - # as an unbound variable and kills the sampler outright. - if [[ "${pid}" =~ ^[0-9]+$ ]] && [ -r "/proc/${pid}/stat" ]; then - # comm can contain spaces and parens, so cut everything through ") " before splitting; - # what remains starts at field 3 (state), putting utime/stime at offsets 12 and 13. - stat_rest="$(cat "/proc/${pid}/stat" 2>/dev/null)"; stat_rest="${stat_rest#*) }" - # shellcheck disable=SC2086 - set -- ${stat_rest} - cpu=$(( ${12:-0} + ${13:-0} )) - fi - - cpu_delta="n/a" - if [ -n "${cpu}" ] && [ "${pid}" = "${prev_pid}" ] && [ -n "${prev_cpu}" ]; then - cpu_delta=$(( cpu - prev_cpu )) - if [ "${rss}" = "${prev_rss}" ] && [ "${cpu_delta}" -le "${idle_jiffy_floor}" ]; then - idle_for=$(( idle_for + interval )) - else - idle_for=0 - fi - else - idle_for=0 - fi - - echo "[mem] $(date -u +%H:%M:%S) total=${total} used=${used} free=${free} available=${available} swap_used=${swap_used} | ${top}| watching ${watched:-?}(${pid:-?}) cpu_jiffies+${cpu_delta} idle_for=${idle_for}s" - - if [ "${fired}" -eq 0 ] && [ $(( SECONDS - started )) -ge "${stall_arm_after}" ]; then - if [ "${idle_for}" -ge "${stall_after}" ]; then - fire "${pid}" "watched process idle for ${idle_for}s (RSS unchanged, under ${stall_cpu_percent}% of one core)" - elif [ "${stall_deadline}" -gt 0 ] && [ $(( SECONDS - started )) -ge "${stall_deadline}" ]; then - fire "${pid}" "still running ${stall_deadline}s in, past this target's measured green ceiling" - fi - fi - - prev_pid="${pid}" - prev_rss="${rss}" - prev_cpu="${cpu}" - - sleep "${interval}" -done diff --git a/build/flakiness-report.sh b/build/flakiness-report.sh index 818f4bdad..996267407 100755 --- a/build/flakiness-report.sh +++ b/build/flakiness-report.sh @@ -64,7 +64,10 @@ jq '[group_by(.Job)[] | { indeterminate: (map(.Indeterminate) | add), flakyTests: (map(.FlakyTests[]) | unique), flakyFailures: (map(.FlakyFailures // [] | .[]) | unique), - serviceRestarts: (map(.ServiceRestarts // [] | .[])) + serviceRestarts: (map(.ServiceRestarts // [] | .[])), + stalled: (map(.Stalled // 0) | add), + stalledTests: (map(.StalledTests // [] | .[]) | unique), + partial: (map(.IsPartial // false) | any) }] | sort_by(-.retries, .job)' \ "${output_dir}/entries.json" > "${output_dir}/aggregate.json" @@ -72,6 +75,10 @@ total_retries=$(jq '[.[] | .retries] | add // 0' "${output_dir}/aggregate.json") # GH-3855. A readiness gate that restarted a wedged container and then succeeded makes the job PASS, # so without this the recovery is invisible and a degrading runner reads as clean. total_restarts=$(jq '[.[] | (.serviceRestarts // []) | length] | add // 0' "${output_dir}/aggregate.json") +# Bobcat 0.8.0 (JasperFx/bobcat#145/#150): a test in flight past the 5-minute stall threshold, and +# jobs whose ledger came from the cancellation handler — the run so far, not a verdict. +total_stalled=$(jq '[.[] | .stalled // 0] | add // 0' "${output_dir}/aggregate.json") +partial_jobs=$(jq -r '[.[] | select(.partial // false) | .job] | join(", ")' "${output_dir}/aggregate.json") total_tests=$(jq '[.[] | .tests] | add // 0' "${output_dir}/aggregate.json") reporting_jobs=$(jq 'length' "${output_dir}/aggregate.json") @@ -179,8 +186,31 @@ delta_for() { # `paste -sd', '` would cycle the two delimiters and yield "a,b c,d" -- one delimiter, then sed. echo "> **Reported no ledger at all:** $(echo "${missing}" | paste -sd, - | sed 's/,/, /g')" echo ">" - echo "> Bobcat prints its summary only at the end, so a job killed by the 20-minute cap reports" - echo "> nothing — not even a partial count. Treat this as unmeasured, not as clean." + echo "> A cancelled job now writes a PARTIAL ledger from its cancellation handler (see" + echo "> build/StallCapture.cs), so total silence means the handler never got a chance —" + echo "> a hard kill, or a wedge before the supervisor started. Treat this as unmeasured," + echo "> not as clean." + echo + fi + + if [ -n "${partial_jobs}" ]; then + echo "> **Partial ledgers (cancelled mid-run): ${partial_jobs}**" + echo ">" + echo "> These counts are the run so far, written in the cancellation grace window; tests the" + echo "> run never got a verdict for are counted Indeterminate, never failed." + echo + fi + + if [ "${total_stalled}" != "0" ]; then + echo "> **Tests stalled past the 5-minute threshold: ${total_stalled}**" + echo ">" + echo "> Named because a hung batch's log otherwise cannot say which test wedged. A stalled" + echo "> test that eventually passed still exceeded its budget — a green run is exactly where" + echo "> a creeping slowdown goes unnoticed." + echo ">" + jq -r '.[] | select((.stalled // 0) > 0) + | "> - **\(.job)**: " + ((.stalledTests // []) | map("`" + . + "`") | join(", "))' \ + "${output_dir}/aggregate.json" echo fi