Recently Microsoft support has fielded inquiries from several customers asking how to troubleshoot problems that cause delays during the boot and user logon processes on a desktop or laptop. The Windows Performance Toolkit xbootmgr.exe tool works well for troubleshooting boot and startup issues on a single machine. (See "Diagnose Shutdown Problems with Xbootmgr" for more information about using xbootmgr.exe.) But what if you're a large enterprise with thousands of desktops? You need a way to identify problem machines before a user reports them to the Help desk. You need to monitor desktop startup times over time and across the enterprise. And you need a way to collect boot time measurements, similar to those collected by xbootmgr.exe, from every machine for every boot. Here, I'll explain how you can use an event log, the new Windows 7 Event Viewer, and the Wevtutil tool to do these things.
A New Event Log to Aid in Troubleshooting
Beginning with Windows Vista, Windows now includes a new category of event logs: Applications and Services logs. The infrastructure underlying event logging now conforms to an XML schema. You can easily access the XML data for any event. The new event log interface lets you construct XML-based queries against event logs. The Event Viewer gives you to access to the new XML functionality in an easy-to-use graphical interface.
One of the logs in this new category is the Diagnostics-Performance/Operational log. This log contains events that record performance measurements similar to those provided by xbootmgr.exe. In fact, the data recorded is generated by the same mechanisms that Xbootmgr uses. Event IDs 100 through 110 record boot and startup performance statistics.
Using the Event Viewer in Windows 7
The new Event Viewer in Windows 7 lets you do more powerful filtering. The new UI lets you specify ranges of events. Under the covers, it builds the XPath query to filter out the events based on the criteria you specify. Figure 1 shows how you can filter for events 100 through 110. Figure 2 shows the XML version of the same query parameters. We're interested in Event ID 100 for the purposes of measuring the boot performance. Figure 3 and Figure 4 show the normal and XML views for event 100.
The XML presentation of the event contains a lot of interesting information. The BootTime value represents the number of milliseconds that elapsed from the time the system booted to the point after the user logged in that the system reached 80 percent idle for 10 seconds. The other time values listed represent the elapsed time for various stages during this boot process. You can find more information about the stages of the boot process in the Windows On/Off Transition Performance Analysis white paper.
The other boot performance events record information about specific events that contributed to delays during the boot/startup sequence. The trick is how to know which boot instance these messages belong to. This is where the ActivityID come in handy. In Figure 4, you'll see the following in the XML data:
<Correlation ActivityID="{00000001-0000-0000-1020-5CA87BB1CA01}" />
All events related to this boot instance in this Event 100 record have this same ActivityID. By performing the following steps, we can use this information to create a more complex filter:
1. Click Filter Current Log… in the Actions Pane of Event Viewer.
2. On the XML tab, check the box Edit query manually, then answer Yes when prompted to continue.
3. Enter the following XML text into the query box:
<QueryList>
<Query Id="0" Path="Microsoft-Windows-Diagnostics-Performance/Operational">
<Select Path="Microsoft-Windows-Diagnostics-Performance/Operational">*[System\[(Correlation\[@ActivityID="{00000001-0000-0000-1020-5CA87BB1CA01}"])]]</Select>
</Query>
</QueryList>
4. Click OK.
Figure 5 shows a total of three events for this ActivityID. We can now examine these events to understand the problems that contributed to any boot/startup delays.