[geekster51]

Andre:

In my ReadyBoost - Operational Event Log, I have an entry like this after each boot:

Boot plan calculation completed in 16302 ms.
Boot Plan Timestamp: ‎2012‎-‎03‎-‎05T07:57:20.967033200Z
Reason: System boot completion
Result: 0x6F

And sometimes one that looks like this:

Boot plan calculation completed in 281 ms.
Boot Plan Timestamp: ‎2012‎-‎03‎-‎05T09:43:47.783533500Z
Reason: Disk defragmentation
Result: 0x6F

Prior to January 27, there are similar entries but the result code is 0x0, not it is 0x6F.


Also, this entry is in ReadyBoost - Operational Log after each boot:

Summary of ReadyBoot Performance:
Io Read Count: 27496
Io Read Bytes: 626086912
Cache Hit Count: 0
Cache Hit Bytes: 0
Cache Hit Percentage: 0
Boot Prefetch Time (us): 0
Boot Prefetch Bytes: 0
Boot Prefetch Read Count: 0

And prior to January 27, there are similar entries, but the Cache Hits and Boot Prefetch values are not zero.

I may never be able to figure out what happened on January 27, but it looks like ReadyBoot can not build a plan and the reason is 0x6F.

Do you have any idea what causes a 0x6F result code?

Thanks!

This post has been edited by geekster51: 05 March 2012 - 11:22 AM

[MagicAndre1981]

I don't know what the values from Eventlog mean. Run the optimization and give me the latest trace file.

0x6F = ERROR_BUFFER_OVERFLOW winerror.h - The file name is too long.

This post has been edited by MagicAndre1981: 05 March 2012 - 01:11 PM

[geekster51]

Andre:

Thank you for your help.

It appears that I have a problem with ReadyBoot or prefetcher (perhaps these are the same).

I downloaded the WPT and entered this command from an elevated command prompt ...

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

My computer then shutdown and rebooted.

After the desktop was displayed, a dialog box was shown saying: Waiting for prefetcher ...


After 5 minutes, another dialog box was displayed saying:

Gave up waiting for Win7RTM physical prefetcher after 300 seconds.
Could not wait for prefetcher.
Couldn't find kernel logger in active logger list.
Couldn't find user-mode logger in active logger list.



I clicked OK. No further automatic boots happened after the first one.

I checked my ReadyBoost - Operational event log, and (as usual) it had this entry (indicating a 0x6F reason code):

Boot plan calculation completed in 5523 ms.
Boot Plan Timestamp: ‎2012‎-‎03‎-‎05T20:16:16.039824500Z
Reason: System boot completion
Result: 0x6F

And indicating that ReadyBoot was not caching anything ...

Summary of ReadyBoot Performance:
Io Read Count: 32000
Io Read Bytes: 724031488
Cache Hit Count: 0
Cache Hit Bytes: 0
Cache Hit Percentage: 0
Boot Prefetch Time (us): 0
Boot Prefetch Bytes: 0
Boot Prefetch Read Count: 0




An xbootmgr.log was created from the one and only boot ... here it is:

[2012/03/05-19:48:15.250] Detected Win7RTM physical (ReadyBoot) prefetcher; the SysMain service is auto-started.
[2012/03/05-19:48:15.250] Registering for auto-run with a 120000 msec delay...
[2012/03/05-19:48:15.250] Completed auto-run change.
[2012/03/05-19:48:15.250] Starting trace...
[2012/03/05-19:48:15.516] Enabled boot logging to 'C:\TEMP\boot_BASE+CSWITCH+POWER_1_km_premerge.etl'
[2012/03/05-19:53:31.513] Detected Win7RTM physical (ReadyBoot) prefetcher; the SysMain service is auto-started.
[2012/03/05-19:53:31.513] Stopping trace...
[2012/03/05-19:53:33.604] Stopped kernel logger.
[2012/03/05-19:53:33.728] Stopped user-mode logger.
[2012/03/05-19:53:33.728] The trace you are capturing "C:\TEMP\boot_BASE+CSWITCH+POWER_1.etl" may contain personally identifiable information, including but not necessarily limited to paths to files accessed, paths to registry accessed and process names. Exact information depends on the events that were logged. Please be aware of this when sharing out this trace with other people.
[2012/03/05-19:54:02.384] Merged ETL file to 'C:\TEMP\boot_BASE+CSWITCH+POWER_1.etl'
[2012/03/05-19:54:02.399] Waiting for prefetcher...
[2012/03/05-19:58:52.841] Gave up waiting for Win7RTM physical prefetcher after 300 seconds.
[2012/03/05-19:58:52.841] Could not wait for prefetcher.
[2012/03/05-19:58:52.841] Stopping trace...
[2012/03/05-19:58:52.856] Couldn't find kernel logger in active logger list.
[2012/03/05-19:58:52.856] Couldn't find user-mode logger in active logger list.
[2012/03/05-19:58:52.856] Unregistering auto-run...
[2012/03/05-19:58:52.856] Completed auto-run change.

The log shows the same problem .... boot manager gave up waiting for prefetcher.


An ETL file (boot_BASE+CSWITCH+POWER_1.etl) was created (from the single boot). I used this command:

xperf /tti -i boot_BASE+CSWITCH+POWER_1.etl -o summary_boot.xml -a boot

... to create a summary_boot.xml file, and I will attach that file to this post for your review. The file only represents one boot, so it might not be very useful for analyzing areas to improve my boot time .... but perhaps it contains a hint on what is causing ReadyBoot and/or prefetcher to throw a non-zero result code and/or not respond. I think that once I fix the problem with ReadyBoot (and it starts to function as it should by caching), my boot time will be greatly reduced.

Boot Manager timed out waiting for the prefetcher. Could that have something to do with the 0x6F return code we are seeing in the event log?

Like I said, I think I have a problem with ReadyBoot and/or prefetcher. It (they) are failing to complete properly. I think this (the lack of proper caching) is resulting in my long (> 2 minutes) boot times, and it appears this caused the boot manager to terminate (after one boot) because the prefetcher did not respond.

Any thoughts or suggestions on what I can do to figure out the cause of this ReadyBoot/prefetcher problem would be appreciated. I know I could just re-install Windows, but at this point I'd rather tolerate a 2 minute boot than deal with reinstalling Windows (easy) and reinstalling/re-customizing apps, etc.

Thanks again!

Attached File(s)

•  summary_boot.xml (118.73K)
  Number of downloads: 2

This post has been edited by geekster51: 05 March 2012 - 10:09 PM

[MagicAndre1981]

symantic driver is slow (takes 18s to start):

 <pnpObject name="SRTSP" type="Driver" activity="Load" startTime="133102" endTime="151144" duration="18041"

Have you updated symantec before the issues started? Can also compress and upload the boot_BASE+CSWITCH+POWER_1.etl?

[geekster51]

Andre:

Quote

Have you updated symantec before the issues started? Can also compress and upload the boot_BASE+CSWITCH+POWER_1.etl?

Symantec (Norton Internet Security) updates on a daily basis (anti-virus signatures). The last version update was on February 2 .... and my long boot times started on January 27 (so we can rule out the Symantec version upgrade as the cause).

I'm a noobie here ... so, just to make sure I understand what you want (re the ETL file), by "compress" do you want me to ZIP it ... or is there some other method of compression you need me to use?

[MagicAndre1981]

zip is not so good in compression. Install 7-Zip ( http://sourceforge.n...7/topic/4711128 ) and compress it as 7z (ULTRA compression ratio, LZMA2 compression type)

[geekster51]

Quote

compress it as 7z (ULTRA compression ratio, LZMA2 compression type)

I downloaded and installed 7-zip.

Compressed my ETL file using ultra compression and LZMA2 type.

Compressed file is 8.41 MB, but my global upload quota here on MSFN is only 500 KB ... so I cannot attach the 7z file. Is there any way for me to increase my upload quota here?

In the mean time, I looked at the ETL file using xperf and noticed that the ReadyBoot I/O chart has a large number of cache misses. I took a screen shot of that chart and attached it.

Until I can increase my upload quota, if you wish, I can take screen shots of any other charts you need to see and attach them.

Seems to me that ReadyBoot is not caching ... and if it did, my boot time would be significantly reduced. But (other than reinstalling Windows) I am not sure how to get ReadyBoot to start caching again (prior to January 27, ReadyBoot was caching).

Attached File(s)

•  ReadyBoot chart.jpg (55.08K)
  Number of downloads: 7

This post has been edited by geekster51: 06 March 2012 - 02:26 PM

[MagicAndre1981]

yes, ReadyBoot is really broken.

I have never does this, but move the files from C:\Windows\Prefetch\ReadyBoot to a different folder and reboot. Does ReadyBoot create new files? Can you now run the optimization?

[GrofLuigi]

When I want to disable ReadyBoot/Prefetch/Superfetch (and I always do, because I don't believe in caching of caching of caching - the HDD, whatever model it is, has its own cache, windows does file caching, and I think that's enough, or else something is bound to go wrong one day) I go to administrative tools > performance monitor > Startup Event Trace Sessions and disable ReadyBoot.

My point is, you should check if you have it disabled there. Some tweaking programs and guides do.

GL

[geekster51]

PROBLEM SOLVED !!!!!!!!!!!!!!

GroftLuigi:
Thanks for the suggestion ... I started the Performance Monitor, and verified that the ReadyBoot task was still enabled.


Andre:

Thanks for your help.

We both thought of the same thing. I went for a walk to think about this problem ... and concluded that the reason ReadyBoot was unable to cache was that it was unable to access its cache folder. When I got home, I checked the date stamps on the files in the c:\windows\prefetch\readyboot folder and found all the dates were January 26 (i.e., the last date when the ReadyBoot cache worked).

Then, I saw your latest post in this thread suggesting that I move the ReadyBoot folder. Instead, I just renamed the ReadyBoot folder and rebooted. The boot was a bit faster, and the Result Code in the Event Log for ReadyBoot's boot plan calculation was no longer 0x6F ... instead the Result Code was 0 .... a very good sign that the cache was being used again.

I rebooted again, and my boot time went from 150 seconds to 51 seconds !!!!!! As I continue to reboot and the ReadyBoot cache gets refined, I'm hoping that my boot time decreases a bit more. But this problem is solved! I am guessing that the problem might have had something to do with folder permissions (ReadyBoot may have lost permission to access the folder/file used to build its boot plan, but I cannot verify that. If we had been able to clearly determine what the 0x6F Result Code meant ... my guess is that it may have indicated that ReadyBoot could not access its designated folder/file).



Lessons that I learned: Window 7's ReadyBoot feature really does reduce boot time. If that feature is broken, then ones boot time can easily double.

To verify that ReadyBoot is working ok ... look in the Event Viewer > Application and Services Logs > Microsoft > Windows > ReadyBoost > Operational for Event IDs 1016 and 1015. These events will occur shortly after the previous boot.


The 1016 record should look like this (and shows that the Boot plan calculation, which determines the files to be cached for booting, returned a zero Result Code):

Boot plan calculation completed in 2449 ms.
Boot Plan Timestamp: ‎2012‎-‎03‎-‎06T19:28:12.885313600Z
Reason: System boot completion
Result: 0x0


The 1015 record should look like this (and shows the Cache Hits for the previous boot). The Cache Hit numbers should not be zero (which would indicate that ReadyBoot's caching is not working).

Summary of ReadyBoot Performance:
Io Read Count: 34728
Io Read Bytes: 745637888
Cache Hit Count: 22178
Cache Hit Bytes: 382853632
Cache Hit Percentage: 0.638620133609767
Boot Prefetch Time (us): 40325470
Boot Prefetch Bytes: 407842816
Boot Prefetch Read Count: 11033


One last comment .... Microsoft (in its infinite wisdom) has implemented two features with very similar names: ReadyBoot and ReadyBoost.

ReadyBoot – decreases boot time (the time from turning power on to reaching the log-on screen) by preloading the files and startup programs needed per-machine into a cache.
ReadyBoost – supports the use of flash storage devices like Universal Serial Bus (USB) flash drives and Secure Digital (SD) flash cards to boost PC performance.

Unfortunately, the Events record for ReadyBoot are found in the ReadyBoost Event Log .... this can be confusing.

[MagicAndre1981]

nice to hear that it works now Run the optimization to fully train ReadyBoot again.

[zare]

Sorry to high jack this thread: have boot problems after changing some option(disable system restore, indexing ...) .. The boot time when from 20sec to 80 sec. In the event log, the biggest difference is BootUserProfileProcessingTime. In the etl file I cannot see any service taking more time, but there is gap(60s) between two group of services. Any advice where I should look for the problem.

[MagicAndre1981]

can you upload the compressed (7z, RAR) tarce?

[zare]

MagicAndre1981, on 21 April 2012 - 05:00 AM, said:

can you upload the compressed (7z, RAR) tarce?

Here it is.

[zare]

zare, on 21 April 2012 - 06:40 AM, said:

MagicAndre1981, on 21 April 2012 - 05:00 AM, said:

can you upload the compressed (7z, RAR) tarce?

Here it is.

Just noticed the file is 47M .. ..here is smaller version with 7z ..

[MagicAndre1981]

this is ok. I already downloaded the file.

Your delay is caused by 2 points:

1.) entering password takes 6 seconds:

 01_password.png (2.98K)
Number of downloads: 19

but the larger delay (53s) is caused by restoring the mapped network connections:

 02_Restorenetworkconnections.png (3.22K)
Number of downloads: 19

So remove the network connections and use the net use command to map the connections on demand (net use X: \\server\share /persistent:No). /persistent:No is important to map them temporary only.

[zare]

MagicAndre1981, on 21 April 2012 - 07:46 AM, said:

this is ok. I already downloaded the file.

Your delay is caused by 2 points:

1.) entering password takes 6 seconds:

01_password.png

but the larger delay (53s) is caused by restoring the mapped network connections:

02_Restorenetworkconnections.png

So remove the network connections and use the net use command to map the connections on demand (net use X: \\server\share /persistent:No). /persistent:No is important to map them temporary only.

That it ! .. My office shares .. man I was so blind .. from where did you get those snapshots? the xml ?

[MagicAndre1981]

zare, on 21 April 2012 - 08:03 AM, said:

from where did you get those snapshots? the xml ?

open the ETL with the xperfviewer, select the WinLogon-interval and click "Clone Selection". No go to the "Generic events" graph and make a rightclick and select "summary table". In this table expand "Microsoft-Windows-Winlogon" and you can see the 2 entries.

[zare]

MagicAndre1981, on 21 April 2012 - 09:31 AM, said:

zare, on 21 April 2012 - 08:03 AM, said:

from where did you get those snapshots? the xml ?

open the ETL with the xperfviewer, select the WinLogon-interval and click "Clone Selection". No go to the "Generic events" graph and make a rightclick and select "summary table". In this table expand "Microsoft-Windows-Winlogon" and you can see the 2 entries.

One more question: what does the password request (Request Credentials) time includes? Does it include the time needed to enter the password?

[MagicAndre1981]

sorry, I have no idea. This is not documented. And I have the issue in Win8 that I have a 10s delay when I've used AutoLogon.