“The web site is slow!” Sure, but why? You could take a guess, or do some “premature optimization.” But in those cases you’re just shooting in the dark. A client recently tasked us with optimizing ten aspects of their
C#, .NET WebForms application that sat on SQL Server. We decided to give Redgate’s ANTs profiler a try.
When it comes to performance, often it is not where you think it is. For instance, I once optimized a three-tiered application that was running slowly and everyone’s guess was, of course, the database. Using a tool (ANTS again as it happens) to gain insight, it turned out to be multiple serializations of objects that was taking up all the time and the database calls were fine. That brief example illustrates that you really need to use a tool to determine what the problem is instead of just hacking at the oft maligned database.
In this post, I’ll cover my recent experience with the ANTS profiler from Redgate. I won’t be comparing it with other tools, but overall it did a fine job for this project.
Preparation
You don’t need to do anything to your app to use ANTS. In this instance, I built the web app into a folder served by IIS. Then I simply started ANTS and told it to profile the site.
The ANTS overhead seems minimal, so I let it run with all but I/O profiling checked. Enabling SQL queries is a great feature as you’ll see below. You can add multiple perfmon counters to the timeline, but in my case CPU is sufficient.
Profiling
ANTS will launch a browser and navigate to your web site. From there you can run through the scenarios you want to profile. Since you can save the session, it’s often handy to run a couple scenarios in one profiling session and analyze the results post-mortem. When it starts running, at the top of the screen will be the overall perfmon graph. Under it is a similar view, but you can grab just part of the timeline as a region. Here I’ve selected a region as the red arrows show, and the zoomed in area is shown below it. You can drag the region, or move either end to change it’s size.
As you run through your code, you’ll want to mark what you did in ANTS so you can find it later. You can use the Start/Stop Live bookmark button to automatically create a bookmark for an action. It will name it with the time range, but you can edit it and give it a meaningful name such as Click Save below.
You can also use drag cursor in the timeline to select a region, then click Bookmark selected region to create a new bookmark.
You can do analysis while ANTS is running, but the timeline will keep growing and the session will get large. I prefer to run through my scenarios, click Stop to halt the profiling, and then do the analysis.
Analyzing
Under the timeline you’ll have several tabs as listed below. Each tab shows data from the selected region, so you’ll almost always want to select a region in the timeline or use a bookmark to narrow down what the profile shows. I’ll dive into each tab below.
- Call tree shows all the calls, and how much CPU or time they took.
- Database calls shows a flat list of the database calls from most time-consuming to least.
- Current SQL execution plan will be populated if you click the
Planbutton for a query. - Methods grid shows a flat list of all the methods, from most to least expensive.
- Current call graph shows a different, zoomed in view of the call tree.
- Requests from client shows web calls made into your application.
Where you start depends on what you’re profiling. In this case, I’ll start with the client request since it’s a web app and that’s the user’s perspective. Clicking on one will highlight where it is on the timeline in green. You can then select the region around the call to focus in on what it does. I usually grab the area where the CPU was above zero around the call. The numbers show the time spent generating the page in ms. There’s also a hit count of the number of times it was called (that’s a recurring theme).
The .NET button will take you into the Call tree tab for this call with it highlighted at the top. The default columns on the right are CPU time, but since I’m not CPU bound I switch them to Wall-clock time and Milliseconds. In this scenario, FieldExists is called 8,684 times, and taking quite a bit of time. There is a search field to allow to to search for methods in the call tree. This is handy for finding other calls to an offending method in the region.
At the right of each method is a button that will create a new call graph for it. This zooms in on that part of the call tree as show below. You can click to open the next level down, or shift-click to go all the way down, or up. (Double click to collapse back.) In this scenario Wall-clock time is on, so the 14K number is number of milliseconds the btnSave_Click took, with its children.
In the next image, I’ve expanded down the more expensive path, and only methods with source are emphasized (others are the small, empty boxes). Like the call tree view, you can see that FieldExists takes 27.9% of the time of the current graph and is called 167K times. Squeezing a little time out of this, or preventing it from being called could really help. (Spoiler, it was called for many times every row, but only needed to be called the first time this query ran in the app. Optimizing this common code gave us a significant improvement across the entire application almost for free.
The Method grids tab shows the flat list of calls. As usual, you can change from Wall-clock to CPU time. You can also filter the results to find a specific call, keeping in mind this is only showing calls in the currently selected region. Also, if your call isn’t found, you may have to uncheck Hide insignificant methods to see it. Another reason why your method may not appear is that ANTS will simplify complex stack traces to same memory by default. You can disable that feature in the Tools->Advanced Options.
One nice thing about ANTS is the integration with your code. As you can see below, the source code is shown for the selected method. This is true on every tab.
Now let’s look at a call that spends too much time in a database call. The call tree or method grid could point that out, but the Database calls tab may be a better place to start since it will show all the database calls made during the selected region.
In this case a call to a stored proc took about a quarter of a second. We can click the .NET button to jump to the code that triggered this, or click the PLAN button to attach to SQL Server and get the plan, similar to what you see in SSMS. Clicking the warning will show the DDL to create the index, which you should blindly do, because it says so.
Save, Analyze, Repeat
Now that you’ve dug in and found some issues, fix them. Re-run the analyzer to make sure they are worth keeping. (I’ve found sometimes a change only gets a percent or so, and may not be worth the risk of altering the code or database.) You can save off the Profiler results in ANTs so you can come back later to verify what happened before and how long it was taking. If you created nicely named bookmarks in the session, you can quickly find the relevant sections of the timeline when reopening it. And a good naming convention for the saves will help, too.
Final Thoughts
Analyzing an app without a tool that gives you insight into the actual running application is like trying to teach a pig to sing, it wastes your time and annoys the pig. Redgate’s ANTS does have its quirks and crashed once in a while, usually only after saving session data. But in this situation it worked very well to let me quickly zoom in on the problem code or queries and optimize them.
Of the ten areas attacked, we made significant improvements cutting some requests down from minutes to a couple seconds. A few areas were expected like bad queries or missing indexes, but others were not and we never would have found them without the tool (or lots of printfs).
Happy profiling!
