Windows Explored

Everyday Windows Desktop Support, Advanced Troubleshooting & Other OS Tidbits

Examining Windows 7 Boot Performance

Posted by William Diaz on September 7, 2011


Boot performance in Windows Vista and 7 has become such a focus that a whole area of the Event Viewer is dedicated to it. Here, you can investigate boot metrics and troubleshoot causes of slow boot up times. You can find these events under Diagnostics-Performance by going to Event Viewer > Applications and Service Logs (this part of the tree will take a few seconds to expand) > Microsoft > Windows.

image

Event ID 100: This indicates boot duration. The sample above is a screen shot from my Windows 7 laptop where I have already sorted by the Event ID. It’s not as bad as it looks. In fact, I haven’t had any boot issues at all. So why the Warning, Error, and Critical events1? The logic is confusing but the level of the event is defined by a particular threshold being exceeded, and since Windows is more “speedy-boot centric”, these tolerances are pretty low. If you are curious, you can find these threshold values in the registry in
HKLM\Software\Microsoft\Windows\CurrentVersion\Diagnostics\Performance\Boot.

Boot duration, or BootTime, is actually the sum of two values and like all the values here, represented in milliseconds, which is about 63 seconds in the example below. You can see this by selecting the Details tab for the event.
image
MainPathBootTime starts when you see the Start Windows splash screen and ends when the desktop appears2. The BootPostBootTime starts when the desktop appears. During this time, services and application may be starting but it is not considered complete until the system has reached a certain idle state3. In the metrics above, this is perfectly acceptable and its not uncommon to see larger than normal boot times after new software installations, Windows updates or after installing new drivers. On the other hand, if you are seeing Critical events back to back that indicate above normal boot times, then its worth investigating. This is where events 101 thru 110 come in useful.

Event ID 101: This indicates that a program took longer than normal to start. The important detail here is the application name and the degradation time, which is the extra amount of time it took the application to start.These tolerances can be quite low, so often you will see events like this that are being measured in fractions of a second and really are not contributing to any excessive boot up time.

In the example below, sidebar.exe, the application that starts the desktop Gadgets, took 9.5 seconds longer to start.
image
If this behavior was consistent, then I would look into turning off the gadget(s) until this event disappeared and turn it on again to see if the symptoms returned.

Event ID 102: This indicates a driver took longer than normal to initialize. If you are finding several instances of the same driver taking excessive amounts of time to load, then explore upgrading (or even downgrading) the driver.

Event ID 103: This indicates a service took longer than normal to start. Services can be explored by running services.msc. Services can be Microsoft or 3rd party and you should consider Windows or application updates to resolve cases where services take to long to start. You can also modify service startup behavior by setting to them to manual if it is rarely used. Vista and Windows 7 also includes a new start up type called Automatic (Delayed Start)4 and by default some services are already placed into this start up type.

image

Event ID 106: This indicates that background optimization operations took longer to complete. I ignore these for the most part as they (almost) always point to the Windows Prefetch. Windows Prefetch stores application data in order to start them faster. This is constantly being built or modified so it’s not uncommon to see this every now and then, especially after starting applications for the first time5.

Event ID 108: There’s not a lot of information on this and all the events details, whether on my domain and non-domain Windows 7 systems, report the same thing: “Application of user policy caused a slow down in system start up process: PreShellInit.” I only see a handful of these

Event ID 109: A device took longer than normal to initialize. This should be a case for concern if the device in question is your hard drive and it is happening consistently.

Event ID 110: The data on this event ID is also sparse. I see only a handful of these and they always report as: “Session manager initialization caused a slow down in the startup process: SMSSInit,” which is the initialization of the Session Manager Subsystem, which in turn is responsible for the starting the user session.

If you want to explore with more detail boot up performance, get the Microsoft Windows SDK tools then visit the Windows Performance Analysis Developer Center. Also see the Windows On/Off Transition Performance Analysis paper from Microsoft.

Check out this Microsoft KB article if you have a large hard drive and many restore points and how it can affect boot performance: http://support.microsoft.com/kb/2555428/


1 Here is an excellent explanation from Microsoft on one of their forums:

These events are defined in Windows Source code

PostBootMinorThreshold_Sec(30) // The time in seconds for postboot must exceed to consider minor issue.

PostBootMajorThreshold_Sec(60) // The time in seconds for postboot must exceed to consider Serious issue.

BootMinorThreshold_Sec(60) // The time in seconds excluding postboot must exceed to consider minor issue.

BootMajorThreshold_Sec(120) // The time in seconds excluding postboot must exceed to consider Serious issue.

At the highest level, there are two separate scenarios for boot, the kernel scenario and the user scenario. Depending on the Scenario (long or short delay) the timer is started. There is a Kernel Timer and a a timer that is triggered for User. We’ll start the Post boot timer when the Winlogon process launches the User’s shell.

Troubleshoot function calls BootScenario::PerformTroubleshooting. This then performs calculations and then logs the event by calling OutputSqmEventLog. OutputSqmEventLog calls EventWriteEx/EventWriteBatchEx to write the events.

This will internally check the BSS trigger for the event.

The Critical Events are logged when we cross beyond BootMajorThreshold_sec

We basically calculate two options for the level we’ll attach to event 100, an option based on what is logged as MainPathBootTime (i.e. BootTime – PostBootTime), and an option based on PostBootTime alone. Whichever option is more severe/critical/whatever is what we ultimately attach to the event. For example, a PostBootTime of 0 to 30 seconds will get a level of Warning, 30-60 seconds gets Error, and greater than 60 gets Critical.

2 If you are going to be using the Windows Performance Analyzer Tools to capture a boot trace, it is recommended you enable auto-logon since the time that elapses while the logon screen is displayed is measured in the boot trace.

3 Idle is defined as the system being 80 or more idle.

4 This setting is ignored when a service dependency exists, i.e. an automatically started service cannot start if it depends on a service that has been set to Automatic Delayed Start.

5 There is a myth that has been floating around since XP that deleting the prefetch will result in increased performance. It is still a myth and, in fact, it can have the opposite effect.

Advertisements

One Response to “Examining Windows 7 Boot Performance”

  1. Philip Colmer said

    I’m seeing two things when I look at these event entries that I would like to try to understand better:

    1. The system has identified the application of a user policy as causing a slow down in the system start up process. How can I find out which policy so that I can then try to figure out what to do to remediate that behaviour?
    2. The boot time event entries have “BootIsRootCauseIdentified: true”, suggesting that the system knows what has caused the problem. Is this what is revealed in the other entries (e.g. PreShellInit) or is there some additional information I can get to further understand this?

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

 
%d bloggers like this: