Measurement metric issue

[nbalu]

I'm copying my test results as sample. If you take a look into the details and into the summary it looks like us are shown as ns which is obviously shouldn't be happening.

// * Detailed results *
LookupBenchmark.LookupLinq: .NET 4.7.2(Runtime=.NET 4.7.2)
Runtime = .NET Framework 4.8 (4.8.4018.0), X64 RyuJIT; GC = Concurrent Workstation
Mean = 1.883 us, StdErr = 0.008 us (0.41%), N = 14, StdDev = 0.029 us
Min = 1.851 us, Q1 = 1.859 us, Median = 1.876 us, Q3 = 1.899 us, Max = 1.938 us
IQR = 0.040 us, LowerFence = 1.799 us, UpperFence = 1.959 us
ConfidenceInterval = [1.851 us; 1.915 us] (CI 99.9%), Margin = 0.032 us (1.71% of Mean)
Skewness = 0.59, Kurtosis = 1.92, MValue = 2
-------------------- Histogram --------------------
[1.846 us ; 1.954 us) | @@@@@@@@@@@@@@

LookupBenchmark.LookupLinq: .NET Core 3.1(Runtime=.NET Core 3.1)
Runtime = .NET Core 3.1.7 (CoreCLR 4.700.20.36602, CoreFX 4.700.20.37001), X64 RyuJIT; GC = Concurrent Workstation
Mean = 2.020 us, StdErr = 0.009 us (0.45%), N = 14, StdDev = 0.034 us
Min = 1.974 us, Q1 = 1.987 us, Median = 2.026 us, Q3 = 2.042 us, Max = 2.070 us
IQR = 0.054 us, LowerFence = 1.906 us, UpperFence = 2.123 us
ConfidenceInterval = [1.982 us; 2.059 us] (CI 99.9%), Margin = 0.038 us (1.89% of Mean)
Skewness = -0.04, Kurtosis = 1.42, MValue = 2
-------------------- Histogram --------------------
[1.972 us ; 2.020 us) | @@@@@@
[2.020 us ; 2.089 us) | @@@@@@@@

LookupBenchmark.LookupDictionary: .NET 4.7.2(Runtime=.NET 4.7.2)
Runtime = .NET Framework 4.8 (4.8.4018.0), X64 RyuJIT; GC = Concurrent Workstation
Mean = 38.878 ns, StdErr = 0.145 ns (0.37%), N = 15, StdDev = 0.562 ns
Min = 38.175 ns, Q1 = 38.385 ns, Median = 38.840 ns, Q3 = 39.280 ns, Max = 39.888 ns
IQR = 0.895 ns, LowerFence = 37.043 ns, UpperFence = 40.623 ns
ConfidenceInterval = [38.278 ns; 39.478 ns] (CI 99.9%), Margin = 0.600 ns (1.54% of Mean)
Skewness = 0.28, Kurtosis = 1.62, MValue = 2
-------------------- Histogram --------------------
[38.060 ns ; 40.187 ns) | @@@@@@@@@@@@@@@

LookupBenchmark.LookupDictionary: .NET Core 3.1(Runtime=.NET Core 3.1)
Runtime = .NET Core 3.1.7 (CoreCLR 4.700.20.36602, CoreFX 4.700.20.37001), X64 RyuJIT; GC = Concurrent Workstation
Mean = 26.929 ns, StdErr = 0.167 ns (0.62%), N = 40, StdDev = 1.053 ns
Min = 25.665 ns, Q1 = 25.925 ns, Median = 26.731 ns, Q3 = 27.905 ns, Max = 30.347 ns
IQR = 1.980 ns, LowerFence = 22.955 ns, UpperFence = 30.876 ns
ConfidenceInterval = [26.337 ns; 27.522 ns] (CI 99.9%), Margin = 0.593 ns (2.20% of Mean)
Skewness = 0.85, Kurtosis = 3.57, MValue = 2.42
-------------------- Histogram --------------------
[25.261 ns ; 26.548 ns) | @@@@@@@@@@@@@@@@@@@
[26.548 ns ; 27.362 ns) | @@@@@@@
[27.362 ns ; 28.171 ns) | @@@@@@@@@@@
[28.171 ns ; 29.521 ns) | @@
[29.521 ns ; 30.752 ns) | @

// * Summary *

BenchmarkDotNet=v0.12.1, OS=Windows 10.0.18363.535 (1909/November2018Update/19H2)
Intel Core i7-8565U CPU 1.80GHz (Whiskey Lake), 1 CPU, 8 logical and 4 physical cores
.NET Core SDK=3.1.401
[Host] : .NET Core 3.1.7 (CoreCLR 4.700.20.36602, CoreFX 4.700.20.37001), X64 RyuJIT
.NET 4.7.2 : .NET Framework 4.8 (4.8.4018.0), X64 RyuJIT
.NET Core 3.1 : .NET Core 3.1.7 (CoreCLR 4.700.20.36602, CoreFX 4.700.20.37001), X64 RyuJIT

Method	Job	Runtime	Mean	Error	StdDev	Ratio	RatioSD
LookupLinq	.NET 4.7.2	.NET 4.7.2	1,882.94 ns	32.248 ns	28.587 ns	1.00	0.00
LookupLinq	.NET Core 3.1	.NET Core 3.1	2,020.43 ns	38.224 ns	33.885 ns	1.07	0.02
LookupDictionary	.NET 4.7.2	.NET 4.7.2	38.88 ns	0.600 ns	0.562 ns	1.00	0.00
LookupDictionary	.NET Core 3.1	.NET Core 3.1	26.93 ns	0.593 ns	1.053 ns	0.70	0.03

// * Hints *
Outliers
LookupBenchmark.LookupLinq: .NET 4.7.2 -> 1 outlier was removed (2.03 us)
LookupBenchmark.LookupLinq: .NET Core 3.1 -> 1 outlier was removed (2.19 us)
LookupBenchmark.LookupDictionary: .NET Core 3.1 -> 1 outlier was removed (35.47 ns)

// * Legends *
Mean : Arithmetic mean of all measurements
Error : Half of 99.9% confidence interval
StdDev : Standard deviation of all measurements
Ratio : Mean of the ratio distribution ([Current]/[Baseline])
RatioSD : Standard deviation of the ratio distribution ([Current]/[Baseline])
1 ns : 1 Nanosecond (0.000000001 sec)

// ***** BenchmarkRunner: End *****
// ** Remained 0 benchmark(s) to run **
Run time: 00:01:20 (80.76 sec), executed benchmarks: 4

Global total time: 00:01:30 (90.03 sec), executed benchmarks: 4

[abelbraaksma]

I've seen similar things happening when you hit this bug: #1338

Since that issue, it's fairly common that number of invocations suddenly doesn't increase, but only does 1 invocation on each iteration, and that reported numbers are off by a factor of 1000, plus extreme outliers. Not entirely sure it's the same issue, but have a look at your full report for how many invocations you have.

I'd fix that issue myself, but I need a bit of guidance from @adamsitnik or someone else with intimate knowledge of the related change.

[nbalu]

I'm not sure what I'm supposed to see in this case but let me paste my result here for sanity check.
Sorry it's my first time with BenchmarkDotNet. I'm not really familiar with the output meanings yet.

In my opinion the operation count seems to be just fine and the result as well. As summary at the end of the run just states it right. Even the detailed result states the same. On the other hand the summary table at the end... It's just missed the unit.

// **************************
// Benchmark: LookupBenchmark.LookupLinq: .NET Core 3.1(Runtime=.NET Core 3.1)
// *** Execute ***
// Launch: 1 / 1
// Execute: dotnet "78324453-f836-4fb8-afab-c8a7d173a1ca.dll" --benchmarkName "performance.LookupBenchmark.LookupLinq" --job ".NET Core 3.1" --benchmarkId 0 in C:\projects\performance\bin\Release\netcoreapp3.1\78324453-f836-4fb8-afab-c8a7d173a1ca\bin\Release\netcoreapp3.1
// BeforeAnythingElse

// Benchmark Process Environment Information:
// Runtime=.NET Core 3.1.7 (CoreCLR 4.700.20.36602, CoreFX 4.700.20.37001), X64 RyuJIT
// GC=Concurrent Workstation
// Job: .NET Core 3.1

OverheadJitting 1: 1 op, 472100.00 ns, 472.1000 us/op
WorkloadJitting 1: 1 op, 822200.00 ns, 822.2000 us/op

OverheadJitting 2: 16 op, 427200.00 ns, 26.7000 us/op
WorkloadJitting 2: 16 op, 475400.00 ns, 29.7125 us/op

WorkloadPilot 1: 16 op, 82600.00 ns, 5.1625 us/op
WorkloadPilot 2: 32 op, 160900.00 ns, 5.0281 us/op
WorkloadPilot 3: 64 op, 315800.00 ns, 4.9344 us/op
WorkloadPilot 4: 128 op, 675800.00 ns, 5.2797 us/op
WorkloadPilot 5: 256 op, 1350300.00 ns, 5.2746 us/op
WorkloadPilot 6: 512 op, 2624800.00 ns, 5.1266 us/op
WorkloadPilot 7: 1024 op, 5048100.00 ns, 4.9298 us/op
WorkloadPilot 8: 2048 op, 12552800.00 ns, 6.1293 us/op
WorkloadPilot 9: 4096 op, 22796200.00 ns, 5.5655 us/op
WorkloadPilot 10: 8192 op, 46962000.00 ns, 5.7327 us/op
WorkloadPilot 11: 16384 op, 99602300.00 ns, 6.0792 us/op
WorkloadPilot 12: 32768 op, 145575900.00 ns, 4.4426 us/op
WorkloadPilot 13: 65536 op, 181205600.00 ns, 2.7650 us/op
WorkloadPilot 14: 131072 op, 325567600.00 ns, 2.4839 us/op
WorkloadPilot 15: 262144 op, 578501700.00 ns, 2.2068 us/op

OverheadWarmup 1: 262144 op, 871000.00 ns, 3.3226 ns/op
OverheadWarmup 2: 262144 op, 785400.00 ns, 2.9961 ns/op
OverheadWarmup 3: 262144 op, 739200.00 ns, 2.8198 ns/op
OverheadWarmup 4: 262144 op, 731500.00 ns, 2.7905 ns/op
OverheadWarmup 5: 262144 op, 825500.00 ns, 3.1490 ns/op
OverheadWarmup 6: 262144 op, 730500.00 ns, 2.7866 ns/op
OverheadWarmup 7: 262144 op, 752800.00 ns, 2.8717 ns/op
OverheadWarmup 8: 262144 op, 730400.00 ns, 2.7863 ns/op

OverheadActual 1: 262144 op, 770700.00 ns, 2.9400 ns/op
OverheadActual 2: 262144 op, 906000.00 ns, 3.4561 ns/op
OverheadActual 3: 262144 op, 902100.00 ns, 3.4412 ns/op
OverheadActual 4: 262144 op, 797400.00 ns, 3.0418 ns/op
OverheadActual 5: 262144 op, 788900.00 ns, 3.0094 ns/op
OverheadActual 6: 262144 op, 796000.00 ns, 3.0365 ns/op
OverheadActual 7: 262144 op, 764300.00 ns, 2.9156 ns/op
OverheadActual 8: 262144 op, 764300.00 ns, 2.9156 ns/op
OverheadActual 9: 262144 op, 1164200.00 ns, 4.4411 ns/op
OverheadActual 10: 262144 op, 1139300.00 ns, 4.3461 ns/op
OverheadActual 11: 262144 op, 1126400.00 ns, 4.2969 ns/op
OverheadActual 12: 262144 op, 809000.00 ns, 3.0861 ns/op
OverheadActual 13: 262144 op, 807200.00 ns, 3.0792 ns/op
OverheadActual 14: 262144 op, 788100.00 ns, 3.0064 ns/op
OverheadActual 15: 262144 op, 860100.00 ns, 3.2810 ns/op
OverheadActual 16: 262144 op, 787900.00 ns, 3.0056 ns/op
OverheadActual 17: 262144 op, 807500.00 ns, 3.0804 ns/op
OverheadActual 18: 262144 op, 872000.00 ns, 3.3264 ns/op
OverheadActual 19: 262144 op, 804600.00 ns, 3.0693 ns/op
OverheadActual 20: 262144 op, 804800.00 ns, 3.0701 ns/op

WorkloadWarmup 1: 262144 op, 583237300.00 ns, 2.2249 us/op
WorkloadWarmup 2: 262144 op, 585585200.00 ns, 2.2338 us/op
WorkloadWarmup 3: 262144 op, 551551000.00 ns, 2.1040 us/op
WorkloadWarmup 4: 262144 op, 537037400.00 ns, 2.0486 us/op
WorkloadWarmup 5: 262144 op, 547256800.00 ns, 2.0876 us/op
WorkloadWarmup 6: 262144 op, 526090400.00 ns, 2.0069 us/op

// BeforeActualRun
WorkloadActual 1: 262144 op, 521146400.00 ns, 1.9880 us/op
WorkloadActual 2: 262144 op, 543566800.00 ns, 2.0735 us/op
WorkloadActual 3: 262144 op, 527471100.00 ns, 2.0121 us/op
WorkloadActual 4: 262144 op, 531676500.00 ns, 2.0282 us/op
WorkloadActual 5: 262144 op, 539626400.00 ns, 2.0585 us/op
WorkloadActual 6: 262144 op, 542751400.00 ns, 2.0704 us/op
WorkloadActual 7: 262144 op, 518281200.00 ns, 1.9771 us/op
WorkloadActual 8: 262144 op, 575327400.00 ns, 2.1947 us/op
WorkloadActual 9: 262144 op, 523736400.00 ns, 1.9979 us/op
WorkloadActual 10: 262144 op, 534895700.00 ns, 2.0405 us/op
WorkloadActual 11: 262144 op, 532399500.00 ns, 2.0309 us/op
WorkloadActual 12: 262144 op, 535753400.00 ns, 2.0437 us/op
WorkloadActual 13: 262144 op, 520386100.00 ns, 1.9851 us/op
WorkloadActual 14: 262144 op, 518489200.00 ns, 1.9779 us/op
WorkloadActual 15: 262144 op, 536108000.00 ns, 2.0451 us/op

// AfterActualRun
WorkloadResult 1: 262144 op, 520340400.00 ns, 1.9849 us/op
WorkloadResult 2: 262144 op, 542760800.00 ns, 2.0705 us/op
WorkloadResult 3: 262144 op, 526665100.00 ns, 2.0091 us/op
WorkloadResult 4: 262144 op, 530870500.00 ns, 2.0251 us/op
WorkloadResult 5: 262144 op, 538820400.00 ns, 2.0554 us/op
WorkloadResult 6: 262144 op, 541945400.00 ns, 2.0674 us/op
WorkloadResult 7: 262144 op, 517475200.00 ns, 1.9740 us/op
WorkloadResult 8: 262144 op, 522930400.00 ns, 1.9948 us/op
WorkloadResult 9: 262144 op, 534089700.00 ns, 2.0374 us/op
WorkloadResult 10: 262144 op, 531593500.00 ns, 2.0279 us/op
WorkloadResult 11: 262144 op, 534947400.00 ns, 2.0407 us/op
WorkloadResult 12: 262144 op, 519580100.00 ns, 1.9820 us/op
WorkloadResult 13: 262144 op, 517683200.00 ns, 1.9748 us/op
WorkloadResult 14: 262144 op, 535302000.00 ns, 2.0420 us/op

// AfterAll
// Benchmark Process 13732 has exited with code 0

Mean = 2.020 us, StdErr = 0.009 us (0.45%), N = 14, StdDev = 0.034 us
Min = 1.974 us, Q1 = 1.987 us, Median = 2.026 us, Q3 = 2.042 us, Max = 2.070 us
IQR = 0.054 us, LowerFence = 1.906 us, UpperFence = 2.123 us
ConfidenceInterval = [1.982 us; 2.059 us] (CI 99.9%), Margin = 0.038 us (1.89% of Mean)
Skewness = -0.04, Kurtosis = 1.42, MValue = 2

[nbalu]

No, you are right. Not just the unit, there's a *1000 multiplication as well... My bad!

[abelbraaksma]

WorkloadResult 14: 262144 op, 535302000.00 ns, 2.0420 us/op

These ones are important. If it would say 1 op on every line, you'd have hit the mentioned bug, and overhead of the call will influence the timings significantly (of you do see that, and the number of ops does not increase, please add your scenario to that referenced bug report).

Normally, you should see what you see now, 262144 operations (that is, invocations of your measured function), taking in total 535302000.00 ns, which is close to 2.0420 us per operation (or 2,042.00ns).

[adamsitnik]

The scaling is proper: 1,882.94 ns is equal to 1.88294 us

If I misunderstood the issue, please let me know and reopen it.