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 <noreply@anthropic.com>
This commit is contained in:
aj
2026-09-25 14:03:10 -04:00
co-authored by Claude Opus 5.5
parent 695ccc0a3b
commit 23dd99fa2f
7 changed files with 193 additions and 7 deletions
@@ -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<NestingEngineInfo>
{
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<NestJobProgress>? 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;
@@ -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());
}
}