Jump to content

Welcome to MSFN Forum
Register now to gain access to all of our features. Once registered and logged in, you will be able to create topics, post replies to existing threads, give reputation to your fellow members, get your own private messenger, post status updates, manage your profile and so much more. This message will be removed once you have signed in.
Login to Account Create an Account


Photo

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

slow Boot bootvis performance

  • Please log in to reply
1212 replies to this topic

#1201
MagicAndre1981

MagicAndre1981

    after Windows 7 GA still Vista lover :)

  • Patrons
  • 5,993 posts
  • OS:Vista Ultimate x86
  • Country: Country Flag

Donator

 

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.


Posted Image


How to remove advertisement from MSFN

#1202
Lumi

Lumi
  • Member
  • 3 posts
  • OS:Windows 7 x64
  • Country: Country Flag

[ origin: http://forum.sysinte...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.


#1203
MagicAndre1981

MagicAndre1981

    after Windows 7 GA still Vista lover :)

  • Patrons
  • 5,993 posts
  • OS:Vista Ultimate x86
  • Country: Country Flag

Donator

PreSMSS is very slow. Open the XML and look under PNP which devices/drivers are slow to start.


Posted Image

#1204
Lumi

Lumi
  • Member
  • 3 posts
  • OS:Windows 7 x64
  • Country: Country Flag

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
 

Attached Files


Edited by Lumi, 07 August 2014 - 04:24 AM.


#1205
MagicAndre1981

MagicAndre1981

    after Windows 7 GA still Vista lover :)

  • Patrons
  • 5,993 posts
  • OS:Vista Ultimate x86
  • Country: Country Flag

Donator

Unknown (0x0) = Caching

 

Try the linked Hotfix Rollup which fixes a lot of issues. It may fixes the RDP issue.


Posted Image

#1206
Lumi

Lumi
  • Member
  • 3 posts
  • OS:Windows 7 x64
  • Country: Country Flag

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

http://support.micro...b/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, 07 August 2014 - 12:45 PM.


#1207
crashnburn4u

crashnburn4u

    Newbie

  • Member
  • 34 posts
  • OS:none specified
  • Country: Country Flag

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?



#1208
Ponch

Ponch

    MSFN Junkie

  • Patrons
  • 3,265 posts
  • OS:none specified
  • Country: Country Flag

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:



#1209
Tripredacus

Tripredacus

    K-Mart-ian Legend

  • Super Moderator
  • 9,766 posts
  • OS:Server 2012
  • Country: Country Flag

Donator

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.
  • crashnburn4u likes this
MSFN RULES | GimageX HTA for PE 3-5 | lol probloms
msfn2_zpsc37c7153.jpg

#1210
crashnburn4u

crashnburn4u

    Newbie

  • Member
  • 34 posts
  • OS:none specified
  • Country: Country Flag

 

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.computerh...ues/chsafe.htm 

 

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



#1211
Tripredacus

Tripredacus

    K-Mart-ian Legend

  • Super Moderator
  • 9,766 posts
  • OS:Server 2012
  • Country: Country Flag

Donator

Well, I guess I haven't had to do that in some time then! :blushing:

 

You can try enabling boot logging, but in my experience sometimes the file isn't helpful.


MSFN RULES | GimageX HTA for PE 3-5 | lol probloms
msfn2_zpsc37c7153.jpg

#1212
ldd11

ldd11
  • Member
  • 1 posts
  • OS:Windows 7 x86
  • Country: Country Flag

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.mediafir...7oa11/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



#1213
MagicAndre1981

MagicAndre1981

    after Windows 7 GA still Vista lover :)

  • Patrons
  • 5,993 posts
  • OS:Vista Ultimate x86
  • Country: Country Flag

Donator

xbootmgr is the wrong tool to find the cause. It is only used to trace Performance issues.


Posted Image





Also tagged with one or more of these keywords: slow, Boot, bootvis, performance

1 user(s) are reading this topic

0 members, 1 guests, 0 anonymous users



How to remove advertisement from MSFN