Performance Engineering for the Cloud with Visual Studio Part 2

Introduction

In the first part of this article, we looked at conventional approaches to building high-performance applications using tools such as PerfView and DebugDiag to troubleshoot performance related issues. However, developers typically don’t use these tools for their day-to-day development tasks. In this article, I will follow up on the concepts I laid out previously and demonstrate how Visual Studio can be used to troubleshoot performance related issues effectively.

This is an area where Microsoft has evolved its tools and technologies tremendously over the years. Visual Studio empowers developers not only to measure the performance of the code, but also provides the ability to look deep inside the root causes of such performance issues. PerfTips, IntelliTrace, Performance & Diagnostic Hub are examples of such tools.

Reviewing the Application

Part 1 of this article established the general application behavior of the application. Figure 1 below shows the Get Directions button click handler code.

The code isn’t too complex. Here is a high-level summary of what’s happening within this function.

1. The inputs for the starting point and destinations are validated. In case of validation failure, a method DisplayAddressValidationError from RouterView class is invoked.
2. Invoke Connect method from SatelliteManager class. If this method returns as failed, RouteViewer.DisplaySatelliteConnectionError is called.
3. If SatelliteManager.Connect succeeds, GetSatelliteLocationFromAddress method is called on the starting point and destination addresses.
4. RouteCalculator.CalculateRoute is called and returns a RouteDirection object.
5. Finally, DisplayDirection method from RouteViewer class is invoked.
6. In case the SatelliteManager.Connect method returns a failure, the RouteViewer.DisplaySatelliteConnectionError method is called.

From the application behavior, we know that when a user clicks on the Get Directions button, the application consumes significant CPU cycles and memory resources. However, the key question is how to determine what each of these lines of code cost. More specifically, we want to find out how long it takes to execute each of these lines of code and also the CPU/memory cost of every single line of code.

Following Joe Duffy’s advice, these are exactly the questions that developers should ask themselves during their development efforts so that they are aware of the cost of their code. These types of questions are the reason why the Visual Studio team introduced PerfTip and Diagnostics Tools features in the IDE.

Stepping through Code Performance in Visual Studio

To start with our measurements, let’s first add breakpoints at the start and end of this function.

Let’s run the application. Once the second break-point is hit, the view should be similar to as shown here:

Towards the end of the function, you see text 34,137ms elapsed in a red rectangle. This is what is called a Performance Tooltip (in short, PerfTip). This is an estimated number showing the time it took to run the code either from the previous step or since the last breakpoint. In this case, it took around 34 seconds to run this function.

On the right side, you also see two key measurements. The memory and CPU consumption between these two break points. As the Diagnostic Session windows show, initially the CPU consumption is quite high and then memory usage goes close to 2GB. These measurements are quite consistent with what was observed when the application was running outside Visual Studio.

The application should be run a few times under the debugger to make sure that the application behavior is consistent across a reasonable sample size. After making sure the issue is reproducible, we can go back and step through the same block of code line by line and observe application behavior. This can help narrow down to specific lines of code that are the most expensive.

The following screens show the process of stepping through the next lines of code where it neither takes longer to run the code nor there is any significant memory/CPU resource consumption. Since this code is performing as expected, we’ll just look at a few lines.

Next, you can see the execution of the RouteCalculator.CalculateRoute method. It took around 10 seconds to execute this particular line of code. We can see that CPU consumption was quite high, although memory consumption is low (around 60 MB), which is insignificant when compared to 2GB for the entire method.

Resource consumption by the next two lines of code is quite insignificant, but execution of RouteViewer.DisplayDirection method took around 17 seconds whereas memory consumption also rises to about 2GB.

Stepping through rest of the lines of code in this function shows no significant memory/CPU resource consumption there.

Digging Deeper into Performance Analysis

With the analysis so far, we know that two functions RouteCalculator.CalculateRoute method and RouteViewer.DisplayDirection are responsible for 27 seconds out of the total 34 seconds that btnDirections_Click took. We also know that:

• RouteCalculator.CalculateRouteMethod is mostly responsible for the high CPU usage
• RouteViewer.DisplayDirection is responsible for the high memory consumption

This means that without leaving the comfort of Visual Studio, developers can not only know how long each line of code takes to execute, but they can also know exactly memory/CPU cost of it as well.

But wait, this analysis does not stop just here. Diagnostic Tools also provides mechanisms to further investigate the reasoning behind these resource consumptions. The Memory usage related Take Snapshot and CPU usage related Record CPU Profile buttons that can help understand the behaviour of specific lines of code.

Revealing CPU Usage

Let’s first try to understand why the application consumes CPU cycles during the execution of RouteCalculator.CalculateRoute method.

For that, we need to click on the Record CPU Profile button and run the RouteCalculator.CalculateRoute line of code. The results of this analysis are shown here:

On the right side, these results are shown in tabular format with columns contain Function Name and Total CPU in %. The data in this table is sorted in descending order by the Total CPU consumption. The results here show that RouteCalculator.XmlDataProcessor method has consumed 96% of the CPU cycles whereas XmlDocument.LoadXml method is responsible for 72% of those cycles.

Double-clicking on the function name in that table will bring up Call Tree view, which shows the chain of method invocations. This shows that out of 96% of the time consumed by RouteCalculator.XmlDataProcessor method, 72% of that was used by the RouteCalculator.XmlDataProcessor method, a loud and clear pointer to where developer should focus to find the root cause of the problem.

Double-clicking on function from the Call Tree view brings up the related source code. As we can see from the code, RouteCalculator.XmlDataProcessor method is calling XmlDocument.LoadXml method in a tight loop causing high CPU.

We also see that XmlDataProcessor method is invoked using the Task Parallel Library(TPL) Data Parallelism Parallel.For. This explains why PerfView traces were showing multiple threads calling this method. Of course, Visual Studio can display same information using Parallel Stack.

Understanding Memory Consumption

Now that we know the reason behind CPU usage, let’s turn our attention to what is causing high memory consumption.

We know from our analysis earlier, RouteViewer.DisplayDirection method is responsible for the high memory consumption. A typical method of analyzing memory related issues is taking two memory snapshots: one before the high-memory consumption and one right after that. The two snapshots can be compared and analyzed for the offensive objects.

We should take our first memory snapshot before execution of the RouteViewer.DisplayDirection method using the Take Snapshot button. The results of the memory snapshot are shown in tabular form. This table contains the number of objects in the GC heap with the size of the heap.

Clicking on either number of object or heap size values will bring up a table showing all the objects on the heap.

Now execute the RouteViewer.DisplayDirection method and take another snapshot as memory usage has crept up. At this point, the Memory Usage tab will show the results from the second snapshot too. These results clearly indicate that both the object count and heap size has increased.

Clicking on the change in heap size link from the second snapshot will bring a list of objects in the heap ordered by the Size Diff between the two snapshots. This shows array of XmlNode object at the top.

Clicking on the object from the table itself will populate the references graph in the bottom tab that can show how that object is referenced.

All the referenced types for XmlNode[] can be viewed as well. Here, you can see a large number of XmlElement objects referenced by that XmlNode[] object.

This analysis has provided a reasonable idea of what objects are responsible for memory consumption. We can inspect the code for RouterViewer.directionPoints. It’s a static field that is also populated in a tight loop causing high memory consumption.

The bottom line is that with Visual Studio, it’s possible for developers to keep an eye on performance on the application during their day to day workflow without depending on any other tools.

Conclusion

This two part series of articles demonstrate how Visual Studio features can help developers troubleshoot complex performance problems during their daily development workflows.

History

• 11^th June, 2019: Initial version