Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
houseofcat opened this issue Jul 15, 2018 · 22 comments · Fixed by #1571
Assignees

Comments

@houseofcat
Copy link
Contributor

houseofcat commented Jul 15, 2018

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:
image

Found the exception in background:
image

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:
image

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.

image

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.
image

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

@houseofcat
Copy link
Contributor Author

houseofcat commented Jul 15, 2018

Starting to see some correlation, the dotnet host never finishes / terminates. CodeGen is throwing errors for files being kept open...

Exact same test now fails to build... very curious.

Error

// Build Exception: Microsoft (R) Build Engine version 15.7.179.6572 for .NET Core
Copyright (C) Microsoft Corporation. All rights reserved.

  CookedRabbit.Core.Library -> C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Library\bin\Release\netcoreapp2.1\CookedRabbit.Core.Library.dll
CSC : error CS2012: Cannot open 'C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\obj\Release\netcoreapp2.1\CookedRabbit.Core.Benchmark.dll' for writing -- 'The process cannot access the file 'C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\obj\Release\netcoreapp2.1\CookedRabbit.Core.Benchmark.dll' because it is being used by another process.' [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]

Build FAILED.

CSC : error CS2012: Cannot open 'C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\obj\Release\netcoreapp2.1\CookedRabbit.Core.Benchmark.dll' for writing -- 'The process cannot access the file 'C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\obj\Release\netcoreapp2.1\CookedRabbit.Core.Benchmark.dll' because it is being used by another process.' [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
    0 Warning(s)
    1 Error(s)

Time Elapsed 00:00:01.93


// Build Exception: Microsoft (R) Build Engine version 15.7.179.6572 for .NET Core
Copyright (C) Microsoft Corporation. All rights reserved.

  CookedRabbit.Core.Library -> C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Library\bin\Release\netcoreapp2.1\CookedRabbit.Core.Library.dll
CSC : error CS2012: Cannot open 'C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\obj\Release\netcoreapp2.1\CookedRabbit.Core.Benchmark.dll' for writing -- 'The process cannot access the file 'C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\obj\Release\netcoreapp2.1\CookedRabbit.Core.Benchmark.dll' because it is being used by another process.' [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]

Build FAILED.

CSC : error CS2012: Cannot open 'C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\obj\Release\netcoreapp2.1\CookedRabbit.Core.Benchmark.dll' for writing -- 'The process cannot access the file 'C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\obj\Release\netcoreapp2.1\CookedRabbit.Core.Benchmark.dll' because it is being used by another process.' [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
    0 Warning(s)
    1 Error(s)

Time Elapsed 00:00:02.02


// Build Exception: Microsoft (R) Build Engine version 15.7.179.6572 for .NET Core
Copyright (C) Microsoft Corporation. All rights reserved.

  Unable to use package assets cache due to I/O error. This can occur when the same project is built more than once in parallel. Performance may be degraded, but the build result will not be impacted.
  CookedRabbit.Core.Library -> C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Library\bin\Release\netcoreapp2.1\CookedRabbit.Core.Library.dll
c:\program files\dotnet\sdk\2.1.300\Microsoft.Common.CurrentVersion.targets(2106,5): warning MSB3101: Could not write state file "obj\Release\netcoreapp2.1\CookedRabbit.Core.Benchmark.csprojAssemblyReference.cache". The process cannot access the file 'C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\obj\Release\netcoreapp2.1\CookedRabbit.Core.Benchmark.csprojAssemblyReference.cache' because it is being used by another process. [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
CSC : error CS2012: Cannot open 'C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\obj\Release\netcoreapp2.1\CookedRabbit.Core.Benchmark.dll' for writing -- 'The process cannot access the file 'C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\obj\Release\netcoreapp2.1\CookedRabbit.Core.Benchmark.dll' because it is being used by another process.' [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Microsoft.Common.CurrentVersion.targets(5084,5): error MSB3491: Could not write lines to file "obj\Release\netcoreapp2.1\CookedRabbit.Core.Benchmark.csproj.FileListAbsolute.txt". The process cannot access the file 'C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\obj\Release\netcoreapp2.1\CookedRabbit.Core.Benchmark.csproj.FileListAbsolute.txt' because it is being used by another process. [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]

Build FAILED.

c:\program files\dotnet\sdk\2.1.300\Microsoft.Common.CurrentVersion.targets(2106,5): warning MSB3101: Could not write state file "obj\Release\netcoreapp2.1\CookedRabbit.Core.Benchmark.csprojAssemblyReference.cache". The process cannot access the file 'C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\obj\Release\netcoreapp2.1\CookedRabbit.Core.Benchmark.csprojAssemblyReference.cache' because it is being used by another process. [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
CSC : error CS2012: Cannot open 'C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\obj\Release\netcoreapp2.1\CookedRabbit.Core.Benchmark.dll' for writing -- 'The process cannot access the file 'C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\obj\Release\netcoreapp2.1\CookedRabbit.Core.Benchmark.dll' because it is being used by another process.' [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Microsoft.Common.CurrentVersion.targets(5084,5): error MSB3491: Could not write lines to file "obj\Release\netcoreapp2.1\CookedRabbit.Core.Benchmark.csproj.FileListAbsolute.txt". The process cannot access the file 'C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\obj\Release\netcoreapp2.1\CookedRabbit.Core.Benchmark.csproj.FileListAbsolute.txt' because it is being used by another process. [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
    1 Warning(s)
    2 Error(s)

Time Elapsed 00:00:02.05

@houseofcat
Copy link
Contributor Author

houseofcat commented Jul 15, 2018

When in doubt... run simple tests again.

Sleep benchmark fails.

public static void Main(string[] args)
{
    var summary = BenchmarkRunner.Run<Sleep>();
    Console.ReadLine();
}
public class Sleep
{
    [Benchmark]
    public void Time50() => Thread.Sleep(50);

    [Benchmark(Baseline = true)]
    public void Time100() => Thread.Sleep(100);

    [Benchmark]
    public void Time150() => Thread.Sleep(150);
}
// Build Exception: Microsoft (R) Build Engine version 15.7.179.6572 for .NET Core
Copyright (C) Microsoft Corporation. All rights reserved.

  CookedRabbit.Core.Library -> C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Library\bin\Release\netcoreapp2.1\CookedRabbit.Core.Library.dll
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018: The "GenerateRuntimeConfigurationFiles" task failed unexpectedly. [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018: System.IO.IOException: The process cannot access the file 'C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\bin\Release\netcoreapp2.1\CookedRabbit.Core.Benchmark.runtimeconfig.json' because it is being used by another process. [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at System.IO.FileStream.ValidateFileHandle(SafeFileHandle fileHandle) [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at System.IO.FileStream.CreateFileOpenHandle(FileMode mode, FileShare share, FileOptions options) [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share, Int32 bufferSize, FileOptions options) [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share, Int32 bufferSize) [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at System.IO.File.Create(String path) [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at Microsoft.NET.Build.Tasks.GenerateRuntimeConfigurationFiles.WriteToJsonFile(String fileName, Object value) [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at Microsoft.NET.Build.Tasks.GenerateRuntimeConfigurationFiles.WriteRuntimeConfig(ProjectContext projectContext) [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at Microsoft.NET.Build.Tasks.GenerateRuntimeConfigurationFiles.ExecuteCore() [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at Microsoft.NET.Build.Tasks.TaskBase.Execute() [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at Microsoft.Build.BackEnd.TaskExecutionHost.Microsoft.Build.BackEnd.ITaskExecutionHost.Execute() [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at Microsoft.Build.BackEnd.TaskBuilder.ExecuteInstantiatedTask(ITaskExecutionHost taskExecutionHost, TaskLoggingContext taskLoggingContext, TaskHost taskHost, ItemBucket bucket, TaskExecutionMode howToExecuteTask) [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]

Build FAILED.

c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018: The "GenerateRuntimeConfigurationFiles" task failed unexpectedly. [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018: System.IO.IOException: The process cannot access the file 'C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\bin\Release\netcoreapp2.1\CookedRabbit.Core.Benchmark.runtimeconfig.json' because it is being used by another process. [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at System.IO.FileStream.ValidateFileHandle(SafeFileHandle fileHandle) [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at System.IO.FileStream.CreateFileOpenHandle(FileMode mode, FileShare share, FileOptions options) [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share, Int32 bufferSize, FileOptions options) [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share, Int32 bufferSize) [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at System.IO.File.Create(String path) [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at Microsoft.NET.Build.Tasks.GenerateRuntimeConfigurationFiles.WriteToJsonFile(String fileName, Object value) [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at Microsoft.NET.Build.Tasks.GenerateRuntimeConfigurationFiles.WriteRuntimeConfig(ProjectContext projectContext) [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at Microsoft.NET.Build.Tasks.GenerateRuntimeConfigurationFiles.ExecuteCore() [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at Microsoft.NET.Build.Tasks.TaskBase.Execute() [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at Microsoft.Build.BackEnd.TaskExecutionHost.Microsoft.Build.BackEnd.ITaskExecutionHost.Execute() [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at Microsoft.Build.BackEnd.TaskBuilder.ExecuteInstantiatedTask(ITaskExecutionHost taskExecutionHost, TaskLoggingContext taskLoggingContext, TaskHost taskHost, ItemBucket bucket, TaskExecutionMode howToExecuteTask) [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
    0 Warning(s)
    1 Error(s)

Time Elapsed 00:00:00.84


// Build Exception: Microsoft (R) Build Engine version 15.7.179.6572 for .NET Core
Copyright (C) Microsoft Corporation. All rights reserved.

  CookedRabbit.Core.Library -> C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Library\bin\Release\netcoreapp2.1\CookedRabbit.Core.Library.dll
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018: The "GenerateRuntimeConfigurationFiles" task failed unexpectedly. [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018: System.IO.IOException: The process cannot access the file 'C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\bin\Release\netcoreapp2.1\CookedRabbit.Core.Benchmark.runtimeconfig.json' because it is being used by another process. [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at System.IO.FileStream.ValidateFileHandle(SafeFileHandle fileHandle) [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at System.IO.FileStream.CreateFileOpenHandle(FileMode mode, FileShare share, FileOptions options) [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share, Int32 bufferSize, FileOptions options) [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share, Int32 bufferSize) [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at System.IO.File.Create(String path) [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at Microsoft.NET.Build.Tasks.GenerateRuntimeConfigurationFiles.WriteToJsonFile(String fileName, Object value) [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at Microsoft.NET.Build.Tasks.GenerateRuntimeConfigurationFiles.WriteRuntimeConfig(ProjectContext projectContext) [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at Microsoft.NET.Build.Tasks.GenerateRuntimeConfigurationFiles.ExecuteCore() [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at Microsoft.NET.Build.Tasks.TaskBase.Execute() [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at Microsoft.Build.BackEnd.TaskExecutionHost.Microsoft.Build.BackEnd.ITaskExecutionHost.Execute() [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at Microsoft.Build.BackEnd.TaskBuilder.ExecuteInstantiatedTask(ITaskExecutionHost taskExecutionHost, TaskLoggingContext taskLoggingContext, TaskHost taskHost, ItemBucket bucket, TaskExecutionMode howToExecuteTask) [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]

Build FAILED.

c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018: The "GenerateRuntimeConfigurationFiles" task failed unexpectedly. [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018: System.IO.IOException: The process cannot access the file 'C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\bin\Release\netcoreapp2.1\CookedRabbit.Core.Benchmark.runtimeconfig.json' because it is being used by another process. [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at System.IO.FileStream.ValidateFileHandle(SafeFileHandle fileHandle) [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at System.IO.FileStream.CreateFileOpenHandle(FileMode mode, FileShare share, FileOptions options) [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share, Int32 bufferSize, FileOptions options) [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share, Int32 bufferSize) [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at System.IO.File.Create(String path) [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at Microsoft.NET.Build.Tasks.GenerateRuntimeConfigurationFiles.WriteToJsonFile(String fileName, Object value) [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at Microsoft.NET.Build.Tasks.GenerateRuntimeConfigurationFiles.WriteRuntimeConfig(ProjectContext projectContext) [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at Microsoft.NET.Build.Tasks.GenerateRuntimeConfigurationFiles.ExecuteCore() [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at Microsoft.NET.Build.Tasks.TaskBase.Execute() [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at Microsoft.Build.BackEnd.TaskExecutionHost.Microsoft.Build.BackEnd.ITaskExecutionHost.Execute() [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
c:\program files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(171,5): error MSB4018:    at Microsoft.Build.BackEnd.TaskBuilder.ExecuteInstantiatedTask(ITaskExecutionHost taskExecutionHost, TaskLoggingContext taskLoggingContext, TaskHost taskHost, ItemBucket bucket, TaskExecutionMode howToExecuteTask) [C:\GitHub\personal\CookedRabbit\NetCore\CookedRabbit.Core.Benchmark\CookedRabbit.Core.Benchmark.csproj]
    0 Warning(s)
    1 Error(s)

Time Elapsed 00:00:00.90

@houseofcat houseofcat changed the title Struggling To Get Started Struggling To Get Started (NetCore 2.1) Jul 15, 2018
@houseofcat houseofcat changed the title Struggling To Get Started (NetCore 2.1) Struggling To Get Simple Test Started (NetCore 2.1) Jul 15, 2018
@AndreyAkinshin
Copy link
Member

@adamsitnik could you take a look?

@adamsitnik
Copy link
Member

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

Hi @thyams . The proposal looks good to me, could you send a PR and include a link to sample StackOverflow issue?

So far I have seen such behavior when [GlobalCleanup] method had a deadlock or when Windows had some issue with console buffering. I hope that your proposal can fix the latter problem.

@houseofcat
Copy link
Contributor Author

@adamsitnik Done!
#830

adamsitnik pushed a commit that referenced this issue Jul 17, 2018
* Minor fix

Potential fix for SynchronousProcessOutputLoggerWithDiagnoser infinite loop.
Added time in Execute, detected freeze during UnitTest.

* Adding timeout to basestream read.

* Stream doesn't support timeout.

* Enhancing ProcessInput

* Minor tweak.

Disabling Executor timeout in Toolchains.
Adjusting While loop and comments on Process
@adamsitnik
Copy link
Member

@thyams as soon as this build passes you should be able to update to 0.10.14.687 and test if your change has fixed the problem. Please let me know once you give it a try

@houseofcat
Copy link
Contributor Author

houseofcat commented Jul 17, 2018

@adamsitnik No dice! I will keep stabbing at it.

Poking CoreFx team (https://github.com/dotnet/corefx/issues/31138)

@houseofcat
Copy link
Contributor Author

@adamsitnik How do I force BenchmarkDotNet to run in Debug mode, I am detecting an error writing/reading to files during simple tests.

This isn't working...

    public class DebugConfig : ManualConfig
    {
        public DebugConfig()
        {
            Add(JitOptimizationsValidator.DontFailOnError); // ALLOW NON-OPTIMIZED DLLS
        }
    }

@adamsitnik
Copy link
Member

@thyams

public class DebugConfig : ManualConfig
{
    public DebugConfig()
    {
        Add(JitOptimizationsValidator.DontFailOnError); // ALLOW NON-OPTIMIZED DLLS

        Add(Job.Default
            .WithCustomBuildConfiguration("Debug") // to compile in DEBUG
            .With(InProcessToolchain.Instance)); // to debug the benchmark in-process

        // add columns, exporters, loggers, diagnosers etc
    }
}

alinasmirnova pushed a commit to alinasmirnova/BenchmarkDotNet that referenced this issue Sep 22, 2018
…, dotnet#828

* Minor fix

Potential fix for SynchronousProcessOutputLoggerWithDiagnoser infinite loop.
Added time in Execute, detected freeze during UnitTest.

* Adding timeout to basestream read.

* Stream doesn't support timeout.

* Enhancing ProcessInput

* Minor tweak.

Disabling Executor timeout in Toolchains.
Adjusting While loop and comments on Process
@houseofcat
Copy link
Contributor Author

houseofcat commented Sep 28, 2018

I am back @adamsitnik!

I have identified the code that causes issues in a simple Solution file!

It all started when I added delays / sleeps to compare runtimes in parallel. In my own personal library, I have a ThrottleSmallBodyLoops (with has an await Task.Delay(random 0 through 2)). This prevents TPL from choking with mass parallel processes.

The code that causes the benchmark to freeze is await Task.Delay(x); or Thread.Sleep(x). It freezes at writing to file (the above code disassembled).

This is what I believe hangs your CI jobs too!

Solution is attached!
ParallelTestApp.zip

I maybe able to do a PR later for you guys again :)

@adamsitnik
Copy link
Member

Hi @houseofcat !

I talked with @stephentoub about your code sample. Here is what Stephen wrote:

You invoke ProcessString, it calls Task.Delay, Task.Delay returns a task that hasn't completed yet (and won't for at least 5 milliseconds, but likely closer to 15 milliseconds), ProcessString then awaits that task, causing this method to immediately return a Task that hasn't yet completed, and it's that Task that's returned to the Select call. 15 milliseconds later, the Task.Delay task will complete, and its continuation will invoke ComputeHash, after which the Task returned from ProcessString will complete.
15 million milliseconds of delay to process the whole thing, or about 4 hours
That's why you don't see anything in the debugger... the app just spends most of its time waiting

@houseofcat
Copy link
Contributor Author

houseofcat commented Oct 1, 2018

I will double check but the issue occurred for me even on 1 string iterations. Or when the only thing the test does is Task.Delay(xms); or the Thread.Sleep(xms). I will write a simpler test/repro. Stephen's answer makes sense on big waits, but it should be invoking in parallel.

Being frozen on the //After All portion of Benchmark DotNet (reading/writing to file) would be something else than my test still running - at least how it looks like to me.

@stephentoub
Copy link
Member

it should be invoking in parallel

You're referring to the AsParallel? That's part of the LINQ query, which is operating on only 12 items as far as it's concerned (the 12 partitions), regardless of how many elements are in the input. And that AsParallel is largely useless, anyway, as the only thing it's parallelizing is the invocation of the Select, which processes at most 12 items, and for each of those 12, it's basically just invoking the async method (which yields immediately due to the Delay) and immediately returning a Task for it, so there's really nothing there to parallelize.

Regardless of that AsParallel, you are going to end up with 12 asynchronous processing loops running concurrently, and so with 1,000,000 items and 12 concurrent processors (each of which spends most of its time waiting for timers to fire), you'd expect it to take somewhere around 20 minutes.

@houseofcat
Copy link
Contributor Author

houseofcat commented Oct 1, 2018

it should be invoking in parallel

You're referring to the AsParallel? That's part of the LINQ query, which is operating on only 12 items as far as it's concerned (the 12 partitions), regardless of how many elements are in the input. And that AsParallel is largely useless, anyway, as the only thing it's parallelizing is the invocation of the Select, which processes at most 12 items, and for each of those 12, it's basically just invoking the async method (which yields immediately due to the Delay) and immediately returning a Task for it, so there's really nothing there to parallelize.

Regardless of that AsParallel, you are going to end up with 12 asynchronous processing loops running concurrently, and so with 1,000,000 items and 12 concurrent processors (each of which spends most of its time waiting for timers to fire), you'd expect it to take somewhere around 20 minutes.

What I was trying to test doesn't super translate well to the demo Benchmark code I wrote. So I will have to write a more thoughtful test to seem less "stupid" but suffice to say the partitioning code is very performant and utilizes very little system memory.

For good reason too, I took it from your article from back in time:
https://blogs.msdn.microsoft.com/pfxteam/2012/03/05/implementing-a-simple-foreachasync-part-2/

So enough butt kissing!

The goal was to limit degrees of parallelism while iterating. I modified it to use PLINQ instead of Task.Run(() => {} ); as it seemed cleaner to me? I could have been wrong. Task.Run or As Parallel are required so that I am processing at most 1 item but in each partition (in this case 12) simultaneously. So asynchronous and parallel. I guess the core idea behind this is a little old school, I have 12 active logical processors on that CPU, let TPL efficiently assign the work (i.e. without Thread Affinity) but limit the workloads to a maximum of 12 at a time.

The real production code is asynchronously publish to RabbitMQ and/or saving to the DB. As of right now, our devs have a terrible design pattern. Put everything in a List<Task>(); and do an await Task.WhenAll(list); for up to a 100 - 1000 tasks all at once, every 5 - 10 ms reacquiring more work to do over again. Error handling not withstanding, this is done over approximately 138 threads... it's just not performing well as I would personally expect. I did notice that when the batches were smaller, the performance skyrocketed across the board. I wrote a bit of code and then needed to simulate wait time to compare methods of iteration. Thats where the sleeps/delays came in. Looking at GC, overhead, CPU usage, that sort of thing. I think I am going to have just actually hit the DB and RabbitMQ to get real results.

I was trying to prove what I was seeing that when there was a Parallel.ForEach (with max degrees of parallelism) or slower iterator as designed, the overall system performance was far greater. I analogously compared it to the tuning of the pistons of an engine.

What's happening here is that the tests run, and finish, but when generating the report it freezes (but only when there is a Sleep or Delay.) It froze previously in my CookedRabbit library and this code wasn't called but in my get Channels I have an await Task.Delay(Random.Next(0,2)); to throttle loops. I totally get what you guys are saying, 1,000,000 waits is a million waits.

EDIT
I am running it right now on my work VM and it's not freezing (slow but unfrozen) :headscratching:

EDIT 2
@stephentoub @adamsitnik
This is where it's frozen forever in NetCore, from the following lines in BenchmarkDotNet:

https://user-images.githubusercontent.com/1414138/42740075-e8a4afe0-886f-11e8-9178-7e21727d28f9.png
image

Being called from here:

while (!process.StandardOutput.EndOfStream && process.StandardOutput.Peek() > 0)

EndOfStream, sub call Get.

The Process StandardOutput or StandardError have a thread deadlock situation and WaitForExit() runs infinitely due to the Dotnet Processes are not terminating.

Related issue #885
And related to this previous discussion with you: https://github.com/dotnet/corefx/issues/31138

So I think a part of this is => what mechanism does a dotnet host project determine it's finished and properly terminate? Because I do have a keep heartbeat alive in the background when this happens... could this prevent the dotnet host from terminating?

@houseofcat
Copy link
Contributor Author

houseofcat commented Oct 2, 2018

Based on my latest step through, it is 100% caused by Benchmark Processes not terminating under dotnet host thus not releasing the EndOfStream.

Since my test code produces no infinite loops, I have to assume a deadlock on StandardOutput, StandardError, or both. Manually terminating the process "unfreezes" the lock, however, no results are passed through to the main logger host thus a report can't be generated.

My stackoverflow research indicates that a full buffer could cause a deadlock scenario as described. I will move code to an event driven paradigm on data received to test a buffer overflow to see if it works.

@houseofcat houseofcat changed the title Struggling To Get Simple Test Started (NetCore 2.1) Benchmark Reporting - Deadlock/Getting Stuck Reading From Process.StandardOutput (NetCore 2.1) Oct 7, 2018
@houseofcat
Copy link
Contributor Author

houseofcat commented Oct 10, 2018

I converted the entire process to event driven paradigm on processing StandardOutput and StandardError. Freezes at the same spot. I pulled everything into my library to step through every component available to me.

Does BenchmarkDotNet not support C# 7.1+? I have my code set to latest but when everything is integrated together, I get an error stating my C# feature set is too high specifically the use of default literal. Can I get a confirmation that BDN doesn't support C# 7.1+ @adamsitnik ?

@adamsitnik
Copy link
Member

adamsitnik commented Oct 10, 2018

@houseofcat if your project file (.csproj/vbproj/fsproj) with benchmarks defines a LangVersion entry, it will be copied to the auto-generated project file

but it does not work when LangVersion is defined in the .props file #854

@houseofcat
Copy link
Contributor Author

I will have a look at it after work! Thanks!

@MBurtsev
Copy link

MBurtsev commented Oct 13, 2019

Today i have some problem after update VS2019 to 16.3.4. Benchmark frozen at:
123
In project properties I saw this:
123
https://docs.microsoft.com/en-us/dotnet/csharp/language-reference/configure-language-version
@adamsitnik Now the benchmark does not work. How I can solve this ?

@MBurtsev
Copy link

The task manager shows that the benchmark is doing something

@adamsitnik
Copy link
Member

Hi @Nim

Did you select some part of the printed text in console? By default Windows OS let's the app run then, but blocks the printing to standard output.

Also, you can always attach debugger to the benchmark process and see what is going on:

obraz

You can read more about troubleshooting BDN in our docs: https://benchmarkdotnet.org/articles/guides/troubleshooting.html

@MBurtsev
Copy link

MBurtsev commented Oct 14, 2019

@adamsitnik I apologize for disturbing you. Freezing was my fault. But I improved the helper class for multi-threaded tests. Later I can share it so that you add an example to the documentation. If it is interesting.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
5 participants