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

Here's a Real Mystery - Something Chewing Up CPU After Bootup


  • Please log in to reply
8 replies to this topic

#1
NoelC

NoelC

    Software Engineer

  • Member
  • PipPipPipPipPipPipPip
  • 1,815 posts
  • Joined 08-April 13
  • OS:Windows 8.1 x64
  • Country: Country Flag

I don't reboot very often, maybe once or twice a month.

 

Over the past couple of months I've noticed that after reboots my Win 8.1 x64 MCE system runs one thread and does more or less continuous but low-rate I/O for some minutes (e.g. 15 or 20 minutes, after which it stops).  I noticed it again after Windows Update dropped its load this week.

 

Today I did some reboots to try to diagnose this.

 

The process that's running is System, and it's using up one of the 24 logical processors (i.e., it shows a continuous roughly 4.2% CPU usage).  After, say, 15 or 20 minutes of doing this the System CPU usage just drops suddenly to near-zero (e.g., 0.01%) and the system runs normally thereafter.

 

During the time System is running that thread I can't start such things as CHKDSK and System Restore.  They just hang, then they proceed when whatever System is doing finally ends.

 

I've watched the Resource Monitor and the System process accesses the master file table of my system volume or backup drive (i.e., G:\$Mft),.  I also saw it occasionally write to C:\Windows\System32\config\SOFTWARE.LOG1.  But those may be coincidence - it's not consistently showing any disk or network access, even though the I/O is constant, so I suspect whatever I/O activity it is doing may be something like IOCtl calls.  To do what, I don't know.

 

  • My system is otherwise well-tuned and stable, and free of malware (verified with MalwareBytes Anti Malware), and I actually feel no significant impact from this - other than if I'd like to do a System Restore or something right after reboot I can't until it finishes.
     
  • Nothing is logged in the System Event Log that gives any clue as to what it's doing or why it should be doing this.
     
  • SFC /VERIFYONLY reports everything's healthy.

Could it be Windows Defender doing some kind of after-boot scan (though I'd expect that to busy MsMpEng, not System)?  On my list of things to do is to disable Defender and see what changes.

 

This activity by the System process shows increasing I/O rates up to a point where it peaks, then it drops to zero and starts up again.  Some of the increases are gradual and some quicker.  Check out this oddball pattern of the thread's I/O rate, from Process Hacker:

 

IORate.png

 

It's clearly following an algorithm of some sort, and not random, as it does finally finish.  Maybe some kind of cache compaction or...  ???

 

My next step will be to set up the Windows Performance Recorder to see if it will shed more light on exactly what's being done.

 

Any other suggestions?

 

-Noel




How to remove advertisement from MSFN

#2
smeezekitty

smeezekitty

    Newbie

  • Member
  • 38 posts
  • Joined 03-December 13
  • OS:Vista Home Premium x86
  • Country: Country Flag

4.2% CPU really isn't much. I am not sure why you are worried about it.

My guess is that it maybe finishing system startup and preparing any services (which may run later)

 

Just because you can see the desktop doesn't mean the system is completely booted.



#3
TELVM

TELVM

    Advanced Member

  • Member
  • PipPipPip
  • 351 posts
  • Joined 09-February 12
  • OS:Windows 7 x64
  • Country: Country Flag

Might be Superfetch doing its stuff?



#4
NoelC

NoelC

    Software Engineer

  • Member
  • PipPipPipPipPipPipPip
  • 1,815 posts
  • Joined 08-April 13
  • OS:Windows 8.1 x64
  • Country: Country Flag

4.2% CPU really isn't much. I am not sure why you are worried about it.

My guess is that it maybe finishing system startup and preparing any services (which may run later)

 

Just because you can see the desktop doesn't mean the system is completely booted.

 

Thing is, I don't know if it's typical, and I do like to know why things happen.  This only started relatively recently.

 

And though the 4% isn't missed, the inability to do certain things for 20 minutes after bootup is definitely not something I want to live with if I don't have to.

 

I have captured an .etl file, now on to analysis...

 

Edit:  Early analysis results:  Looks like the system is validating all its volume snapshots... 

 

Specifically, the ntoskrnl.exe!KiStartSystemThread going through volsnap.sys!VspOpenFilesAndValidateSnapshots, boiling down to low level I/O control calls.

 

StartupCPUAnalysis.png

 

Now what I need to figure out is why this activity became [more] noticeable / intrusive not too long ago. 

 

-Noel


Edited by NoelC, 13 March 2015 - 12:10 AM.


#5
MagicAndre1981

MagicAndre1981

    after Windows 7 GA still Vista lover :)

  • Patrons
  • 6,119 posts
  • Joined 28-August 05
  • OS:Windows 8 x64
  • Country: Country Flag

Donator

share the ETL file (compress it as 7z to reduce the size)


Posted Image

#6
NoelC

NoelC

    Software Engineer

  • Member
  • PipPipPipPipPipPipPip
  • 1,815 posts
  • Joined 08-April 13
  • OS:Windows 8.1 x64
  • Country: Country Flag

Hi Andre, thanks for your interest.  You have infinitely more experience analyzing these traces than I do, and I'd be grateful if you'd look over the data to see what you think.  I'd rather not make it public, but I'll be happy to send it to you personally...  Watch for a PM...

 

Bootup isn't something I pay much attention to since I do it infrequently.

 

FYI, I have my volume snapshot space set to 50 GB.

 

Edit:  I finally figured out what I did that caused this process to stretch out like it has: 

 

Late last year I increased the space available for volume snapshots on my external backup drive up to some 900 GB.  Thus it has been dutifully accumulating snapshots due to my nightly backups.  On looking just now I see that I have over 2 months worth (e.g., 60+ snapshots) available.  Thus, the process that the system normally goes through at startup validating volume snapshots quietly has gone from just a few minutes to tens of minutes because of the sheer additional volume of snapshots.

 

Now that I know that the system does this, and the downside, I'm happy to know that it's normal activity.  For what it's worth I've just reconfigured to be a bit more conservative.  I really don't need the ability to do a restore from any snapshot in the last 2+ months.  Just a few weeks is enough.

 

-Noel


Edited by NoelC, 13 March 2015 - 09:58 AM.


#7
MagicAndre1981

MagicAndre1981

    after Windows 7 GA still Vista lover :)

  • Patrons
  • 6,119 posts
  • Joined 28-August 05
  • OS:Windows 8 x64
  • Country: Country Flag

Donator

the trace is too large to be opened with my 16GB of RAM in my laptop. That large volume shadow copy can indeed cause boot issues. I've seen similar things.


Posted Image

#8
NoelC

NoelC

    Software Engineer

  • Member
  • PipPipPipPipPipPipPip
  • 1,815 posts
  • Joined 08-April 13
  • OS:Windows 8.1 x64
  • Country: Country Flag

Thanks anyway.  I'm pretty sure I've got it right.

 

Next bootup - I guess in April - I'll watch to see that the process is shortened.

 

-Noel



#9
cluberti

cluberti

    Gustatus similis pullus

  • Supervisor
  • 11,018 posts
  • Joined 09-September 01
  • OS:Windows 8.1 x64
  • Country: Country Flag

Donator

No, that call is doing exactly what you think it is.  I think you're right given the data. :)


MCTS Windows Internals, MCITP Server 2008 EA, MCTS MDT/BDD, MCSE/MCSA Server 2003, Server 2012, Windows 8
--------------------
Please read the rules before posting!
Please consider donating to MSFN to keep it up and running!




0 user(s) are reading this topic

0 members, 0 guests, 0 anonymous users