Recently I had to do some performance profiling for one of our applications that was almost ready for production. Always on the lookout for new tools, I decided to check out what open source profilers were available.
The best one I found was nprof, the .NET profiler. Download the zip file and extract to a folder on your computer. Following the instructions, I ran the RegisterProfilerHook.bat file to register the hook file. Then I started nprof and was getting work done almost immediately. There is also a file that will register nprof as a Visual Studio add-in. Make sure you close all instances of Visual Studio before running the batch file, a fact I learned the hard way. Then under the Tools menu you should see nprof Profiling. Expand that and click it to turn profiling on. Click again to turn profiling off.
For this example, I am using an application that John Robbins wrote to illustrate the features of Visual Studio’s new Enterprise Performance Tool in MSDN Magazine’s December 2004 issue. Download the code from that article, install it and compile it before continuing. I also follow the article pretty closely, and end up getting similar results to John Robbins. I highly suggest reading his article because the concepts will be similar, although the new EPT tool will have a lot more functionality than nprof. But you can’t beat free!
To profile, go to the File menu and select New. The screen looks like this:
The File radio button lets you select standard windows and console applications to profile. The ASP.NET radio button is for profiling web sites. The Debug profiler hook is supposed to allow you to debug into the application you are profiling, but I haven’t gotten it to work. The Profile started applications option tells nprof whether to profile any applications your application starts (such as a windows form application starting Excel). If you are using the Visual Studio add-in, you won’t need to setup this screen at all unless you want to change the default options.
For this, click the browse button next to “Application to run” and navigate to the AnimatedAlgorithm.exe file. Then click the “Create Project” button. You know have an unsaved profiling project. You can save it if you expect to reuse it. In fact you should save it because proper performance profiling goes through a process of profiling, make a code change, and then profile again to see if the change improved performance or not. So save the project as AnimatedAlgorithmProfile and click save. Your screen should now look like this:
The File menu is standard stuff, so let’s skip to the Project menu. Currently the only options we have are to Start a project run and Options. Clicking the options menu item takes you back to the Create Profiler Project dialog we saw earlier.
Select Start project run or press F5 to start profiling. If everything is setup properly, the Animated Algorithm Display form should launch. Everything that you do to the application will be recorded by nprof for performance data. Click the Sort button with “Bidirectional Bubble Sort” selected in the dropdown list. Watch the pretty display. When it’s done, close the Animated Algorithms form. Nprof will now crunch through the data, which may take a little bit of time depending on the speed of your computer and how much data was gathered during profiling.
Now nprof should look similar to this:
The first thing to notice is that nprof groups the profiling data based on which thread the code ran on. Unfortunately there is no combined view to see everything from all threads, but the feature may make it into a future version. It’s not necessary, just nice to have.
Now take a look at main window underneath “Filter signatures”. The Signature column is the method signature that was called. You will probably recognize most of these, as they are mostly calls to the .NET Framework. If your app is relatively performant, it is expected that most of the time be taken up with system calls.
The “# of Calls” column is just that, the total number of calls to that method. Clicking on the column header sorts the data by that column’s value, and clicking again reverses the sort.
The next column is the “% of Total” column, which shows how long the application spent in that method as a percentage of the total profiled run time. If you sort by this column and you’re on the first thread (which it should be by default), you’ll notice that the biggest number is only like 0.05 or so. What gives? Well, the main thread isn’t doing that much work compared to the other threads. Click on one of the other threads to see higher numbers.
Making sure that the percent of total column is sorted descending (with higher numbers at the top), find the thread that has the application Main. The signature will be “static voic AnimatedAlgorithm.AnimatedAlgorithmForm::Main()”. Notice that it is called once and the percent of time in the method should be close to 98 or 99%. One might think this is where we should start our performance analysis, but hold on!
The next column, “% in Method”, shows the percentage of the time the program actually spent in the method. On my computer that number is zero. If the time spent in the method is 0%, and the total percent is 99%, then the percentage spent in called methods must also be 99%. And that is exactly what the next column, “% in Children”, tells us. So that means any performance efforts will not happen in this method. The final column, “% Suspended”, shows how much time the method was waiting for something to happen not in a called method. If the suspended percentage is much above 0.1%, it is probably worth checking out to see why.
Click the “% in Method” column to sort by which methods actually ran the longest. If you’re on the right thread, the RunMessageLoopInner should be the highest, which is perfectly fine. What we need to do is see what code (if any) that John Robbins wrote or that is included in the NSort assembly is slow.
Fortunately nprof provides a handy namespace treeview on the left below the thread tree. Uncheck the System and Microsoft namespaces. Now you’ll notice that while the RunMessageLoopInner is still on top, the Wintellect.SortDisplayGraph.SorterGraph::UpdateSingleFixedElement is the next highest with 1.03%. The next method after that only has 0.12%. At least now we are to code that we can change to improve the application. Alternatively, you can uncheck the All Namespaces node and then check the Wintellect, NSort, and AnimatedAlgorithm namespaces. This finally gets rid of that pesky RunMessageLoopInner.
Looking at the results, we can see that the UpdateSingleFixedElement is the best looking candidate for performance improvement on this thread. Clicking up to the second thread, the Wintellect.SortDisplayGraph.GraphSwapper::Swap method is the highest with 1.59%, and the next method with a mere 0.12%. On the first thread there is nothing over 0.05% anyway, so it’s not even worth looking at, unless you are really obsessed.
If you select a method signature, the callees and callers will be filled in. The callees are those methods that the selected method calls. The data includes how much time is spent in each of the called methods. The callers are the methods that make a call to the selected method. You can click on methods in the callee/caller tabs and it will select that method in the main method signature area, which will then show you the callees and callers of that method.
Now we have at least two good candidate methods to look at to improve performance. I’m not going to go any further until John Robbins posts his follow-up article. Until then, happy profiling!