Use Xperf's Wait Analysis for Application-Performance Troubleshooting

void CStuckUIDlg::OnBnClickedButtonWork()
{
    HANDLE hEvent = CreateEvent( NULL, TRUE, FALSE, NULL );

    QueueUserWorkItem(
        WorkFunction,
        hEvent,
        WT_EXECUTEDEFAULT
    );

    WaitForSingleObject( hEvent, INFINITE );
}

Notice that in this handler, I create an event, hand it off to WorkFunc via the process thread pool, and then wait on it. Since the button handler runs in the context of the main UI thread, I can easily hang the UI in my application by writing WorkFunc like this:

DWORD WorkFunction( void* param )
{
    HANDLE hEvent = (HANDLE) param;

    Sleep( 5000 );
    SetEvent( hEvent );

    return 0;
}

This approach will effectively hang the UI thread of the StuckUI application for roughly 5 seconds. Now, let's use Xperf to diagnose the problem.

Capturing the Trace

Since I'm on an x64 platform, I built my sample application, which I named StuckUI.exe, to match that platform. To capture the trace, I used Xperf:

Xperf -on Base+CSWITCH+DISPATCHER -stackwalk CSwitch+ReadyThread -BufferSize 1024 -MinBuffers 50 -MaxBuffers 50
StuckUI.exe
Xperf -d StuckUI.etl

There are several things to note when capturing the trace in this way. Notice that I used the Base kernel group and added CSWITCH and DISPATCHER. The latter two kernel flags capture the CSwitch and ReadyThread events that are necessary to perform wait analysis. Additionally, the CSwitch and ReadyThread flags after the stackwalk argument capture the necessary stacks when these events are generated. If you are suspicious that you might also have a CPU spike and haven't yet ruled that out, you can replace Base with Latency and add Profile to the stackwalk list. However, if you've already ruled out a CPU spike, then it's always best to capture only the necessary data so that your trace file does not grow unnecessarily large.

Since CSWITCH and DISPATCHER can quickly generate many events, I also gave Xperf a hint about how much of a memory buffer to allocate in non-paged memory. In this case, I specified a buffer size of 1MB and told Xperf to pre-allocate 50 buffers. I accomplished these tasks by setting MinBuffers and MaxBuffers to the same value -- 50 -- which reserves 50MB of non-paged memory. Depending on your situation, you might need to massage these buffer numbers so as not to lose events. As you can imagine, Xperf is extremely fragile to missed ETW events and will notify you of such events later, when you use Xperf to analyze your trace. It is next to impossible to trust the Xperf analysis if events are missing from the trace.

Don't forget that to capture stack traces on x64 platforms, you must disable paging of the executive and restart, if you haven't already done so. You can conveniently set the necessary registry setting by using this command line:

REG ADD "HKLM\System\CurrentControlSet\Control\Session Manager\Memory Management" -v DisablePagingExecutive -d 0x1 -t REG_DWORD -f

Analyzing the Trace

Now the fun begins! Open the resulting ETL file in Xperf. You're presented with several graphs, depending on the configuration of Xperf, which is automatically saved each time you run the tool. (Xperfview.exe is the application that is used for analyzing the ETL. You can launch this application implicitly, simply by passing your ETL file to Xperf.exe.) You should see a graph called Process Lifetimes.

If you don't see the Process Lifetimes graph, you might need to enable it via either the Graphs menu or the fly-out on the left side of the main Xperf window. Incidentally, if you don't see the option to turn on a specific graph that you're looking for, it's usually because your trace was not set up to capture the relevant information for that graph.

I started and stopped the sample application during the trace collection, so you should see diamond shapes in the Process Lifetimes chart; these shapes indicate the start and end times of the StuckUI.exe process. Notice that most of the processes that are running on the machine are grouped together in one line, with no specific start and stop times other than the beginning and end of the trace. If you want, you can separate all the processes by right-clicking and choosing Toggle Permanent Process Grouping.

If I know that the trace has captured the start and end times of my process, I like to select that range within the Process Lifetimes graph, right-click it, and select Clone Selection. This action replicates the selection across all the currently visible graphs. 'Notice that the start and stop diamonds act as snap points, making it easy to select the exact range of the StuckUI.exe process lifetime, as I've done in Figure 1.

Figure 1: Process Lifetimes graph

srv*c:\symbols*http://msdl.microsoft.com/download/symbols;C:\StuckUI\x64\Debug

To set up the symbol paths, select Trace, Configure Symbol Paths, from the menu. To load the symbols, choose Trace, Load Symbols. You might occasionally see the Xperf UI freeze or hang. This issue is caused by symbol loading and could happen at various times, since Xperf loads symbols on demand. Depending on how many symbols you already have cached and the speed of your connection, these hangs could last for several minutes.

Alternatively, you can set the environment variable _NT_SYMBOL_PATH to set up the symbol path for Xperf. In the Configure Symbol Paths dialog box, you will also see a value for _NT_SYMCACHE_PATH, which typically defaults to C:\symcache. This is an internal, Xperf-formatted symbol cache. Xperf really needs only a subset of the symbol information from the PDB. Therefore, it skims the relevant information from the PDBs and puts it in a file in symbol cache. If your symbol cache is sufficiently complete, you might not even need to set up _NT_SYMBOL_PATH and can simply point Xperf at the symcache path. This option might help avoid the annoying delays caused by Xperf symbol loading.

Now, enable the CPU Scheduling graph (if you haven't already) and select the appropriate range, which might even be the entire span of the trace (in which case no selection is necessary). My wait analysis graph looks like the one in Figure 2, but yours might look much different, depending on the amount of cores and work that are active on the machine during the trace.

Figure 2: CPU Scheduling graph

The most powerful component of the summary table is the gold bar, or aggregator bar. Any column that is enabled and is to the left of this bar becomes a sorting column. The ordering of these columns is important. For example, my summary table begins with the following columns, which are all to the left of the gold bar: NewProcess, NewThreadId, NewThreadStack, Max:Waits (us), ReadyThreadStack, ReadyingProcess, and ReadyingThreadId. So first, I sort by process, then by thread ID, then by thread stack, and so on. If one of these columns is not visible in your chart, then make sure that it is enabled in the menu or the fly-out. To reorder the columns, you can drag and drop them. If you have many columns enabled and cannot see them all without horizontal scrolling, you can drag the column names within the fly-out to reorder them.

After locating the StuckUI.exe process in the NewProcess column, click the plus sign next to that process to expand the tree and reveal the threads within the process. You will then see the process threads in the NewThreadId column. In the NewThreadStack column, you should see two expandable items named [Root]. These items are the stacks that were captured during each CSwitch event. As you drill down the stacks and expand them, you will encounter "forks in the road," so to speak, where the call tree branches.

In an analysis like this, the more information you have, the easier the analysis will be. For example, I know that the UI message pump is stuck and that a UI window (HWND) is associated with one thread at most. Knowing these things, I can use Spy++ to identify the thread that owns the UI. In this example, identifying the right thread is easy because StuckUI.exe has only two threads recorded in the ETL. But if I were troubleshooting explorer.exe and an extension that it loaded, then knowing which of the many Explorer threads to focus on would be helpful indeed. In Figure 3, I have drilled down a few levels into the stacks of thread 9888, which happens to be my UI thread.

Figure 3: A portion of the CSwitch stacks for thread 9888

Figure 4: Top of the waiting thread

Figure 5: The readying stack

Figure 6: The sleeping thread

The waiting stack indicates that this thread was the worker thread that called our WorkFunction and, subsequently, SleepEx. The sleep timeout passed was 5 seconds, which explains the max wait value. However, take a look at the readying stack and the associated process and thread ID. The thread ID of zero indicates that it is the idle thread that executes when there is essentially nothing for the processor to do. The idle thread is also responsible for putting the processor to sleep momentarily, to conserve energy. But why is the idle thread the readying thread? Because SleepEx is implemented by using a kernel timer, which fires a Deferred Procedure Call (DPC) to KiTimerExpiration within the kernel at the required time to expire the timer. In addition, the idle thread is a common point from which DPCs are executed. To learn more about DPCs, refer to Windows Internals 5th Edition, by Mark Russinovich, David Solomon, and Alex Ionescu (O'Reilly Media).

The last thing I want to point out is that the ETL also recorded the exact time that the waiting thread was switched out, that the readying thread readied the waiting thread, and that the waiting thread was allowed to execute again. You can see this information by arranging the LastSwitchoutTime (s), ReadyTime (s), and SwitchInTime (s) columns just to the right of the gold bar, as shown in Figure 7, where the information is revealed after you expand the readying stack.

Figure 7: Thread timings

An Invaluable Tool

Yet again, Xperf proves its amazing capabilities to analyze your application's execution. (For more details about Xperf, see the sidebar "Where to Get Xperf" below.) In this article, I've demonstrated how you can use Xperf to track down waiting threads and discover how to set them free. However, this is only one use of Xperf's wait analysis. You can also use it to analyze general latency issues, by analyzing which code paths are waiting on which threads. Given the advances in parallel development libraries, this capability is invaluable in validating the performance gain of the parallelization of applications. Happy troubleshooting!

Where to Get Xperf