From 23dd99fa2fb7bf681751612ea53d9c8af40a8830 Mon Sep 17 00:00:00 2001 From: AJ Isaacs Date: Fri, 25 Sep 2026 14:03:10 -0400 Subject: [PATCH] feat(benchmark): add --progress logging for engine solves Long whole-job solves ran silently, so there was no way to tell a slow engine from a hung one until the timeout fired. --progress hands each solve a JobProgressLog that prints [job/engine] lines for start, finish (or failure/timeout), every plate commit, and candidate evaluations throttled to one line per 2 s so parallel runs stay readable. Co-Authored-By: Claude Opus 5.5 --- CLAUDE.md | 2 +- OpenNest.Benchmark/BenchmarkRunner.cs | 18 +++- OpenNest.Benchmark/JobProgressLog.cs | 88 +++++++++++++++++++ OpenNest.Benchmark/Program.cs | 11 ++- .../Benchmark/BenchmarkRunnerTests.cs | 34 +++++++ .../Benchmark/JobProgressLogTests.cs | 45 ++++++++++ README.md | 2 +- 7 files changed, 193 insertions(+), 7 deletions(-) create mode 100644 OpenNest.Benchmark/JobProgressLog.cs create mode 100644 OpenNest.Tests/Benchmark/JobProgressLogTests.cs diff --git a/CLAUDE.md b/CLAUDE.md index fc4750c..40ae53a 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -87,7 +87,7 @@ Compares registered `INestingEngine` implementations against each other on real - `BenchmarkRunner` fans the (job × engine) pairs out with `Parallel.ForEach` (`NoBuffering`, `MaxDegreeOfParallelism` from `--parallel`, CLI default 3, `Run`'s own default 1) and writes results by index so report order stays job-then-engine. Each solve builds its own `NestJob` snapshot and materialized drawings, so solves share no mutable drawing state. Concurrent solves compete for cores, so `Time(ms)` is only clean at `--parallel 1`. It calls each engine's `INestingEngine.Solve(NestJob)` once per job, under a wall-clock timeout so a runaway or hanging engine can't stall the whole benchmark run, then materializes the result back into legacy `Plate`/`Part` objects via `NestResultMaterializer` for scoring. - `NestValidator` checks the returned layout: every part inside `Plate.WorkArea()`, every pair at least `Plate.PartSpacing` apart (checked geometrically: each part's perimeter inflated and cutouts shrunk by the spacing, tested against the other part's raw material with holes subtracted, so part-in-part inside a cutout is legal; an X-sorted bounding-box sweep prunes distant pairs), and no drawing over its requested quantity. `ValidateAgainstJob` also checks the raw `NestJobResult`: every sheet must match a stock entry the job offered (size, spacing, edge spacing, quadrant; finite quantity not overdrawn), and every placement rotation must satisfy its part's `RotationPolicy.Allows`. An invalid, throwing, or timed-out run places nothing for scoring. - Ranking (`Report.Compare`): valid > invalid, fully placed > not, then lower `JobResult.Cost`, then fewer plates. Cost = salvage-credited sheet area (`StockLadderNestingEngine.EstimateNetArea` per plate, recomputed from job geometry) + `BenchmarkJob.UnplacedPartPenalty` (largest candidate sheet area) per unplaced part, so dropping hard parts never improves the score. The summary sums cost and areas across jobs (area-weighted, not a mean of per-job percentages). Without `--sheet-sizes`, `.nest` jobs only offer their original sizes, and the CLI warns that this hints engines. Numeric CLI and manifest sheet sizes parse with the invariant culture (`JobLoader.TryParseSheetSize`). -- `--engines Name1,Name2` filters to specific registered engines (default: all); `--csv ` writes a flat per-job CSV alongside the console report. +- `--engines Name1,Name2` filters to specific registered engines (default: all); `--csv ` writes a flat per-job CSV alongside the console report. `--progress` passes each solve a `JobProgressLog`, which writes `[job/engine]` lines for start, finish, every `PlateCommitted`, and `EvaluatingCandidate` throttled to one line per 2 s. - `tools/PepNestExport` (outside the solution; references `PepLib.Core` from the sibling `PepApi.Core` repo) converts a PepApi year of PEP nests into `.nest` files that keep PEP's placements as the benchmark `Baseline`. PEP loop quirks: sub-loop calls continue the incremental position; lead-in/out, `DESTRUCT CUT` and non-cut moves must not reach the program as rapids (a program's bounding box counts rapid endpoints); contours may be broken by uncut micro-joint tabs (a rapid of up to 0.25 across the tab, at the seam or mid-contour, e.g. a cutout cut as two halves), which the export bridges only where the pieces chain into a closed loop; and one drawing can be placed through several loops with different origins. ### OpenNest.Mcp (console app, depends on Core + Engine + IO) diff --git a/OpenNest.Benchmark/BenchmarkRunner.cs b/OpenNest.Benchmark/BenchmarkRunner.cs index 1ad3b84..484d4de 100644 --- a/OpenNest.Benchmark/BenchmarkRunner.cs +++ b/OpenNest.Benchmark/BenchmarkRunner.cs @@ -33,7 +33,8 @@ namespace OpenNest.Benchmark double? salvageRate = null, double? minimumSalvageDimension = null, string outputDirectory = null, - int maxParallelism = 1 + int maxParallelism = 1, + System.IO.TextWriter progressLog = null ) { var pairs = jobs.SelectMany(job => engines.Select(engine => (Job: job, Engine: engine))) @@ -68,7 +69,8 @@ namespace OpenNest.Benchmark pairs[i].Engine, salvageRate, minimumSalvageDimension, - outputDirectory + outputDirectory, + progressLog ) ); @@ -223,10 +225,15 @@ namespace OpenNest.Benchmark NestingEngineInfo engineInfo, double? salvageRate, double? minimumSalvageDimension, - string outputDirectory + string outputDirectory, + System.IO.TextWriter progressLog ) { var requested = job.TotalRequestedQuantity; + var log = progressLog == null + ? null + : new JobProgressLog(progressLog, $"{job.Name}/{engineInfo.Name}"); + log?.Started(); var sw = Stopwatch.StartNew(); try @@ -234,7 +241,8 @@ namespace OpenNest.Benchmark var nestJob = job.BuildNestJob(MaxPlates, salvageRate, minimumSalvageDimension); var engine = engineInfo.Factory(); using var cts = new CancellationTokenSource(SolveTimeout); - var jobResult = engine.Solve(nestJob, null, cts.Token); + var jobResult = engine.Solve(nestJob, log, cts.Token); + log?.Finished(jobResult, sw.ElapsedMilliseconds); var materialized = NestResultMaterializer.Materialize(nestJob, jobResult); var plateRuns = materialized @@ -357,6 +365,7 @@ namespace OpenNest.Benchmark catch (OperationCanceledException) { sw.Stop(); + log?.Failed("timed out", sw.ElapsedMilliseconds); return new JobResult { EngineName = engineInfo.Name, @@ -371,6 +380,7 @@ namespace OpenNest.Benchmark catch (Exception ex) { sw.Stop(); + log?.Failed($"{ex.GetType().Name}: {ex.Message}", sw.ElapsedMilliseconds); return new JobResult { EngineName = engineInfo.Name, diff --git a/OpenNest.Benchmark/JobProgressLog.cs b/OpenNest.Benchmark/JobProgressLog.cs new file mode 100644 index 0000000..627081b --- /dev/null +++ b/OpenNest.Benchmark/JobProgressLog.cs @@ -0,0 +1,88 @@ +using System; +using System.Diagnostics; +using System.IO; +using OpenNest.Engine.Jobs; + +namespace OpenNest.Benchmark +{ + /// + /// Writes one solve's NestJobProgress as log lines prefixed with "[job/engine]". Every + /// PlateCommitted is written; EvaluatingCandidate is throttled to one line per interval so a + /// chatty engine cannot flood the console. One instance per solve; Report is thread-safe. + /// + public sealed class JobProgressLog : IProgress + { + public static readonly TimeSpan DefaultInterval = TimeSpan.FromSeconds(2); + + private readonly TextWriter writer; + private readonly string label; + private readonly TimeSpan interval; + private readonly Func clock; + private readonly object sync = new(); + private TimeSpan? lastEvaluating; + + public JobProgressLog( + TextWriter writer, + string label, + TimeSpan? interval = null, + Func clock = null + ) + { + this.writer = writer ?? throw new ArgumentNullException(nameof(writer)); + this.label = label; + this.interval = interval ?? DefaultInterval; + if (clock == null) + { + var stopwatch = Stopwatch.StartNew(); + clock = () => stopwatch.Elapsed; + } + this.clock = clock; + } + + public void Started() => Write("started"); + + public void Finished(NestJobResult result, long elapsedMs) => + Write( + $"finished in {elapsedMs} ms: {result.Status} ({result.StopReason}), " + + $"{result.Plates.Count} plate(s)" + ); + + public void Failed(string error, long elapsedMs) => + Write($"failed after {elapsedMs} ms: {error}"); + + public void Report(NestJobProgress value) + { + if (value == null) + return; + + if (value.Stage == NestJobStage.PlateCommitted) + { + Write( + $"committed plate {value.CommittedPlates} on stock {value.StockId} " + + $"({value.CommittedParts} parts placed)" + ); + return; + } + + lock (sync) + { + var now = clock(); + if (lastEvaluating.HasValue && now - lastEvaluating.Value < interval) + return; + lastEvaluating = now; + } + + var plate = value.PlateIndex >= 0 ? value.PlateIndex + 1 : value.CommittedPlates + 1; + Write( + $"evaluating plate {plate} on stock {value.StockId} " + + $"({value.CommittedPlates} plate(s), {value.CommittedParts} parts committed)" + ); + } + + private void Write(string message) + { + lock (sync) + writer.WriteLine($"[{label}] {message}"); + } + } +} diff --git a/OpenNest.Benchmark/Program.cs b/OpenNest.Benchmark/Program.cs index 9a1aae3..b46059c 100644 --- a/OpenNest.Benchmark/Program.cs +++ b/OpenNest.Benchmark/Program.cs @@ -123,7 +123,8 @@ static class BenchmarkConsole options.SalvageRate, options.MinimumSalvageDimension, options.OutputDirectory, - options.Parallel + options.Parallel, + options.Progress ? Console.Out : null ); Report.PrintDetailed(results); @@ -196,6 +197,10 @@ static class BenchmarkConsole ); break; + case "--progress": + o.Progress = true; + break; + case "--help": PrintUsage(); return null; @@ -322,6 +327,9 @@ static class BenchmarkConsole Console.Error.WriteLine( " which gives the cleanest per-engine timings)" ); + Console.Error.WriteLine( + " --progress Log each solve's start, engine progress and finish" + ); Console.Error.WriteLine(" --help Show this message"); } @@ -336,5 +344,6 @@ static class BenchmarkConsole public double? SalvageRate; public double? MinimumSalvageDimension; public int Parallel = 3; + public bool Progress; } } diff --git a/OpenNest.Tests/Benchmark/BenchmarkRunnerTests.cs b/OpenNest.Tests/Benchmark/BenchmarkRunnerTests.cs index e2eed85..6118ac8 100644 --- a/OpenNest.Tests/Benchmark/BenchmarkRunnerTests.cs +++ b/OpenNest.Tests/Benchmark/BenchmarkRunnerTests.cs @@ -296,6 +296,40 @@ public sealed class BenchmarkRunnerTests : IDisposable Assert.True(File.Exists(Path.Combine(output, "job-Engine0.json"))); } + [Fact] + public void Run_WithProgressLog_ForwardsEngineProgress() + { + var writer = new StringWriter(); + var engines = new List + { + new("Reporter", "test double", () => new ReportingEngine()), + }; + + BenchmarkRunner.Run(LoadJob(), engines, maxParallelism: 1, progressLog: writer); + + var log = writer.ToString(); + Assert.Contains("[job/Reporter] started", log); + Assert.Contains("[job/Reporter] evaluating plate 1 on stock", log); + Assert.Contains("[job/Reporter] finished in", log); + } + + private sealed class ReportingEngine : INestingEngine + { + public NestJobResult Solve( + NestJob job, + IProgress? progress = null, + CancellationToken token = default + ) + { + progress?.Report( + new NestJobProgress(NestJobStage.EvaluatingCandidate, job.Plates[0].Id, 0, 0, 0) + ); + return new NestJobResultBuilder(job, progress).Build( + NestJobStopReason.NoPlacementFound + ); + } + } + private sealed class ConcurrencyProbe { private int _current; diff --git a/OpenNest.Tests/Benchmark/JobProgressLogTests.cs b/OpenNest.Tests/Benchmark/JobProgressLogTests.cs new file mode 100644 index 0000000..d4ba7c7 --- /dev/null +++ b/OpenNest.Tests/Benchmark/JobProgressLogTests.cs @@ -0,0 +1,45 @@ +using OpenNest.Benchmark; +using OpenNest.Engine.Jobs; + +namespace OpenNest.Tests.Benchmark; + +public sealed class JobProgressLogTests +{ + private static NestJobProgress Evaluating(int plateIndex = 0) => + new(NestJobStage.EvaluatingCandidate, "stock", plateIndex, 0, 0); + + [Fact] + public void Report_ThrottlesEvaluatingButAlwaysWritesCommits() + { + var writer = new StringWriter(); + var now = TimeSpan.Zero; + var log = new JobProgressLog(writer, "job/engine", TimeSpan.FromSeconds(2), () => now); + + log.Report(Evaluating()); + log.Report(Evaluating()); + log.Report(new NestJobProgress(NestJobStage.PlateCommitted, "stock", 0, 1, 5)); + now = TimeSpan.FromSeconds(3); + log.Report(Evaluating(1)); + + var lines = writer.ToString().Split(Environment.NewLine, StringSplitOptions.RemoveEmptyEntries); + Assert.Equal( + [ + "[job/engine] evaluating plate 1 on stock stock (0 plate(s), 0 parts committed)", + "[job/engine] committed plate 1 on stock stock (5 parts placed)", + "[job/engine] evaluating plate 2 on stock stock (0 plate(s), 0 parts committed)", + ], + lines + ); + } + + [Fact] + public void Report_UnknownPlateIndexFallsBackToNextCommittedPlate() + { + var writer = new StringWriter(); + var log = new JobProgressLog(writer, "j/e"); + + log.Report(new NestJobProgress(NestJobStage.EvaluatingCandidate, "s", -1, 2, 9)); + + Assert.Contains("evaluating plate 3 on stock s", writer.ToString()); + } +} diff --git a/README.md b/README.md index 38ebe0a..9be2c6c 100644 --- a/README.md +++ b/README.md @@ -59,7 +59,7 @@ dotnet run --project OpenNest.Benchmark -- ./benchmark-jobs \ --sheet-sizes 48x96,60x120,72x120 --engines Default,StockLadder --csv results.csv ``` -Layouts are validated (bounds, spacing, quantity, rotation, stock match); invalid runs place nothing and pay the penalty. `--parallel` (default 3) speeds up scoring but inflates `Time(ms)` — use `--parallel 1` when comparing speed. Pass `--sheet-sizes` for an unbiased run; otherwise only each file's original sizes are offered. Custom engines drop in as DLLs implementing `INestingEngine` (public parameterless constructor) in an `Engines/` folder next to the benchmark. Community engines live in [OpenNest-Engines](https://git.thecozycat.net/aj/OpenNest-Engines). +Layouts are validated (bounds, spacing, quantity, rotation, stock match); invalid runs place nothing and pay the penalty. `--parallel` (default 3) speeds up scoring but inflates `Time(ms)` — use `--parallel 1` when comparing speed. Pass `--sheet-sizes` for an unbiased run; otherwise only each file's original sizes are offered. `--progress` logs each solve's start, the engine's `NestJobProgress` (plate evaluations throttled to one line per 2 s, every plate commit) and its finish. Custom engines drop in as DLLs implementing `INestingEngine` (public parameterless constructor) in an `Engines/` folder next to the benchmark. Community engines live in [OpenNest-Engines](https://git.thecozycat.net/aj/OpenNest-Engines). ## Project Structure