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

[kenco]

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.

[MagicAndre1981]

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

[sano88]

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.

[MagicAndre1981]

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.

[sano88]

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.

[MagicAndre1981]

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.

[daboss25]

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

[MagicAndre1981]

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.

[sano88]

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.

[MagicAndre1981]

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

[sano88]

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

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 September 10, 2011 by sano88

[MagicAndre1981]

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.

[daboss25]

hi guys,

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

thanks

[BKeadle]

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!).

[MagicAndre1981]

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?