Windows boot performance diagnostics. Part 1

By | April 25, 2016

Have you ever seen that your computer starts booting slowly? Or it slowly restores its state from hibernation. Maybe you observe performance issues when shutdown or hibernate process? In this article, I will show you how you can use Event Log Explorer to find performance problems linked with the startup/shutdown/hibernate/resume processes.

Starting from Windows Vista, Microsoft provides a bunch of event logs for different system purposes. In Windows Event Viewer, these logs are located in a special branch: “Applications and Services Logs”. Windows records performance diagnostics events into Microsoft-Windows-Diagnostics-Performance/Operational event log. To open this log in Windows Event Viewer, open Applications and Services Logs branch, then open Microsoft, then open Windows, then select Diagnostics-Performance and click on Operational.  In Event Log Explorer you can do it easier: open your computer in the tree, then open Microsoft-Windows folder and then click  Microsoft-Windows-Diagnostics-Performance/Operational.

Microsoft-Windows-Diagnostics-Performance

Now you can see a list of different diagnostic events. As you can see, events with the same event ID may have different types – Warning, Error and Critical. It looks like these event types depend on the duration of the startup/shutdown process. Another observation – theses events contain many important parameters internally, but you can’t see them in the event description (Windows Event Viewer doesn’t display them as well). The only way to display these parameters is to double click on the event to display event properties and switch to XML tab.

Compare:
diagnostics-performance event details

Unfortunately, I didn’t find a detailed documentation about all these events, so I did some research. First, I got meaning of events in Microsoft-Windows-Diagnostics-Performance:

Event ID Event Description
Boot Performance Monitoring
100 Windows has started up
101 This application took longer than usual to start up, resulting in a performance degradation in the system startup process
102 This driver took longer to initialize, resulting in a performance degradation in the system start up process
103 This startup service took longer than expected to startup, resulting in a performance degradation in the system start up process
104 Core system took longer to initialize, resulting in a performance degradation in the system start up process
105 Foreground optimizations (prefetching) took longer to complete, resulting in a performance degradation in the system start up process
106 Background optimizations (prefetching) took longer to complete, resulting in a performance degradation in the system start up process
107 Application of machine policy caused a slow down in the system start up process
108 Application of user policy caused a slow down in the system start up process
109 This device took longer to initialize, resulting in a performance degradation in the system start up process
110 Session manager initialization caused a slow down in the startup process
Shutdown Performance Monitoring
200 Windows has shutdown
201 This application caused a delay in the system shutdown process
202 This device caused a delay in the system shutdown process
203 This service caused a delay in the system shutdown process
Standby Performance Monitoring
300 Windows has resumed from standby
301 This application caused a delay during standby
302 This driver caused a delay during standby while servicing a device
303 This service caused a delay during hybrid-sleep
304 Creation of the hiber-file was slower than expected
305 Persisting disk caches was slower than expected
306 Preparing the video subsystem for sleep was slower than expected
307 Preparing Winlogon for sleep was slower than expected
308 Preparing system memory for sleep was slower than expected
309 Preparing core system for sleep was slower than expected
310 Preparing system worker threads for sleep was slower than expected
350 Bios initialization time was greater than 250ms (logo requirement) during system resume
351 This driver responded slower than expected to the resume request while servicing this device
352 Reading the hiber-file was slower than expected
System Performance Monitoring
400 Information about the system performance monitoring event
401 This process is using up processor time and is impacting the performance of Windows
402 This process is doing excessive disk activities and is impacting the performance of Windows
403 This driver is using up too many resources and is impacting the performance of Windows
404 This driver is waiting longer than expected on a device
405 This file is fragmented and is impacting the performance of Windows
406 Disk IO to this file is taking longer than expected
407 This process is using up too much system memory
408 Many processes are using too much system memory
Desktop Window Manager Monitoring
500 The Desktop Window Manager is experiencing heavy resource contention
501 The Desktop Window Manager is experiencing heavy resource contention

Since we research boot/shutdown/standby/resume performance, we should pay attention to 1xx, 2xx and 3xx events. We can see that events 100, 200 and 300 are basic events followed by 1xx, 2xx and 3xx which give extra information about the problem.

E.g. I can see two events

Event 100 :

Windows has started up:
    Boot Duration        :              34857ms
    IsDegradation        :              0
    Incident Time (UTC)  :              18.11.2015 23:58:10

 

Event 102:

This driver took longer to initialize, resulting in a performance degradation in the system start up process:
    File Name             :              mssmbios
    Friendly Name         :              System Management BIOS Driver
    Version               :              6.1.7600.16385 (win7_rtm.090713-1255)
    Total Time            :              1027ms
    Degradation Time      :              1026ms
    Incident Time (UTC)   :              18.11.2015 23:58:10

So we can see that System Management BIOS Driver caused the delay in the system boot up.

Unfortunately sometimes events 100, 200 and 300 occur alone without followed events. In this case it is impossible to detect the reason of the delay using Diagnostics-Performance event log.

You should pay attention to parameters of Event 100 (Microsoft-Windows-Diagnostics-Performance):

                 
 System
 ...
 EventData          
                 BootTsVersion 2
                 BootStartTime  2015-11-18T20:58:10.671600300Z
                 BootEndTime    2015-11-18T20:58:10.671600300Z
                 SystemBootInstance     89
                 UserBootInstance          84
                 BootTime           34857
                 MainPathBootTime       12657
                 BootKernelInitTime      21
                 BootDriverInitTime       3101
                 BootDevicesInitTime    18
                 BootPrefetchInitTime  0
                 BootPrefetchBytes        0
                 BootAutoChkTime         0
                 BootSmssInitTime          5084
                 BootCriticalServicesInitTime    436
                 BootUserProfileProcessingTime             2683
                 BootMachineProfileProcessingTime    0
                 BootExplorerInitTime   848
                 BootNumStartupApps  24
                 BootPostBootTime        22200
                 BootIsRebootAfterInstall           false
                 BootRootCauseStepImprovementBits 0
                 BootRootCauseGradualImprovementBits          0
                 BootRootCauseStepDegradationBits    4
                 BootRootCauseGradualDegradationBits             0
                 BootIsDegradation         False
                 BootIsStepDegradation               false
                 BootIsGradualDegradation        false
                 BootImprovementDelta              0
                 BootDegradationDelta 0
                 BootIsRootCauseIdentified       true
                 OSLoaderDuration         735
                 BootPNPInitStartTimeMS           21
                 BootPNPInitDuration    1342
                 OtherKernelInitDuration            332
                 SystemPNPInitStartTimeMS     1665
                 SystemPNPInitDuration              1776
                 SessionInitStartTimeMS             3451
                 Session0InitDuration    2088
                 Session1InitDuration    339
                 SessionInitOtherDuration          2656
                 WinLogonStartTimeMS               8536
                 OtherLogonInitActivityDuration             587
                 UserLogonWaitDuration             3551

Most of parameters are self-descriptive.

Pay attention that BootTime= MainPathBootTime + BootPostBootTime

MainPathBootTime is the time (in milliseconds)  from when the Windows Logo first appears on screen and until your desktop or logon prompt is presented.

BootPostBootTime is the time (in milliseconds) from the logon screen or desktop showing up and until the system become actually usable (the system has reached 80% idle).

In  many cases (but not in my sample), the problem with long boot time is linked with Windows Prefetcher – you will see that BootPrefetchInitTime is set to a large value, e.g. 60000 or more. In this case you can play with Superfetch service and Superfetch caching parameters (registry key HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Control\Session Manager\Memory Management\PrefetchParameters). If you have just changed your HDD or SSD, you should re-run the assessment in Performance Information and Tools applet (or just run Winsat command as winsat.exe diskformal) to make Windows use the best prefetch strategy.

Now you have some background information about Diagnostics-Performance events. In the next part I will show how Event Log Explorer helps to detect boot performance issues.

facebooktwittergoogle_plusredditpinterestlinkedinmail