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:
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.
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!
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!
Interesting post. Thanks for sharing. Is there any similar facility which can calculate Time to Desktop as well? Say from the time you enter credentials to a stable/accessible desktop.
ReplyDeleteHi Sitaram,
ReplyDeletesome of the counter exposed by the data in event 100 are overlapping. Normally as soon as you can see your logon window, the BootPostBootTime counter starts end ends when your system has been idle for 10 seconds.
There also is the UserLogonWaitDuration counter which, to my understanding, measures the time between the credential Windows appear and the actual logon action.
Hope this helps
Carlo
I am trying to check the time between user login desktop ready and responsive. The UserLogonWaitDuration parameter seems to be that value, but there's not Microsoft ufficial documentation about it. Aldo, on some PC the value of UserLogonWaitDuration is very high, up to 15 minutes an it seems unreal because actualy the desktop is ready earlier... maybe is a backgroud process that is still running and maked the UserLogonWaitDuration dilay. Can you pls support?
DeleteHi,
ReplyDeleteon my pc, events tagged with ID 100 appear with a variable delay in the event log. Do you know why?
Henry
Hello Henry,
ReplyDeletethat is normal, since event are written in an asynchronous manner by a writer thread, so that there is no impact on the boot process. Also the use of this buffer allow for very highly accurate timestamps for events, which is primordial for problem analysis.
Hope this answers you question.
Carlo
I couldn't help to notice that when you run your first command you are getting full xml output. This is not what I am getting but rather when I run the command I just receive a default output of Time Created, ProviderName, and ID Message. How are you getting the xml output on powershell without importing a xml file?
ReplyDelete"...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..."
ReplyDeleteI don't think this is true. These event ID's occur only when a performance degradation is detected. Normal boots are not recorded. I don't know how Windows determines what is not normal nor do I know how to change this so every boot event is recorded. If any knows, please let me know. Thanks.
Thank you for posting. What would be the best approach to pass a list of machines to the script you created? I would like to get the boot duration on multiple machines.
ReplyDeleteThank you for posting. I need to get the boot duration of many machines. What would be the best approach to pass a list machines to the script you created?
ReplyDeleteI am trying to check the time between user login desktop ready and responsive. The UserLogonWaitDuration parameter seems to be that value, but there's not Microsoft ufficial documentation about it. Aldo, on some PC the value of UserLogonWaitDuration is very high, up to 15 minutes an it seems unreal because actualy the desktop is ready earlier... maybe is a backgroud process that is still running and maked the UserLogonWaitDuration dilay. Does anybody can support?
ReplyDeleteYou have a typo error. wan should be want
ReplyDeleteThis time I wan to dig