There’s real satisfaction to be had in debugging and fixing performance problems. They’re such a potent source of irritation to users that there’s often a certain amount of kudos on offer if you manage to fix one. And fortunately nowadays there are many tools that make this easier – although I’ve always felt it’s important to keep users in the dark about exactly how much easier (you never know when that kudos is going to come in handy). Often you can see where the problem lies as soon as you open the results. My favourite performance tool is (obviously, usual disclaimers apply, blah, blah, etc.) ANTS Performance Profiler.
It’s easy to find yourself expecting that all performance problems will be similarly easy, so it comes as rather a disappointment when they’re not, and you actually have to do some real work to see any improvement. Sometimes you find yourself having to make changes in several places to shave execution time from different activities, which can become quite involved.
A case in point is the start-up time of .NET Reflector 7, which has been the crab infestation in the groin of my development schedule for at least two weeks now and which, frustratingly, I still don’t feel I’ve truly understood.
Of course, one starts off with the cheap solutions and the usual suspects.
The cheap solution relates to an issue caused by assemblies on network shares that, for whatever reason, aren’t available when you open up .NET Reflector: there’s this appalling delay before you can use Reflector whilst it waits for a network timeout. And the solution? For now, just don’t do that. Unfortunately this isn’t the problem people have been experiencing.
Moving on to the usual suspects: our check for updates and licensing components.
Check for updates does exactly what it says on the tin – phones home to find out if a new version of the software is available. (Don’t worry: it doesn’t tell us anything about you, other than which version you’re licensed for so we can tell you which updates are available for free.) This happens on start-up and, because it means involving t’internet (which might or might not be accessible), it really should happen on a background thread so it doesn’t get in the way. This was the case, but it turns out the call was being marshalled onto the thread and executed synchronously, for reasons lost in antiquity, which explains why it was the biggest performance bottleneck I could see when I ran ANTS Performance Profiler over our start-up code. Nice easy fix though!
I also discovered a bug in licensing, fixed in our other products, that can really slow down start-up on some machines due to a faulty network configuration. Again, not difficult to fix.
So, did this work? Not so far. The check for updates issue was fixed for 7.1, but licensing wasn’t. Nevertheless, as you’ll see if you read the discussion at http://forums.reflector.net/questions/589/startup-time it doesn’t look like either of these was the problem.
Time to fire up the profiler again…
I managed to identify several problem areas from the results over several runs:
- WPF application initialisation
- Creation and population of the ElementHost control, used to host WPF elements
- Unnecessary update and redraw of the assembly browser tree
- Unnecessary decompilation with multiple tabs open
I managed to improve (1) by moving WPF App creation onto a background thread. This is quite an expensive constructor call, as you can see from Figure 1, and is necessary so that the WPF resources (BAML, etc.) are available when adding WPF elements to a WinForms ElementHost control. I posted about this on StackOverflow a while back at http://stackoverflow.com/questions/4326621/wpf-control-not-displaying-in-elementhost-in-winforms-app. Fortunately this is a one-time cost.
Figure 1. This illustrates the cost of creating a new WPF App instance. Originally this was called without locking from the main thread once as almost the first start-up action. This method is now invoked on a background thread at start-up, and then by anything that creates a WPF element so that, if App creation is incomplete, the main thread will block before element creation until it is complete. Incidentally this illustrates how the average time for a line of code can be misleading – in reality the check to see if the App has been created is only expensive the first time it’s performed, as can be clearly seen from the call graph in Figure 2, which illustrates both execution paths calling this method.
Figure 2. Here you can see that it’s the first call to EnsureMergeWpfApplicationResources() that costs so much – the second call is close to instantaneous. You can also see the significance of the contributions from BAML loading and JIT compilation. You have to wonder how much quicker it would be to get rid of the middle man and turn the BAML into IL, a la WinForms, so it doesn’t need interpreting at runtime. You’d still have the JIT cost of course, but that’s a rant for another day.
Unfortunately there’s not much I can do about (2) because it’s just creating a control that is visible almost immediately upon startup, so it’s not as though I can defer it until later. It also needs to happen on the main thread. I hope that the cost of creating ElementHost controls isn’t a linear relationship proportional to the number of them you create, otherwise this could get really ugly as we replace more bits of the WinForms UI with WPF elements that, for now, will need to be hosted in ElementHost controls. There will come a point where we can flip over to all-WPF for the main UI, and this problem will disappear, but that’s not likely to happen for a while, and it’s not a topic the WPF books cover!
I wonder if (2) contributes to WPF’s reputation for being slow. I think the charge overall is unfair – WPF is certainly quicker than WinForms when comparing like for like interfaces and controls, but perhaps because you can do more with WPF the tendency is to take advantage of that, go overboard with your UI design, and then run into performance problems. You might notice that I’ve slightly de-chromed the tab interface in comparison to 7.1, which should help here too. This wasn’t a massive problem, but it was potentially distracting. I suspect that, because there are often multiple ways of solving a problem with WPF, it’s all too easy to pick a suboptimal solution that underperforms.
Back on message again…
(3) was an easy fix, once I could see it was happening. The tree now generally only updates and repaints once, when all assemblies having finished loading. The only time this might not happen is if an individual assembly took more than a couple of seconds or so to load, in which case there might be an intermediate update. We also still force updates when assemblies are removed, but this obviously doesn’t affect start-up time.
I thought I’d managed to stop (4) some time ago, but either I didn’t or it had been broken again subsequently. This caused a decompilation event for every open tab, which was particularly apparent if you’d chosen to persist tabs when you closed Reflector. Now only the item in the selected tab is decompiled. As a result, loading multiple tabs on start-up and refresh is now very fast, since all we do is populate the tab headers, not the tabs themselves.
All of this has shaved the odd second off, here and there, and has cut start-up time roughly in half for me. It now takes between 3 and 5 seconds to open Reflector, with about 25 assemblies in the list, and 30 or 40 tabs open (obviously a bit excessive), obviously depending upon what else my machine is doing.
OK, so this is all great, but do I think it’s got to the root of the problem reported here?
Not so much. I’d be surprised if there was no improvement but at the same time I can’t help thinking there’s some pathological edge case here that we haven’t yet been able to identify. Thus far nothing in the configuration files from these users indicates anything amiss: no huge lists of assemblies, no misbehaving add-ins, no references to anything on network shares – in fact nothing interesting whatsoever.
We’ll find out soon enough: I’ve just uploaded a new .NET Reflector EA build, which you can get from the www.reflector.net homepage.
This all might sound a little negative, but it’s really not: I’m confident we’ll get to the bottom of the problem, it might just take some time. Once I understand what’s going wrong I suspect the fix will be relatively straightforward.