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.

Sign up for GitHub

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

Jump to bottom

Don't run the benchmark once per iteration if only the first ivocation lasts longer than IterationTime #1573

Merged
merged 2 commits into from
Oct 26, 2020
Merged

Don't run the benchmark once per iteration if only the first ivocation lasts longer than IterationTime #1573

merged 2 commits into from
Oct 26, 2020

Conversation

adamsitnik
Copy link
Member

if the Jitting took more than IterationTime but still less than 1s (a magic number based on observations of the reported bug)
we call it one more time to see if Jitting itself has not dominated the first invocation
if it did, it should NOT be a single invocation engine (fixes #837, fixes #1337 and fixes #1338)

example:

public class Repro
{
    int count;

    [Benchmark]
    public void Tricky()
    {
        if (count++ == 0)
        {
            System.Threading.Thread.Sleep(TimeSpan.FromSeconds(0.5));
        }
    }
}
--filter Repro --iterationtime 250

Before:

// Benchmark Process Environment Information:
// Runtime=.NET Core 2.1.22 (CoreCLR 4.6.29220.03, CoreFX 4.6.29220.01), X64 RyuJIT
// GC=Concurrent Workstation
// Job: Job-QFHVLA(IterationTime=250.0000 ms)

OverheadJitting  1: 1 op, 299700.00 ns, 299.7000 us/op
WorkloadJitting  1: 1 op, 501425100.00 ns, 501.4251 ms/op

WorkloadWarmup   1: 1 op, 2200.00 ns, 2.2000 us/op
WorkloadWarmup   2: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadWarmup   3: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadWarmup   4: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadWarmup   5: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadWarmup   6: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadWarmup   7: 1 op, 200.00 ns, 200.0000 ns/op

// BeforeActualRun
WorkloadActual   1: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual   2: 1 op, 300.00 ns, 300.0000 ns/op
WorkloadActual   3: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual   4: 1 op, 0.00 ns, 0.0000 ns/op
WorkloadActual   5: 1 op, 300.00 ns, 300.0000 ns/op
WorkloadActual   6: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual   7: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual   8: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual   9: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  10: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual  11: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual  12: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  13: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual  14: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual  15: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  16: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  17: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  18: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  19: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  20: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual  21: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual  22: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual  23: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  24: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  25: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual  26: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual  27: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  28: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual  29: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  30: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  31: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual  32: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  33: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual  34: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  35: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  36: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  37: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  38: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  39: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual  40: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual  41: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  42: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  43: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  44: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  45: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  46: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual  47: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual  48: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  49: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  50: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  51: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual  52: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  53: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  54: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual  55: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  56: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  57: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual  58: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual  59: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual  60: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  61: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  62: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  63: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  64: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  65: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual  66: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  67: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  68: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  69: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  70: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  71: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  72: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual  73: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  74: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual  75: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  76: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual  77: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  78: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  79: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual  80: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual  81: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  82: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  83: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual  84: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  85: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  86: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual  87: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  88: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  89: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  90: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual  91: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual  92: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  93: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  94: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual  95: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadActual  96: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  97: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  98: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  99: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadActual  100: 1 op, 100.00 ns, 100.0000 ns/op

// AfterActualRun
WorkloadResult   1: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult   2: 1 op, 300.00 ns, 300.0000 ns/op
WorkloadResult   3: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult   4: 1 op, 0.00 ns, 0.0000 ns/op
WorkloadResult   5: 1 op, 300.00 ns, 300.0000 ns/op
WorkloadResult   6: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult   7: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult   8: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult   9: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  10: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult  11: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult  12: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  13: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult  14: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult  15: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  16: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  17: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  18: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  19: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  20: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult  21: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult  22: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult  23: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  24: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  25: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult  26: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult  27: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  28: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult  29: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  30: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  31: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult  32: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  33: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult  34: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  35: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  36: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  37: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  38: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  39: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult  40: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult  41: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  42: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  43: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  44: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  45: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  46: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult  47: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult  48: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  49: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  50: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  51: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult  52: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  53: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  54: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult  55: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  56: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  57: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult  58: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult  59: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult  60: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  61: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  62: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  63: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  64: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  65: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult  66: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  67: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  68: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  69: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  70: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  71: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  72: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult  73: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  74: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult  75: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  76: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult  77: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  78: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  79: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult  80: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult  81: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  82: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  83: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult  84: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  85: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  86: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult  87: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  88: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  89: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  90: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult  91: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult  92: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  93: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  94: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult  95: 1 op, 100.00 ns, 100.0000 ns/op
WorkloadResult  96: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  97: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  98: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  99: 1 op, 200.00 ns, 200.0000 ns/op
WorkloadResult  100: 1 op, 100.00 ns, 100.0000 ns/op

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

Mean = 164.000 ns, StdErr = 5.416 ns (3.30%), N = 100, StdDev = 54.160 ns
Min = 0.000 ns, Q1 = 100.000 ns, Median = 200.000 ns, Q3 = 200.000 ns, Max = 300.000 ns
IQR = 100.000 ns, LowerFence = -50.000 ns, UpperFence = 350.000 ns
ConfidenceInterval = [145.631 ns; 182.369 ns] (CI 99.9%), Margin = 18.369 ns (11.20% of Mean)
Skewness = -0.38, Kurtosis = 2.46, MValue = 3.28

// ***** BenchmarkRunner: Finish  *****

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

// * Detailed results *
Repro.Tricky: Job-HOIEPP(IterationTime=250.0000 ms)
Runtime = .NET Core 2.1.22 (CoreCLR 4.6.29220.03, CoreFX 4.6.29220.01), X64 RyuJIT; GC = Concurrent Workstation
Mean = 164.000 ns, StdErr = 5.416 ns (3.30%), N = 100, StdDev = 54.160 ns
Min = 0.000 ns, Q1 = 100.000 ns, Median = 200.000 ns, Q3 = 200.000 ns, Max = 300.000 ns
IQR = 100.000 ns, LowerFence = -50.000 ns, UpperFence = 350.000 ns
ConfidenceInterval = [145.631 ns; 182.369 ns] (CI 99.9%), Margin = 18.369 ns (11.20% of Mean)
Skewness = -0.38, Kurtosis = 2.46, MValue = 3.28
-------------------- Histogram --------------------
[-15.315 ns ;  15.315 ns) | @
[ 15.315 ns ;  45.945 ns) |
[ 45.945 ns ;  84.685 ns) |
[ 84.685 ns ; 115.315 ns) | @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
[115.315 ns ; 145.945 ns) |
[145.945 ns ; 184.685 ns) |
[184.685 ns ; 215.315 ns) | @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
[215.315 ns ; 245.945 ns) |
[245.945 ns ; 284.685 ns) |
[284.685 ns ; 315.315 ns) | @@
---------------------------------------------------

// * Summary *

BenchmarkDotNet=v0.12.1.20201024-develop, OS=Windows 10.0.18363.1139 (1909/November2019Update/19H2)
Intel Xeon CPU E5-1650 v4 3.60GHz, 1 CPU, 12 logical and 6 physical cores
.NET SDK=5.0.100-rc.2.20479.15
  [Host]     : .NET Core 2.1.22 (CoreCLR 4.6.29220.03, CoreFX 4.6.29220.01), X64 RyuJIT
  Job-HOIEPP : .NET Core 2.1.22 (CoreCLR 4.6.29220.03, CoreFX 4.6.29220.01), X64 RyuJIT

IterationTime=250.0000 ms

| Method |     Mean |    Error |   StdDev |   Median |
|------- |---------:|---------:|---------:|---------:|
| Tricky | 164.0 ns | 18.37 ns | 54.16 ns | 200.0 ns |

// * Warnings *
MultimodalDistribution
  Repro.Tricky: IterationTime=250.0000 ms -> It seems that the distribution is bimodal (mValue = 3.28)
MinIterationTime
  Repro.Tricky: IterationTime=250.0000 ms -> The minimum observed iteration time is 0.0000 ns which is very small. It's recommended to increase it to at least 100.0000 ms using more operations.

After:

OverheadJitting  1: 1 op, 292500.00 ns, 292.5000 us/op
WorkloadJitting  1: 1 op, 501963300.00 ns, 501.9633 ms/op

OverheadJitting  2: 1 op, 1500.00 ns, 1.5000 us/op
WorkloadJitting  2: 1 op, 2200.00 ns, 2.2000 us/op

OverheadJitting  3: 16 op, 279100.00 ns, 17.4438 us/op
WorkloadJitting  3: 16 op, 272400.00 ns, 17.0250 us/op

WorkloadPilot    1: 16 op, 1800.00 ns, 112.5000 ns/op
WorkloadPilot    2: 2222224 op, 4812100.00 ns, 2.1654 ns/op
WorkloadPilot    3: 115449808 op, 247367700.00 ns, 2.1426 ns/op
WorkloadPilot    4: 116678352 op, 249743700.00 ns, 2.1404 ns/op
WorkloadPilot    5: 116798096 op, 249340300.00 ns, 2.1348 ns/op
WorkloadPilot    6: 117107120 op, 251407800.00 ns, 2.1468 ns/op
WorkloadPilot    7: 116451360 op, 246593600.00 ns, 2.1176 ns/op
WorkloadPilot    8: 118060000 op, 253275900.00 ns, 2.1453 ns/op
WorkloadPilot    9: 116533008 op, 251018900.00 ns, 2.1541 ns/op

OverheadWarmup   1: 116533008 op, 188750600.00 ns, 1.6197 ns/op
OverheadWarmup   2: 116533008 op, 189271600.00 ns, 1.6242 ns/op
OverheadWarmup   3: 116533008 op, 189067500.00 ns, 1.6224 ns/op
OverheadWarmup   4: 116533008 op, 186085200.00 ns, 1.5968 ns/op
OverheadWarmup   5: 116533008 op, 188822100.00 ns, 1.6203 ns/op
OverheadWarmup   6: 116533008 op, 188893800.00 ns, 1.6209 ns/op
OverheadWarmup   7: 116533008 op, 188747400.00 ns, 1.6197 ns/op

OverheadActual   1: 116533008 op, 188405600.00 ns, 1.6168 ns/op
OverheadActual   2: 116533008 op, 188850600.00 ns, 1.6206 ns/op
OverheadActual   3: 116533008 op, 185817100.00 ns, 1.5945 ns/op
OverheadActual   4: 116533008 op, 184427400.00 ns, 1.5826 ns/op
OverheadActual   5: 116533008 op, 184578900.00 ns, 1.5839 ns/op
OverheadActual   6: 116533008 op, 185092700.00 ns, 1.5883 ns/op
OverheadActual   7: 116533008 op, 185209000.00 ns, 1.5893 ns/op
OverheadActual   8: 116533008 op, 184899600.00 ns, 1.5867 ns/op
OverheadActual   9: 116533008 op, 185934800.00 ns, 1.5956 ns/op
OverheadActual  10: 116533008 op, 184836400.00 ns, 1.5861 ns/op
OverheadActual  11: 116533008 op, 185414900.00 ns, 1.5911 ns/op
OverheadActual  12: 116533008 op, 185527700.00 ns, 1.5921 ns/op
OverheadActual  13: 116533008 op, 186210900.00 ns, 1.5979 ns/op
OverheadActual  14: 116533008 op, 185053000.00 ns, 1.5880 ns/op
OverheadActual  15: 116533008 op, 184632100.00 ns, 1.5844 ns/op

WorkloadWarmup   1: 116533008 op, 245832600.00 ns, 2.1096 ns/op
WorkloadWarmup   2: 116533008 op, 245293000.00 ns, 2.1049 ns/op
WorkloadWarmup   3: 116533008 op, 245162000.00 ns, 2.1038 ns/op
WorkloadWarmup   4: 116533008 op, 244961000.00 ns, 2.1021 ns/op
WorkloadWarmup   5: 116533008 op, 245657200.00 ns, 2.1080 ns/op
WorkloadWarmup   6: 116533008 op, 246294900.00 ns, 2.1135 ns/op
WorkloadWarmup   7: 116533008 op, 245725600.00 ns, 2.1086 ns/op
WorkloadWarmup   8: 116533008 op, 245393600.00 ns, 2.1058 ns/op
WorkloadWarmup   9: 116533008 op, 246094600.00 ns, 2.1118 ns/op
WorkloadWarmup  10: 116533008 op, 245749700.00 ns, 2.1088 ns/op

// BeforeActualRun
WorkloadActual   1: 116533008 op, 245788700.00 ns, 2.1092 ns/op
WorkloadActual   2: 116533008 op, 245751100.00 ns, 2.1089 ns/op
WorkloadActual   3: 116533008 op, 245487500.00 ns, 2.1066 ns/op
WorkloadActual   4: 116533008 op, 245508200.00 ns, 2.1068 ns/op
WorkloadActual   5: 116533008 op, 246769300.00 ns, 2.1176 ns/op
WorkloadActual   6: 116533008 op, 245382800.00 ns, 2.1057 ns/op
WorkloadActual   7: 116533008 op, 245853100.00 ns, 2.1097 ns/op
WorkloadActual   8: 116533008 op, 249405600.00 ns, 2.1402 ns/op
WorkloadActual   9: 116533008 op, 250143500.00 ns, 2.1465 ns/op
WorkloadActual  10: 116533008 op, 249928400.00 ns, 2.1447 ns/op
WorkloadActual  11: 116533008 op, 246092400.00 ns, 2.1118 ns/op
WorkloadActual  12: 116533008 op, 246482600.00 ns, 2.1151 ns/op
WorkloadActual  13: 116533008 op, 246144800.00 ns, 2.1122 ns/op
WorkloadActual  14: 116533008 op, 245960900.00 ns, 2.1107 ns/op
WorkloadActual  15: 116533008 op, 245346400.00 ns, 2.1054 ns/op

// AfterActualRun
WorkloadResult   1: 116533008 op, 60579700.00 ns, 0.5199 ns/op
WorkloadResult   2: 116533008 op, 60542100.00 ns, 0.5195 ns/op
WorkloadResult   3: 116533008 op, 60278500.00 ns, 0.5173 ns/op
WorkloadResult   4: 116533008 op, 60299200.00 ns, 0.5174 ns/op
WorkloadResult   5: 116533008 op, 61560300.00 ns, 0.5283 ns/op
WorkloadResult   6: 116533008 op, 60173800.00 ns, 0.5164 ns/op
WorkloadResult   7: 116533008 op, 60644100.00 ns, 0.5204 ns/op
WorkloadResult   8: 116533008 op, 60883400.00 ns, 0.5225 ns/op
WorkloadResult   9: 116533008 op, 61273600.00 ns, 0.5258 ns/op
WorkloadResult  10: 116533008 op, 60935800.00 ns, 0.5229 ns/op
WorkloadResult  11: 116533008 op, 60751900.00 ns, 0.5213 ns/op
WorkloadResult  12: 116533008 op, 60137400.00 ns, 0.5161 ns/op

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

Mean = 0.521 ns, StdErr = 0.001 ns (0.21%), N = 12, StdDev = 0.004 ns
Min = 0.516 ns, Q1 = 0.517 ns, Median = 0.520 ns, Q3 = 0.523 ns, Max = 0.528 ns
IQR = 0.005 ns, LowerFence = 0.510 ns, UpperFence = 0.530 ns
ConfidenceInterval = [0.516 ns; 0.525 ns] (CI 99.9%), Margin = 0.005 ns (0.93% of Mean)
Skewness = 0.55, Kurtosis = 2.12, MValue = 2

// ***** BenchmarkRunner: Finish  *****

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

// * Detailed results *
Repro.Tricky: Job-JWNAWB(IterationTime=250.0000 ms)
Runtime = .NET Core 2.1.22 (CoreCLR 4.6.29220.03, CoreFX 4.6.29220.01), X64 RyuJIT; GC = Concurrent Workstation
Mean = 0.521 ns, StdErr = 0.001 ns (0.21%), N = 12, StdDev = 0.004 ns
Min = 0.516 ns, Q1 = 0.517 ns, Median = 0.520 ns, Q3 = 0.523 ns, Max = 0.528 ns
IQR = 0.005 ns, LowerFence = 0.510 ns, UpperFence = 0.530 ns
ConfidenceInterval = [0.516 ns; 0.525 ns] (CI 99.9%), Margin = 0.005 ns (0.93% of Mean)
Skewness = 0.55, Kurtosis = 2.12, MValue = 2
-------------------- Histogram --------------------
[0.514 ns ; 0.531 ns) | @@@@@@@@@@@@
---------------------------------------------------

// * Summary *

BenchmarkDotNet=v0.12.1.20201024-develop, OS=Windows 10.0.18363.1139 (1909/November2019Update/19H2)
Intel Xeon CPU E5-1650 v4 3.60GHz, 1 CPU, 12 logical and 6 physical cores
.NET SDK=5.0.100-rc.2.20479.15
  [Host]     : .NET Core 2.1.22 (CoreCLR 4.6.29220.03, CoreFX 4.6.29220.01), X64 RyuJIT
  Job-JWNAWB : .NET Core 2.1.22 (CoreCLR 4.6.29220.03, CoreFX 4.6.29220.01), X64 RyuJIT

IterationTime=250.0000 ms

| Method |      Mean |     Error |    StdDev |
|------- |----------:|----------:|----------:|
| Tricky | 0.5206 ns | 0.0048 ns | 0.0038 ns |

// * Hints *
Outliers
  Repro.Tricky: IterationTime=250.0000 ms -> 3 outliers were removed (2.14 ns..2.15 ns)

@adamsitnik
add the test
22685a1
@adamsitnik
if the Jitting took more than IterationTime but still less than 1s (a…
f64d94e 
… magic number based on observations of the reported bug)

we call it one more time to see if Jitting itself has not dominated the first invocation
if it did, it shoud NOT be a single invocation engine (fixes #837, fixes #1337 and fixes #1338)
@adamsitnik adamsitnik added this to the v0.13.0 milestone Oct 24, 2020
This was referenced Oct 24, 2020
Closed
Closed
Closed
@AndreyAkinshin AndreyAkinshin merged commit 178b6ad into master Oct 26, 2020
@AndreyAkinshin AndreyAkinshin deleted the oncePerIterationBug branch October 26, 2020 15:43
adamsitnik added a commit to adamsitnik/performance that referenced this pull request Nov 10, 2020
@adamsitnik
there is no need for the warmup workaround anymore, dotnet/BenchmarkD…
6c3b2e3 
…otNet#1573 has solved the problem
@airbreather airbreather mentioned this pull request Jan 12, 2021
Merged
MarkPflug pushed a commit to MarkPflug/Benchmarks that referenced this pull request Jan 12, 2021
@airbreather
Update Cursively benchmark code. (#1)
ba6a1b1 
* Update Cursively benchmark code.
- VisitPartialFieldContents is required for correctness
- Use the original byte array, since we have one, instead of forcing a stream around it
- Set iteration time to 1 second, to work around dotnet/BenchmarkDotNet#837 while we wait for a version of this package that includes dotnet/BenchmarkDotNet#1573

* Change the order of this check

Whether or not this is the optimal order is almost certain to depend on the data: data sets that would almost never use the pool would likely hurt more by doing it this way, especially if this were a real-world application since this would likely push a line out of the CPU cache for no reason.

Then again, a real-world application probably wouldn't use the pool conditionally like this, so there's not much of a reason NOT to either.
adamsitnik added a commit to dotnet/performance that referenced this pull request Feb 4, 2021
@adamsitnik
Refactor initialization logic to allow for enabling Memory Randomizat…
e8a8fc6 
…ion (#1587)

* there is no need for the warmup workaround anymore, dotnet/BenchmarkDotNet#1573 has solved the problem

* allocate the array first to try to take advantage of memory randomization as it's usually the first thing called from GlobalSetup method

which with MemoryRandomization enabled is the first method called right after allocation of random-sized memory by BDN engine

* avoid having big global setup methods and try to have Targeted setups that allocate less

as Global Setup methods might get called right after random-size memory allocation

* avoid readonly fields, initialize them in [GlobalSetup] instead of ctors (to allow for re-allocation with different alignment)

* this code can be executed only once

* make sure that every setup creates a brand new delegate instead of combining with existing one

* the "WriteDeepUtf16" benchmark can report up to x4 more time when MemoryRandmization is enabled

this is due to having new _arrayBufferWriter every time and allocating a lot of memory
so we don't always allocate a new instance

* allocate the array in GlobalSetup, not in field initializer
@AndreyAkinshin AndreyAkinshin mentioned this pull request Aug 19, 2021
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@AndreyAkinshin AndreyAkinshin AndreyAkinshin approved these changes

Assignees
No one assigned
Labels
Area:Engine
Projects
None yet
Milestone
v0.13.0
2 participants
@adamsitnik @AndreyAkinshin