August 7th, 2010

Weekend Scripter: Boot Tracing with Windows PowerShell

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 a long time to load. Unfortunately, there is no such tool (that I know of) for Windows 7.

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 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, idle, and the audiodg process. If the errors bother you, you can hide them by specifying an error action of silentlycontinue. The alias for this property is EA, and it must be supplied to the Sort-Object cmdlet as shown here. I use the sort alias for the Sort-Object cmdlet, and the ft alias for Format-Table cmdlet.

PS C:Windowssystem32> Get-Process | sort startTime -ea silentlycontinue | ft name,
starttime –AutoSize

Here is the complete output (with the errors that arise):

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 <<<<  startTime | ft name, starttime -AutoSize
    + CategoryInfo          : InvalidResult: (System.Diagnostics.Process (audiodg):
   PSObject) [Sort-Object], GetValueInvocationException
    + FullyQualifiedErrorId : ExpressionEvaluation,Microsoft.PowerShell.Commands.So
   rtObjectCommand

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

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

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

The thing I was looking for in the sorted list is the first process to start up. That is the smss process. Taskhost seems to be the first process that runs after you press Ctrl+Alt+Delete to log on. Next the dwm (dynamic windows manager) process runs, and finally the explorer process runs, which displays the desktop. Depending on the computer, either the SearchIndexer, svchost, WmiPrvSE, 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.

For comparison purposes, you should not use the explorer 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 as the last boot process seems to be a relatively safe point.

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?”

Okay, I am upstairs now on my computer. Here is the bootup time from my desktop machine:

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

Days              : 0
Hours             : 0
Minutes           : 0
Seconds           : 10
Milliseconds      : 940
Ticks             : 109400189
TotalDays         : 0.00012662058912037
TotalHours        : 0.00303889413888889
TotalMinutes      : 0.182333648333333
TotalSeconds      : 10.9400189
TotalMilliseconds : 10940.0189

PS C:Windowssystem32>

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:

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>

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.

PS C:Windowssystem32> Compare-Object -ReferenceObject $proc -DifferenceObject $proc
4

InputObject                                SideIndicator
———–                                ————-
System.Diagnostics.Process (PIconStartup)  <=
System.Diagnostics.Process (SearchFilte… <=
System.Diagnostics.Process (SearchProto… <=
System.Diagnostics.Process (SearchProto… <=
System.Diagnostics.Process (sppsvc)        <=
System.Diagnostics.Process (userinit)      <=

PS C:Windowssystem32>

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

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

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

PS C:Windowssystem32>

This output is shown in the following image.

 

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 or Facebook. If you have any questions, send email to us at scripter@microsoft.com, or post your questions on the Official Scripting Guys Forum. See you tomorrow. Until then, peace.

 

Ed Wilson and Craig Liebendorfer, Scripting Guys

Author

0 comments

Discussion are closed.