Jump to content

Trace Windows 7 boot/shutdown/hibernate/standby/resume issues


MagicAndre1981
 Share

Recommended Posts

 

help

 

- <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-27T00:24:29.585781500Z" />
  <EventRecordID>1337</EventRecordID>
  <Correlation ActivityID="{8F7DA2B4-A930-0005-C9A2-7D8F30A9CF01}" />
  <Execution ProcessID="1336" ThreadID="1636" />
  <Channel>Microsoft-Windows-Diagnostics-Performance/Operational</Channel>
  <Computer>Mubarak-PC</Computer>
  <Security UserID="S-1-5-19" />
  </System>
- <EventData>

  <Data Name="BootTime">156908</Data>
  <Data Name="MainPathBootTime">88108</Data>

  <Data Name="BootMachineProfileProcessingTime">4481</Data>
  <Data Name="BootExplorerInitTime">47949</Data>
  <Data Name="BootNumStartupApps">20</Data>
  <Data Name="BootPostBootTime">68800</Data>
  <Data Name="UserLogonWaitDuration">36269</Data>

 

Your Windows needs 156s to boot. Long delays happen during Explorer load and starting all startup tools.

 

capture a trace with this command:

 

xbootmgr -trace boot -traceFlags BASE+LATENCY+DISPATCHER+FILE_IO+FILENAME -stackwalk profile+CSwitch+ReadyThread -resultPath C:\TEMP

 

zip and upload the generated ETL file.

Link to comment
Share on other sites

  • 2 weeks later...

[ origin: http://forum.sysinternals.com/topic30672.html ]

 

Thank you, Andre. That's an interesting tutorial you've put together there … completely new to me!

 
So I installed the Performance Tools (from the 8.1 distro) on the old platter disk, configured Windows Auto Logon, and issued the boot log command:
 
xbootmgr -trace boot -resultPath C:\
 
I omitted the -traceFlags BASE+CSWITCH+DRIVERS+POWER because it would error out although I had already increased the HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Control\WMI\Autologger\ReadyBoot\MaxFileSize Parameter to 100 MB.
 
05.08.2014  17:30         3.641.720 boot_BASE+CSWITCH_1.cab
05.08.2014  17:30        93.323.264 boot_BASE+CSWITCH_1.etl
05.08.2014  17:36           143.793 boot_BASE+CSWITCH_1.summary.XML
 
The timing node in the XML summary has the following attributes (values in milliseconds):
 
bootDoneViaExplorer="37886"
bootDoneViaPostBoot="59686"
osLoaderDuration="2688"
postBootRequiredIdleTime="10000"
postBootDisturbance="11800"
pnpBootStartStartTime="110"
pnpBootStartEndTime="1991"
pnpBootStartDuration="1882"
pnpSystemStartStartTime="5039"
pnpSystemStartEndTime="21405"
pnpSystemStartDuration="16365"

At just 60 seconds, this reads much better than what the eventvwr has to say, which is more than 100 seconds. Maybe that's because of the Auto logon? The following Quote from the site you linked to seems to confirm this assumption:

»If auto-logon is not enabled, the time that elapses while the logon screen is displayed affects the measured boot time in a trace.«
 
Interval data:
 
interval name="PreSMSS" startTime="0" endTime="21416" duration="21416">
interval name="SMSSInit" startTime="21416" endTime="28522" duration="7106">
interval name="WinlogonInit" startTime="28522" endTime="33735" duration="5214">
interval name="ExplorerInit" startTime="33735" endTime="37886" duration="4151">
interval name="PostExplorerPeriod" startTime="37886" endTime="59686" duration="21800">
interval name="TraceTail" startTime="59686" endTime="165778" duration="106092">

Maybe this is not too bad after all for a laptop running a 2010 Intel dual-core i5-430 and a 1 TB 5400 U/min platter disk? I just read your tutorial page and the first two pages of comments, so I'm not aware of what might have been said in this huge thread …
 
Anyway, guess I need to repeat that test on the SSD copy of my system. Have already run it once, but without auto logon, which I think (see above) skews the result.
Link to comment
Share on other sites

First, this is a new boot log obtained by doing the bootPrep sequence (but without having installed the recommended hotfixes).

 

    <timing bootDoneViaExplorer="36204" bootDoneViaPostBoot="59004" osLoaderDuration="2988"
            postBootRequiredIdleTime="10000" postBootDisturbance="12800"
            pnpBootStartStartTime="110" pnpBootStartEndTime="1975" pnpBootStartDuration="1865"
            pnpSystemStartStartTime="4989" pnpSystemStartEndTime="21257" pnpSystemStartDuration="16268">
 

Second, the slow items are the same as in my Procmon log, the three RDP related drivers:

 

      <phase name="systemStart" startTime="4989" endTime="21257" duration="16268">

        <pnpObject name="RDPENCDD" type="Driver" activity="Load"
                   startTime="10655" endTime="15947" duration="5292" prePendTime="5292"/>
        <pnpObject name="\REGISTRY\MACHINE\SYSTEM\ControlSet001\services\RDPENCDD" type="unknown" activity="unknown"
                   startTime="10658" endTime="15947" duration="5289" prePendTime="5289"/>

        <pnpObject name="RDPCDD" type="Driver" activity="Load"
                   startTime="5461" endTime="10654" duration="5194" prePendTime="5194"/>
        <pnpObject name="\REGISTRY\MACHINE\SYSTEM\ControlSet001\services\RDPCDD" type="unknown" activity="unknown"
                   startTime="5464" endTime="10654" duration="5191" prePendTime="5191"/>

        <pnpObject name="RDPREFMP" type="Driver" activity="Load"
                   startTime="15947" endTime="21132" duration="5185" prePendTime="5185"/>
        <pnpObject name="\REGISTRY\MACHINE\SYSTEM\ControlSet001\services\RDPREFMP" type="unknown" activity="unknown"
                   startTime="15951" endTime="21132" duration="5182" prePendTime="5182"/>

        <pnpObject name="cdrom" type="Driver" activity="Load"
                   startTime="5017" endTime="5444" duration="427" prePendTime="427"/>

 

Third, I'm attaching three screenshots. They show 370 MB of "Unknown" disk reads. I assume this is Prefetch? (Looks like only the first screenshot made it to the server. Will see if I can add the other two somehow.)

 

Path_Name_Unknown_3.png

 

Path_Name_Unknown_4_Prefetch.png
 

post-396277-0-26869800-1407406592_thumb.

Edited by Lumi
Link to comment
Share on other sites

I installed the Hotfix Rollup and the three updates required as per the Hotfix Notice.

http://support.microsoft.com/kb/2775511/en-us

KB 2732673, 2728738, 2878378

Rebooted as required, then requested another boot log:

xbootmgr -trace boot -resultPath C:\XBootMgr3

The result is here:

 

interval name="PreSMSS" startTime="0" endTime="28453" duration="28453">
interval name="SMSSInit" startTime="28453" endTime="35494" duration="7041">
interval name="WinlogonInit" startTime="35494" endTime="41581" duration="6087">
interval name="ExplorerInit" startTime="41581" endTime="44898" duration="3317">
interval name="PostExplorerPeriod" startTime="44898" endTime="71498" duration="26600">
interval name="TraceTail" startTime="71498" endTime="176652" duration="105153">

 

PreSMSS increased by about seven seconds. The reason is the freshly hotfixed rdbss.sys, which now leads the ranking of sluggy drivers. No significant change for the RDP drivers.

 

        <pnpObject name="rdbss" type="Driver" activity="Load"
                   startTime="19955" endTime="28408" duration="8452" prePendTime="8452"/>
        <pnpObject name="RDPREFMP" type="Driver" activity="Load"
                   startTime="14698" endTime="19866" duration="5168" prePendTime="5168"/>
        <pnpObject name="\REGISTRY\MACHINE\SYSTEM\ControlSet001\services\RDPREFMP" type="unknown" activity="unknown"
                   startTime="14701" endTime="19866" duration="5165" prePendTime="5165"/>
        <pnpObject name="RDPCDD" type="Driver" activity="Load"
                   startTime="4697" endTime="9698" duration="5000" prePendTime="5000"/>
        <pnpObject name="RDPENCDD" type="Driver" activity="Load"
                   startTime="9698" endTime="14698" duration="5000" prePendTime="5000"/>
        <pnpObject name="\REGISTRY\MACHINE\SYSTEM\ControlSet001\services\RDPCDD" type="unknown" activity="unknown"
                   startTime="4700" endTime="9698" duration="4997" prePendTime="4997"/>
        <pnpObject name="\REGISTRY\MACHINE\SYSTEM\ControlSet001\services\RDPENCDD" type="unknown" activity="unknown"
                   startTime="9701" endTime="14698" duration="4997" prePendTime="4997"/>
        <pnpObject name="cdrom" type="Driver" activity="Load"
                   startTime="4249" endTime="4682" duration="432" prePendTime="432"/>

 

Guess the Hotfix Rollup was not needed, after all, and I'll have to take a look at the Procmon log. Other ideas?

 

Update: Back to my original SysInternals Procmon forum post.
 

Edited by Lumi
Link to comment
Share on other sites

Can this or some method be used to trace or log issues if Windows does not even enter SafeMode (screen freezes at classpnp.sys / disk.sys - culprit is probably next item but not visible) in Native Boot VHD but same VHD works inside VMWare?

Link to comment
Share on other sites

For boot tracing:

xbootmgr -trace boot -traceFlags BASE+CSWITCH+DRIVERS+POWER -resultPath C:\TEMP

Attention: Some users reported that they get a bugcheck (BSOD) when using the DRIVERS flag in the boot trace command. If you get this, use system restore to go back to a working Windows and run the command without DRIVERS

xbootmgr -trace boot -traceFlags BASE+CSWITCH+POWER -resultPath C:\TEMP

 

Or boot in Safe Mode and type this in an elevated command prompt,

xbootmgr -remove

then reboot.    (this was not funny) :puke:

Link to comment
Share on other sites

Can this or some method be used to trace or log issues if Windows does not even enter SafeMode (screen freezes at classpnp.sys / disk.sys - culprit is probably next item but not visible) in Native Boot VHD but same VHD works inside VMWare?

You can determine what the next "invisible" item is by doing a step-by-step boot.

  • Upvote 1
Link to comment
Share on other sites

 

Can this or some method be used to trace or log issues if Windows does not even enter SafeMode (screen freezes at classpnp.sys / disk.sys - culprit is probably next item but not visible) in Native Boot VHD but same VHD works inside VMWare?

You can determine what the next "invisible" item is by doing a step-by-step boot.

 

Step by Step is only an option in Windows 98. 

http://www.computerhope.com/issues/chsafe.htm 

 

Which option would I choose from here for Windows 7? Once I find driver thats causing issue, what do I do next? 

Link to comment
Share on other sites

  • 3 weeks later...

Hello MagicAndre

 

my laptop doesn't want anymore to go to hibernate state

 

it comes again to login screen 10 seconds after hibernate

 

I think it's after an update but even the system restore doesn't fix the trouble

I try many things found on google without success

 

 

I run these 2 commands :xbootmgr -trace hibernate -traceFlags BASE+CSWITCH+DRIVERS+P
OWER -resultPath C:\TEMP

xperf /tti -i c:\temp\hibernate_BASE+CSWITCH+DRIVERS+POWER_1
.etl -o c:\temp\summary_hibernation.xml -a suspend

 

 

here is the etl file :  https://www.mediafire.com/folder/1tr5ctbk7oa11/Documents

 

the xml file shows nothing :

<?xml version="1.0"?>

-<suspend min_reported="0" time_precision="us" time_unit="us">

<scenario resume="-0" resumecritical="-0" suspend="-0" duration="-0" start="242603"/>

</suspend>

 

 

can you find something wrong in the file please ?

 

 

best regards

Link to comment
Share on other sites

  • 1 month later...

Hello. I use GT70 barebone laptop. The laptop has two same 7200 RPM HDDs. One for the system and other for the storage purpose.

I have a big problem with Windows 7's desktop boot time. As mentioned, the OS (Windows 7 SP1 Ultimate x64, MSDN version, no UEFI) has installed into relatively fast 7200 RPM HDD (Here its bench results: http://i.imgur.com/9BV76p0.png).

It boots fine about 20-22 sec until Welcome Screen appears. Then it waits for 30 sec to get desktop. It is extremely troublesome. Even my old desktop doesn't hang at Welcome Screen that much.

You can clearly see the delay at my video:

http://www.youtube.com/watch?v=Vs48xfuY2Q8

MSConfig is clean, there is only touchpad and sidebars in startup. Task scheduler is clean too. I also disabled all the services except Microsoft's from MSConfig and restart but it had no posivite effect.

I also heard that there is a bug. If the background is set to solid color then it waits 30 seconds to get desktop. I don't use solid color background, as you can see in my video I use Windows 7's wallpaper. I tried Microsoft's hotfix for it but it gives me error that this hotfix is not for my system so I understand from that SP1 already has this hotfix.

This situation has been there all the time since I bought this laptop. I don't know what to do. I'm humbly asking for your help. I will be very appreciated. Thank you very much.

 

summary_boot.xml file:

 

https://www.mediafire.com/?kad8mwq5p8cqapl

 

Full boot trace etl file:

 

http://www.mediafire.com/download/97tgph0hd99ayay/boot_LATENCY+DISPATCHER+DISK_IO_INIT+NETWORKTRACE+MEMINFO+POWER+PERF_COUNTER+PRIORITY+REGISTRY+FILE_IO+FILE_IO_INIT_1.7z

Link to comment
Share on other sites

your HDD is still the bottleneck. The queue depth at disk IO init is still over 60 (everything over 10 is bad).

 

I also see some delay by the driver btath_a2dp.sys, btfilter.sys and btath_bus.sys (Bluetooth drivers?) , DeepFrz.sys and ATHR.SYS (Atheros wifi driver). Update all remove not needed ones and look if this improves boot a bit.

  • Upvote 1
Link to comment
Share on other sites

Create an account or sign in to comment

You need to be a member in order to leave a comment

Create an account

Sign up for a new account in our community. It's easy!

Register a new account

Sign in

Already have an account? Sign in here.

Sign In Now
 Share

  • Recently Browsing   0 members

    • No registered users viewing this page.


×
×
  • Create New...