Investigating Weird Result Times in Benchmark.NET
Why Are You Out of Your Foxhole?!
As you may or may not know, I am not a big fan of blogging. Well, not personally, at least. It takes a lot of energy and I would rather put that energy into coding — where it belongs! So, why am I taking time to do something mundane as share my thoughts around //build 2018 and write even more things I might immediately regret to produce yet another article here for you?
Did I have a change of heart? Not really, but, in short, I will say that I have been completely derailed on an issue that has taken a good amount of time to diagnose (having three different forms when combined over the course of the past year) and I thought I would do a bit of a retrospective here to bring closure to this most difficult time. 😂
SO GET TO IT, MAN!
Alright, it’s actually very difficult to articulate, but the short of it is that when running Benchmark.NET benchmarks, results will vary by 10-15% with the smallest of changes in code. Additionally, if one was not paying close attention (i.e. overly obsessive and quite possibly a tad OCD 🤔) then it was very easy to over look this very strange phenomena as the times are off by a slim margin and difficult to perceive unless you are really locked into spotting it.
For me, this all began a little over a year ago, when I started to experience some very peculiar (and very subtle) anomalies while running some Benchmark.NET performance testing for my contributions to ExtendedXmlSerializer v2. These anomalies would seem to be fixed, only to return after I ended up writing more code and writing more code that had nothing to do with the code being benchmarked. We are talking Grade A Insanity Fodder here.
The pattern ran as such:
- Identify poor performance.
- Change some code.
- Notice better performance.
- Change/add/remove some code that had nothing to do with the code being benchmarked (e.g. comment out a class altogether).
- Notice different result times (could be better, could be worse).
I thought for sure there was something wrong with my machine — it was overclocked, and it was running Windows Server, with the images from several upgrades images from Windows 8.0. I was also running tests within a Virtual Machine and this is also known to impact results (although this was a different issue altogether).
So I formatted my server and reinstalled everything from scratch. In the end, I ended up being very uncharacteristic of myself and abandoning the whole performance story all together because it was simply taking up too much time to diagnose. Part of the problem was that I was using .NET Core 1.1 tooling and I thought for sure there might be a latent bug lurking somewhere in there. However, thinking it was mostly a Benchmark.NET issue, I managed to make a mess of their repository in my pursuit by setting up issues here, here, here, and here.
Fast forward a year later, and you find me trying out the latest .NET Core 2.0 magic (which is really quite incredible, btw! more below). This involved getting all the latest versions of everything with up-to-date Windows OS software, the whole ordeal. Despite all of this, guess what I manage to discover is still easily readily visible and lurking within Benchmark.NET? That’s right, the very gremlin that is the subject of this entire ordeal.
This time, however, I was able to capture it with a simple LINQ
ToArray call, and produce different variations of results from the exact same code being benchmarked. While the actual benchmark code did not change, the results differed if I added new attributes, or a different component such as the
If you are interested in seeing these different variations, you can start here. Note this branch especially which demonstrates this issue simply by adding a
System.ComponentModel.DescriptionAttribute (!) to this branch (you can see the result times from their respective READMEs). Additionally, note that this issue occurs when you keep the
BenchmarkDotNet.Artifacts folder on the local system disk versus deleting it.
Additionally, for a much simpler reproduction of this issue, you can see my simple reproduction application here along with an alternate version here. These make use of the
BenchmarkSwitcher to easily go through different cases and demonstrate the different times.
What On Earth is Going on Here?
In the spirit of trying to keep the amount of time I have invested into this to under 110 hours 😉, I was fortunate to discover that upgrading between .NET Core 2.0 and .NET 2.1 produced this error without any additional code changes. Aha! At this point, I knew for certain that I was no longer dealing with a Benchmark.NET-specific issue, but rather, some odd behavior in the .NET Core CLR/SDK/Tooling. So, I set up the Bat Signal on their repository to see what the deal was. You can follow along here. A big shout out to @mikedn for taking the time and having the patience to walk through this with me. I thought for sure I was crazy, but it turns out that I am not … well, as far as this particular issue is concerned, that is. 🎉
When the dust settled, it appears that we are looking at a JIT-related code alignment issue, and one that is now being tackled by the Benchmark.NET team. Additionally, I was able to find a workaround for the interim to get me unblocked. So I am finally free to code again. WHEW! 😌😂
The Awesome State of the Current .NET Ecosystem
With all of that out of the way, I did want to take a second to send a shout out to the current state of the .NET ecosystem. Just how awesome is it right now?! You know, it used to be that you would go on Connect, wait a full day for the page to load (or whatever was/is going on there), then wait a full month for their team to figure out a reason not to fix your issue, and then have them return with the lame excuse to relay to all the people who have voted to have that issue fixed. (Turns out that Connect has been sunsetted, as it should be — it’s too bad as I had some great examples of closing issues without a whole lot of merit.)
These days, you have full collaborative exposure to the _entire team_ that is building the product in which you are having a problem and really have some awesome conversations and insight into the entire process! It’s really amazing. AND if you feel so daring you can actually contribute with your own pull requests and actually make a difference.
Now THAT is making the world a better place. 😉
And, I am not sure if you frequent blog posts, but the .NET team also does a terrifically amazing job of being very engaging and interactive with their developers and customers. Maybe it’s been like this for years and I haven’t noticed? There’s also Twitter, as well. But, I find Twitter to be cumbersome and awkward — not to mention, EVIL! 🤣 Sorry, but I cannot be constrained by x-characters and require freedom to expression! But, regardless of your medium, it’s fantastic to see such a transparent, open, and engaging community and process these days. Let’s hope it only gets better from here (although I am not sure how it can!).
Some notable performance/.NET shout outs (in order that they arise to me, don’t hold it against me!):
- Wojciech Nagórski: For putting together ExtendedXmlSerializer to make this whole adventure possible.
- Andrey Akinshin, Adam Sitnik, and Matt Warren: For your efforts towards Benchmark.NET, truly a transformative application and asset for our community.
- mikedn: I appreciate your help so much you get two mentions. 😁
- Stephen Toub: For being as attentive to feedback as you are meticulous in your writings!
- Andy Ayers: For your insight, assistance, and engagement with the community.
- Mike Strobel: While I have the horn out, a massive shout out to all your research on my performance question on StackOverflow!
- Immo Landwerth: Not really related to this issue, but wanted to send a quick shout out to thank you for managing .NET the way it should be. 😊
OK… enough of this writing business. Now, where was that foxhole of mine… 🦊 IT’S TIME TO CODE AGAIN Y’ALL!!!