BenchmarkDotNet: Benchmark Reporting - Deadlock/Getting Stuck Reading From Process.StandardOutput (NetCore 2.1)

Update (7/15/2018 @ 7:25 PM EST)

Decoupled my Benchmark project from a local project and instead added reference to the NuGet it corresponds to.

In addition to that, I installed 2.302 SDK (NetCore 2.1.2).

Standard Sleep benchmark is working again.

Moving to BenchmarkDotNet nightlies (BDN v0.10.14.685, Core v0.10.14.508).

Update (7/15/2018 @ 8:07 PM EST)

Nothing seems to work.

Thread stuck here:

Found the exception in background:

Not sure how I can help but the file it’s stuck on seems to be the .log.

I allowed continuation found the code frozen in one spot - continuously frozen in one spot:

Not Flagged	>	40620	1	Main Thread	Main Thread  

System.Private.CoreLib.dll!System.IO.FileStream.ReadFileNative    

[Managed to Native Transition]   

System.Private.CoreLib.dll!System.IO.FileStream.ReadFileNative(Microsoft.Win32.SafeHandles.SafeFileHandle handle, System.Span<byte> bytes, System.Threading.NativeOverlapped* overlapped, out int errorCode) Line 1190  
System.Private.CoreLib.dll!System.IO.FileStream.ReadNative(System.Span<byte> buffer) Line 507   
System.Private.CoreLib.dll!System.IO.FileStream.ReadSpan(System.Span<byte> destination) Line 433   
System.Private.CoreLib.dll!System.IO.FileStream.Read(byte[] array, int offset, int count) Line 302   
System.Private.CoreLib.dll!System.IO.StreamReader.ReadBuffer() Line 637  
System.Private.CoreLib.dll!System.IO.StreamReader.ReadLine() Line 812  
BenchmarkDotNet.dll!BenchmarkDotNet.Loggers.SynchronousProcessOutputLoggerWithDiagnoser.ProcessInput()  
BenchmarkDotNet.dll!BenchmarkDotNet.Toolchains.DotNetCli.DotNetCliExecutor.Execute(BenchmarkDotNet.Running.BenchmarkCase benchmarkCase, BenchmarkDotNet.Running.BenchmarkId benchmarkId, BenchmarkDotNet.Loggers.ILogger logger, BenchmarkDotNet.Toolchains.ArtifactsPaths artifactsPaths, BenchmarkDotNet.Diagnosers.IDiagnoser diagnoser, string executableName, BenchmarkDotNet.Configs.IConfig config, BenchmarkDotNet.Characteristics.IResolver resolver)   
BenchmarkDotNet.dll!BenchmarkDotNet.Toolchains.DotNetCli.DotNetCliExecutor.Execute(BenchmarkDotNet.Toolchains.Parameters.ExecuteParameters executeParameters)  
BenchmarkDotNet.dll!BenchmarkDotNet.Running.BenchmarkRunner.Execute(BenchmarkDotNet.Loggers.ILogger logger, BenchmarkDotNet.Running.BenchmarkCase benchmarkCase, BenchmarkDotNet.Running.BenchmarkId benchmarkId, BenchmarkDotNet.Toolchains.IToolchain toolchain, BenchmarkDotNet.Toolchains.Results.BuildResult buildResult, BenchmarkDotNet.Configs.IConfig config, BenchmarkDotNet.Characteristics.IResolver resolver)  
BenchmarkDotNet.dll!BenchmarkDotNet.Running.BenchmarkRunner.RunCore(BenchmarkDotNet.Running.BenchmarkCase benchmarkCase, BenchmarkDotNet.Running.BenchmarkId benchmarkId, BenchmarkDotNet.Loggers.ILogger logger, BenchmarkDotNet.Configs.ReadOnlyConfig config, BenchmarkDotNet.Characteristics.IResolver resolver, BenchmarkDotNet.Toolchains.Results.BuildResult buildResult)  
BenchmarkDotNet.dll!BenchmarkDotNet.Running.BenchmarkRunner.Run(BenchmarkDotNet.Running.BenchmarkRunInfo benchmarkRunInfo, System.Collections.Generic.Dictionary<BenchmarkDotNet.Running.BenchmarkCase, (BenchmarkDotNet.Running.BenchmarkId benchmarkId, BenchmarkDotNet.Toolchains.Results.BuildResult buildResult)> buildResults, BenchmarkDotNet.Characteristics.IResolver resolver, BenchmarkDotNet.Loggers.ILogger logger, System.Collections.Generic.List<string> artifactsToCleanup, string rootArtifactsFolderPath, ref BenchmarkDotNet.Horology.StartedClock runChronometer)
BenchmarkDotNet.dll!BenchmarkDotNet.Running.BenchmarkRunner.Run(BenchmarkDotNet.Running.BenchmarkRunInfo[] benchmarkRunInfos, BenchmarkDotNet.Configs.IConfig commonSettingsConfig)  
BenchmarkDotNet.dll!BenchmarkDotNet.Running.BenchmarkRunner.Run(BenchmarkDotNet.Running.BenchmarkRunInfo benchmarkRunInfo)  
CookedRabbit.Core.Benchmark.dll!CookedRabbit.Core.Benchmark.Program.Main(string[] args)  
CookedRabbit.Core.Benchmark.dll!CookedRabbit.Core.Benchmark.Program.<Main>(string[] args)  

Guessing this needs a timeout?

BenchmarkDotNet.dll!BenchmarkDotNet 
.Loggers
.SynchronousProcessOutputLoggerWithDiagnoser
.ProcessInput()

BenchmarkDotNet.Loggers.SynchronousProcessOutputLoggerWithDiagnoser Line 38

internal void ProcessInput()
{
    string line;
    while ((line = process.StandardOutput.ReadLine()) != null)
    {
        logger.WriteLine(LogKind.Default, line);

        if (string.IsNullOrEmpty(line))
            continue;

        if (!line.StartsWith("//"))
            LinesWithResults.Add(line);
        else if (Engine.Signals.TryGetSignal(line, out var signal))
        {
            diagnoser?.Handle(signal, diagnoserActionParameters);
            process.StandardInput.WriteLine(Engine.Signals.Acknowledgment);
        }
        else
            LinesWithExtraOutput.Add(line);
    }
}

There appears to be a couple of Stackoverflow open issues which indicate that they experienced infinite loops in this same manner.

Code Change Proposal:

internal void ProcessInput()
{
    string line;
    while (!process.StandardOutput.EndOfStream)
    {
        line = process.StandardOutput.ReadLine();
        if (!string.IsNullOrEmpty(line))
        {
            logger.WriteLine(LogKind.Default, line);

            if (!line.StartsWith("//"))
                LinesWithResults.Add(line);
            else if (Engine.Signals.TryGetSignal(line, out var signal))
            {
                diagnoser?.Handle(signal, diagnoserActionParameters);
                process.StandardInput.WriteLine(Engine.Signals.Acknowledgment);
            }
            else
                LinesWithExtraOutput.Add(line);
        }
    }
}

Asynchronous would be considered a better choice and adding a cancellation token on a timer.

Original Post

I started using BenchmarkDotNet yesterday so forgive my ignorance. I clearly have done something wrong. Can’t ever get a test to finish. It’s always frozen at // AfterAll.

It’s a NetCore only test, using version 2.1.0.

I have manipulated parameters, I have manipulated Jobs… It’s probably something simple but even my simplest of tests fail to finish.

I have tried both regular Main and async Main (my preference is async Main).

public class Program
{
    public static async Task Main(string[] args)
    {
        var summary = BenchmarkRunner.Run<Publish>();

        await Console.Out.WriteLineAsync("CookedRabbit benchmark has finished!");
    }
}

I have tried [CoreJob], [SimpleJob]. I have tried simple parameters… just running one iteration example. Nothing seems to work.

[MarkdownExporter]
[SimpleJob(RunStrategy.Monitoring, launchCount: 1, warmupCount: 2, targetCount: 3)]
public class Publish
{
    public Publish()
    { }

    RabbitTopologyService _topologyService;
    RabbitDeliveryService _deliveryService;
    RabbitMaintenanceService _maintenanceService;

    public List<byte[]> Payloads { get; set; }

    public string QueueName { get; set; }
    public string ExchangeName { get; set; }

    [GlobalSetup]
    public void Setup()
    {
        QueueName = "CookedRabbit.Benchmark.Scaling";
        ExchangeName = string.Empty;

        // Configured for performance.
        var seasoning = new RabbitSeasoning
        {
            ThrottleFastBodyLoops = false,
            ThrowExceptions = false,
            WriteErrorsToConsole = false,
            WriteErrorsToILogger = false,
            BatchBreakOnException = true
        };

        seasoning.PoolSettings.EnableAutoScaling = true;
        seasoning.PoolSettings.EmptyPoolWaitTime = 10;
        seasoning.PoolSettings.WriteSleepNoticeToConsole = false;
        seasoning.PoolSettings.ConnectionPoolCount = 4;
        seasoning.PoolSettings.ChannelPoolCount = 16;

        var channelPool = new RabbitChannelPool();
        channelPool.Initialize(seasoning).GetAwaiter().GetResult();

        _deliveryService = new RabbitDeliveryService(seasoning, channelPool);
        _topologyService = new RabbitTopologyService(seasoning, channelPool);
        _maintenanceService = new RabbitMaintenanceService(seasoning, channelPool);

        _topologyService.QueueDeclareAsync(QueueName).GetAwaiter().GetResult();
    }

    [GlobalCleanup]
    public void GlobalCleanup()
    {
        _maintenanceService.PurgeQueueAsync(QueueName).GetAwaiter().GetResult();
    }

    [Params(1, 10, 100, 1000)]
    public int MessagesToSend { get; set; }
    [Params(100, 200, 500, 1000)]
    public int MessageSize;

    [IterationSetup]
    public void IterationSetup()
    {
        _maintenanceService.PurgeQueueAsync(QueueName).GetAwaiter().GetResult();
        Payloads = CreatePayloadsAsync(MessagesToSend, MessageSize).GetAwaiter().GetResult();
    }

    [IterationCleanup]
    public void IterationCleanup()
    {
        Payloads = new List<byte[]>();
    }

    [Benchmark]
    public async Task Benchmark_Delivery_PublishManyAsync()
    {
        await _deliveryService.PublishManyAsync(ExchangeName, QueueName, Payloads, false, null);
    }
}

Also when stopping the tests, or closing the test, I never see any cleanup done so multiple instances of dotnet host are left running.

I was thinking hypothetically, my complicated code may have an issue… Maybe some infinite loop so… I created specifically complex functional and integration tests. All passing with flying colors.

Any help is much appreciated. The GitHub repo is here: https://github.com/thyams/CookedRabbit