Windows boot history and boot performance, explored in Powershell

Last week I spent quite a few lines explaining how we could use Powershell to retrieve the Windows boot time with the highest possible precision. I came to the conclusion that the best option we had was to reverse-engineer the system boot timestamp from the [Environment]::TickCount counter using the following command line:

(Get-Date) - ([timespan]::FromMilliseconds([Math]::Abs([Environment]::TickCount)))

This time I wan to dig in the possiblity under Windows client operating systems (Windows 7, Windows 8 and Windows 8.1) to get an even more accurate timestamp using the information offered by the Microsoft-Windows-Diagnostics-Performance provider (which is not available on Windows server versions). I will also take advantage of the large amount of information this provider brings back to build an history of my laptop boots, as well as to retrieve the duration of each boot process.

The little known Event Id 100

The key cmdlet I will be using here, you should now know, is Get-WinEvent, used against the aforementioned provider to fetch events tagged with ID 100:

Get-WinEvent -FilterHashtable @{
     logname='Microsoft-Windows-Diagnostics-Performance/Operational';
     id=100
     } -MaxEvents 10

By investigating all the Event ID 100 events, you will be able to find out exactly how long it took to boot up your system every time since the day you installed your Windows computer. Here's a sample content of an instance of Event ID 100:

Log Name:      Microsoft-Windows-Diagnostics-Performance/Operational
Source:        Microsoft-Windows-Diagnostics-Performance
Date:          09/07/2014 09:38:32
Event ID:      100
Task Category: Boot Performance Monitoring
Level:         Critical
Keywords:      Event Log
User:          LOCAL SERVICE
Computer:      computer.happysysadm.com
Description:
Windows has started up: 
     Boot Duration  : 258644ms
     IsDegradation  : false
     Incident Time (UTC) : ?2014?-?07?-?09T07:33:10.656000200Z
Event Xml:
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
  <System>
    <Provider Name="Microsoft-Windows-Diagnostics-Performance" Guid="{CFC18EC0-96B1-4EBA-961B-622CAEE05B0A}" />
    <EventID>100</EventID>
    <Version>2</Version>
    <Level>1</Level>
    <Task>4002</Task>
    <Opcode>34</Opcode>
    <Keywords>0x8000000000010000</Keywords>
    <TimeCreated SystemTime="2014-07-09T07:38:32.025911700Z" />
    <EventRecordID>477</EventRecordID>
    <Correlation ActivityID="{032FBC50-F800-0002-0C58-EA08489BCF01}" />
    <Execution ProcessID="1776" ThreadID="4708" />
    <Channel>Microsoft-Windows-Diagnostics-Performance/Operational</Channel>
    <Computer>computer.happysysadm.com</Computer>
    <Security UserID="S-1-5-19" />
  </System>
  <EventData>
    <Data Name="BootTsVersion">2</Data>
    <Data Name="BootStartTime">2014-07-09T07:33:10.656000200Z</Data>
    <Data Name="BootEndTime">2014-07-09T07:38:09.839166700Z</Data>
    <Data Name="SystemBootInstance">43</Data>
    <Data Name="UserBootInstance">23</Data>
    <Data Name="BootTime">258644</Data>
    <Data Name="MainPathBootTime">224783</Data>
    <Data Name="BootKernelInitTime">22</Data>
    <Data Name="BootDriverInitTime">10421</Data>
    <Data Name="BootDevicesInitTime">1082</Data>
    <Data Name="BootPrefetchInitTime">58338</Data>
    <Data Name="BootPrefetchBytes">347176960</Data>
    <Data Name="BootAutoChkTime">0</Data>
    <Data Name="BootSmssInitTime">29186</Data>
    <Data Name="BootCriticalServicesInitTime">32461</Data>
    <Data Name="BootUserProfileProcessingTime">4496</Data>
    <Data Name="BootMachineProfileProcessingTime">2</Data>
    <Data Name="BootExplorerInitTime">57583</Data>
    <Data Name="BootNumStartupApps">15</Data>
    <Data Name="BootPostBootTime">33861</Data>
    <Data Name="BootIsRebootAfterInstall">false</Data>
    <Data Name="BootRootCauseStepImprovementBits">0</Data>
    <Data Name="BootRootCauseGradualImprovementBits">0</Data>
    <Data Name="BootRootCauseStepDegradationBits">0</Data>
    <Data Name="BootRootCauseGradualDegradationBits">0</Data>
    <Data Name="BootIsDegradation">false</Data>
    <Data Name="BootIsStepDegradation">false</Data>
    <Data Name="BootIsGradualDegradation">false</Data>
    <Data Name="BootImprovementDelta">0</Data>
    <Data Name="BootDegradationDelta">0</Data>
    <Data Name="BootIsRootCauseIdentified">false</Data>
    <Data Name="OSLoaderDuration">2511</Data>
    <Data Name="BootPNPInitStartTimeMS">22</Data>
    <Data Name="BootPNPInitDuration">1333</Data>
    <Data Name="OtherKernelInitDuration">4272</Data>
    <Data Name="SystemPNPInitStartTimeMS">5591</Data>
    <Data Name="SystemPNPInitDuration">10169</Data>
    <Data Name="SessionInitStartTimeMS">15776</Data>
    <Data Name="Session0InitDuration">16869</Data>
    <Data Name="Session1InitDuration">965</Data>
    <Data Name="SessionInitOtherDuration">11350</Data>
    <Data Name="WinLogonStartTimeMS">44962</Data>
    <Data Name="OtherLogonInitActivityDuration">117737</Data>
    <Data Name="UserLogonWaitDuration">40540</Data>
  </EventData>
</Event>

As you can see, there is more information here than you could have hoped for, and I admit one could feel overwhelmed, especially because most of those counters in the EventData node are not so well documented. Fortunately their name is self-explanatory and this helps a bit.

Our attention will focus on four of those fields: BootStartTime, BootEndTime, MainPathBootTime and BootPostBootTime.

 

 

Let's see what they are.

How Windows measures its boot performance
 

To make it simple (even do I think I'll write a specific blog post on this in the future, since this is pretty interesting), when you start your computer, as soon as WinLoad.exe loads the kernel, Windows logs a first timestamp in the BootStartTime variable. When every background service has been started and the computer has been idle for 10 seconds, Windows will log a second timestamp in the BootEndTime variable. The duration between these two timestamps is divided into two separate counters. The first one is MainPathBootTime, which records the number of milliseconds it takes for the system to load all kernel drivers and services that are meant to make Windows available for interaction. Following this, BootPostBootTime measures the time needed to load low-priority processes and services.

 

Great, isn't it? If you had been using a stopwatch to get this information you were on the wrong path. The new event logging system based on ETW and born with Windows Vista is seriously doing a great job of recording handy performance data and Event ID 100 is a great example of this mechanism.

Here's the values for these fields on my laptop.

BootStartTime                                               2014-07-09T07:33:10.656000200Z
BootEndTime                                                 2014-07-09T07:38:09.839166700Z
MainPathBootTime                                            224783
BootPostBootTime                                            33861

As I said, the values of MainPathBootTime and of BootPostBootTime are expressed in milliseconds. Each time the Diagnostics-Performance provider asynchronously writes this information in the event log, the event severity is dinamically calculated against some values which are stored in the registry under HKLM:\SOFTWARE\Microsoft\Windows\CurrentVersion\Diagnostics\Performance\Boot.

Their default values can be retrieved in Powershell and are exactly the same on Windows 7 or Windows 8:

cd HKLM:
cd .\SOFTWARE\Microsoft\Windows\CurrentVersion\Diagnostics\Performance
Get-Item Boot

Hive: HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Windows\CurrentVersion\Diagnostics\Performance

Name                           Property
----                           --------
Boot                           PostBootMajorThreshold_Sec      : 60
                               PostBootMinorThreshold_Sec      : 30
                               BootMajorThreshold_Sec          : 120
                               HardThresholds_CritServicesList : CscService,DcomLaunch,EventLog,EventSystem,gpsvc,PlugPlay,ProfSvc,RpcSs,SENS,Themes,MMCSS,AudioEndpointBuilder,Audiosrv,Windefend
                               BootMinorThreshold_Sec          : 60
                               PostBootDelay_Sec               : 90
                               UserWaitTimeout_Sec             : 60
                               PostBoot_TimeToAccumulate_Sec   : 10
                               PostBoot_BusyThreshold          : 20
                               MinDelayPercentageToIdentify    : 10
                               NumInitialBootsToIgnore         : 1

Twelve keys here. As far as I was able to determine, here's the logic behind the level (critical, error, warning) assignment:

• if MainPathBootTime duration is less than BootMinorThreshold_Sec and BootPostBootTime is less than PostBootMinorThreshold_Sec you will get a Warning event. You will always have at least a Warning, even with an SSD drive (which makes Windows usually stay in the MainPathBootTime phase for less than 10 seconds).
• if MainPathBootTime duration is less than BootMajorThreshold_Sec and more than BootMinorThreshold_Sec and BootPostBootTime is less than PostBootMajorThreshold_Sec and more than PostBootMinorThreshold_Sec you will get an Error event.
• if MainPathBootTime exceeds BootMajorThreshold_Sec or BootPostBootTime exceeds PostBootMajorThreshold_Sec you will get a Critical event.

In a few words, whichever value is more critical, this is what Windows ultimately attaches to event ID 100.

The script - Building a boot history based on events with Id 100

In the first part of the script I build an object containing the Windows boot history. Notice that you need to make sure that you have the admin token to access the information of the Diagnostics-Performance provider, otherwise you'll get an error. Happily enough, checking for admin rights has become pretty easy in Powershell 4.0 thanks to the new #requires syntax.

#requires -version 4.0
#requires –runasadministrator

#Retrieving all events with ID 100

$BootEvents = Get-WinEvent -FilterHashtable @{
  logname='Microsoft-Windows-Diagnostics-Performance/Operational';
  id=100}

#Building a boot history with, for each boot, the duration of the boot process

$BootHistory = $BootEvents | Select-Object TimeCreated, LevelDisplayName,
        @{
   n="BootStartTime";
   e={Get-Date -Date (([xml]$_.ToXml()).Event.EventData.Data |
  Where-Object {$_.name -eq "BootStartTime"})."#text"}
  },
        @{
   n="BootEndTime";
   e={Get-Date -Date (([xml]$_.ToXml()).Event.EventData.Data |
  Where-Object {$_.name -eq "BootEndTime"})."#text"}
  },
        @{
   n="MainPathBootTime";
   e={([timespan]::FromMilliseconds((([xml]$_.ToXml()).Event.EventData.Data |
  Where-Object {$_.name -eq "MainPathBootTime"})."#text"))}
  },
 @{
   n="BootPostBootTime";
   e={([timespan]::FromMilliseconds((([xml]$_.ToXml()).Event.EventData.Data |
  Where-Object {$_.name -eq "BootPostBootTime"})."#text"))}
  }

The script - Setting up temporary variables

In the second part I work out temporary variables to evite too long lines and make the script more readable (though this is pretty difficult in a blog...). Notice also that in the .ToString method I use backslashes to escape the colons, which otherwise have a special meaning.

$BootStartTime = $BootHistory.bootstarttime

$MainPathBootTime = $BootHistory.MainPathBootTime

$PostBootTime = $BootHistory.BootPostBootTime

$LastBootDate = $BootStartTime | Select-Object -First 1

$OldestRecordedBoot = $BootStartTime | Select-Object -last 1

$BootFrequencyInDays = ($LastBootDate - $OldestRecordedBoot).days / $BootStartTime.Count

$AvgMainBootDuration = [timespan]::FromSeconds((($MainPathBootTime.totalseconds |
  Measure -A).average)).ToString("hh\:mm\:ss")

$AvgPostBootDuration = [timespan]::FromSeconds((($PostBootTime.totalseconds |
  Measure -A).average)).ToString("hh\:mm\:ss")

$ActualWindowsBootTime = (Get-Date) - `
  ([timespan]::FromMilliseconds([Math]::Abs([Environment]::TickCount)))

$LastEvent12 = Get-WinEvent -FilterHashtable @{
  LogName='System';
  ProviderName='Microsoft-Windows-Kernel-General';
  ID=12} -MaxEvents 1 | Select -ExpandProperty TimeCreated

The script - Generating summary information on Windows boot performance

In the third part I build an object contaning summary information on Windows boot performance, like the average boot duration (divided in main boot phase and post boot phase), or the current boot date as retrieved from the last event 12 of the Microsoft-Windows-Kernel-General provider.

#Building an object containing a quick summary of your last computer boot, as
#well as of the average boot duration. 

$BootInformation = 1 | Select-Object BootFrequencyInDays, AvgMainBootDuration, `
   AvgPostBootDuration, LastBootDate, OldestRecordedBoot, `
   ActualWindowsBootTime, LastEvent12
$BootInformation.BootFrequencyInDays = $BootFrequencyInDays
$BootInformation.AvgMainBootDuration = $AvgMainBootDuration
$BootInformation.AvgPostBootDuration = $AvgPostBootDuration
$BootInformation.LastBootDate = $LastBootDate
$BootInformation.OldestRecordedBoot = $OldestRecordedBoot
$BootInformation.ActualWindowsBootTime = $ActualWindowsBootTime
$BootInformation.LastEvent12 = $LastEvent12

The script - Assessing Windows boot performance

In the fourth and last part I implement an object which allow you to see how Windows assesses boot performance, based on the values of the registry keys we saw above.

#Grouping boot events by Level, in order to see if your computer boot duration is below or
#beyond the thresholds defined in the Registry
$BootAnalysis = Get-WinEvent -FilterHashtable @{
  logname='Microsoft-Windows-Diagnostics-Performance/Operational';
  id=100} |
  Group-Object LevelDisplayName

The results - Windows boot history based on event with Id 100

Here's a sample output of each portion of this script:

$BootHistory | Format-Table

TimeCreated           LevelDisplayName   BootStartTime        BootEndTime            MainPathBootTime   BootPostBootTime
-----------           ----------------   -------------         -----------           ----------------   ----------------
09/07/2014 09:38:32   Critical           09/07/2014 09:33:10   09/07/2014 09:38:09   00:03:44.7830000   00:00:33.8610000
01/07/2014 09:45:33   Critical           01/07/2014 09:41:37   01/07/2014 09:45:28   00:02:27.4760000   00:00:51.8410000
27/06/2014 10:11:47   Critical           27/06/2014 10:08:11   27/06/2014 10:11:35   00:02:18.1190000   00:00:46.0080000

Powerful, isn't it? For improved readabilty, why not to take advantage of the cmdlet Out-GridView to generate a nice GUI:

The results - Windows boot overview

Here's my laptop boot summary. You can see that I boot my test machine roughly every month (32 days to be exact) and that the Main Boot Phase lasts twice the Post Boot Phase.

$BootInformation

BootFrequencyInDays       : 32,0810810810811
AvgMainBootDuration       : 00:02:08
AvgPostBootDuration       : 00:00:50
LastBootDate              : 09/07/2014 09:33:10
OldestRecordedBoot        : 09/04/2011 01:48:37
ActualWindowsBootTime     : 09/07/2014 09:33:34
LastEvent12               : 09/07/2014 09:33:10

The results - Windows boot assessment

The information contained in $BootAnalysis shows us that I have pretty bad boot performance, with a majority of Critical events, which means that my total boot time exceeds 3 minutes, and that some investigation should be on my action plan.

$BootAnalysis | Format-Table -Property Name, Count -AutoSize

Name          Count
----          -----
Critical         24
Error            7
Warning          6

Off-topic - Diagnostics-Performance is only for Windows clients

As I said at the beginning of this blog post, the "Microsoft-Windows-Diagnostics-Performance/Operational" provider is available only on Windows Client systems. If you used my script above against any Windows Server (2008 or 2012) you would get this red error:

Get-WinEvent : There is not an event log on the localhost computer that matches "Microsoft-Windows-Diagnostics-Performance/Operational".
At line:4 char:11
+ $events = Get-WinEvent -FilterHashtable @{logname='Microsoft-Windows-Diagnostics ...
+ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : ObjectNotFound: (Microsoft-Windo...nce/Operational:String) [Get-WinEvent], Exception
    + FullyQualifiedErrorId : NoMatchingLogsFound,Microsoft.PowerShell.Commands.GetWinEventCommand

So, before running the script, check you have the provider:

Get-WinEvent -ListLog Microsoft-Windows-Diagnostics-Performance/Operational

LogMode   MaximumSizeInBytes RecordCount LogName
-------   ------------------ ----------- -------
Circular             3080192         497 Microsoft-Windows-Diagnostics-Performance/Operational

Off-topic - Changing event log sizes

Let me add here that an important action that should be part of any Windows management process is to customize these event log sizes for storing more boot events.

The code below helps to you increase the System log file size of your choice to the desired value:

Get-EventLog -list | Where-Object {$_.logdisplayname -eq "System"}

  Max(K) Retain OverflowAction        Entries Log
  ------ ------ --------------        ------- ---
   1 024      0 OverwriteAsNeeded      23 327 System

Limit-EventLog -LogName 'System' -MaximumSize 30MB

Get-EventLog -list | Where-Object {$_.logdisplayname -eq "System"}

  Max(K) Retain OverflowAction        Entries Log
  ------ ------ --------------        ------- ---
  30 720      0 OverwriteAsNeeded      23 327 System

As for changing the size of the new Microsoft-Windows-Diagnostics-Performance/Operational log, there is no way for the moment you can do that using Limit-EventLog (because it doesn't work on the additional event logs existing from Windows Vista), and .NET must be leveraged in order to accomplish the task. Fortunately this is a breeze in Powershell:

$Log = New-Object -TypeName System.Diagnostics.Eventing.Reader.EventLogConfiguration -ArgumentList "Microsoft-Windows-Diagnostics-Performance/Operational"

$Log.MaximumSizeInBytes = 3080192

$Log.SaveChanges()

$Log

LogMode   MaximumSizeInBytes LogName
-------   ------------------ -------
Circular             3080192 Microsoft-Windows-Diagnostics-Performance/Operational

Increasing the timespan of recorded events will give you a better insight of your computer boot duration over a long period of time.

Conclusions

Each version of Windows has a great deal of new features and functionalities aimed at making system administration more precise than it was before. This is meant to make Windows a better operating system, in the sense that any Windows owner can have access to a lot of technical information that were before hidden behind the interface. Having access to all the information stored in events tagged with Id 100 is an example of this philosophy, which I like. Powershell, as always, it the tool for the job, and anyone interested in system administration should give it a try to see how the best of both worlds (Unix-like and Windows) has been put into it.

Hope you enjoyed this second trip inside windows boot, and, as always, if you have any question on the code, please leave a comment and I'll be more than happy to explain. If you enjoyed the content of this post, please share!

Until next time!