{"id":17501,"date":"2010-08-07T00:01:00","date_gmt":"2010-08-07T00:01:00","guid":{"rendered":"https:\/\/blogs.technet.microsoft.com\/heyscriptingguy\/2010\/08\/07\/weekend-scripter-boot-tracing-with-windows-powershell\/"},"modified":"2010-08-07T00:01:00","modified_gmt":"2010-08-07T00:01:00","slug":"weekend-scripter-boot-tracing-with-windows-powershell","status":"publish","type":"post","link":"https:\/\/devblogs.microsoft.com\/scripting\/weekend-scripter-boot-tracing-with-windows-powershell\/","title":{"rendered":"Weekend Scripter: Boot Tracing with Windows PowerShell"},"content":{"rendered":"

Microsoft Scripting Guy Ed Wilson here. There used to be a really cool tool available in the Windows Driver Development Kit (DDK)<\/span><\/span><\/a> that was called bootvis.exe. I used to use it to create a boot trace for my Windows XP computer. This tool was useful because it would let you know which drivers were taking a long time to load. Unfortunately, there is no such tool (that I know of) for Windows 7. <\/p>\n

<\/span><\/p>\n

I was reflecting on the absence of such a tool this morning when I turned on the laptop that belongs to the female who inhabits my humble abode in Charlotte. I waited for a seemingly interminable amount of time to log on to the machine. I decided to open a Windows PowerShell prompt, list all of the processes, and sort by start time. When doing this, I had to open the Windows PowerShell prompt as an administrator because the starttime<\/b> of some processes is protected from non-elevated users. Even with running the Windows PowerShell console as an administrator, several “Access Denied” errors are raised. These are for system processes such as system<\/b>, idle<\/b>, and the audiodg<\/b> process. If the errors bother you, you can hide them by specifying an error action of silentlycontinue<\/b>. The alias for this property is EA<\/b>, and it must be supplied to the Sort-Object<\/b> cmdlet as shown here. I use the sort<\/b> alias for the Sort-Object<\/b> cmdlet, and the ft<\/b> alias for Format-Table<\/b> cmdlet. <\/p>\n

<\/span><\/p>\n

PS C:Windowssystem32> Get-Process | sort startTime -ea silentlycontinue | ft name,
starttime –AutoSize<\/span><\/span><\/span><\/p>\n

<\/p>\n

<\/span><\/span><\/span><\/p>\n

Here is the complete output (with the errors that arise):<\/p>\n

<\/span><\/p>\n

PS C:Windowssystem32> Get-Process | sort startTime | ft name, starttime -AutoSize
Sort-Object : Exception getting “StartTime”: “Access is denied”
At line:1 char:19
+ Get-Process | sort <<<<  <\/span>startTime | ft name, starttime -AutoSize
    <\/span>+ CategoryInfo          <\/span>: InvalidResult: (System.Diagnostics.Process (audiodg):
   <\/span>PSObject) [Sort-Object], GetValueInvocationException
    <\/span>+ FullyQualifiedErrorId : ExpressionEvaluation,Microsoft.PowerShell.Commands.So
   <\/span>rtObjectCommand<\/p>\n

Sort-Object : Exception getting “StartTime”: “Access is denied”
At line:1 char:19
+ Get-Process | sort <<<<  <\/span>startTime | ft name, starttime -AutoSize
    <\/span>+ CategoryInfo          <\/span>: InvalidResult: (System.Diagnostics.Process (Idle):PSO
   <\/span>bject) [Sort-Object], GetValueInvocationException
    <\/span>+ FullyQualifiedErrorId : ExpressionEvaluation,Microsoft.PowerShell.Commands.So
   <\/span>rtObjectCommand<\/p>\n

Sort-Object : Exception getting “StartTime”: “Access is denied”
At line:1 char:19
+ Get-Process | sort <<<<  <\/span>startTime | ft name, starttime -AutoSize
    <\/span>+ CategoryInfo          <\/span>: InvalidResult: (System.Diagnostics.Process (System):P
   <\/span>SObject) [Sort-Object], GetValueInvocationException
    <\/span>+ FullyQualifiedErrorId : ExpressionEvaluation,Microsoft.PowerShell.Commands.So
   <\/span>rtObjectCommand<\/p>\n

Name                       <\/span>StartTime
—-                       <\/span>———
audiodg
Idle
System
smss                       <\/span>8\/2\/2010 8:48:57 AM
csrss                      <\/span>8\/2\/2010 8:49:01 AM
wininit                    <\/span>8\/2\/2010 8:49:02 AM
csrss                      <\/span>8\/2\/2010 8:49:02 AM
services                   <\/span>8\/2\/2010 8:49:02 AM
lsm                        <\/span>8\/2\/2010 8:49:02 AM
lsass                      <\/span>8\/2\/2010 8:49:02 AM
winlogon           <\/span>        <\/span>8\/2\/2010 8:49:03 AM
svchost                    <\/span>8\/2\/2010 8:49:03 AM
svchost                    <\/span>8\/2\/2010 8:49:03 AM
MsMpEng                    <\/span>8\/2\/2010 8:49:03 AM
atiesrxx                   <\/span>8\/2\/2010 8:49:03 AM
svchost                    <\/span>8\/2\/2010 8:49:03 AM
svchost                    <\/span>8\/2\/2010 8:49:03 AM
svchost                    <\/span>8\/2\/2010 8:49:03 AM
svchost                    <\/span>8\/2\/2010 8:49:05 AM
svchost                    <\/span>8\/2\/2010 8:49:05 AM
atieclxx                   <\/span>8\/2\/2010 8:49:05 AM
spoolsv       <\/span>             <\/span>8\/2\/2010 8:49:05 AM
svchost                    <\/span>8\/2\/2010 8:49:05 AM
PhotoshopElementsFileAgent 8\/2\/2010 8:49:06 AM
svchost                    <\/span>8\/2\/2010 8:49:06 AM
Iap                        <\/span>8\/2\/2010 8:49:06 AM
inetinfo                   <\/span>8\/2\/2010 8:49:06 AM
LMS                        <\/span>8\/2\/2010 8:49:06 AM
mdm                        <\/span>8\/2\/2010 8:49:06 AM
MSCamS64                   <\/span>8\/2\/2010 8:49:06 AM
svchost                    <\/span>8\/2\/2010 8:49:06 AM
svchost                    <\/span>8\/2\/2010 8:49:06 AM
UNS      <\/span>                  <\/span>8\/2\/2010 8:49:06 AM
WLIDSVC                    <\/span>8\/2\/2010 8:49:07 AM
DCPSysMgrSvc               <\/span>8\/2\/2010 8:49:07 AM
IAANTmon                   <\/span>8\/2\/2010 8:49:07 AM
WmiPrvSE                   <\/span>8\/2\/2010 8:49:07 AM
SearchIndexer              <\/span>8\/2\/2010 8:49:08 AM
svchost                    <\/span>8\/2\/2010 8:49:08 AM
WmiPrvSE                   <\/span>8\/2\/2010 8:49:09 AM
WLIDSVCM                   <\/span>8\/2\/2010 8:49:09 AM
taskhost                   <\/span>8\/2\/2010 8:50:05 AM
dwm                        <\/span>8\/2\/2010 8:50:05 AM
explorer                   <\/span>8\/2\/2010 8:50:05 AM
ipoint                     <\/span>8\/2\/2010 8:50:06 AM
IAAnotif                   <\/span>8\/2\/2010 8:50:06 AM
Dell.ControlPoint          <\/span>8\/2\/2010 8:50:07 AM
msseces                    <\/span>8\/2\/2010 8:50:07 AM
ZuneLauncher             <\/span>  <\/span>8\/2\/2010 8:50:07 AM
DCPSysMgr                  <\/span>8\/2\/2010 8:50:07 AM
dpupdchk                   <\/span>8\/2\/2010 8:50:07 AM
smax4pnp                   <\/span>8\/2\/2010 8:50:07 AM
MOM                        <\/span>8\/2\/2010 8:50:08 AM
CCC                        <\/span>8\/2\/2010 8:50:09 AM<\/span><\/span><\/span><\/p>\n

<\/p>\n

<\/span><\/span><\/span><\/p>\n

The thing I was looking for in the sorted list is the first process to start up. That is the smss<\/b> process. Taskhost<\/b> seems to be the first process that runs after you press Ctrl+Alt+Delete to log on. Next the dwm<\/b> (dynamic windows manager) process runs, and finally the explorer<\/b> process runs, which displays the desktop. Depending on the computer, either the SearchIndexer<\/b>, svchost<\/b>, WmiPrvSE<\/b>, or some other program may be the last process that starts up before you attempt to log on to the computer. Using this information, you can characterize the startup of the computer. <\/p>\n

<\/span><\/p>\n

For comparison purposes, you should not use the explorer<\/b> process because that runs after you have logged onto the computer, which means that speed of typing, network latency, and processor utilization on the domain controller can all play a part in the presentation of the desktop. Because different computers may have different drivers, using the SearchIndexer<\/b> as the last boot process seems to be a relatively safe point. <\/p>\n

<\/span><\/p>\n

Wait just a few minutes. It seems I am going to be awhile, and Teresa has a tendency to get grumpy if I am using her computer when she comes down in the morning. She always says something like, “You have a dozen computers upstairs. Why can’t you leave mine alone?” <\/p>\n

<\/span><\/p>\n

Okay, I am upstairs now on my computer. Here is the bootup time from my desktop machine:<\/p>\n

<\/span><\/p>\n

PS C:Windowssystem32> $smss = $proc | ? {$_.name -eq “smss”}
PS C:Windowssystem32> $search = $proc | ? {$_.name -eq “SearchIndexer”}
PS C:Windowssystem32> $search.StartTime – $smss.StartTime<\/p>\n

Days              <\/span>: 0
Hours             <\/span>: 0
Minutes           <\/span>: 0
Seconds           <\/span>: 10
Milliseconds      <\/span>: 940
Ticks             <\/span>: 109400189
TotalDays         <\/span>: 0.00012662058912037
TotalHours        <\/span>: 0.00303889413888889
TotalMinutes    <\/span>  <\/span>: 0.182333648333333
TotalSeconds      <\/span>: 10.9400189
TotalMilliseconds : 10940.0189<\/p>\n

PS C:Windowssystem32><\/span><\/span><\/span><\/p>\n

<\/p>\n

<\/span><\/span><\/span><\/p>\n

One of the things that is fun to do is to reboot the computer, and after logging on, start the Windows PowerShell console as an administrator and store the processes every minute or so for a few minutes. Do not start any processes other than Windows PowerShell. The results can be pretty interesting. After you have four samples, compare the number of processes that are running. The results from my computer are seen here:<\/p>\n

<\/span><\/p>\n

PS C:Windowssystem32> $proc = gps
PS C:Windowssystem32> $proc1 = gps
PS C:Windowssystem32> $proc2 = gps
PS C:Windowssystem32> $proc3 = gps
PS C:Windowssystem32> $proc4 = gps
PS C:Windowssystem32> $proc.Count
64
PS C:Windowssystem32> $proc1.Count
64
PS C:Windowssystem32> $proc2.Count
60
PS C:Windowssystem32> $proc3.Count
59
PS C:Windowssystem32> $proc4.Count
58
PS C:Windowssystem32><\/span><\/span><\/span><\/p>\n

<\/p>\n

<\/span><\/span><\/span><\/p>\n

On my computer 6 processes went away between the initial logon and logon + 4 minutes. To find the names of the processes, use the compare-object cmdlet as seen here.<\/p>\n

<\/span><\/p>\n

PS C:Windowssystem32> Compare-Object -ReferenceObject $proc -DifferenceObject $proc
4<\/p>\n

InputObject                                <\/span>SideIndicator
———–               <\/span>                 <\/span>————-
System.Diagnostics.Process (PIconStartup)  <\/span><=
System.Diagnostics.Process (SearchFilte… <=
System.Diagnostics.Process (SearchProto… <=
System.Diagnostics.Process (SearchProto… <=
System.Diagnostics.Process (sppsvc)      <\/span>  <\/span><=
System.Diagnostics.Process (userinit)      <\/span><=<\/p>\n

PS C:Windowssystem32><\/span><\/span><\/span><\/p>\n

<\/p>\n

<\/span><\/span><\/span><\/p>\n

If you are interested in which processes start after logon, you can store the taskhost<\/b> process in a variable, and then pipe the results of the last process snapshot. Use the Where-Object<\/b> cmdlet (?<\/b> Is the alias) to look for processes that start after the taskhost<\/b> process. Sort by company name, and then print a table (ft<\/b> is alias for Format-Table<\/b>) that includes the name of the process, the company name, and the product description. This command is shown here: <\/p>\n

<\/span><\/p>\n

PS C:Windowssystem32> $task = $proc | ? { $_.name -eq ‘taskhost’}
PS C:Windowssystem32> $proc4 | ? { $_.startTime -gt $task.starttime} | sort company
| ft name, company, product -auto<\/p>\n

Name              <\/span>Company              <\/span>       <\/span>Product
—-              <\/span>——-                     <\/span>——-
apdproxy          <\/span>Adobe Systems Incorporated  <\/span>Adobe Photo Downloader 4.0 component
MOM               <\/span>Advanced Micro Devices Inc. Catalyst Control Centre
smax4pnp          <\/span>Analog Devices, Inc.        <\/span>SMax4PNP Application
CCC               <\/span>ATI Technologies Inc.       <\/span>Catalyst Control Centre
DCPSysMgr         <\/span>Dell Inc.                   <\/span>Dell ControlPoint System Manager
Dell.ControlPoint Dell Inc.                   <\/span>Dell ControlPoint
IAAnotif  <\/span>        <\/span>Intel Corporation           <\/span>RAID Event Monitor
WmiPrvSE          <\/span>Microsoft Corporation       <\/span>Microsoftr Windowsr Operating System
msseces           <\/span>Microsoft Corporation       <\/span>Microsoft Security Essentials
ZuneLauncher      <\/span>Microsoft Corporation   <\/span>    <\/span>Zuner
powershell        <\/span>Microsoft Corporation       <\/span>Microsoftr Windowsr Operating System
dpupdchk          <\/span>Microsoft Corporation       <\/span>Microsoft IntelliPoint
conhost           <\/span>Microsoft Corporation       <\/span>Microsoftr Windowsr Operating System
dwm        <\/span>       <\/span>Microsoft Corporation       <\/span>Microsoftr Windowsr Operating System
ipoint            <\/span>Microsoft Corporation       <\/span>Microsoft IntelliPoint
explorer          <\/span>Microsoft Corporation       <\/span>Microsoftr Windowsr Operating System<\/p>\n

PS C:Windowssystem32><\/span><\/span><\/span><\/p>\n

<\/p>\n

<\/span><\/span><\/span><\/p>\n

This output is shown in the following image.<\/p>\n

<\/span><\/p>\n

<\/span><\/p>\n

 <\/p>\n

<\/span><\/p>\n

Tomorrow I will expand on this concept and perhaps write a script to automate some of the manual computations. We invite you to follow us on Twitter<\/span><\/span><\/a> or <\/span>Facebook<\/span><\/span><\/a><\/span>. If you have any questions, send email to us at scripter@microsoft.com<\/span><\/span><\/a>, or post your questions on the Official Scripting Guys Forum<\/span><\/span><\/a>. See you tomorrow. Until then, peace.<\/p>\n

<\/span><\/p>\n

 <\/p>\n

<\/span>\nEd Wilson and Craig Liebendorfer, Scripting Guys<\/p>\n

<\/span><\/b><\/p>\n

<\/span><\/b><\/p>\n","protected":false},"excerpt":{"rendered":"

Microsoft Scripting Guy Ed Wilson here. There used to be a really cool tool available in the Windows Driver Development Kit (DDK) that was called bootvis.exe. I used to use it to create a boot trace for my Windows XP computer. This tool was useful because it would let you know which drivers were taking […]<\/p>\n","protected":false},"author":595,"featured_media":87096,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"_acf_changed":false,"footnotes":""},"categories":[1],"tags":[31,87,3,61,45],"class_list":["post-17501","post","type-post","status-publish","format-standard","has-post-thumbnail","hentry","category-scripting","tag-operating-system","tag-processes","tag-scripting-guy","tag-weekend-scripter","tag-windows-powershell"],"acf":[],"blog_post_summary":"

Microsoft Scripting Guy Ed Wilson here. There used to be a really cool tool available in the Windows Driver Development Kit (DDK) that was called bootvis.exe. I used to use it to create a boot trace for my Windows XP computer. This tool was useful because it would let you know which drivers were taking […]<\/p>\n","_links":{"self":[{"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/posts\/17501","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/users\/595"}],"replies":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/comments?post=17501"}],"version-history":[{"count":0,"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/posts\/17501\/revisions"}],"wp:featuredmedia":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/media\/87096"}],"wp:attachment":[{"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/media?parent=17501"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/categories?post=17501"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/tags?post=17501"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}