Thursday, July 24, 2014

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 @{
     } -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
Windows has started up: 
     Boot Duration  : 258644ms
     IsDegradation  : false
     Incident Time (UTC) : ?2014?-?07?-?09T07:33:10.656000200Z
Event Xml:
<Event xmlns="">
    <Provider Name="Microsoft-Windows-Diagnostics-Performance" Guid="{CFC18EC0-96B1-4EBA-961B-622CAEE05B0A}" />
    <TimeCreated SystemTime="2014-07-09T07:38:32.025911700Z" />
    <Correlation ActivityID="{032FBC50-F800-0002-0C58-EA08489BCF01}" />
    <Execution ProcessID="1776" ThreadID="4708" />
    <Security UserID="S-1-5-19" />
    <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>
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 @{

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

$BootHistory = $BootEvents | Select-Object TimeCreated, LevelDisplayName,
   e={Get-Date -Date (([xml]$_.ToXml()).Event.EventData.Data |
  Where-Object {$ -eq "BootStartTime"})."#text"}
   e={Get-Date -Date (([xml]$_.ToXml()).Event.EventData.Data |
  Where-Object {$ -eq "BootEndTime"})."#text"}
   e={([timespan]::FromMilliseconds((([xml]$_.ToXml()).Event.EventData.Data |
  Where-Object {$ -eq "MainPathBootTime"})."#text"))}
   e={([timespan]::FromMilliseconds((([xml]$_.ToXml()).Event.EventData.Data |
  Where-Object {$ -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) - `

$LastEvent12 = Get-WinEvent -FilterHashtable @{
  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 @{
  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.

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



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.


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!

Tuesday, July 8, 2014

Windows boot time, explored in Powershell

In this post I am going to explore most of the existing ways offered by Windows and Powershell to return the timestamp of the last boot.
Let's start with saying that there are multiple ways to retrieve this piece of information and exploring them all will make for what I hope is an interesting trip through some Windows internal mechanisms. Be wary by the way that this subject is very wide, and I have allowed myself some small off-topics that are meant to shed some light on the pieces of code we are now so used to see out there.

Windows is booting, but what time is it?
In old times (more or less one to two decades ago) we could (and still we can) use various legacy tools to fetch a Windows computer boot timestamp.
In more recent Windows versions some alternatives to those legacy Tools have appeared and we can today use the information stored:
  • in the Performance counters
  • in the Win32_OperatingSystem WMI instance
  • in the Windows event logs
Each of this approach has pros and cons. Some syntaxes are easier and some are trickier. Going through them all will give you an interesting insight of how you can take advantage of Windows Powershell as your all-in-one administration tool. In any case, please notice that the following examples have been prepared and tested on computers with European settings for the date (dd/MM/yyyy). As a consequence those that are based on text parsing or regular expressions might need some correction if you want to run them on a computer with different regional settings.

Let's start from the beginning: there are three possible legacy executables that you can use the retrieve the last reboot date:
  1. systeminfo.exe in C:\Windows\System32
  2. net.exe in C:\Windows\System32
  3. wmic.exe in C:\Windows\System32\wbem
1. System boot time with SYSTEMINFO
Systeminfo.exe is the old good tool every Windows admin used to get a quick look at system information. Used in conjunction with another legacy command, FIND, it allows you to see system boot time.

systeminfo | find "System Boot Time:"
System Boot Time:          07/07/2014, 17:41:11
The returned information is of System.String type.
systeminfo |
     find "System Boot Time:" |
     Get-Member |
     Select-Object Typename -Unique

As usual in Powershell, our aim is to return a re-usable object. In this case, better than a System.String, we would like to have a System.DateTime variable. The transformation can be achieved with an easy one-liner (for an explication of which you can refer to the final part my other blog post:

[datetime]::ParseExact($(systeminfo |
     find "System Boot Time:").substring(27,20),"dd/MM/yyyy, HH:mm:ss",$null)

Monday, July 7, 2014, 17:41:11
The main drawback of using systeminfo is that, since it retrieves the list of all the installed patches, it can take quite a long time to be executed, especially on long living systems, and there is nothing you can do to improve that.
2.  System boot time with NET

The second legacy executable is net.exe, which has two possible syntaxes, a long one (net statistics server) and a short one (net stats srv), both returning the same result:

net statistics server
Server Statistics for \\SRV01

Statistics since 07/07/2014 17:41:21

Sessions accepted                  0
Sessions timed-out                 0
Sessions errored-out               0

Kilobytes sent                     16
Kilobytes received                 0

Mean response time (msec)          0

System errors                      0
Permission violations              0
Password violations                0

Files accessed                     21
Communication devices accessed     0
Print jobs spooled                 0

Times buffers exhausted

  Big buffers                      0
  Request buffers                  0

The command completed successfully.
Lot of text in the output, as you can see, and the proceeding to get something meaningful out of it is a bit less comfortable, since some regex pattern matching needs to be done (if you have any kind of question do not hesitate to ask in the comment section below):

[datetime]::ParseExact($($(net stats srv) `
     -match "\d{2}/\d{2}/\d{4}").substring(17,19),"dd/MM/yyyy HH:mm:ss",$null)

Monday, July 7, 2014, 17:41:11

3. System boot time with WMIC
Third option, WMIC (which, if don't have it yet, you can get with the WMI Administrative Tools). The only thing you need to know for the moment is that WMIC is an alias based tool which interfaces with WMI (Windows Management Instrumentation). While it has many uses, I find it especially useful for querying certain system parameters, like the type and frequency of the processor, such as in 'wmic cpu get Name'.

To get the system boot up time, the syntax is:
wmic os get lastbootuptime

To explain the result of this WMIC example, let me start a brief discussion on the ways WMI stores dates and times, which is always good to know if you are a Windows sysadm. The Common Information Model (CIM) standard, where WMI is sitting on, uses the Universal Time Coordinate (UTC) format. Although UTC dates are non-intuitive at first glance, they are relatively easy to convert to a standard date-time format.

Let's have a look at their format, 20140707174111.489051+120, which is easy for humans to translate to yyyymmddHHMMSS.mmmmmmsUUU (full syntax over here)
In technical terms, this is a variant VT_BSTR returned by WMI as a 27 chars string (where the last two characters are blank in the WMIC output).
wmic os get lastbootuptime | Get-Member | Select-Object typename -Unique

Luckily, to convert this string to a valid Datetime, we can rely on the SWbemDateTime object. This is an object which, starting from Windows XP (way old, isn't it?) is used as a helper to parse CIM datetime values, as in the following example I wrote, where I first use a REGEX expression to skip the undesired text, then I force the remaining data into the Value property:
# Convert from VT_BSTR to System.Datetime
$DateTimeObject = New-Object -ComObject WbemScripting.SWbemDateTime 
$DateTimeObject.Value = $($(wmic os get lastbootuptime) `
     -match "\d{14}\.\d{6}\+\d{3}").TrimEnd() #TrimEnd removes the 2 last blank chars

Monday, July 7, 2014, 17:41:11
$DateTimeObject.GetVarDate($DateTimeObject.Value) |
     Get-Member |
     Select-Object typename -Unique

TypeName : System.DateTime
This was a general introduction to the three golden ways to retrieve the system boot time on a Windows box using legacy executables and returning the result as a DateTime object.

Of course there are other more Powershell-oriented ways to get to this very same result. Let's take the long windy road to that, by starting to introduce some WMI performance class information.

4. An introduction to WMI performance classes

There are two kinds of WMI performance classes: raw counter classes and cooked counter classes (yes, I didn't made it up: 'cooked' is the technical term for them).
The difference? Well, raw counters are simply raw numbers which have gone through no post-processing. Cooked counters, on the other side, are counters supplied by the Formatted Performance Data Provider, which is in charge of supplying calculated counter data.

As an example, take the two performance classes that store the actual uptime, from which, using a simple subtraction, we can make the system boot date:
Get-WmiObject -List Win32_Perf*System | select Name

Both these classes have the same properties with different values, and this can be confusing. But the raw class has two additional information, which you have to use to get the results you expect (and which are pre-cooked in the formatted class) from the raw data:
  • The first is the Timestamp_Object, which is an object-defined timestamp, defined by the provider, storing the current time measure.
  • The second is the Frequency_Object, which represents the frequency, in ticks per second, of the mentioned Timestamp_Object.
5. System boot time from RAW Performance Counters

Wait, ticks you said? You might be wondering what the heck a tick is, and this allows for a nice short discussion on the internals of Microsoft Windows and, more generally, of how a computer works.
Inside any CPU there are processor registers which are in charge of storing data used by arithmetic calculations. One of these, named Time Stamp Counter is a 64-bit register present on all x86 processors since the Pentium (remember?) which counts the number of cycles since reset, known as ticks.

Over time a tick has become a constant which is independent from the processor clock, even do tick count is updated at the System clock interval (every 10msec or 15.6 msec on most systems). The value of this constant is 10 millions per second (as stated over here), which gives a tick a duration of 100 ns.

So, each raw measure of the uptime has this Frequency_Object property constantly set at 10 million ticks per second, which is the frequency at which the Timestamp_Object is recorded.
To calculate the system uptime in seconds from this raw data, the following formula should then logically be used:

UptimeInSec = (Timestamp - SystemUptime) / Frequency

where the SystemUptime is another property containing the timestamp at boot expressed in the same unit as Timestamp_Object.

Let's convert this formula to Powershell:

$TimestampAtBoot = Get-WmiObject Win32_PerfRawData_PerfOS_System |
     Select-Object -ExpandProperty systemuptime
$CurrentTimestamp = Get-WmiObject Win32_PerfRawData_PerfOS_System |
     Select-Object -ExpandProperty Timestamp_Object
$Frequency = Get-WmiObject Win32_PerfRawData_PerfOS_System |
     Select-Object -ExpandProperty Frequency_Object
$UptimeInSec = ($CurrentTimestamp - $TimestampAtBoot)/$Frequency

Fine. We have been able to calculate our system uptime in seconds starting from truly primary data using a short Powershell script. Now let's try to convert this to something more meaningful and show the system boot time as a DateTime like in the previous examples:

(Get-Date) - (New-TimeSpan -seconds $UptimeInSec)

Monday, July 7, 2014, 17:41:11
Here you have your system boot date and time and the type of the returned object is already of DateTime type, so no parsing required. Great!
6. System boot time from [Environment]::TickCount

Another way to get your system boot date is to rely on some information exposed by the .NET Environment class. As explained in MSDN, the system timer we talked above behaves in a way that it increments the value of the property TickCount (which stores in a 32-bit signed integer the number of milliseconds elapsed since the system started) going from zero to Int32.MaxValue (where [int32]::MaxValue is 2147483647) for 24.9 days, then jump to Int32.MinValue (where [int32]::MinValue is -2147483648), which is a negative number, and starts incrementing back to zero for the next 24.9 days.

To see the attributes of the TickCount counter, issue:

[Environment]  |
     Select-Object -ExpandProperty DeclaredProperties |
     Where-Object Name -like TickCount
To get the system boot date using [Environment] we have first to get the time span from the number of milliseconds stored in TickCount, then subtract that time interval from the current date and time:

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

Monday, July 7, 2014, 17:41:11
The function [Math]::Abs() is used to return the absolute value of any number, and it is pretty useful here if your tick count is a negative number (which could be the case on systems up from more than 25 days).

7. System boot time from COOKED Performance Counters

Until now we have explained the differences between raw and cooked performance classes and we have seen how to retrieve the system boot time from the current uptime using the New-TimeSpan cmdlet. Time to see how easy is to get the same information using a cooked performance class in conjunction with a time interval.

The class Win32_PerfFormattedData_PerfOS_System contains a number of performance counters related to the operating system, including SystemUpTime, which tells you how many second the machine has been running, while its raw version Win32_PerfRawData_PerfOS_System stored in Systemuptime just a unit showing the time at boot.

(Get-Date) - (New-TimeSpan -Seconds (Get-WmiObject Win32_PerfFormattedData_PerfOS_System).systemuptime)
Lots of different examples to get the same information, isn't it? Now I am going to show you two more way to get the system uptime. One relies on WMI and the other one on the System eventlogs.

8. System boot time from Win32_OperatingSystem

Let's start from the WMI method. All the lessons we learned above on UTC time formatting and conversion operations from VT_BSTR to DATETIME will be re-used in our next examples and will make you more confident with this kind of Powershell game.

For the WMI part, the only class that we need here is Win32_OperatingSystem. The instance of this class keeps a pretty big bunch of information, such as the Manufacturer of your PC, the name of the registered user, or the OS architecture and language. Furthermore there are a few interesting properties containing precious time-oriented information: CurrentTimeZone, InstallDate, LocalDateTime and, can't believe it, LastBootUpTime. As I explained before, WMI dates are returned as strings and not as datetime objects. These strings are compliant with the CIM standards, so to get a valid re-usable System.DateTime object we have first to make some rework.

Two ways to do that.

The first one is, like I showed in the WMIC example, using the SWbemDateTime helper object:

# Convert from VT_BSTR to System.Datetime
$DateTimeObject = New-Object -ComObject WbemScripting.SWbemDateTime 
$DateTimeObject.Value = (Get-WmiObject Win32_OperatingSystem).LastBootUpTime
The second method relies on the fact that most WMI objects returned by Powershell have a comfortable "ConvertFromDateTime" method implemented out-of-the-box. Cool.
For example:
Get-WmiObject -Class win32_operatingsystem | Get-Member -MemberType ScriptMethod
will return:
ConvertFromDateTime               ScriptMethod  System.Object ConvertFromDateTime();                                                                               
convertToDateTime                 ScriptMethod  System.Object ConvertToDateTime();
Did I already say: "Cool!"?

Let's take advantage of it then:

$OSInfo = Get-WmiObject Win32_OperatingSystem
or, if you are a seasoned old school programmer:

$OSInfo  = Get-WmiObject -query "select * from win32_OperatingSystem"

For the most curious, there is also a pretty nice ManagementDateTimeConverter Class, which provides methods to convert CIM datetime to System.DateTime:

$OSInfo = Get-WmiObject Win32_OperatingSystem
That's all for the WMI part.

9. An introduction to Event Tracing for Windows (ETW) 

Time to pass to exploring the information that can be retrieved from your system event logs and see how they compare, but before we see that, and for better understanding, it's interesting to see how the Microsoft Eventing engine has evolved in the past 10 years.

Under Windows NT4 or Windows XP, the Event Log service recorded computer events in three simple logs, like you can see in the following screenshot: System, Security and Application.

Like most Windows developers know (while many administrators have never heard of it), starting with Windows Vista in 2006, the Windows Event Logs has been rewritten on top of the Event Tracing for Windows (ETW) technology, which is a system and software diagnostic, troubleshooting and performance monitoring component.

This new Event Viewer has been completely re-engineered and its appearance has also changed, but it is still familiar enough to not to feel miles from home:

In the new interface there are still a tree pane and a list of events. You can still access the well-known Application, System, and Security logs under the Windows Logs node.
  • some new nodes have been added, such as the Applications and Services logs which is a new category of event logs aimed at storing events from a single application or component rather than systemwide events.
  • the new ForwardedEvents log has been added to the Windows Logs node.
A lot of other Windows components were since then built on top of it, such as Resource Monitor, which allows sysadmins to drill down computer performance much better they could do with Task Manager on older versions.

Version after version, ETW exposes an increasing number of consistent information providers (through the use of a unified event provider model). Those information providers can be retrieved using logman and counted using the Powershell Count() method:

(c:\Windows\System32\logman.exe query providers).count
  • In Windows 8.1 there are 964 providers
  • In Windows 2012 r2 there are 830 providers
  • In Windows 7 there were 668 providers and 513 in Windows 2008 R2
  • In Windows 2003 R2 no more than 10 providers were exposed
Of course these figures increase when additional features or products are installed (such as Active Directory or, say, Hyper-V).

Unlike its predecessors, Windows (starting from Windows NT 4.0/2000/XP) records the system startup and shutdown times in the event log with the following informational Event IDs: 6005,6006,6008,6009.
For what we are trying to achieve, EventID 6005 is the most meaningful, because it occurs when the Event log service is started, just after the system has been booted and Windows has loaded.

In addition to these event IDs, there are some events from the Microsoft-Windows-Kernel-General event provider (exposed by ETW, which we just discussed) which indicate system startup and shutdown time.
You can find deeper information on this event provider as well as on the mentioned events by issuing the following Powershell commands:

c:\Windows\System32\logman.exe query providers Microsoft-Windows-Kernel-General
which can also be used in the form: 

c:\Windows\System32\logman.exe query providers Kernel-General

(Get-WinEvent -listprovider Microsoft-Windows-Kernel-General).events |
     Select-Object Id, Description |
     Format-Table -AutoSize
As you can see in the output, there are thirteen possible events. For calculation our system last boot date, we can optimistically refer to entries tagged with the EventID 12: "The operating system started at system time %7"

Let's focus then on Event ID 12, source Microsoft-Windows-Kernel-General, and Event ID 6005, source EventLog, to see which one gives us the most reliable information on our system boot time.

In Powershell, as you would expect now that you are an accustomed Powershell user, there are six ways to query the Event Logs:
  • Get-WmiObject -Class Win32_NTLogEvent
  • Get-WmiObject -Query "SELECT * FROM Win32_NTLogEvent"
  • Get-EventLog
  • Get-WinEvent -FilterXml
  • Get-WinEvent -FilterHashtable
  • Get-WinEvent -FilterXPath
Let's have a deeper look at each and every one of these possibilities.
10. System boot time from Win32_NTLogEvent

First of all, we also have the option of using WMI against the Win32_NTLogEvent class, as shown here:

$Event12 = Get-WmiObject -Class Win32_NTLogEvent `
     -Filter "LogFile = 'System' AND SourceName='Microsoft-Windows-Kernel-General' AND EventCode=12" |
     Select-Object -First 1
and here:

$Event6005 = Get-WmiObject -Class Win32_NTLogEvent `
     -Filter "LogFile = 'System' AND SourceName='EventLog' AND EventCode=6005" |
     Select-Object -First 1

$Event12 = Get-WmiObject -Query "SELECT * FROM Win32_NTLogEvent `
     WHERE (logfile='System') AND (SourceName='Microsoft-Windows-Kernel-General') AND (EventCode='12')" |
     Select-Object -First 1

$Event6005 = Get-WmiObject -Query "SELECT * FROM Win32_NTLogEvent `
     WHERE (logfile='System') AND (SourceName='EventLog') AND  (EventCode='6005')" |
     Select-Object -First 1

In both cases, the Win32_NTLogEvent WMI class is used to translate instances from the Windows event log, using the same mechanism explained before for Win32_OperatingSystem.
11. System boot time from Get-EventLog

Second option (which, let me say, is so Powershell 1.0, and you'll see why in the performance section at the end of the post) is to use Get-EventLog. The main drawback of using Get-EventLog is that it doesn't support much in the way of filtering. That means you have to retrieve all of the entries, and then use Where-Object to filter. Needless to say, it can be pretty CPU and time consuming in case of large logs and can make your System process peak very high. That's why I always suggest to use this cmdlet in conjunction with at least the -After parameters, to shorten the time window.

12, 6005 | % {
     Get-EventLog -LogName System -After 05/05/2012 |
          Where-Object EventId -eq $_ |
          Select-Object EventId, Source, TimeGenerated -First 1
To extract just the TimeGenerated field for Event IDs 12, use:

((Get-EventLog -logname system) | Where-Object {($_.eventid -eq 12) -and ($_.Source -eq 'Microsoft-Windows-Kernel-General') } )[0] | Select-Object -ExpandProperty TimeGenerated
or, for Event IDs 6005:

((Get-EventLog -logname system) | Where-Object {($_.eventid -eq 6005) -and ($_.Source -eq 'EventLog') } )[0] | Select-Object -ExpandProperty TimeGenerated
Notice in both these examples the different syntax I used to index inside the array of the returned results.
12. System boot time from Get-WinEvent
Third major option is to rely on the powerful Get-WinEvent cmdlet, which was introduced in Powershell 2.0 in 2009.
It does support three types of built-in filtering (making it lighting fast) and it can query the newer log types introduced since Vista/Win2008, so it should be preferred to Get-EventLog.
These three types of filtering are:
        Required?                    true
        Position?                    0
        Accept pipeline input?       false
        Parameter set name           HashQuerySet
        Aliases                      None
        Dynamic?                     false
        Required?                    false
        Position?                    Named
        Accept pipeline input?       false
        Parameter set name           FileSet, GetProviderSet, GetLogSet
        Aliases                      None
        Dynamic?                     false
    -FilterXml <xml>
        Required?                    true
        Position?                    0
        Accept pipeline input?       false
        Parameter set name           XmlQuerySet
        Aliases                      None
        Dynamic?                     false
FilterXml takes in a XML-style string of text. This is the example for EventID 6005:

$xml6005='<QueryList><Query Id="0" Path="System"><Select Path="System">*[System[Provider[@Name="EventLog"] and (EventID=6005)]]</Select></Query></QueryList>'
Get-WinEvent -FilterXml $xml6005 -MaxEvents 1 | Select-Object -ExpandProperty TimeCreated
and this is the example for EventID 12:

$xml12='<QueryList><Query Id="0" Path="System"><Select Path="System">*[System[Provider[@Name="Microsoft-Windows-Kernel-General"] and (EventID=12)]]</Select></Query></QueryList>'
Get-WinEvent -FilterXml $xml12 -MaxEvents 1 | Select-Object -ExpandProperty TimeCreated
In both cases the returned result is of System.DateTime type. What else?

FilterHashtable takes in a hashtable containing three properties in our case: LogName, Providername and ID:

Get-WinEvent -FilterHashtable @{LogName='System'; ProviderName='Microsoft-Windows-Kernel-General'; ID=12} -MaxEvents 1 | Select-Object -ExpandProperty TimeCreated
Get-WinEvent -FilterHashtable @{LogName='System'; ProviderName='EventLog'; ID=6005} -MaxEvents 1 | Select-Object -ExpandProperty TimeCreated
Last option is to use FilterXPath. To make a long story short, XPath is a language used to query specific nodes from an XML document. If you don't use it often, its syntax can look quit scaring. But I am here to help.

For event 12 you have:

(Get-WinEvent -LogName "System" -MaxEvents 1 -FilterXPath "*[System[Provider[@Name='Microsoft-Windows-Kernel-General']][EventID=12]]").TimeCreated
and for event 6005 you have:

(Get-WinEvent -LogName "System" -MaxEvents 1 -FilterXPath "*[System[Provider[@Name='EventLog']][EventID=6005]]").TimeCreated
This was the last example I wanted to use to show you how to find out the system boot up time and date. To resume, there are 23 possible choices, and it could be difficult to choose the right tool for the job. That's why I have decided that this post wouldn't be complete without a performance analysis.
13. Performance
Performancewise, any of the above solution has its execution time depending on the information provider. That's why I have tested all of them with Measure-Command on a Windows 2012 R2 and on a Windows 8.1.  The resulting duration is expressed in seconds (from faster to slower):

Duration Title                                   Result              ResultType     
-------- -----                                   ------              ----------     
0,0393308 TickCount + TimeSpan + Get-Date         07/07/2014 17:41:11 System.DateTime
0,0417487 WMI query + SWbemDateTime               07/07/2014 17:41:11 System.DateTime
0,0429207 WMI + ManagementDateTimeConverter       07/07/2014 17:41:11 System.DateTime
0,0459907 Net Statistics Server                   07/07/2014 17:41:21 System.DateTime
0,0484394 WMI + SWbemDateTime                     07/07/2014 17:41:11 System.DateTime
0,0512981 Net Stats Srv                           07/07/2014 17:41:21 System.DateTime
0,0775581 WMI Query 6005 + ConvertToDateTime      07/07/2014 17:41:19 System.DateTime
0,0796125 WMI + ConvertToDateTime                 07/07/2014 17:41:11 System.DateTime
0,0860807 WMI filter 6005 + ConvertToDateTime     07/07/2014 17:41:19 System.DateTime
0,1026782 WMI filter 12 + ConvertToDateTime       07/07/2014 17:41:11 System.DateTime
0,1307235 WMIC + SWbemDateTime                    07/07/2014 17:41:11 System.DateTime
0,2467589 Get-WinEvent + FilterXML 12             07/07/2014 17:41:11 System.DateTime
0,2678846 Get-WinEvent + FilterXPath 6005         07/07/2014 17:41:19 System.DateTime
0,2697007 Get-WinEvent + FilterXPath 12           07/07/2014 17:41:11 System.DateTime
0,2825668 Get-WinEvent + FilterHastTable 6005     07/07/2014 17:41:19 System.DateTime
0,2962874 Get-WinEvent + FilterHastTable 12       07/07/2014 17:41:11 System.DateTime
0,2978704 PerfFormattedData + TimeSpan + Get-Date 07/07/2014 17:41:11 System.DateTime
0,3042627 WMI Query 12 + ConvertToDateTime        07/07/2014 17:41:11 System.DateTime
0,4015614 Get-WinEvent + FilterXML 6005           07/07/2014 17:41:19 System.DateTime
2,7686521 PerfRawData + TimeSpan + Get-Date       07/07/2014 17:41:11 System.DateTime
3,5873439 Systeminfo + ParseExact                 07/07/2014 17:41:11 System.DateTime
12,3051242 Get-EventLog 6005 + Where-Object        07/07/2014 17:41:19 System.DateTime
35,5054786 Get-EventLog 12 + Where-Object          07/07/2014 17:41:11 System.DateTime

The result is self-explanatory:
  • Get-EventLog is to be considered deprecated
  • Systeminfo is pretty time consuming, since it fetches all hotfix information
  • All the others are pretty fast
  • [Environment]::TickCount has jaw-dropping performance
14. Precision

Not all the Tools return the same result. There are three main groups:
  1. those that fetch the system boot date from WMI and those that fetch Event 12 as asynchronously provided from the ETW Kernel-General provider and stored in the System eventlog. This is the most accurate information, and, as I was able to verify, returns the exact time your Windows computer bootstraps after POST.
  2. those that fetch Event 6005, which is less accurate, because it returns the date and time the Event Log service has started and that is 8 seconds late on Kernel-provided information.
  3. those that are based on Network Statistics, which are returning the date and time since when the Server service has started. In this case there is a huge 10 seconds delay from what's being returned by Kernel-General.
Here's the complete result ordered by boot time:

Duration Title                                   Result              ResultType     
  -------- -----                                   ------              ----------     
 3,5873439 Systeminfo + ParseExact                 07/07/2014 17:41:11 System.DateTime
35,5054786 Get-EventLog 12 + Where-Object          07/07/2014 17:41:11 System.DateTime
 0,1307235 WMIC + SWbemDateTime                    07/07/2014 17:41:11 System.DateTime
 0,0484394 WMI + SWbemDateTime                     07/07/2014 17:41:11 System.DateTime
 2,7686521 PerfRawData + TimeSpan + Get-Date       07/07/2014 17:41:11 System.DateTime
 0,0393308 TickCount + TimeSpan + Get-Date         07/07/2014 17:41:11 System.DateTime
 0,2978704 PerfFormattedData + TimeSpan + Get-Date 07/07/2014 17:41:11 System.DateTime
 0,0796125 WMI + ConvertToDateTime                 07/07/2014 17:41:11 System.DateTime
 0,0417487 WMI query + SWbemDateTime               07/07/2014 17:41:11 System.DateTime
 0,0429207 WMI + ManagementDateTimeConverter       07/07/2014 17:41:11 System.DateTime
 0,3042627 WMI Query 12 + ConvertToDateTime        07/07/2014 17:41:11 System.DateTime
 0,1026782 WMI filter 12 + ConvertToDateTime       07/07/2014 17:41:11 System.DateTime
 0,2467589 Get-WinEvent + FilterXML 12             07/07/2014 17:41:11 System.DateTime
 0,2962874 Get-WinEvent + FilterHastTable 12       07/07/2014 17:41:11 System.DateTime
 0,2697007 Get-WinEvent + FilterXPath 12           07/07/2014 17:41:11 System.DateTime
 0,0860807 WMI filter 6005 + ConvertToDateTime     07/07/2014 17:41:19 System.DateTime
 0,0775581 WMI Query 6005 + ConvertToDateTime      07/07/2014 17:41:19 System.DateTime
12,3051242 Get-EventLog 6005 + Where-Object        07/07/2014 17:41:19 System.DateTime
 0,4015614 Get-WinEvent + FilterXML 6005           07/07/2014 17:41:19 System.DateTime
 0,2825668 Get-WinEvent + FilterHastTable 6005     07/07/2014 17:41:19 System.DateTime
 0,2678846 Get-WinEvent + FilterXPath 6005         07/07/2014 17:41:19 System.DateTime
 0,0512981 Net Stats Srv                           07/07/2014 17:41:21 System.DateTime
 0,0459907 Net Statistics Server                   07/07/2014 17:41:21 System.DateTime
15. Conclusions

All in all, taking into consideration speed of execution and precision, the syntax to remember is:

(Get-Date) - ([timespan]::FromMilliseconds([Math]::Abs([Environment]::TickCount)))
I hope you have enjoyed this post. If you do, do not hesitate to leave a comment and to share. Also, if you want to suggest any modification, correction or improvement, or should you need any help with the code, feel free to get in touch.

Thursday, July 3, 2014

How to open the Powershell ISE in Windows 8.1

More or less one week ago I have started using the latest Windows 8.1 version on two test laptops . As you can imagine my first reflex was to fire Powershell, which is pretty easy: I brought up the Start Screen and saw that Powershell was well there while the Integrated Scripting Environment (ISE) was missing from the Application menu:

Where is the Powershell ISE gone?
I was kind of surprised but I knew for sure that Windows Powershell 4.0 as well as the ISE are installed by default on the desktop version of the OS:

PS C:\Users\Carlo> $PSVersionTable

Name                           Value
----                           -----
PSVersion                      4.0
WSManStackVersion              3.0
CLRVersion                     4.0.30319.34014
BuildVersion                   6.3.9600.17090
PSCompatibleVersions           {1.0, 2.0, 3.0, 4.0}
PSRemotingProtocolVersion      2.2

I quickly understood that only PowerShell is visible under Apps. The ISE is somewhat hidden inside the Admnistrative Tools. There are three solutions to solve this.

The first one is to launch a classic Powershell than rely on the ISE alias to open the ISE:

PS C:\Users\Carlo> Get-Command ise

CommandType     Name
-----------     ----
Alias           ise -> powershell_ise.exe

The second solution is to bring up the Search screen and type powershell_ise then press Enter:

The third solution is to open the Windows settings (by moving you mouse pointer in the top right corner of your screen), and then select Tiles under the Settings section. To unhide the Administrative Tools, move the slider to the Yes position:

Hope this helps.
Related Posts Plugin for WordPress, Blogger...