Wait, I thought Visual Studio already had an Instrumentation tool?<\/h3>\n
If you were thinking, \u201cDoesn’t Visual Studio already have an Instrumentation Tool\u201d then you were thinking right! So, what\u2019s\u2026 new? Well, a whole list of things<\/p>\n
- \n
- Faster and less resources:<\/strong> The tool is significantly faster and uses less disk space, clone the repo and check out the measurements for yourself.\nSample App: ScabbleFinderDotNet<\/a>\n
![\"Graph](\"https:\/\/devblogs.microsoft.com\/visualstudio\/wp-content\/uploads\/sites\/4\/2023\/04\/InstrumentationToolPerformance.png\")
<\/li>\n- Enhanced targeting for .NET:<\/strong> The tool has better targeting for .NET scenarios so you can scope your instrumentation all the way down to specific functions to lower overhead and get better data.<\/li>\n
- Flame Graph:<\/strong> The flame graph helps you graphically see where the most amount of time is spent in your application and quickly narrow on areas to improve.<\/li>\n
- Better error handling:<\/strong> The tool helps with common issues such as missing the \u201c\/profiler\u201d linker flag for C++ projects. If you do hit issues that you can\u2019t figure out, we are ready to help over at Developer Community<\/a>.<\/li>\n<\/ul>\n
Let\u2019s go mine for performance!<\/h3>\n
To start, I have a console application called AnalyzerBench which takes in a diagsession from the Performance Profiler and runs our analysis backend on it then exits. This lets me have a repeatable benchmark that I can measure and see the effects of my changes. The diagsession I have is from tracing every allocation of Visual Studio startup, over 4.3 million allocations, with the .NET Object Allocation tool. Running the Instrumentation tool from the Performance Profiler (Alt+F2) I get the following dialog:\n
![\"Targeted](\"https:\/\/devblogs.microsoft.com\/visualstudio\/wp-content\/uploads\/sites\/4\/2023\/03\/TargetedInstrumentationDialog.png\")
<\/a><\/p>\nThis lets me select what projects I want to instrument, allowing me to target my instrumentation to reduce overhead. In my case I want to see our analysis for the .NET Allocation tool, so I select our DataWarehouse and the DotNetAllocAnalyzer projects but not AnalyzerBench since I don\u2019t care about that. If you are unsure of what you want to profile, the CPU Usage tool is great for getting a general idea of where time is being spent and then you can investigate deeper with the Instrumentation tool targeting specific areas. After running the tool, I see the following:\n
![\"Summary](\"https:\/\/devblogs.microsoft.com\/visualstudio\/wp-content\/uploads\/sites\/4\/2023\/03\/InstrumentationToolSummaryPage.png\")
<\/a><\/p>\nThe top functions show us which functions are taking the most amount of time and the hot path shows us the most expensive code path. My go-to is to open the details panel and switch over to the flame graph which shows the following.\n
![\"Flame](\"https:\/\/devblogs.microsoft.com\/visualstudio\/wp-content\/uploads\/sites\/4\/2023\/03\/InstrumentationToolFlameChart.png\")
<\/a><\/p>\nLooking at the flame graph I see a
System.Threading.Monitor.Enter<\/code> taking ~20% of the time which is interesting. By right clicking on the node, I can cross reference to where this is happening in the call tree.\n![\"Call](\"https:\/\/devblogs.microsoft.com\/visualstudio\/wp-content\/uploads\/sites\/4\/2023\/03\/InstrumentationToolLockContention.png\")
<\/a><\/p>\nTurns out our
Monitor.Enter<\/code> function is showing as a hot function and its parentImportDataSource<\/code> is taking ~17% of the total time. In the call tree you\u2019ll notice there are a few new columns with more hidden in the context menu of the header. Since the instrumentation tool gives us exact call counts, we can calculate stats like min, max, and average function time. Not only does Instrumentation give us exact call counts, but it also measures wall clock time. This lets us see non-CPU bound issues like contention. In this case, based on the call count we can see that there are three calls toImportDataSource<\/code> and they spend about 5s on average waiting on the lock. What is really happening is that the first call gets the lock and the other two wait ~8s for the first data source to complete before they can import. This means 2 thread pool threads are synchronously blocked and can\u2019t do any work which could lead to thread pool starvation.<\/p>\nTo fix this we could investigate using some parallel data structures so that the lock isn\u2019t needed or change the method signature so that it is async and use SemaphoreSlim.WaitAsync<\/a> so that we at least don\u2019t block thread pool threads. As both changes are a bit more involved, we can add a TODO to the code and come back later.<\/p>\n
Switching back to the flame graph, the next thing jumping out at me is
List.Sort<\/code>, from a glance it looks like we are spending ~20% of our time sorting some data. Again, right-clicking on the node and cross referencing over to the call tree we can see our details stats. This shows we are calling sort over 24K times, spending 20 seconds sorting data!\n![\"Call](\"https:\/\/devblogs.microsoft.com\/visualstudio\/wp-content\/uploads\/sites\/4\/2023\/03\/InstrumentationToolSortIssue.png\")
<\/a><\/p>\nIn this code we are sorting the allocations for each unique type which is needed to quickly filter when selecting time ranges on the graph in the profiler. For the most part, though these allocations should be sorted as we get a callback for each allocation and write it to our diagsession file. If there are many allocations at the same time on different threads they might be out of order, but this is probably something we can check for when adding to the list and then only sort the unsorted lists here. Making this change and rerunning the instrumentation tool we can see that now we have nearly removed all the time spent here, and in the case of this trace we didn\u2019t have to sort anything as all of the allocations were already sorted in the file.<\/p>\n
\/\/\/ <summary>\r\n\/\/\/ Add an allocation instance to the current type\r\n\/\/\/ <\/summary>\r\n\/\/\/ <param name=\"allocationObject\">allocation object<\/param>\r\ninternal void AddAllocation(AllocationObject allocationObject)\r\n{\r\n if (this.Allocations.Count > 0)\r\n {\r\n this.allocationsSorted &= allocationObject.AllocTimeNs >= this.Allocations[this.Allocations.Count - 1].AllocTimeNs;\r\n }\r\n\r\n this.Allocations.Add(allocationObject);\r\n}\r\n\r\n\/\/\/ <summary>\r\n\/\/\/ Finalizes the data for fast retrieval\r\n\/\/\/ <\/summary>\r\npublic void FinalizeData()\r\n{\r\n if (!this.allocationsSorted)\r\n {\r\n this.Allocations.Sort(TypeObject.comparer);\r\n this.allocationsSorted = true;\r\n }\r\n}\r\n<\/code><\/pre>\n - Enhanced targeting for .NET:<\/strong> The tool has better targeting for .NET scenarios so you can scope your instrumentation all the way down to specific functions to lower overhead and get better data.<\/li>\n
![\"Call](\"https:\/\/devblogs.microsoft.com\/visualstudio\/wp-content\/uploads\/sites\/4\/2023\/03\/InstrumentationToolFixedSort.png\")
<\/a><\/p>\n