v0.13.5: GlobalCleanup Console.WriteLine output messed within //AfterActualRun area (fine in 0.13.2)

[Taneeda]

trafficstars

Hi there,

today I updated from 0.13.2 to the latest version 0.13.5 and recognized that my Console.WriteLine outputs are now messed up within the //AfterActualRun output area of the log file.

Not sure what exactly is going on, I haven't changed my benchmarks or outputs lately... unfortunately I can't upgrade to the latest version with this issue and hope you can help with this issue. Seems version 0.13.3 introduced this new behavior.

Log-Files from tests of different versions:

• v0.13.5 --> BenchmarkDotNetOutputBug.Benchmarks-20230508-084211.log
• v0.13.4 --> BenchmarkDotNetOutputBug.Benchmarks-20230508-084553.log
• v0.13.3 --> BenchmarkDotNetOutputBug.Benchmarks-20230508-084837.log
• v0.13.2 --> BenchmarkDotNetOutputBug.Benchmarks-20230508-085341.log

Here an example project to reproduce the behavior: BenchmarkDotNetOutputBug.zip

using BenchmarkDotNet.Attributes;
using BenchmarkDotNet.Configs;
using System.Text;

namespace BenchmarkDotNetOutputBug
{
    public class BenchmarksRunner
    {
        public const string BenchmarkProjectName = "BenchmarkDotNetOutputBug";
        public static readonly string BenchmarkArtifactsRootPath =
            Path.Combine(
                Path.GetFullPath(
                    DefaultConfig.Instance.ArtifactsPath + "/../../../../../"
                    + BenchmarkProjectName
                ), "BenchmarkDotNet.Artifacts"
            );

        public static void Main()
        {
            ManualConfig customConfig = DefaultConfig.Instance
                .WithArtifactsPath(BenchmarkArtifactsRootPath);
            _ = BenchmarkDotNet.Running.BenchmarkRunner
                .Run(typeof(Benchmarks).Assembly, customConfig);
        }
    }

    public class Benchmarks
    {
        private long _result = 0;
        private int _loopCount = 0;

        [Params(10, 25, 50)]
        public int _count = 0;

        private string GetOutput()
        {
            return new StringBuilder()
                .Append("Pseudo stats:").Append('\n')
                .Append('\t').Append("- _loopCount: ").Append(_loopCount).Append('\n')
                .Append('\t').Append("- _result: ").Append(_result)
                .ToString();
        }

        [GlobalCleanup]
        public void Cleanup()
        {
            Console.WriteLine(GetOutput());
        }

        [GlobalSetup]
        public void Setup()
        {
            _loopCount = _count;
        }

        [Benchmark]
        public double MyBenchmark()
        {
            for (int i = 0; i < _loopCount; i++)
                _result++;
            return _result;
        }
    }
}

Greetings

[AndreyAkinshin]

@Taneeda thanks for the detailed report! It is a side effect of anonymous pipes that were introduced in v0.13.3: now native BenchmarkDotNet logs are handled asynchronously from handling the direct Console.WriteLine output (partially related to #2299).

@adamsitnik do you have any thoughts on that?

@Taneeda

unfortunately I can't upgrade to the latest version with this issue and hope you can help with this issue.

Why do you experience a problem because of this mixed log?

[Taneeda]

Hi there,

thx for the response...

Why do you experience a problem because of this mixed log?

In the log, I output some benchmarking stats from GlobalCleanup() which I read from log file in later process. I could handle this, but I assumed it isn't intended that the outputs (Setup and Cleanup) are messed up, please correct me if I am wrong :)

[Taneeda]

Something new to this topic, any comments? Thx for the help.

Update: new content mixing behavior I recently discovered while adjusting my implementation to read the "Calculation statistics" content from the mixed log...

[AndreyAkinshin]

@Taneeda

from GlobalCleanup() which I read from log file in later process

The fact that the BenchmarkDotNet log contains the output of your benchmarks is a side-effect of the internal implementation specifics, it's not a feature. In our Intro samples, we use this side-effect to illustrate the internal logic of BenchmarkDotNet, not to promote the 'printing to the console' approach.

To resolve your problem, I can suggest you manually save data in GlobalCleanup (e.g., to a separate log file that you can fully control). What do you think about such an approach?

@adamsitnik do you have any thoughts on how we should handle the console output?

[Taneeda]

Sorry for the late answer, completely forgot this issue meanwhile. For the moment I solved this by some simple markers in the output, as long the output is there this is ok for me. Your suggestions is the better way and will be done in the future, so thx for that.

@AndreyAkinshin thx for the hint, maybe a little hint or warning in the Setup and Cleanup documentation related to the possible output mess could help.

Personally, i would appreciate some feature that allows log-output in several benchmarking stages, at least for me there is a high benefit.