Feature request: quiet mode

[jskeet]

It would be really nice to be able to start a long run, and instead of getting a long scrolling list where most of the time I can't see what's executing, instead have an in-place display, updated appropriately and consisting of:

• Possibly the options involved (may be too long-winded)
• Current / total test count, e.g. "Running test 32/152"
• Name of currently running test
• Maybe the results of the previous test, for the sake of interest?
• Current execution time and estimated total time (or remaining time)

I don't know enough about the execution timing to know whether estimating the total remaining time is viable, but I suspect it is... we have a target time for each test, right?

[jskeet]

I realize that a multi-line updating status box may be tricky - a weaker form of this feature request would be a mode which just says which test it's executing each time it starts a new one, along with the count, e.g. output of

[1/250] FooBenchmark
[2/250] BarBenchmark
[...]
[250/250] BazBenchmark
Tests complete. Total time: ...
Output in ...

Also, "quiet" may not be an ideal option name for this, as that would probably suggest even quieter output...

[ig-sinicyn]

I've recently done something like this. The idea is borrowed from SynchronousProcessOutputLoggerWithDiagnoser.

There's HostLogger class that filters the output and prints only error messages and messages that starts with // ! or // ?.
Also, all output between "// !<-- and // !--> lines is not filtered at all.

Code
Tests

This approach works well for us, for example, output for the test simplifies up to:

Test Name:  RunSensitivityPerfTests
Test Outcome:   Skipped
Result Message: 
Test completed with warnings, details below.
Warnings:
    * Run #1: Job X64_Jit-RyuJit_Warmup3_Target10_Process1_IterationTime10, property Platform: The current process is not run as x64.
    * Run #1: Job X64_Jit-RyuJit_Warmup3_Target10_Process1_IterationTime10, property Jit: The current setup does not support RyuJit.
Diagnostic messages:
    * Run #1: Analyser CompetitionLimitsAnnotateAnalyser: no warnings.
Result StandardOutput:  
BenchmarkDotNet=v0.9.6.0
OS=Microsoft Windows NT 10.0.10586.0
Processor=Intel(R) Core(TM) i7-3537U CPU @ 2.00GHz, ProcessorCount=4
Frequency=2435882 ticks, Resolution=410.5289 ns, Timer=TSC
HostCLR=MS.NET 4.0.30319.42000, Arch=32-bit RELEASE
JitModules=clrjit-v4.6.1080.0

Type=SensitivityPerfTests  Mode=Throughput  Platform=X64  
Jit=RyuJit  Toolchain=InProcessToolchain  LaunchCount=1  
WarmupCount=3  TargetCount=10  

         Method |   Count |            Median |        StdDev | Scaled |               Min | ScaledP50 | ScaledP85 | ScaledP95 |               Max |
--------------- |-------- |------------------ |-------------- |------- |------------------ |---------- |---------- |---------- |------------------ |
 Test00Baseline |    1000 |       629.0304 ns |     7.1469 ns |   1.00 |       625.7406 ns |      1.00 |      1.00 |      1.00 |       647.6896 ns |
  Test01PlusOne |    1000 |     1,041.4007 ns |     8.7152 ns |   1.66 |     1,025.6839 ns |      1.66 |      1.63 |      1.62 |     1,047.7402 ns |
 Test00Baseline |   10000 |     6,200.4248 ns |   225.6878 ns |   1.00 |     6,105.1141 ns |      1.00 |      1.00 |      1.00 |     6,838.3135 ns |
  Test01PlusOne |   10000 |    10,473.4569 ns |    58.9077 ns |   1.69 |    10,413.6062 ns |      1.69 |      1.64 |      1.59 |    10,578.6820 ns |
 Test00Baseline |  100000 |    63,458.4028 ns | 1,452.6043 ns |   1.00 |    61,918.2306 ns |      1.00 |      1.00 |      1.00 |    66,715.0819 ns |
  Test01PlusOne |  100000 |   105,205.5974 ns | 1,648.3552 ns |   1.66 |   104,572.5186 ns |      1.66 |      1.64 |      1.65 |   110,060.6420 ns |
 Test00Baseline | 1000000 |   651,163.0078 ns | 3,761.8947 ns |   1.00 |   643,914.6069 ns |      1.00 |      1.00 |      1.00 |   656,204.8163 ns |
  Test01PlusOne | 1000000 | 1,048,798.7510 ns | 6,459.7725 ns |   1.61 | 1,042,291.8680 ns |      1.61 |      1.61 |      1.62 | 1,066,266.7570 ns |


========================================

// !Run 1, total runs (expected): 1.
Job X64_Jit-RyuJit_Warmup3_Target10_Process1_IterationTime10, property Platform: The current process is not run as x64.
Job X64_Jit-RyuJit_Warmup3_Target10_Process1_IterationTime10, property Jit: The current setup does not support RyuJit.
// ? #1.1, Informational@Analyser: Analyser CompetitionLimitsAnnotateAnalyser: no warnings.
// ! #1.2, Warning@Validator: Job X64_Jit-RyuJit_Warmup3_Target10_Process1_IterationTime10, property Platform: The current process is not run as x64.
// ! #1.3, Warning@Validator: Job X64_Jit-RyuJit_Warmup3_Target10_Process1_IterationTime10, property Jit: The current setup does not support RyuJit.

(the log content starts after the ============= line)

[mattwarren]

@ig-sinicyn would you be happy to submit a PR that adds HostLogger.cs to BenchmarkDotNet?

It looks really nice and it would be good to have it available OOTB.

[ig-sinicyn]

@mattwarren will do.

Any suggestions for prefixes / logger class name / constant names?

UPD: Note that the logger name will be widely used, example:

                if (competitionState.HasCriticalErrorsInRun)
                {
                    logger.WriteLineInfo($"{HostLogger.LogImportantInfoPrefix}Breaking the run. High severity error occured.");
                    break;
                }

so it has to be short and obvious.

Also, I dislike the prefixes used to mark LogImportantAreaStart / End, but have no idea how to make it better.
Real-world example:

some text
...
// !<--------xml_annotation_begin------
<?xml version="1.0" encoding="utf-16"?>
<CompetitionBenchmarks>
    <Competition Target="CodeJam.PerfTests.CompetitionLimitsAnnotateAnalyserTests+HighAccuracyBenchmark, CodeJam.PerfTests-Tests">
        <Candidate Target="SlowerX10" MinRatio="9.70" MaxRatio="30.90" />
    </Competition>
</CompetitionBenchmarks>
// !-->-------xml_annotation_end-------
...
some text

The log contains sections with xml that are parsed and used to adjust perftest limits. It allows to collect timings from another machines / CI build servers and annotate perftest code with these timings.

Here's the test that checks it. Note that the benchmark is automatically annotated with limits from the log.

[ig-sinicyn]

@mattwarren

Well, the develop branch does not build at all, #187 .
You DEFINITELY need to setup an appveyor build:)

If this is urgent, feel free to copy the HostLogger' code by yourself.

[adamsitnik]

@ig-sinicyn do you suffer from the same problems when trying to build from develop branch?

[ig-sinicyn]

@adamsitnik yes, same issue here.