MagicAndre1981

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

1,275 posts in this topic

Hi MagicAndre1981 - I'm just wondering if you could take a look at my etl file, if you would be so kind. I have zipped 'boot_BASE+CSWITCH+POWER_1.etl' and 'summary_boot.xml' and the filesize is 13,962KB. Where do I best upload this file so you can view it? And, do you need the etl file as it's a fair old size!

I am experiencing an issue that occured on my previous ssd and now a brand new ssd that has had a fresh Windows7 x64 install. Basically what happens is around the point where the usb devices are re-initialised during boot (I can tell because my keyboard and mouse lights go out then come back on), and they are re-lit the pulsing Windows logo stays onscreen and the hdd indicator light flashes once every second or so, then eventually after about 30 seconds or so the hdd light builds up momentum and starts flashing quicker and quicker until it stays suddenly on then all of a sudden the login screen appears.

I have reinstalled the gfx card drivers and disabled devices such as onboard bluetooth, on-cpu gfx.

My specs are:

Intel i5-2500k

Asus P8Z68-V Pro 0606 firmware

G.Skill Ripjaw 2 x 4GB DDR3

Asus Xonar DG

Gainward GTX560Ti 280.26 drivers

Crucial M4 128GB 0009 firmware

Samsung F2 1.5TB

Samsung F4EG 2TB

Hitachi 2TB

I hope you can help.

0

Share this post


Link to post
Share on other sites

upload the zip to mediafire.com please and send me the link per PM.

0

Share this post


Link to post
Share on other sites

Hi Magic Andre,

I've got a really long delay in resuming from hibernation. I've gone ahead and followed your instructions and have generated a dump that I'm not quite sure how to read..

I Here is a snippet from the top of the file generated by:

xperf /tti -i "hibernate_BASE+CSWITCH+DRIVERS+POWER_1.etl" -o summary.hibernate.xml -a suspend

=>

[/font]

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

<scenario start="150325" duration="316038307" suspend="55633000" resumecritical="2356435" hiberwrite="51923000" hiberpageswritten="315438" hiberread="166322000" resume="3213000">

<queryapps start="150606" duration="0" totalChildrenDuration="0" />

<queryservices start="150606" duration="0" totalChildrenDuration="0" />

<suspendapps start="150606" duration="2762575" totalChildrenDuration="1331394">

<app start="150817" duration="999651" exe="\Device\HarddiskVolume3\Program Files (x86)\Symantec\Symantec Endpoint Protection\Smc.exe" pid="1692" />

<app start="2588930" duration="84397" exe="\Device\HarddiskVolume3\Windows\explorer.exe" pid="3300" />

<app start="2807322" duration="40936" exe="\Device\HarddiskVolume3\Windows\explorer.exe" pid="3300" />

<app start="2723695" duration="35175" exe="\Device\HarddiskVolume3\Windows\explorer.exe" pid="3300" />

<app start="2706308" duration="17382" exe="\Device\HarddiskVolume3\Windows\explorer.exe" pid="3300" />

<app start="2894256" duration="16697" exe="\Device\HarddiskVolume3\Windows\System32\LogonUI.exe" pid="17836" />

<app start="2868122" duration="10187" exe="\Device\HarddiskVolume3\Program Files\Sony\VAIO Power Management\SPMgr.exe" pid="2152" />

Given the really long duration in smc.exe, I'm guessing my virus protection is the culprit--? Is that the right interpretation? If so, what can I do about this, short of uninstalling/removing the software? (which actually wouldn't strike me as a wholly bad solution). Are those duration times in milliseconds?

Thanks for you help.. This is all very cryptic to me.

0

Share this post


Link to post
Share on other sites

those data are µs, so it is only 1s whic his ok.

hiberread="166322000" 

this is too long. So reading the hibernation file is too slow. So disable the hibernation file, defrag C: and enable it the file again.

0

Share this post


Link to post
Share on other sites

This is an SSD drive.. Do you think it would make a difference? I'd be happy to do so but I've also read that people with SSDs shouldn't defrag. The system also carries 8GB of ram which is a lot. The system is a Z12MGX sony vaio running windows 7 64bit.

Thanks for your response btw! You are really a great guy for helping so many people out!

those data are µs, so it is only 1s whic his ok.

hiberread="166322000" 

this is too long. So reading the hibernation file is too slow. So disable the hibernation file, defrag C: and enable it the file again.

0

Share this post


Link to post
Share on other sites

hm, do you use the latest firmware for the SSD? Do you run the SSD in AHCI or IDE Mode?

You can also start Process Monitor, start the logging and run the xbootmgr command. After the reboot look in the ProcMon Log which action causes a long duration.

0

Share this post


Link to post
Share on other sites

Hi MagicAndre,

Hope you are well. If you could look at the trace file I have PM'd you I would greatly appreciate this.

I have installed SP1 and followed instructions in mentioned in the post.

thank-you

0

Share this post


Link to post
Share on other sites

you need 7 seconds to enter the password:

30.419280566, RequestCredentials, win:Start, , , , , , , , , , , , , , , , 1

37.234015929, RequestCredentials, win:Stop, , , , , , , , , , , , , , , , 1

Why does this takes so long?

Next the long delay is caused by applying group polices.:

Time (s), Task Name,

, 68.872165528, NotifySubscriber, NotificationPended, 2, "GPClient", "Applying user settings...", , , , , , , , , , , , , 1

, 68.873644154, CallSubscriber, win:Start, 2, "GPClient", , , , , , , , , , , , , , 1

, 68.873773012, CallSubscriber, win:Stop, 2, "GPClient", , , , , , , , , , , , , , 1

, 68.873777064, NotifySubscriber, NotificationPended, 2, "GPClient", "Applying Group Policy Power Options policy...", , , , , , , , , , , , , 1

, 68.874752009, CallSubscriber, win:Start, 2, "GPClient", , , , , , , , , , , , , , 1

, 70.539830507, CallSubscriber, win:Stop, 2, "GPClient", , , , , , , , , , , , , , 1

, 70.539836990, NotifySubscriber, NotificationPended, 2, "GPClient", "Applying Group Policy Drive Maps policy...", , , , , , , , , , , , , 1

, 70.541186353, CallSubscriber, win:Start, 2, "GPClient", , , , , , , , , , , , , , 1

, 70.711729971, CallSubscriber, win:Stop, 2, "GPClient", , , , , , , , , , , , , , 1

, 70.711734834, NotifySubscriber, NotificationPended, 2, "GPClient", "Applying Group Policy Scheduled Tasks policy...", , , , , , , , , , , , , 1

Provider Name, Time (s), Task Name, Opcode Name, Field 1, Field 2, Field 3, Field 4, Field 5, Field 6, Field 7, Field 8, Field 9, Field 10, Field 11, Field 12, Field 13, Field 14, Field 15, Count

, 101.988533255, ExecuteShellCommandList, win:Start, "C:\Windows\system32\userinit.exe;", , , , , , , , , , , , , , , 1

this takes 32s and next the Explorer is started. The rest is fast.

So the group polices are the cause of the slow booting.

0

Share this post


Link to post
Share on other sites

Yes the computer is completely updated as per manufacturer recommendation (though Sony is really bad at getting updates to end users-- but that's another discussion). I believe it's running in AHCI mode, but I can't verify this because the bios is locked down by the manufacturer. The drives themselves I believe are 2 SSDs running in RAID 0. HDTune reports 164MB/sec with 250MB/sec burst and 0.4ms access time.

Is there a run through on how to use process monitor to see what action causes a long duration? I was looking at it but there's a crazy amount of information to sift through.

Thanks!

hm, do you use the latest firmware for the SSD? Do you run the SSD in AHCI or IDE Mode?

You can also start Process Monitor, start the logging and run the xbootmgr command. After the reboot look in the ProcMon Log which action causes a long duration.

0

Share this post


Link to post
Share on other sites

filter the data and look at the duration column what takes so long.

0

Share this post


Link to post
Share on other sites

Great advice-- maybe we're a little closer to figuring it out then!

For reference, I'm running windows 7 x64. I did a search for "procmon.exe" and ran it. It asked for elevated privileges which I granted. I made sure the logging was running (ctrl e).

At first running from an elevated command prompt:

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

complained that it could not start the trace file so I disabled all my Otaku software (DeskSpace and TopDesk) and ran the above command in a bat file with ping -n 10 localhost as a delay, enabling by ctrl e the log at the moment the xbootmgr command hit. This probably wasn't necessary-- it probably was the Otaku stuff, but I don't know. I'm putting this all down in case someone else runs into the same problems-- it could be this, or it could be running in a bat file, either is worth a shot.

At any case, it hibernated and resumed successfully, so I filtered as you said by duration, with a minimum of 1s. I got back the following

post-332179-0-45593300-1315687315_thumb.

So is that right? Searchindexer is the problem? I wonder why that would be the case. In any event, it's very close to my delay.. I will try to disable search and let you know how that goes! Thanks MagicAndrei

[Edit] I verified that it does indeed speed up hibernation in a huge way by disabling the Windows Search. This is disappointing because while I don't use the search all the time, when I do need to use it I really need to use it. I wonder if this is a common problem, and if there is a way to optimize this a little bit so I can have a decent hibernation resume and at the same time be able to search efficiently.

filter the data and look at the duration column what takes so long.

Edited by sano88
0

Share this post


Link to post
Share on other sites

ok, so you verified that the Search is the cause. You can start the service again and force a rebuild of the search index. Maybe this helps.

0

Share this post


Link to post
Share on other sites

hi guys,

does anyone have a way to trace the time it takes for each GPO to process?

thanks

0

Share this post


Link to post
Share on other sites

Hey Andre'!

I too am having several minutes to resume from hibernate. I've created the trace file and uploaded to mediafire.com here.

I've taken this as far as I can alone - I'm hoping you can save the day (again!).

0

Share this post


Link to post
Share on other sites

from what I see the slowdown occurs by writing

hiberwrite="55381000"

hiberwrite: The total time that was spent writing the hiberfile to disk. Writing the hiberfile is performed by using a special driver stack because other drivers are currently in sleep.

and reading the hibernation file.

hiberread="437581000"

hiberread: The total time that was spent reading the hiberfile from disk. Reading the hiberfile is performed by using a special driver stack because other drivers are currently still in sleep.

I see you use a Crucial C300 SSD (C300-CTFDDAC064MAG ATA Device). Do you use the latest firmware? Do you run the SSD in IDE or AHCI mode? If you run in AHCI mode, which AHCI driver do you use? The Intel or the MS driver?

0

Share this post


Link to post
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

  • Recently Browsing   0 members

    No registered users viewing this page.