In my previous post on this topic, I did mention that it wasn’t about the code, but the concept. Still, I wrote that code a while back and only really used it that one day. For the code I timed that day, it was fine, but for anything more, it was not, as I found last night when I needed to time an async method that’s called all the time. So here is some more robust code that times methods without accidently interfering with them. It also tracks calls to the methods it times, and logs the timings and averages per method, and at a much better resolution.
Again, the source, for this and a whole bunch of other stuff, is here: RomyView.zip
Here is an example of its results:
2013-01-23 12:09:00.00 Thumbnail.LoadImageAsync Time: 74.2155ms Average: 119.179ms 2013-01-23 12:09:00.00 Thumbnail.LoadImageAsync Time: 74.5946ms Average: 118.2873ms 2013-01-23 12:09:00.00 Thumbnail.LoadImageAsync Time: 73.3504ms Average: 117.4062ms 2013-01-23 12:09:00.02 Thumbnail.LoadImageAsync Time: 80.4276ms Average: 116.6951ms 2013-01-23 12:09:00.02 Thumbnail.LoadImageAsync Time: 81.7943ms Average: 116.0366ms 2013-01-23 12:09:05.71 BaseForm.LoadTheme Time: 17.6966ms Average: 9.7432ms 2013-01-23 12:09:05.71 BaseForm.LoadTheme Time: 1.4265ms Average: 6.971ms 2013-01-23 12:09:05.71 BaseForm.LoadTheme Time: 0.5618ms Average: 5.3687ms 2013-01-23 12:09:06.66 BaseForm.LoadTheme Time: 182.235ms Average: 40.7419ms 2013-01-23 12:09:06.66 BaseForm.LoadTheme Time: 0.8616ms Average: 34.0952ms
The timing methods look a little different to before, since the code no longer tries to write a file for every method call. They now just take two parameters: the method to time, and a description (or the method name or whatever you want to pass as a string). According to the Visual Studio 2012 Code Analysis, it commits some sort of mortal sin, because it uses a static constructor. Initialize all of your static fields inline, it tells me… Hello, I did that! But I couldn’t think of another way to save the results file, other than creating an event handler for Application.ApplicationExit, which I did in the constructor. The code now looks like this:
Perhaps it’s worth mentioning that you can’t directly time an async void method. I’m not sure how obvious it is to everyone, but the reason for this (and if you weren’t aware of it, you could get excited for nothing, thinking that your code runs super-fast) is that async void methods return immediately. That’s why they’re also called fire-and-forget methods. The async additions to .Net 4.5 are still new enough that many developers might not realize the difference between async methods that return a Task or Task<Result> and async methods that return void, but it’s a difference you need to understand if you write much async code. The methods that return results require you to use the await keyword, to wait asynchronously on their return values, while async void methods return immediately, promising that their work will be done eventually.
So if I want to time an async void method, I temporarily change it to an async Task method, and add a new temporary async void method that calls it. I did this in the example near the top of this post. LoadImageAsync is called from a property setter, which can’t be declared as async. The code below is from my Thumbnail control. I changed the signature of the LoadImageAsync method as mentioned above, and added the temporary LoadImage method, which is where I called the timing method.