How can I analyze performance issues before/during the logon process?

Question

How can I analyze a performance issue that happens before or during the logon process?

Answer 1

Using Process Monitor

Process Monitor is a tool that will collect file system, registry and network events for all running processes. The collected events can then be analyzed to determine how a system (or an application) is behaving internally in certain situations.

In this case, we want to utilize the tool to determine which events during the boot process took a long time to complete.

1. Download Process Monitor and run it.

2. In the Options menu, check Enable Boot Logging.

   

3. In the resulting dialog, check Generate profiling events and click OK.

   

4. Reboot the system and replicate your issue. Once the logon process has completed, start Process Monitor.

5. Process Monitor will notify you that it collected boot-time activity and will ask you if you want to save that data now. Confirm the process by clicking Yes.

   

6. Select an appropriate storage location for the .pml file and wait for the data to be converted. Once the data has been loaded, display the Duration column by opening the context menu on one of the column headers and clicking Select Columns...

   

   ...and checking the appropriate checkbox in the resulting dialog.

   

7. Create a new filter by selecting Filter...* from the **Filter menu.

   

8. Create a filter for the Duration column where it is more than a value of 1, in which case the entry should be Included. Click Add to add the filter to the list and confirm the selection with OK.

   

9. At this point, the event list in Process Monitor will only show events that took longer than 1 second to complete. You're going to want to check the Duration column for events that took a long time to complete.

   For demonstration purposes, here is a selection of events that took longer than 10 seconds to complete. This was captured in a virtual machine for demonstration purposes.

   
   ^{click to enlarge}

   While these events don't necessarily have to be culprits of blocking the logon process to complete, disabling the Windows Indexing service and Avast Anti-Virus could be worth a shot on this installation.

Using xperf

xperf is a performance analysis tool from the Windows Performance Toolkit. Using it and being able to analyze the collected data can be a challenge. Nevertheless, we'll see how to collect the required data and how to view relevant sections of it.

Please note that the Windows Assessment and Deployment Kit (ADK), which is required for this, only works on Windows 7 and upwards.

1. Download the Windows ADK and install at least the Windows Performance Toolkit component.

2. Once the installation is completed, open an elevated command prompt.

   

3. Change into a directory where you would want your trace to be located. Like the Desktop.

4. The recommended way (according to Using XBOOTMGR to capture slow boots, or slow logons caused by slow boots) to capture a trace during boot is:

   xbootmgr -trace boot -traceflags base+latency+dispatcher -stackwalk profile+cswitch+readythread -notraceflagsinfilename -postbootdelay 10

   The system will now initiate the trace and reboot.

5. After the reboot, follow the instructions on the screen. You will be asked to allow the collection process to elevate. After the process completes, you'll find the resulting trace in the folder from where you initiated the trace.

   In my case, it created a boot_1.etl (and a corresponding boot_1.cab) on the Desktop.

   Open the .etl file in Windows Performance Analyzer.

Analysis

After you've opened the trace, you can already see possible indications of your problem being bound to hardware. A quick look at the Computation, Storage and Memory overviews in the Graph Explorer would show peaks which should be further analyzed.

For demonstration purposes, let's have a look at the Utilization By Process graph. To display the content, simply double-click the graph to add it to the Analysis view.

^{click to enlarge}

Note that none of the graphs display any concerning peaks. The blue peaks at the start belong to the System process and are expected to happen at this time.

The other peaks in the CPU Usage graph might be better viewed in context. So, let's add another graph to the Analysis view. The graph we're looking for is the Boot Phases graph, which is located in the System Activity section.

^{click to enlarge}

In the screenshot above, I also added Generic Events graph at the bottom to provide additional context. However, what should be noted here is the fact that the first visible peak in CPU usage was caused by the Avast service. We already noticed in the Process Monitor analysis that this process was one of the processes that took up a large portion of time in the boot process.

What we also see here, now that we can see it in the context of the boot phases, is that the peak happened after the Winlogon Init phase (and even in the Post Boot phase which happens when you can already see the desktop). So it could be considered unlikely that this process is actually causing us a problem in the phase before we see the desktop.

What we would be looking for are events that happen in or around the Winlogon Init phase. To make that easier, you can select the phase in the Boot Phases graph. This will highlight all entries in all graphs that happened in that phase.

A graph to take a better look at, is certainly the Services graph, as most of them are started during the Winlogon Init phase.

As I said in the introduction, analyzing this data can be complicated, unless the problem jumps right at you once you open the trace. However, this is definitely the right tool to analyze the issue. Depending on the situation, you might even want to collect stack traces with it to drill even deeper. This process is far outside the scope of this post though.

Further reading

• Tools for Troubleshooting Slow Boots and Slow Logons (sbsl) (TechNet)
• Slow Boot Slow Logon (SBSL), A Tool Called XPerf and Links You Need To Read (TechNet Blogs)