"Peaky" CPU Usage on Domain Controllers

Question

We have two Windows Server 2008 SP2 (sadly not 2008 R2) Domain Controllers in a small 150 client domain that are exhibiting very "peaky" CPU usage. The Domain Controllers both exhibit the same behavior and are hosted on vSphere 5.5.0, 1331820. Every two or three seconds the CPU usage jumps up to 80-100% and then quickly drops, remains low for a second or two and then jumps up again.

Looking at the historical performance data for the virtual machine indicates that this condition has been going on for at least a year but the frequency has increased since March.

The offending process is SVChost.exe which is wrapping the DHCP Client (dhcpcsvc.dll), EventLog (wevtsvc.dll) and LMHOSTS (lmhsvc.dll) services. I'm certainly not a Windows internals expert but I could not seem to find anything especially amiss when viewing the process with Process Explorer other than it appears the EventLog is triggering a ton of RpcBindingUnbind calls.

At this point I'm out of coffee and ideas. How should I continue to troubleshoot this issue?

Answer 1

TL;DR: EventLog file was full. Overwriting entries is expensive and/or not implemented very well in Windows Server 2008.

At @pk. and @joeqwerty suggestion and after asking around, I decided that it seemed most likely that a forgotten monitoring implementation was scraping the event logs.

I installed Microsoft's Network Monitor on one of the Domain Controllers and started filtering for MSRPC using the ProtocolName == MSRPC filter. There was lots of traffic but it was all between our remote site's RODC and unfortunately did not use same destination port as the listening EventLog process. Darn! There goes that theory.

To simplify things and make it easier to run monitoring software I decided to unwrap the EventLog service from SVCHost. The following command and a reboot of the Domain Controller dedicates one SVCHost process to the EventLog service. This makes investigation a little easier since you do not have multiple services attached to that PID.

SC config EventLog Type= own

I then resorted to ProcMon and setup a filter to exclude everything that did not use that PID. I did not see tons of failed attempts by EventLog to open missing registry keys as indicated as a possible cause here (apparently crappy applications can register as a Event Sources in extremely poor ways). Predictably I saw lots of successful ReadFile entries of the Security Event Log (C:\Windows\System32\WinEvt\Logs\Security.evtx).

Here's a look at the Stack on one of those events:

You'll notice first the RPCBinding and then RPCBindingUnbind. There were a lot of these. Like thousands per second. Either the Security Log is really busy or something is not working right with the Security.evtx log.

In EventViewer the Security Log was only logging a between 50-100 events per minute which seemed appropriate for a domain of this size. Darn! There goes theory number two that we had some application with very verbose event auditing turned on left in a forgotten corner still dutifully chugging away. There were a still a lot (~250,000) of events recorded even though the rate of events being logged was low. Log size perhaps?

Security Logs - (Right Click) - Properties... and the maximum log size was set for 131,072 KB and log size was currently holding at 131,072 KB. The 'Overwrite events as needed' radio button was checked. I figured that constantly deleting and writing to the log file was probably hard work especially when it was so full so I opted to Clear the Log (I saved the old log just in case we need it for auditing later) and let the EventLog service create a new empty file. The result: CPU usage returned to a sane level around 5%.

Answer 2

You may be able to chase this down by creating a small Data Collector Set.

• Open Performance Monitor and create a new user-defined Data Collector Set.
• Choose Manual (no template) and select Event trace data only.
• Add the Active Directory Domain Service: Core data and save the set.
• Change the Stop Condition under Properties to 1 minute.
• Start the set and wait.
• When completed, convert the saved .etl file to a .csv using tracerpt –l “file.etl” –of CSV
• Analyze the summary.csv and dumpfile.csv data in Excel. You may want to download this Import-DC-Info.xlsm doc to help you with your analysis.

If my hunch is correct, you're going to see some devices (IP:port) hammering your DC.

Answer 3

Certainly a difficult one. Apart from just leaving it alone (1 CPU / 50% load.. who cares?), you could try to setup a new domain controller and see after some days if this one gives you the same behavior. If it does, you might want to try with a Wireshark trace (obviously, there's something from the Network causing this then)

The next thing which comes to mind is a simple call to microsoft

Answer 4

Travis, "archive" did not help you. In fact, even clearing the event log when it was 2/3rd grown did not help you. But "archive" did help KraigM.

kce: cleared a 131MB "overwrite" file and saw performance drop from say 55% o 5% but QUESTION: perhaps you eventually you saw high utilization again since this may (a) only be triggered when the overwriting condition is reached or (b) it may get linearly worse as the cleared file increases from 0mb in size to 131MB in size.

Some see this for the security.evtx and one saw it for the Task Scheduler operational log. I suggest completely uninstalling your AV (which one are you using) and trying. Intruders need to hide their tracks and their tracks are made in scheduled tasks they set up or logins they do. So they will hide their tracks by breaking handles to these event logs and rewriting them to skip over their tracks. AVs may may be detecting this in a buggy Way since if it were Microsoft, more of this high utilization would have been reported but I am seeing just a scant few posts when Googling. I am also seeing this on server 2008 R2 for the security.evtx log. No event log subscribers, no external monitors. I observed a couple of AV services (McAfee) running and they had very low total utilization for a server up so many days so I suspect it was uninstalled and only partially so (likely needs McAfee's special uninstaller) and I wonder if there are hooks in the vestige (or even normally installed) McAfee service or McAfee filter drivers running that somehow take a normal write to the event log and decide in their filtering that they need to turn this into a full blown read of the entire event log. Trust me, third party filter drivers from some AV companies are buggy and certainly 10000x buggier than Microsoft's implementation of event logging, which is very likely perfect. In summary, 100% uninstall ALL OF YOUR av AND SEE IF issue resolves. If so, work with your AV company to fix their AV. It's ill-advised to make file exceptions for .EVTX files since you may be losing out on this intrusion detection, which believe me, is important to bad guys.

Also, when using procmon, pay attention to WriteFile calls because the Writefile is what will trigger the filter manager to read the entire file. In my case, the read was initiated approximately 30-seconds after the write completed which might be by design. But it was consistent and in my case the file was 4GB and the file read involved 64K Readfiles each 64KB in length and it utilized 35% of the CPU to accomplish this. Very sad.

---

Update 03/23/2016 I looked at the filter drivers on this machine after concluding this had to be caused by one of them (the event log mechanism could never be buggy on it's own or the number of reports of this kind would be staggering and it is not). I saw some filter drivers from an AV and from a well known 3rd party company which boosts virtual machine disk performance with look ahead reads and asked their chief architect (who was very kind and gracious) if his product might be over-aggressively reading the entire security event log (which was clearly happening per procmon). This would be helpful for smaller security logs but not the ones of the sizes reported here. No way he said. He agreed it might be the AV.

As I said to the Azure fellow below, we do not have a followup from the original Poster if the problem re-surfaced after clearing the event log because that is a common and mistaken solution since the performance degrades over time yet again. This is called "followup" and I see first-hand the original poster's solution can fool those who don't followup into believing they have solved the problem. I almost got fooled as well. I cleared the event log and performance improved -- but I used procmon and saw the issue will grow and grow slowly over time until it becomes problematic. For some reason, the Azure fellow harshly criticizes me when the original poster didn't followup (may have died, been fired, quit, or gotten busy). The Azure fellow below thinks if the original poster didn't followup, it must be a fixed problem. This is vexing and puzzling because I can't think of anyone who is so highly regarded technically who would take this position. I apologize if I pricked a nerve. Perhaps in my activism elsewhere on the Internet where I call people out I got on his nerve -- here (serverfault) I am simply being kind and sharing deep technical knowledge and the result from Mr. Azure is bullying about whether my technical contribution is even necessary or is for some blog of mine (I have no such blog). I don't yet intend to send this link to around half a dozen key cronies at Microsoft and ask them what the hey is going on with this type of bullying from a key MSFT employee because I am singularly focused on having the best of interest of the community in mind and the responses below from Mr. Azure are, in a few words, unbelievable, vitriolic, unnerving and bullying -- which I am sure some people enjoy doing to others. I was initially offended but am over it and know that, passive or active readers will appreciate what I am saying and appreciate my comments -- I stand 100% behind it without regard for legalistic reasons why it is subtly inappropriate here or not. M. Azure, please practice kindness and refrain from casting my comments in a poor light. Just get over it and show restraint and not comment yet again.

Harry