search

petabridge / NBench

Performance benchmarking and testing framework for .NET applications :chart_with_upwards_trend:
https://nbench.io/
Apache License 2.0
532 stars 46 forks source link

Investigate pauses and time disparity for specific benchmark runs #34

Closed Aaronontheweb closed 8 years ago

Aaronontheweb commented 8 years ago

Seeing some instances of benchmarks where we have a major StdDev disparity between two runs of the same benchmark:

[03:43:39][Step 1/1] ------------ STARTING NBench.Tests.Performance.ThroughputLoopPerformanceSpec+ForLoop ---------- 
[03:43:39][Step 1/1] --------------- BEGIN WARMUP ---------------
[03:43:39][Step 1/1] Elapsed: 00:00:00.6828316
[03:43:39][Step 1/1] [Counter] TestCounter - operations: 37,500,000.00 ,operations: /s 54,918,372.26 , ns / operations: 18.21
[03:43:39][Step 1/1] --------------- END WARMUP ---------------
[03:43:39][Step 1/1] 
[03:43:41][Step 1/1] --------------- BEGIN RUN ---------------
[03:43:41][Step 1/1] Elapsed: 00:00:00.6704073
[03:43:41][Step 1/1] [Counter] TestCounter - operations: 37,500,000.00 ,operations: /s 55,936,145.09 , ns / operations: 17.88
[03:43:41][Step 1/1] --------------- END RUN ---------------
[03:43:41][Step 1/1] 
[03:46:02][Step 1/1] --------------- BEGIN RUN ---------------
[03:46:02][Step 1/1] Elapsed: 00:02:20.9072606
[03:46:02][Step 1/1] [Counter] TestCounter - operations: 37,500,000.00 ,operations: /s 266,132.49 , ns / operations: 3,757.53

TROUBLE

[03:46:02][Step 1/1] --------------- END RUN ---------------
[03:46:02][Step 1/1] 
[03:46:02][Step 1/1] --------------- BEGIN RUN ---------------
[03:46:02][Step 1/1] Elapsed: 00:00:00.6566757
[03:46:02][Step 1/1] [Counter] TestCounter - operations: 37,500,000.00 ,operations: /s 57,105,813.42 , ns / operations: 17.51
[03:46:02][Step 1/1] --------------- END RUN ---------------
[03:46:02][Step 1/1] 
[03:46:03][Step 1/1] --------------- BEGIN RUN ---------------
[03:46:03][Step 1/1] Elapsed: 00:00:00.6865853
[03:46:03][Step 1/1] [Counter] TestCounter - operations: 37,500,000.00 ,operations: /s 54,618,122.47 , ns / operations: 18.31
[03:46:03][Step 1/1] --------------- END RUN ---------------
[03:46:03][Step 1/1] 
[03:48:21][Step 1/1] --------------- BEGIN RUN ---------------
[03:48:21][Step 1/1] Elapsed: 00:02:18.1465176
[03:48:21][Step 1/1] [Counter] TestCounter - operations: 37,500,000.00 ,operations: /s 271,450.93 , ns / operations: 3,683.91
[03:48:21][Step 1/1] --------------- END RUN ---------------
[03:48:21][Step 1/1] 
[03:48:22][Step 1/1] --------------- BEGIN RUN ---------------
[03:48:22][Step 1/1] Elapsed: 00:00:00.6592115
[03:48:22][Step 1/1] [Counter] TestCounter - operations: 37,500,000.00 ,operations: /s 56,886,143.52 , ns / operations: 17.58
[03:48:22][Step 1/1] --------------- END RUN ---------------
[03:48:22][Step 1/1] 
[03:50:44][Step 1/1] --------------- BEGIN RUN ---------------
[03:50:44][Step 1/1] Elapsed: 00:02:21.7176385
[03:50:44][Step 1/1] [Counter] TestCounter - operations: 37,500,000.00 ,operations: /s 264,610.68 , ns / operations: 3,779.14

TROUBLE

[03:50:44][Step 1/1] --------------- END RUN ---------------
[03:50:44][Step 1/1] 
[03:50:44][Step 1/1] --------------- BEGIN RUN ---------------
[03:50:44][Step 1/1] Elapsed: 00:00:00.6883052
[03:50:44][Step 1/1] [Counter] TestCounter - operations: 37,500,000.00 ,operations: /s 54,481,645.64 , ns / operations: 18.35
[03:50:44][Step 1/1] --------------- END RUN ---------------
[03:50:44][Step 1/1] 
[03:50:45][Step 1/1] --------------- BEGIN RUN ---------------
[03:50:45][Step 1/1] Elapsed: 00:00:00.6448187
[03:50:45][Step 1/1] [Counter] TestCounter - operations: 37,500,000.00 ,operations: /s 58,155,881.65 , ns / operations: 17.20
[03:50:45][Step 1/1] --------------- END RUN ---------------
[03:50:45][Step 1/1] 
[03:50:46][Step 1/1] --------------- BEGIN RUN ---------------
[03:50:46][Step 1/1] Elapsed: 00:00:00.6796817
[03:50:46][Step 1/1] [Counter] TestCounter - operations: 37,500,000.00 ,operations: /s 55,172,884.60 , ns / operations: 18.12
[03:50:46][Step 1/1] --------------- END RUN ---------------
[03:50:46][Step 1/1] 
[03:50:46][Step 1/1] --------------- RESULTS: NBench.Tests.Performance.ThroughputLoopPerformanceSpec+ForLoop ---------------
[03:50:46][Step 1/1] --------------- DATA ---------------
[03:50:46][Step 1/1] [Counter] TestCounter: Max: 37,500,000.00 operations, Average: 37,500,000.00 operations, Min: 37,500,000.00 operations, StdDev: 0.00 operations
[03:50:46][Step 1/1] [Counter] TestCounter: Max / s: 58,155,881.65 operations, Average / s: 39,315,883.05 operations, Min / s: 264,610.68 operations, StdDev / s: 26,969,798.52 operations

Could just be background noise and I just need to increase the number of iterations of each benchmark, or we could be doing something that isn't a best practice that leaves us susceptible to JIT time or GC overhead mid-benchmark.

Aaronontheweb commented 8 years ago

Fixed it - caused by having "prefer X86" enabled on the .csproj file for the runner.