In previous blogs, we took a look at how to install Xperf, and how to use it to look at file I/O. For SQL Server administrators, a potentially important use of Xperf is to examine the consumption of CPU cycles, particularly when tools like the performance counters are showing high CPU use, but the reason is not readily apparent. There is a bit of extra preparation we must do to look at what SQL Server functions are responsible for CPU usage.
We can create a test trace as we did before, but this time we will use a difference set of predefined profiles. The following Xperf command line includes stackwalk, especially valuable when looking at CPU usage.
xperf -on Latency -stackwalk profile
Running a stack trace will produce data at an even more prodigious rate than recording file I/O. You can reduce the filesize somewhat if you shut down everything that is not immediately relevant to the task at hand. Furthermore, it is very helpful to have everything ready to go. For example, if you are going to run a particular query, have the query already highlighted in the Management Studio and ready to go. When you are all set, hit <enter> at the command line and immediately go to SMSS and execute the query. The instant the query starts, return to the command prompt and start typing xpert -d <filename>.etl so you are ready to stop the trace when the query completes. We hope to achieve a trace file containing as little extraneous material as practical.
As before you can open the etl file using the Windows Performance Analyzer (WPA) tool. However, you must resist the temptation to start your analysis immediately. To make sense of a stack trace, WPA needs to substitute human-readabe function names into the Analysis window report. Programmers call these names “Symbols” and you will be loading function names not only for SQL Server, but for pretty much the entire Windows environment. This can take a while, so you might want to start loading your symbols just before break time.
Go to the Trace menu of WPA and select “Configure Symbol Paths”.
Clicking on “Configure Symbol Paths” brings up the dialog box.
The values shown are the defaults. After clicking OK, click
Load Symbols” on the same Trace menu. This will download pdb (program database) files into the C:\Symbols folder. Cached copies of symbols in use by WPA will be stored in C:\SymCache. When I performed these tests in July 2016, there were 583 symbol files for a total of 727 MB.
The pdb files need only be downloaded once, but the symbols will have to be loaded into your WPA analysis when you open an etl file.
When the symbols have loaded, open the “Computation” folder in the Graph Explorer and then open up the “CPU Usage (Sampled) ” folder within it. Double-click on “Utilization by Process, Stack”.
In the middle section the CPU activity graph we see a block of activity that represents the execution of the test query. The Windows processes are listed in descending order of contibution to the trace. After the system idle process, SQL Server and SSMS are, not surprisingly second and third respectively. Curiously, xperf, which is doing heavy duty during this interval, is in position five, while firefox.exe, which should be doing nothing at all, is in position four. Forgetting to close a browser consumes more CPU cycles than a powerful trace tool.
As an interesting sidelight, just after the activity resulting from the test query (red arrow) we see activity in the Managment Studio (green arrow) representing the filling of the grid control with row data.
In the Analysis window, open sqlservr.exe in the Process column, then open Root and ntdll in the Stack column. If you see a bunch of entries with library names followed by question marks, this is an indication that the symbols, although loaded onto your machine, have not been loaded into the Activity window trace view. Go back to the Trace menu and click “Load Symbols”.
Once the symbols have loaded, you can begin to drill down into the call stack. As a general rule of thumb, within each level the line that has a larger weight as well as another arrow to open up will prove a useful path to take. At every step of the way, when you click on a row vertical blues lines will appear in the chart along the top, indication the times that function was invoked.
At this point, you will have to begin exploring on your own. For the test query used here, we can clearly identify the function call that leads to the flurry of CPU activity. When diagnosing a real world problem, wading through the trace entries may be a challenging task indeed.
Recording critical events in a running system is very easy with xperf. The difficulties lie in the interpretation of the data once recorded. The Windows Performance Analyzer (WPA) provides a reasonably good working environment, but there is precious little documentation on the details presented in an Analysis window and how they can be interpreted. SQL Server administrators willing to slog through these details will be rewarded with a superior understanding of their systems.