WorkloadJitting executed more than once

[adamsitnik]

I am trying to benchmark some of the new Process APIs using latest preview from the MyGet feed (what we offer at nuget.org does not support .NET 11 yet). When running following benchmark:

public class GlobalLock
{
    private ProcessStartInfo info;

    [Params(true, false)]
    public bool SetInheritedHandles { get; set; }

    [GlobalSetup]
    public void Setup()
    {
        info = OperatingSystem.IsWindows()
            ? new("cmd.exe", ["/c", "exit 42"])
            : new("sh", ["-c", "exit 42"]);

        info.InheritedHandles = SetInheritedHandles ? [] : null;
    }

    [Benchmark]
    public ParallelLoopResult Run() => Parallel.For(0, 1_000, (_, _) => _ = Process.Run(info));
}

With explicitly asking for running the benchmark once per iteration, for 10 iterations, with a single warmup:

dotnet run -c Release -f net11.0 --filter "*Lock*" --launchCount 1 --iterationCount 10 --invocationCount 1 --unrollFactor 1 --warmupCount 1

I can see WorkloadJitting being printed more than once:

// Benchmark Process Environment Information:
// BenchmarkDotNet v0.16.0-nightly.20260505.517
// Runtime=.NET 11.0.0 (11.0.0-preview.5.26255.101, 11.0.26.25601), X64 RyuJIT x86-64-v3
// GC=Concurrent Workstation
// HardwareIntrinsics=AVX2+BMI1+BMI2+F16C+FMA+LZCNT+MOVBE,AVX,SSE3+SSSE3+SSE4.1+SSE4.2+POPCNT,X86Base+SSE+SSE2,AES+PCLMUL VectorSize=256
// Job: Job-HFOVVH(InvocationCount=1, IterationCount=10, LaunchCount=1, UnrollFactor=1, WarmupCount=1)

WorkloadJitting  1: 1 op, 4193300600.00 ns, 4.1933 s/op
WorkloadJitting  2: 1 op, 4045230800.00 ns, 4.0452 s/op
WorkloadJitting  3: 1 op, 4034639500.00 ns, 4.0346 s/op
WorkloadJitting  4: 1 op, 4043227900.00 ns, 4.0432 s/op

WorkloadWarmup   1: 1 op, 4118601300.00 ns, 4.1186 s/op

// BeforeActualRun
WorkloadActual   1: 1 op, 3993833200.00 ns, 3.9938 s/op
WorkloadActual   2: 1 op, 4038450400.00 ns, 4.0385 s/op
WorkloadActual   3: 1 op, 4028608700.00 ns, 4.0286 s/op
WorkloadActual   4: 1 op, 3990243600.00 ns, 3.9902 s/op
WorkloadActual   5: 1 op, 4001137100.00 ns, 4.0011 s/op
WorkloadActual   6: 1 op, 4014296800.00 ns, 4.0143 s/op
WorkloadActual   7: 1 op, 4003703800.00 ns, 4.0037 s/op
WorkloadActual   8: 1 op, 4004910800.00 ns, 4.0049 s/op
WorkloadActual   9: 1 op, 4008993200.00 ns, 4.0090 s/op
WorkloadActual  10: 1 op, 4058972600.00 ns, 4.0590 s/op

// AfterActualRun
WorkloadResult   1: 1 op, 3993833200.00 ns, 3.9938 s/op
WorkloadResult   2: 1 op, 4038450400.00 ns, 4.0385 s/op
WorkloadResult   3: 1 op, 4028608700.00 ns, 4.0286 s/op
WorkloadResult   4: 1 op, 3990243600.00 ns, 3.9902 s/op
WorkloadResult   5: 1 op, 4001137100.00 ns, 4.0011 s/op
WorkloadResult   6: 1 op, 4014296800.00 ns, 4.0143 s/op
WorkloadResult   7: 1 op, 4003703800.00 ns, 4.0037 s/op
WorkloadResult   8: 1 op, 4004910800.00 ns, 4.0049 s/op
WorkloadResult   9: 1 op, 4008993200.00 ns, 4.0090 s/op
WorkloadResult  10: 1 op, 4058972600.00 ns, 4.0590 s/op

WorkloadJitting  1: 1 op, 1868394200.00 ns, 1.8684 s/op
WorkloadJitting  2: 1 op, 1809145900.00 ns, 1.8091 s/op
WorkloadJitting  3: 1 op, 1818846700.00 ns, 1.8188 s/op
WorkloadJitting  4: 1 op, 1873981600.00 ns, 1.8740 s/op
WorkloadJitting  5: 1 op, 1889514800.00 ns, 1.8895 s/op
WorkloadJitting  6: 1 op, 1836730200.00 ns, 1.8367 s/op
WorkloadJitting  7: 1 op, 2030291800.00 ns, 2.0303 s/op

WorkloadWarmup   1: 1 op, 1935149300.00 ns, 1.9351 s/op

// BeforeActualRun
WorkloadActual   1: 1 op, 1890218000.00 ns, 1.8902 s/op
WorkloadActual   2: 1 op, 1879179200.00 ns, 1.8792 s/op
WorkloadActual   3: 1 op, 2079051200.00 ns, 2.0791 s/op
WorkloadActual   4: 1 op, 2031099700.00 ns, 2.0311 s/op
WorkloadActual   5: 1 op, 2016355900.00 ns, 2.0164 s/op
WorkloadActual   6: 1 op, 1997384600.00 ns, 1.9974 s/op
WorkloadActual   7: 1 op, 1966403300.00 ns, 1.9664 s/op
WorkloadActual   8: 1 op, 1988965700.00 ns, 1.9890 s/op
WorkloadActual   9: 1 op, 1885926700.00 ns, 1.8859 s/op
WorkloadActual  10: 1 op, 1848450100.00 ns, 1.8485 s/op

// AfterActualRun
WorkloadResult   1: 1 op, 1890218000.00 ns, 1.8902 s/op
WorkloadResult   2: 1 op, 1879179200.00 ns, 1.8792 s/op
WorkloadResult   3: 1 op, 2079051200.00 ns, 2.0791 s/op
WorkloadResult   4: 1 op, 2031099700.00 ns, 2.0311 s/op
WorkloadResult   5: 1 op, 2016355900.00 ns, 2.0164 s/op
WorkloadResult   6: 1 op, 1997384600.00 ns, 1.9974 s/op
WorkloadResult   7: 1 op, 1966403300.00 ns, 1.9664 s/op
WorkloadResult   8: 1 op, 1988965700.00 ns, 1.9890 s/op
WorkloadResult   9: 1 op, 1885926700.00 ns, 1.8859 s/op
WorkloadResult  10: 1 op, 1848450100.00 ns, 1.8485 s/op

@timcassell @AndreyAkinshin have we recently changed something around this particular heuristic? I would expect JITting to be executed just once.

[timcassell]

The JIT stage now attempts to invoke the method enough times to get it to tier1, within a 10 second (arbitrary) time limit to not make long running benchmarks take too long. I am surprised to see your 4s benchmark run 4 times, though, as that clearly exceeds the time limit we set. I would expect a maximum of 3 invocations. [Edit] Oh I see why, we run the first invocation without a timer, then start the timer for the remaining invocations. This is because we didn't want to include cctors in the timer (#2004).

With explicitly asking for running the benchmark once per iteration, for 10 iterations, with a single warmup:

I think in this case since you have knowledge of your benchmarks that you know how it should be ran, you can pass RunStrategy.Monitoring to skip the JIT stage.

[adamsitnik]

It's a bug. Long-running benchmarks should not be executed more than once before running the actual benchmarks.

[timcassell]

It's not a bug. Tiering up the workload before measurements is intentional. We can't know whether the benchmark is long-running before we actually run it with the default config. We can adjust the heuristic to bail out earlier if we detect the invocation takes too long rather than waiting a full 10 seconds.