Xperf and Visual Studio: The Case of the Breakpoint Hangs

Xperf (also known as Windows Performance Toolkit) is my favorite profiler. I have used it to find and fix dozens of performance problems in the programs that I develop. However xperf, as a whole-system profiler, is also particularly useful for profiling other people’s software.

This morning I was using Visual Studio on a large project (more than 100 project files in a single solution) and Visual Studio kept hanging. My work machine has six cores and 24 GB of RAM so it is not supposed to be slow, and yet during certain operations Visual Studio would hang for more than 40 seconds, which is plenty long enough to trigger counter-productive key smashing and desk punching. After this happened a half-dozen times I figured it was time to get all scientific.

I always have xperf running in the background, recording profile data to a circular memory buffer, so at the end of one of the hangs I asked xperf to flush the buffers to disk and then I took a look to see what was going on.

You can do this easily also. Just grab UIforETW and leave it running. For more information on ETW trace analysis see ETW Central.

Xperf shows me all of the processes on my system, but Visual Studio was the only one that was significantly active. During the ~31 second period that I examined Visual Studio was consuming 100% of one CPU core. Thanks to Microsoft’s publishing of symbols on their public symbol server I can use WPA’s CPU Usage (Sampled) summary table to find out where the time is being spent:

The ‘Weight’ column is a statistical approximation of how many milliseconds were spent along particular call stacks. About 30.7 seconds was being spent on the call stack represented by the first nine lines shown here. After that the execution time was spread out amongst various call stacks (not all shown), but more than half of the time was being spent in a DoesFileExist() call which then called the operating system’s GetFileAttributesW function.

The key points are that all of the time was spent in ExecCmd – presumably trying to execute whatever command I had given – and within ExecCmd Visual Studio seemed to be busily trying to match up breakpoints to source files by seeing whether files exist.

A sampling profiler can tell you that a lot of time was spent along these call stacks, but it can’t tell you whether this is because the functions are extremely slow, or because they are called extremely frequently. However, since these call stacks end in file I/O functions we have other ways to answer that question.

The File I/O graph was looking pretty busy so I pulled up a summary table. Sure enough, Visual Studio was doing an extravagant number of file I/O operations:

If we ignore the 288,000 calls to close files then we can account for all of the elapsed time if CreateFile was taking an average of 30 microseconds (millionths of a second). The Win32 CreateFile function is not particularly fast so that seems pretty reasonable. In fact, if it weren’t for the caching of file data in RAM then CreateFile would take a lot longer than that.

I’m going to go out on a limb here and say that calling CreateFile more than a million times is inappropriate. My entire solution doesn’t contain that many source files (with very generous accounting I can find less than 40,000 files that are even potentially in the solution), and even if it did I can think of no reason for Visual Studio’s debugger to care.

At this stage it can be rewarding to contact some friends at Microsoft and share out the trace file. With luck maybe they’ll pass it along to the right team and the bug will get fixed in the next version of Visual Studio. Xperf traces are great for reporting performance bugs because they encapsulate virtually everything about the problem. However getting the bug fixed in a few years isn’t going to help my productivity today.

The sampling profiler pointed to the problem being related to breakpoints, so I took a look at my breakpoint window. I had about a dozen breakpoints set, so nothing extravagant. One of the breakpoints had been set while doing assembly language debugging and was therefore set to a specific address. There is only one instruction at any particular address, but Visual Studio somehow decided that there were actually 39 different variants of that same breakpoint:

Even though these breakpoints were disabled it seemed that they must be the source of the problem, and indeed they were. I deleted the whole set and the hangs went away and I was able to get back to profiling my own code.

I can’t repro this problem on other solutions and I don’t know what I did to get Visual Studio into this state. But it seems like there are at least two bugs here:

1. While overloaded or template functions mean that the same function name may have multiple addresses, an individual address has, well, just one address. The multiple copies of the address breakpoint are a bug.
2. Visual Studio’s performance with the redundant breakpoints is, quite simply, unacceptable. If I had counted up all of the breakpoints, including duplicates, and then rounded up generously, I would certainly have got no higher than about eighty. There is no excuse for a mere 80 breakpoints to cause such long hangs. It has the smell of an n-squared or exponential algorithm.
3. The same issue (over a million calls to CreateFile causing a ~40 second hang) happened when closing my solution file with the 39 breakpoints set, so it’s more than just setting and clearing breakpoints that is affected.

So, the next time that your computer is being slow, record an xperf trace and take a look. Even though you can’t fix other people’s bugs you may be able to figure out a way to work around the problem – or at least you can report the bug more precisely.