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

Feature request: quiet mode #190

Open
jskeet opened this issue May 24, 2016 · 18 comments · May be fixed by #2161 or #2594
Open

Feature request: quiet mode #190

jskeet opened this issue May 24, 2016 · 18 comments · May be fixed by #2161 or #2594

Comments

@jskeet
Copy link

jskeet commented May 24, 2016

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?

@AndreyAkinshin AndreyAkinshin self-assigned this May 24, 2016
@AndreyAkinshin AndreyAkinshin added this to the v0.9.x milestone May 24, 2016
@jskeet
Copy link
Author

jskeet commented May 25, 2016

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
Copy link
Contributor

ig-sinicyn commented May 26, 2016

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
Copy link
Contributor

@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
Copy link
Contributor

ig-sinicyn commented May 27, 2016

@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
Copy link
Contributor

@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
Copy link
Member

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

@ig-sinicyn
Copy link
Contributor

@adamsitnik yes, same issue here.

@dbogatov
Copy link

dbogatov commented Jun 28, 2018

I want similar functionality for different reason.
I run dry jobs from unit tests to make sure benchmarks are valid.
I don't want any output from the tool.

Is this possible?

For now I have

No loggers defined, you will not see any progress!
No loggers defined, you will not see any progress!
No loggers defined, you will not see any progress!
No loggers defined, you will not see any progress!
No loggers defined, you will not see any progress!
No loggers defined, you will not see any progress!
No loggers defined, you will not see any progress!
No loggers defined, you will not see any progress!
Global total time: 00:00:02 (2.86 sec), executed benchmarks: 36
No loggers defined, you will not see any progress!
No loggers defined, you will not see any progress!
Global total time: 00:00:00 (0.05 sec), executed benchmarks: 2

@adamsitnik
Copy link
Member

I don't want any output from the tool.

No, but the issue is up for grabs ;)

@vivekbm
Copy link

vivekbm commented Apr 22, 2020

Hi @adamsitnik ,

Is this issue still open?

Regards,
Vivek M

@adamsitnik
Copy link
Member

Some hints for the potential contributor:

  • When I run a sample benchmark like the following:
cd samples\BenchmarkDotNet.Samples\
dotnet run -c Release -f net6.0 --filter *IntroDisassembly.* --job dry

I am currently getting a lot of output:

// Validating benchmarks:
// ***** BenchmarkRunner: Start   *****
// ***** Found 2 benchmark(s) in total *****
// ***** Building 1 exe(s) in Parallel: Start   *****
// start dotnet  restore /p:UseSharedCompilation=false /p:BuildInParallel=false /m:1 /p:Deterministic=true /p:Optimize=true in D:\projects\BenchmarkDotNet\samples\BenchmarkDotNet.Samples\bin\Release\net6.0\da12d07c-1a7c-4683-82fb-8b86b224d89c
// command took 0.7s and exited with 0
// start dotnet  build -c Release --no-restore /p:UseSharedCompilation=false /p:BuildInParallel=false /m:1 /p:Deterministic=true /p:Optimize=true in D:\projects\BenchmarkDotNet\samples\BenchmarkDotNet.Samples\bin\Release\net6.0\da12d07c-1a7c-4683-82fb-8b86b224d89c
// command took 2.08s and exited with 0
// ***** Done, took 00:00:02 (2.93 sec)   *****
// Found 2 benchmarks:
//   IntroDisassembly.SumLocal: DefaultJob
//   IntroDisassembly.SumField: DefaultJob

Setup power plan (GUID: 8c5e7fda-e8bf-4a96-9a85-a6e23a8c635c FriendlyName: High performance)
// **************************
// Benchmark: IntroDisassembly.SumLocal: DefaultJob
// *** Execute ***
// Launch: 1 / 1
// Execute: dotnet da12d07c-1a7c-4683-82fb-8b86b224d89c.dll --anonymousPipes 5884 5888 --benchmarkName BenchmarkDotNet.Samples.IntroDisassembly.SumLocal --job Default --benchmarkId 0 in D:\projects\BenchmarkDotNet\samples\BenchmarkDotNet.Samples\bin\Release\net6.0\da12d07c-1a7c-4683-82fb-8b86b224d89c\bin\Release\net6.0
// BeforeAnythingElse

// Benchmark Process Environment Information:
// Runtime=.NET 6.0.10 (6.0.1022.47605), X64 RyuJIT AVX2
// GC=Concurrent Workstation
// HardwareIntrinsics=AVX2,AES,BMI1,BMI2,FMA,LZCNT,PCLMUL,POPCNT VectorSize=256
// Job: DefaultJob

OverheadJitting  1: 1 op, 190400.00 ns, 190.4000 us/op
WorkloadJitting  1: 1 op, 349100.00 ns, 349.1000 us/op

OverheadJitting  2: 16 op, 317400.00 ns, 19.8375 us/op
WorkloadJitting  2: 16 op, 345100.00 ns, 21.5688 us/op

WorkloadPilot    1: 16 op, 1100.00 ns, 68.7500 ns/op
WorkloadPilot    2: 32 op, 1500.00 ns, 46.8750 ns/op
WorkloadPilot    3: 64 op, 2700.00 ns, 42.1875 ns/op
WorkloadPilot    4: 128 op, 5400.00 ns, 42.1875 ns/op
WorkloadPilot    5: 256 op, 9800.00 ns, 38.2812 ns/op
WorkloadPilot    6: 512 op, 19100.00 ns, 37.3047 ns/op
WorkloadPilot    7: 1024 op, 38000.00 ns, 37.1094 ns/op
WorkloadPilot    8: 2048 op, 76100.00 ns, 37.1582 ns/op
WorkloadPilot    9: 4096 op, 151900.00 ns, 37.0850 ns/op
WorkloadPilot   10: 8192 op, 308700.00 ns, 37.6831 ns/op
WorkloadPilot   11: 16384 op, 621900.00 ns, 37.9578 ns/op
WorkloadPilot   12: 32768 op, 1233700.00 ns, 37.6495 ns/op
WorkloadPilot   13: 65536 op, 2628800.00 ns, 40.1123 ns/op
WorkloadPilot   14: 131072 op, 5023500.00 ns, 38.3263 ns/op
WorkloadPilot   15: 262144 op, 9782600.00 ns, 37.3177 ns/op
WorkloadPilot   16: 524288 op, 19743000.00 ns, 37.6568 ns/op
WorkloadPilot   17: 1048576 op, 41267200.00 ns, 39.3555 ns/op
WorkloadPilot   18: 2097152 op, 91984800.00 ns, 43.8618 ns/op
WorkloadPilot   19: 4194304 op, 166421200.00 ns, 39.6779 ns/op
WorkloadPilot   20: 8388608 op, 315102900.00 ns, 37.5632 ns/op
WorkloadPilot   21: 16777216 op, 637755600.00 ns, 38.0132 ns/op

OverheadWarmup   1: 16777216 op, 68318800.00 ns, 4.0721 ns/op
OverheadWarmup   2: 16777216 op, 68309900.00 ns, 4.0716 ns/op
OverheadWarmup   3: 16777216 op, 67619500.00 ns, 4.0304 ns/op
OverheadWarmup   4: 16777216 op, 34646800.00 ns, 2.0651 ns/op
OverheadWarmup   5: 16777216 op, 25317900.00 ns, 1.5091 ns/op
OverheadWarmup   6: 16777216 op, 25819000.00 ns, 1.5389 ns/op
OverheadWarmup   7: 16777216 op, 25664200.00 ns, 1.5297 ns/op
OverheadWarmup   8: 16777216 op, 25577200.00 ns, 1.5245 ns/op
OverheadWarmup   9: 16777216 op, 26031900.00 ns, 1.5516 ns/op
OverheadWarmup  10: 16777216 op, 25626500.00 ns, 1.5275 ns/op

OverheadActual   1: 16777216 op, 25544700.00 ns, 1.5226 ns/op
OverheadActual   2: 16777216 op, 25610100.00 ns, 1.5265 ns/op
OverheadActual   3: 16777216 op, 25730000.00 ns, 1.5336 ns/op
OverheadActual   4: 16777216 op, 26567200.00 ns, 1.5835 ns/op
OverheadActual   5: 16777216 op, 26090400.00 ns, 1.5551 ns/op
OverheadActual   6: 16777216 op, 25994300.00 ns, 1.5494 ns/op
OverheadActual   7: 16777216 op, 25604900.00 ns, 1.5262 ns/op
OverheadActual   8: 16777216 op, 25673900.00 ns, 1.5303 ns/op
OverheadActual   9: 16777216 op, 25632300.00 ns, 1.5278 ns/op
OverheadActual  10: 16777216 op, 25532100.00 ns, 1.5218 ns/op
OverheadActual  11: 16777216 op, 25620100.00 ns, 1.5271 ns/op
OverheadActual  12: 16777216 op, 26015300.00 ns, 1.5506 ns/op
OverheadActual  13: 16777216 op, 25812200.00 ns, 1.5385 ns/op
OverheadActual  14: 16777216 op, 25872000.00 ns, 1.5421 ns/op
OverheadActual  15: 16777216 op, 25497200.00 ns, 1.5198 ns/op

WorkloadWarmup   1: 16777216 op, 629386900.00 ns, 37.5144 ns/op
WorkloadWarmup   2: 16777216 op, 633095000.00 ns, 37.7354 ns/op
WorkloadWarmup   3: 16777216 op, 633127200.00 ns, 37.7373 ns/op
WorkloadWarmup   4: 16777216 op, 629163000.00 ns, 37.5010 ns/op
WorkloadWarmup   5: 16777216 op, 624077300.00 ns, 37.1979 ns/op
WorkloadWarmup   6: 16777216 op, 642822900.00 ns, 38.3152 ns/op
WorkloadWarmup   7: 16777216 op, 628804800.00 ns, 37.4797 ns/op

// BeforeActualRun
WorkloadActual   1: 16777216 op, 630146500.00 ns, 37.5597 ns/op
WorkloadActual   2: 16777216 op, 642437500.00 ns, 38.2923 ns/op
WorkloadActual   3: 16777216 op, 634689800.00 ns, 37.8305 ns/op
WorkloadActual   4: 16777216 op, 654861100.00 ns, 39.0328 ns/op
WorkloadActual   5: 16777216 op, 689573300.00 ns, 41.1018 ns/op
WorkloadActual   6: 16777216 op, 637270900.00 ns, 37.9843 ns/op
WorkloadActual   7: 16777216 op, 636116800.00 ns, 37.9155 ns/op
WorkloadActual   8: 16777216 op, 633013200.00 ns, 37.7305 ns/op
WorkloadActual   9: 16777216 op, 642153700.00 ns, 38.2753 ns/op
WorkloadActual  10: 16777216 op, 630290200.00 ns, 37.5682 ns/op
WorkloadActual  11: 16777216 op, 626370100.00 ns, 37.3346 ns/op
WorkloadActual  12: 16777216 op, 629002800.00 ns, 37.4915 ns/op
WorkloadActual  13: 16777216 op, 625766800.00 ns, 37.2986 ns/op
WorkloadActual  14: 16777216 op, 632426400.00 ns, 37.6956 ns/op
WorkloadActual  15: 16777216 op, 632578700.00 ns, 37.7046 ns/op

// AfterActualRun
WorkloadResult   1: 16777216 op, 604472600.00 ns, 36.0294 ns/op
WorkloadResult   2: 16777216 op, 616763600.00 ns, 36.7620 ns/op
WorkloadResult   3: 16777216 op, 609015900.00 ns, 36.3002 ns/op
WorkloadResult   4: 16777216 op, 611597000.00 ns, 36.4540 ns/op
WorkloadResult   5: 16777216 op, 610442900.00 ns, 36.3852 ns/op
WorkloadResult   6: 16777216 op, 607339300.00 ns, 36.2002 ns/op
WorkloadResult   7: 16777216 op, 616479800.00 ns, 36.7451 ns/op
WorkloadResult   8: 16777216 op, 604616300.00 ns, 36.0379 ns/op
WorkloadResult   9: 16777216 op, 600696200.00 ns, 35.8043 ns/op
WorkloadResult  10: 16777216 op, 603328900.00 ns, 35.9612 ns/op
WorkloadResult  11: 16777216 op, 600092900.00 ns, 35.7683 ns/op
WorkloadResult  12: 16777216 op, 606752500.00 ns, 36.1653 ns/op
WorkloadResult  13: 16777216 op, 606904800.00 ns, 36.1743 ns/op

// AfterAll
// Benchmark Process 22748 has exited with code 0.

Mean = 36.214 ns, StdErr = 0.087 ns (0.24%), N = 13, StdDev = 0.313 ns
Min = 35.768 ns, Q1 = 36.029 ns, Median = 36.174 ns, Q3 = 36.385 ns, Max = 36.762 ns
IQR = 0.356 ns, LowerFence = 35.496 ns, UpperFence = 36.919 ns
ConfidenceInterval = [35.839 ns; 36.589 ns] (CI 99.9%), Margin = 0.375 ns (1.04% of Mean)
Skewness = 0.37, Kurtosis = 1.98, MValue = 2

// ** Remained 1 (50.0%) benchmark(s) to run. Estimated finish 2022-10-14 19:43 (0h 0m from now) **
Setup power plan (GUID: 8c5e7fda-e8bf-4a96-9a85-a6e23a8c635c FriendlyName: High performance)
// **************************
// Benchmark: IntroDisassembly.SumField: DefaultJob
// *** Execute ***
// Launch: 1 / 1
// Execute: dotnet da12d07c-1a7c-4683-82fb-8b86b224d89c.dll --anonymousPipes 1572 1872 --benchmarkName BenchmarkDotNet.Samples.IntroDisassembly.SumField --job Default --benchmarkId 1 in D:\projects\BenchmarkDotNet\samples\BenchmarkDotNet.Samples\bin\Release\net6.0\da12d07c-1a7c-4683-82fb-8b86b224d89c\bin\Release\net6.0
// BeforeAnythingElse

// Benchmark Process Environment Information:
// Runtime=.NET 6.0.10 (6.0.1022.47605), X64 RyuJIT AVX2
// GC=Concurrent Workstation
// HardwareIntrinsics=AVX2,AES,BMI1,BMI2,FMA,LZCNT,PCLMUL,POPCNT VectorSize=256
// Job: DefaultJob

OverheadJitting  1: 1 op, 158900.00 ns, 158.9000 us/op
WorkloadJitting  1: 1 op, 216400.00 ns, 216.4000 us/op

OverheadJitting  2: 16 op, 303600.00 ns, 18.9750 us/op
WorkloadJitting  2: 16 op, 298500.00 ns, 18.6562 us/op

WorkloadPilot    1: 16 op, 1300.00 ns, 81.2500 ns/op
WorkloadPilot    2: 32 op, 1900.00 ns, 59.3750 ns/op
WorkloadPilot    3: 64 op, 3600.00 ns, 56.2500 ns/op
WorkloadPilot    4: 128 op, 6900.00 ns, 53.9062 ns/op
WorkloadPilot    5: 256 op, 13600.00 ns, 53.1250 ns/op
WorkloadPilot    6: 512 op, 26700.00 ns, 52.1484 ns/op
WorkloadPilot    7: 1024 op, 54000.00 ns, 52.7344 ns/op
WorkloadPilot    8: 2048 op, 106100.00 ns, 51.8066 ns/op
WorkloadPilot    9: 4096 op, 278300.00 ns, 67.9443 ns/op
WorkloadPilot   10: 8192 op, 429000.00 ns, 52.3682 ns/op
WorkloadPilot   11: 16384 op, 847600.00 ns, 51.7334 ns/op
WorkloadPilot   12: 32768 op, 1688600.00 ns, 51.5320 ns/op
WorkloadPilot   13: 65536 op, 3495200.00 ns, 53.3325 ns/op
WorkloadPilot   14: 131072 op, 6845500.00 ns, 52.2270 ns/op
WorkloadPilot   15: 262144 op, 13762400.00 ns, 52.4994 ns/op
WorkloadPilot   16: 524288 op, 27370400.00 ns, 52.2049 ns/op
WorkloadPilot   17: 1048576 op, 54702800.00 ns, 52.1687 ns/op
WorkloadPilot   18: 2097152 op, 109218200.00 ns, 52.0793 ns/op
WorkloadPilot   19: 4194304 op, 217543800.00 ns, 51.8665 ns/op
WorkloadPilot   20: 8388608 op, 436138400.00 ns, 51.9917 ns/op
WorkloadPilot   21: 16777216 op, 873989900.00 ns, 52.0939 ns/op

OverheadWarmup   1: 16777216 op, 33203300.00 ns, 1.9791 ns/op
OverheadWarmup   2: 16777216 op, 33121100.00 ns, 1.9742 ns/op
OverheadWarmup   3: 16777216 op, 33496800.00 ns, 1.9966 ns/op
OverheadWarmup   4: 16777216 op, 33920600.00 ns, 2.0218 ns/op
OverheadWarmup   5: 16777216 op, 33115600.00 ns, 1.9738 ns/op
OverheadWarmup   6: 16777216 op, 34175900.00 ns, 2.0370 ns/op
OverheadWarmup   7: 16777216 op, 33622600.00 ns, 2.0041 ns/op

OverheadActual   1: 16777216 op, 33037000.00 ns, 1.9692 ns/op
OverheadActual   2: 16777216 op, 33324300.00 ns, 1.9863 ns/op
OverheadActual   3: 16777216 op, 33408700.00 ns, 1.9913 ns/op
OverheadActual   4: 16777216 op, 34150100.00 ns, 2.0355 ns/op
OverheadActual   5: 16777216 op, 33474400.00 ns, 1.9952 ns/op
OverheadActual   6: 16777216 op, 33997300.00 ns, 2.0264 ns/op
OverheadActual   7: 16777216 op, 33800400.00 ns, 2.0147 ns/op
OverheadActual   8: 16777216 op, 34093900.00 ns, 2.0322 ns/op
OverheadActual   9: 16777216 op, 34101100.00 ns, 2.0326 ns/op
OverheadActual  10: 16777216 op, 26218000.00 ns, 1.5627 ns/op
OverheadActual  11: 16777216 op, 25898200.00 ns, 1.5437 ns/op
OverheadActual  12: 16777216 op, 25215400.00 ns, 1.5030 ns/op
OverheadActual  13: 16777216 op, 25507200.00 ns, 1.5203 ns/op
OverheadActual  14: 16777216 op, 25170900.00 ns, 1.5003 ns/op
OverheadActual  15: 16777216 op, 25066900.00 ns, 1.4941 ns/op
OverheadActual  16: 16777216 op, 25425400.00 ns, 1.5155 ns/op
OverheadActual  17: 16777216 op, 25321100.00 ns, 1.5093 ns/op
OverheadActual  18: 16777216 op, 25219000.00 ns, 1.5032 ns/op
OverheadActual  19: 16777216 op, 25552100.00 ns, 1.5230 ns/op
OverheadActual  20: 16777216 op, 25496100.00 ns, 1.5197 ns/op

WorkloadWarmup   1: 16777216 op, 884909100.00 ns, 52.7447 ns/op
WorkloadWarmup   2: 16777216 op, 892600700.00 ns, 53.2031 ns/op
WorkloadWarmup   3: 16777216 op, 875557000.00 ns, 52.1873 ns/op
WorkloadWarmup   4: 16777216 op, 878414600.00 ns, 52.3576 ns/op
WorkloadWarmup   5: 16777216 op, 874033300.00 ns, 52.0964 ns/op
WorkloadWarmup   6: 16777216 op, 878473800.00 ns, 52.3611 ns/op

// BeforeActualRun
WorkloadActual   1: 16777216 op, 885216700.00 ns, 52.7630 ns/op
WorkloadActual   2: 16777216 op, 896691400.00 ns, 53.4470 ns/op
WorkloadActual   3: 16777216 op, 887262500.00 ns, 52.8850 ns/op
WorkloadActual   4: 16777216 op, 892163100.00 ns, 53.1771 ns/op
WorkloadActual   5: 16777216 op, 884707700.00 ns, 52.7327 ns/op
WorkloadActual   6: 16777216 op, 886072700.00 ns, 52.8140 ns/op
WorkloadActual   7: 16777216 op, 887113900.00 ns, 52.8761 ns/op
WorkloadActual   8: 16777216 op, 890271100.00 ns, 53.0643 ns/op
WorkloadActual   9: 16777216 op, 889467500.00 ns, 53.0164 ns/op
WorkloadActual  10: 16777216 op, 888488500.00 ns, 52.9580 ns/op
WorkloadActual  11: 16777216 op, 887074400.00 ns, 52.8738 ns/op
WorkloadActual  12: 16777216 op, 889794900.00 ns, 53.0359 ns/op
WorkloadActual  13: 16777216 op, 883611000.00 ns, 52.6673 ns/op
WorkloadActual  14: 16777216 op, 885368200.00 ns, 52.7721 ns/op
WorkloadActual  15: 16777216 op, 883108700.00 ns, 52.6374 ns/op

// AfterActualRun
WorkloadResult   1: 16777216 op, 859158600.00 ns, 51.2098 ns/op
WorkloadResult   2: 16777216 op, 861204400.00 ns, 51.3318 ns/op
WorkloadResult   3: 16777216 op, 866105000.00 ns, 51.6239 ns/op
WorkloadResult   4: 16777216 op, 858649600.00 ns, 51.1795 ns/op
WorkloadResult   5: 16777216 op, 860014600.00 ns, 51.2609 ns/op
WorkloadResult   6: 16777216 op, 861055800.00 ns, 51.3229 ns/op
WorkloadResult   7: 16777216 op, 864213000.00 ns, 51.5111 ns/op
WorkloadResult   8: 16777216 op, 863409400.00 ns, 51.4632 ns/op
WorkloadResult   9: 16777216 op, 862430400.00 ns, 51.4049 ns/op
WorkloadResult  10: 16777216 op, 861016300.00 ns, 51.3206 ns/op
WorkloadResult  11: 16777216 op, 863736800.00 ns, 51.4827 ns/op
WorkloadResult  12: 16777216 op, 857552900.00 ns, 51.1141 ns/op
WorkloadResult  13: 16777216 op, 859310100.00 ns, 51.2189 ns/op
WorkloadResult  14: 16777216 op, 857050600.00 ns, 51.0842 ns/op

// AfterAll
// Benchmark Process 26564 has exited with code 0.

Mean = 51.323 ns, StdErr = 0.042 ns (0.08%), N = 14, StdDev = 0.159 ns
Min = 51.084 ns, Q1 = 51.212 ns, Median = 51.322 ns, Q3 = 51.449 ns, Max = 51.624 ns
IQR = 0.237 ns, LowerFence = 50.857 ns, UpperFence = 51.803 ns
ConfidenceInterval = [51.145 ns; 51.502 ns] (CI 99.9%), Margin = 0.179 ns (0.35% of Mean)
Skewness = 0.22, Kurtosis = 1.85, MValue = 2

// ** Remained 0 (0.0%) benchmark(s) to run. Estimated finish 2022-10-14 19:43 (0h 0m from now) **
Successfully reverted power plan (GUID: 8c5e7fda-e8bf-4a96-9a85-a6e23a8c635c FriendlyName: High performance)
// ***** BenchmarkRunner: Finish  *****

// * Export *
  BenchmarkDotNet.Artifacts\results\BenchmarkDotNet.Samples.IntroDisassembly-report.csv
  BenchmarkDotNet.Artifacts\results\BenchmarkDotNet.Samples.IntroDisassembly-report-github.md
  BenchmarkDotNet.Artifacts\results\BenchmarkDotNet.Samples.IntroDisassembly-report.html
  BenchmarkDotNet.Artifacts\results\BenchmarkDotNet.Samples.IntroDisassembly-asm.md

// * Detailed results *
IntroDisassembly.SumLocal: DefaultJob
Runtime = .NET 6.0.10 (6.0.1022.47605), X64 RyuJIT AVX2; GC = Concurrent Workstation
Mean = 36.214 ns, StdErr = 0.087 ns (0.24%), N = 13, StdDev = 0.313 ns
Min = 35.768 ns, Q1 = 36.029 ns, Median = 36.174 ns, Q3 = 36.385 ns, Max = 36.762 ns
IQR = 0.356 ns, LowerFence = 35.496 ns, UpperFence = 36.919 ns
ConfidenceInterval = [35.839 ns; 36.589 ns] (CI 99.9%), Margin = 0.375 ns (1.04% of Mean)
Skewness = 0.37, Kurtosis = 1.98, MValue = 2
-------------------- Histogram --------------------
[35.593 ns ; 36.937 ns) | @@@@@@@@@@@@@
---------------------------------------------------

IntroDisassembly.SumField: DefaultJob
Runtime = .NET 6.0.10 (6.0.1022.47605), X64 RyuJIT AVX2; GC = Concurrent Workstation
Mean = 51.323 ns, StdErr = 0.042 ns (0.08%), N = 14, StdDev = 0.159 ns
Min = 51.084 ns, Q1 = 51.212 ns, Median = 51.322 ns, Q3 = 51.449 ns, Max = 51.624 ns
IQR = 0.237 ns, LowerFence = 50.857 ns, UpperFence = 51.803 ns
ConfidenceInterval = [51.145 ns; 51.502 ns] (CI 99.9%), Margin = 0.179 ns (0.35% of Mean)
Skewness = 0.22, Kurtosis = 1.85, MValue = 2
-------------------- Histogram --------------------
[50.998 ns ; 51.710 ns) | @@@@@@@@@@@@@@
---------------------------------------------------

// * Summary *

BenchmarkDotNet=v0.13.2.20221014-develop, OS=Windows 11 (10.0.22621.674)
AMD Ryzen Threadripper PRO 3945WX 12-Cores, 1 CPU, 24 logical and 12 physical cores
.NET SDK=7.0.100-rc.1.22431.12
  [Host]     : .NET 6.0.10 (6.0.1022.47605), X64 RyuJIT AVX2
  DefaultJob : .NET 6.0.10 (6.0.1022.47605), X64 RyuJIT AVX2


|   Method |     Mean |    Error |   StdDev | Code Size |
|--------- |---------:|---------:|---------:|----------:|
| SumLocal | 36.21 ns | 0.375 ns | 0.313 ns |      35 B |
| SumField | 51.32 ns | 0.179 ns | 0.159 ns |      67 B |

// * Hints *
Outliers
  IntroDisassembly.SumLocal: Default -> 2 outliers were removed (39.03 ns, 41.10 ns)
  IntroDisassembly.SumField: Default -> 1 outlier  was  removed (53.45 ns)

// * Legends *
  Mean      : Arithmetic mean of all measurements
  Error     : Half of 99.9% confidence interval
  StdDev    : Standard deviation of all measurements
  Code Size : Native code size of the disassembled method(s)
  1 ns      : 1 Nanosecond (0.000000001 sec)

// * Diagnostic Output - DisassemblyDiagnoser *
Disassembled benchmarks got exported to ".\BenchmarkDotNet.Artifacts\results\*asm.md"

// ***** BenchmarkRunner: End *****
Run time: 00:00:38 (38.07 sec), executed benchmarks: 2

Global total time: 00:00:41 (41.25 sec), executed benchmarks: 2
// * Artifacts cleanup

Which could be minimized to:

// Validating benchmarks:
// ***** BenchmarkRunner: Start   *****
// ***** Found 2 benchmark(s) in total *****
// ***** Building 1 exe(s) in Parallel: Start   *****
// start dotnet  restore /p:UseSharedCompilation=false /p:BuildInParallel=false /m:1 /p:Deterministic=true /p:Optimize=true in D:\projects\BenchmarkDotNet\samples\BenchmarkDotNet.Samples\bin\Release\net6.0\da12d07c-1a7c-4683-82fb-8b86b224d89c
// command took 0.7s and exited with 0
// start dotnet  build -c Release --no-restore /p:UseSharedCompilation=false /p:BuildInParallel=false /m:1 /p:Deterministic=true /p:Optimize=true in D:\projects\BenchmarkDotNet\samples\BenchmarkDotNet.Samples\bin\Release\net6.0\da12d07c-1a7c-4683-82fb-8b86b224d89c
// command took 2.08s and exited with 0
// ***** Done, took 00:00:02 (2.93 sec)   *****
// Found 2 benchmarks:
//   IntroDisassembly.SumLocal: DefaultJob
//   IntroDisassembly.SumField: DefaultJob

// Execute: dotnet da12d07c-1a7c-4683-82fb-8b86b224d89c.dll --anonymousPipes 5884 5888 --benchmarkName BenchmarkDotNet.Samples.IntroDisassembly.SumLocal --job Default --benchmarkId 0 in D:\projects\BenchmarkDotNet\samples\BenchmarkDotNet.Samples\bin\Release\net6.0\da12d07c-1a7c-4683-82fb-8b86b224d89c\bin\Release\net6.0
// ** Remained 1 (50.0%) benchmark(s) to run. Estimated finish 2022-10-14 19:43 (0h 0m from now) **
Setup power plan (GUID: 8c5e7fda-e8bf-4a96-9a85-a6e23a8c635c FriendlyName: High performance)

// Execute: dotnet da12d07c-1a7c-4683-82fb-8b86b224d89c.dll --anonymousPipes 1572 1872 --benchmarkName BenchmarkDotNet.Samples.IntroDisassembly.SumField --job Default --benchmarkId 1 in D:\projects\BenchmarkDotNet\samples\BenchmarkDotNet.Samples\bin\Release\net6.0\da12d07c-1a7c-4683-82fb-8b86b224d89c\bin\Release\net6.0
// BeforeAnythingElse
// ** Remained 0 (0.0%) benchmark(s) to run. Estimated finish 2022-10-14 19:43 (0h 0m from now) **
// ***** BenchmarkRunner: Finish  *****

// * Export *
  BenchmarkDotNet.Artifacts\results\BenchmarkDotNet.Samples.IntroDisassembly-report.csv
  BenchmarkDotNet.Artifacts\results\BenchmarkDotNet.Samples.IntroDisassembly-report-github.md
  BenchmarkDotNet.Artifacts\results\BenchmarkDotNet.Samples.IntroDisassembly-report.html
  BenchmarkDotNet.Artifacts\results\BenchmarkDotNet.Samples.IntroDisassembly-asm.md

// * Detailed results *
IntroDisassembly.SumLocal: DefaultJob
Runtime = .NET 6.0.10 (6.0.1022.47605), X64 RyuJIT AVX2; GC = Concurrent Workstation
Mean = 36.214 ns, StdErr = 0.087 ns (0.24%), N = 13, StdDev = 0.313 ns
Min = 35.768 ns, Q1 = 36.029 ns, Median = 36.174 ns, Q3 = 36.385 ns, Max = 36.762 ns
IQR = 0.356 ns, LowerFence = 35.496 ns, UpperFence = 36.919 ns
ConfidenceInterval = [35.839 ns; 36.589 ns] (CI 99.9%), Margin = 0.375 ns (1.04% of Mean)
Skewness = 0.37, Kurtosis = 1.98, MValue = 2
-------------------- Histogram --------------------
[35.593 ns ; 36.937 ns) | @@@@@@@@@@@@@
---------------------------------------------------

IntroDisassembly.SumField: DefaultJob
Runtime = .NET 6.0.10 (6.0.1022.47605), X64 RyuJIT AVX2; GC = Concurrent Workstation
Mean = 51.323 ns, StdErr = 0.042 ns (0.08%), N = 14, StdDev = 0.159 ns
Min = 51.084 ns, Q1 = 51.212 ns, Median = 51.322 ns, Q3 = 51.449 ns, Max = 51.624 ns
IQR = 0.237 ns, LowerFence = 50.857 ns, UpperFence = 51.803 ns
ConfidenceInterval = [51.145 ns; 51.502 ns] (CI 99.9%), Margin = 0.179 ns (0.35% of Mean)
Skewness = 0.22, Kurtosis = 1.85, MValue = 2
-------------------- Histogram --------------------
[50.998 ns ; 51.710 ns) | @@@@@@@@@@@@@@
---------------------------------------------------

// * Summary *

BenchmarkDotNet=v0.13.2.20221014-develop, OS=Windows 11 (10.0.22621.674)
AMD Ryzen Threadripper PRO 3945WX 12-Cores, 1 CPU, 24 logical and 12 physical cores
.NET SDK=7.0.100-rc.1.22431.12
  [Host]     : .NET 6.0.10 (6.0.1022.47605), X64 RyuJIT AVX2
  DefaultJob : .NET 6.0.10 (6.0.1022.47605), X64 RyuJIT AVX2


|   Method |     Mean |    Error |   StdDev | Code Size |
|--------- |---------:|---------:|---------:|----------:|
| SumLocal | 36.21 ns | 0.375 ns | 0.313 ns |      35 B |
| SumField | 51.32 ns | 0.179 ns | 0.159 ns |      67 B |

// * Hints *
Outliers
  IntroDisassembly.SumLocal: Default -> 2 outliers were removed (39.03 ns, 41.10 ns)
  IntroDisassembly.SumField: Default -> 1 outlier  was  removed (53.45 ns)

// * Legends *
  Mean      : Arithmetic mean of all measurements
  Error     : Half of 99.9% confidence interval
  StdDev    : Standard deviation of all measurements
  Code Size : Native code size of the disassembled method(s)
  1 ns      : 1 Nanosecond (0.000000001 sec)

// * Diagnostic Output - DisassemblyDiagnoser *
Disassembled benchmarks got exported to ".\BenchmarkDotNet.Artifacts\results\*asm.md"

// ***** BenchmarkRunner: End *****
Run time: 00:00:38 (38.07 sec), executed benchmarks: 2

Global total time: 00:00:41 (41.25 sec), executed benchmarks: 2
// * Artifacts cleanup

The new option should be currently disabled by default. It should be possible to enable it via command line args, fluent API and an attribute. You can use KeepFiles as an example of similar boolean config switch, find all its usages in the code should show how to implement something very similar:

https://github.com/dotnet/BenchmarkDotNet/blob/master/src/BenchmarkDotNet/Attributes/KeepBenchmarkFilesAttribute.cs

[PublicAPI] public static IConfig KeepBenchmarkFiles(this IConfig config, bool value = true) => config.WithOption(ConfigOptions.KeepBenchmarkFiles, value);

I don't have any strong preferences for how it should be implemented. One way would be passing NullLogger instead of actual logger in some places in BDN. The simpler the solution, the better.

@franciscomoloureiro
Copy link
Contributor

I want to work on this issue

@adamsitnik
Copy link
Member

@franciscomoloureiro great, I've assigned you. Please let me know if you need help.

@YegorStepanov
Copy link
Contributor

Still verbose. We always have log file that we can open and see the logs. Console is a UI, not a log viewer.

I would like to see the same -verbosity option as MSBuild and dotnet cli have:

-verbosity: q[uiet], m[inimal], n[ormal] (default), d[etailed], and diag[nostic].

diag[nostic]

current output: full logs

d[etailed]

like Adam suggests

n[ormal]

It should not contain any debug/log information:
Also we can remove remaining benchmarks and time to finish because it already displays in console title #2140

Detailed results are often helpful? Maybe we can hide it too.

Details
Benchmark: IntroDisassembly.SumLocal: DefaultJob
Benchmark: IntroDisassembly.SumField: DefaultJob

Detailed results:
IntroDisassembly.SumLocal: DefaultJob
Runtime = .NET 6.0.10 (6.0.1022.47605), X64 RyuJIT AVX2; GC = Concurrent Workstation
Mean = 36.214 ns, StdErr = 0.087 ns (0.24%), N = 13, StdDev = 0.313 ns
Min = 35.768 ns, Q1 = 36.029 ns, Median = 36.174 ns, Q3 = 36.385 ns, Max = 36.762 ns
IQR = 0.356 ns, LowerFence = 35.496 ns, UpperFence = 36.919 ns
ConfidenceInterval = [35.839 ns; 36.589 ns] (CI 99.9%), Margin = 0.375 ns (1.04% of Mean)
Skewness = 0.37, Kurtosis = 1.98, MValue = 2
-------------------- Histogram --------------------
[35.593 ns ; 36.937 ns) | @@@@@@@@@@@@@
---------------------------------------------------

IntroDisassembly.SumField: DefaultJob
Runtime = .NET 6.0.10 (6.0.1022.47605), X64 RyuJIT AVX2; GC = Concurrent Workstation
Mean = 51.323 ns, StdErr = 0.042 ns (0.08%), N = 14, StdDev = 0.159 ns
Min = 51.084 ns, Q1 = 51.212 ns, Median = 51.322 ns, Q3 = 51.449 ns, Max = 51.624 ns
IQR = 0.237 ns, LowerFence = 50.857 ns, UpperFence = 51.803 ns
ConfidenceInterval = [51.145 ns; 51.502 ns] (CI 99.9%), Margin = 0.179 ns (0.35% of Mean)
Skewness = 0.22, Kurtosis = 1.85, MValue = 2
-------------------- Histogram --------------------
[50.998 ns ; 51.710 ns) | @@@@@@@@@@@@@@
---------------------------------------------------

// * Summary *

BenchmarkDotNet=v0.13.2.20221014-develop, OS=Windows 11 (10.0.22621.674)
AMD Ryzen Threadripper PRO 3945WX 12-Cores, 1 CPU, 24 logical and 12 physical cores
.NET SDK=7.0.100-rc.1.22431.12
  [Host]     : .NET 6.0.10 (6.0.1022.47605), X64 RyuJIT AVX2
  DefaultJob : .NET 6.0.10 (6.0.1022.47605), X64 RyuJIT AVX2


|   Method |     Mean |    Error |   StdDev | Code Size |
|--------- |---------:|---------:|---------:|----------:|
| SumLocal | 36.21 ns | 0.375 ns | 0.313 ns |      35 B |
| SumField | 51.32 ns | 0.179 ns | 0.159 ns |      67 B |

// * Hints *
Outliers
  IntroDisassembly.SumLocal: Default -> 2 outliers were removed (39.03 ns, 41.10 ns)
  IntroDisassembly.SumField: Default -> 1 outlier  was  removed (53.45 ns)

// * Legends *
  Mean      : Arithmetic mean of all measurements
  Error     : Half of 99.9% confidence interval
  StdDev    : Standard deviation of all measurements
  Code Size : Native code size of the disassembled method(s)
  1 ns      : 1 Nanosecond (0.000000001 sec)

// * Diagnostic Output - DisassemblyDiagnoser *
Disassembled benchmarks got exported to ".\BenchmarkDotNet.Artifacts\results\*asm.md"

m[inimal]

Show table without 'legend'. The console will be nice and clean.

"legend" does not give any information on the second day of using the BDN. But if you forgot, you can open the log file.

"Hints" can be disabled via Config

Details
BenchmarkDotNet=v0.13.2.20221014-develop, OS=Windows 11 (10.0.22621.674)
AMD Ryzen Threadripper PRO 3945WX 12-Cores, 1 CPU, 24 logical and 12 physical cores
.NET SDK=7.0.100-rc.1.22431.12
  [Host]     : .NET 6.0.10 (6.0.1022.47605), X64 RyuJIT AVX2
  DefaultJob : .NET 6.0.10 (6.0.1022.47605), X64 RyuJIT AVX2


|   Method |     Mean |    Error |   StdDev | Code Size |
|--------- |---------:|---------:|---------:|----------:|
| SumLocal | 36.21 ns | 0.375 ns | 0.313 ns |      35 B |
| SumField | 51.32 ns | 0.179 ns | 0.159 ns |      67 B |

// * Hints *
Outliers
  IntroDisassembly.SumLocal: Default -> 2 outliers were removed (39.03 ns, 41.10 ns)
  IntroDisassembly.SumField: Default -> 1 outlier  was  removed (53.45 ns)

q[uiet]

No output

API example:

dotnet run -c Release -- --verbosity minimal
[ConsoleVerbosity(Verbosity.Minimal, redirectOutput: true)]

@adamsitnik
Copy link
Member

@YegorStepanov your proposal sounds very reasonable, I like it! @franciscomoloureiro if possible, please take it into consideration

@franciscomoloureiro franciscomoloureiro linked a pull request Oct 18, 2022 that will close this issue
@YegorStepanov
Copy link
Contributor

I'm thinking about the next normal verbosity level. I consider it as the default mode (at least in the future).

Found 2 benchmarks
Log file: C:/src/github/BenchmarkDotNet/samples/BenchmarkDotNet.Sample/bin/BenchmarkDotNet.Artifacts/log.....txt

Execute IntroDisassembly.SumLocal: DefaultJob
Execute IntroDisassembly.SumField: DefaultJob

** Summary **
BenchmarkDotNet=v0.13.2.20221014-develop, OS=Windows 11 (10.0.22621.674)
AMD Ryzen Threadripper PRO 3945WX 12-Cores, 1 CPU, 24 logical and 12 physical cores
.NET SDK=7.0.100-rc.1.22431.12
  [Host]     : .NET 6.0.10 (6.0.1022.47605), X64 RyuJIT AVX2
  DefaultJob : .NET 6.0.10 (6.0.1022.47605), X64 RyuJIT AVX2

|   Method |     Mean |    Error |   StdDev | Code Size |
|--------- |---------:|---------:|---------:|----------:|
| SumLocal | 36.21 ns | 0.375 ns | 0.313 ns |      35 B |
| SumField | 51.32 ns | 0.179 ns | 0.159 ns |      67 B |

** Hints **
Outliers
  IntroDisassembly.SumLocal: Default -> 2 outliers were removed (39.03 ns, 41.10 ns)
  IntroDisassembly.SumField: Default -> 1 outlier  was  removed (53.45 ns)

** Legends **
  Mean      : Arithmetic mean of all measurements
  Error     : Half of 99.9% confidence interval
  StdDev    : Standard deviation of all measurements
  Code Size : Native code size of the disassembled method(s)
  1 ns      : 1 Nanosecond (0.000000001 sec)

Run time: 00:00:19 (19.87 sec)
Global total time: 00:00:36 (36.87 sec)

Did I clean up more than necessary?

If you ok with this, then I will try to make diagnostic and detailed levels more consistent.

P.S Each verbosity level contains all the information of the less verbose level. (diagnostic contains all message of detailed, which contains all messages from normal, etc)

cc @AndreyAkinshin

@eduherminio
Copy link
Member

@franciscomoloureiro do you plan to continue with #2161 to try to address this?

@tamirs9876
Copy link

@franciscomoloureiro can you please share an update about the PR to address this issue?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment