{"id":602,"date":"2019-06-03T14:36:16","date_gmt":"2019-06-03T18:36:16","guid":{"rendered":"https:\/\/crossan007.dev\/blog\/?p=602"},"modified":"2019-06-03T16:42:53","modified_gmt":"2019-06-03T20:42:53","slug":"intermittently-slow-iis-web-site","status":"publish","type":"post","link":"https:\/\/crossan007.dev\/blog\/windows-server\/intermittently-slow-iis-web-site\/","title":{"rendered":"Intermittently Slow IIS web site"},"content":{"rendered":"\n
Tweet<\/a><\/div>\n\n

TL;DR: <\/p>

An issue in the Windows Management Instrumentation (WMI) performance counter collection process caused periodic system-wide performance degradation.<\/p>


This issue became visible when our infrastructure monitoring software invoked specific WMI queries.<\/p>


We disabled the specific WMI query set which was causing the performance issues, and the problem went away.<\/p><\/blockquote>\n\n\n\n

A few days ago one of our clients began reporting performance issues on one of their web sites. This site is an IIS web application responsible for rendering visualizations of very large data sets (hundreds of gigabytes). As such, the application pool consumes a corresponding amount of RAM (which is physically available on the server).<\/p>\n\n\n\n

Normally, these sites (I manage a few hundred instances) are fast, with most queries returning in under 300ms; however, this one instance proved difficult. To make matters worse, the performance issues were intermittent: most of the time, the site was blazing fast, but sometimes the site would hang for minutes<\/strong>. <\/p>\n\n\n\n

Given a few hours of observation, one of my team members noticed a correlation between the performance issues of the site and a seemingly unrelated process on the host: WmiPrvSe.exe<\/code><\/p>\n\n\n\n

I began digging in, and was able to corroborate this correlation by looking at the process’s CPU usage over time (using ELK \/ MetricBeat to watch windows processes). Sure enough, there’s a direct correlation between WmiPrvSe.exe<\/code> using ~3-4% CPU, and IIS logs indicating a timeTaken<\/code> of greater than 90 seconds. This correlation also established an interval between instances of the issue: 20 minutes.<\/p>\n\n\n\n

I fired up Sysinternals’ ProcMon.exe to get a better handle on what exactly WmiPrvSe.exe<\/code> was doing during these so-called “spikes”. I observed an obscene<\/strong> count of Registry queries to things looking like Performance counters (RegQueryValue<\/code>, RegCloseKey<\/code>, RegEnumKey<\/code>, RegOpenKey<\/code>). Note that there are multiple instances of WmiPrvSe.exe<\/code> running on the sytsem, but only one instance was “misbehaving:” the one running as NT AUTHORITY\\SYTSEM<\/code> (which also happens to have the lowest PID). The instances running as NT AUTHORITY\\NETWORK SERVICE<\/code> and as NT AUTHORITY\\LOCAL SERVICE<\/code> did not seem to be misbehaving.<\/p>\n\n\n\n

Almost all of the registry keys in question contained the string Performance<\/code> or PERFLIB<\/code>; many (but not all) queries were against keys within HKLM\\System\\CurrentControlSet\\Services.<\/code><\/p>\n\n\n\n

I know that I have the Elastic Co.’s “Beats” agents installed on this host; could Metricbeat<\/code>, or one of my other monitoring tools be the culprit? So, I tried disabling all of the “beats” agents (filebeat, metricbeat, winlogbeat, etc), but was still seeing these intermittent spikes in WmiPrvSe.exe<\/code> CPU usage correlating with slow page loads from IIS.<\/p>\n\n\n\n

Stumped, I searched for how to capture WMI application logs, and found this article: https:\/\/docs.microsoft.com\/en-us\/windows\/desktop\/wmisdk\/tracing-wmi-activity<\/a>.<\/p>\n\n\n\n

I ran the suggested command (Wevtutil.exe sl Microsoft-Windows-WMI-Activity\/Trace \/e:true<\/code>) and fired up Event Veiwer (as admin) to the above path. Bingo. <\/p>\n\n\n\n

Log hits inMicrosoft-Windows-WMI-Activity\/Trace<\/code> included mostly checks against the networking devices:select __RELPATH, Name, BytesReceivedPersec, BytesSentPersec, BytesTotalPersec from Win32_PerfRawData_Tcpip_NetworkInterface<\/code><\/p>\n\n\n\n

These WMI queries were executed by the ClientProcessId<\/code> owned by nscp.exe.<\/code><\/p>\n\n\n\n

I perused the source code for NSCP a bit, and discovered that the Network queries for NSCP are executed through WMI(
https:\/\/github.com\/mickem\/nscp\/blob\/master\/modules\/CheckSystem\/check_network.cpp#L105<\/a> ); while the standard performance counter queries were executed through PDH (https:\/\/github.com\/mickem\/nscp\/blob\/master\/modules\/CheckSystem\/pdh_thread.cpp#L132<\/a>):
<\/p>\n\n\n\n

Something else I noticed was that the Microsoft-Windows-WMI-Activity\/Operational<\/code> log contained events directly corresponding to the issue at hand: WMIProv provider started with result code 0x0. HostProcess = wmiprvse.exe; ProcessID = 3296; ProviderPath = %systemroot%\\system32\\wbem\\wmiprov.dll<\/code><\/p>\n\n\n\n

Some more creative google searches yielded me an interesting issue in a GitHub repo for a different project:<\/strong> CPU collector blocks every ~17 minutes on call to wmi.Query<\/a> #89 . <\/p>\n\n\n\n

Sounds about right.<\/p>\n\n\n\n

Skimming through the issue I see this; which sets off the “ah-ha” moment: <\/p>\n\n\n\n

Perfmon uses the PDH library, not WMI. I did not test with Perfmon, but PDH is not affected. <\/p>
leoluk<\/a> <\/strong> commented on Feb 16, 2018<\/a> (https:\/\/github.com\/martinlindhe\/wmi_exporter\/issues\/89#issuecomment-366195581<\/a>)<\/cite><\/blockquote>\n\n\n\n

Now knowing that only NSCP’s check_network<\/code> uses WMI, I found the documentation to disable the network routine in nscp’s CheckSystem<\/code> module: https:\/\/docs.nsclient.org\/reference\/windows\/CheckSystem\/#disable-automatic-checks<\/a><\/p>\n\n\n\n

I added the bits to my nsclient.ini<\/code> config to disable automatic network checks, restarted NSCP, and confirmed the performance issue was gone:<\/p>\n\n\n

\n[\/settings\/system\/windows]\n# Disable automatic checks\ndisable=network\n\n<\/pre><\/div>\n\n\n
I’ve opened an issue on NSCP’s GitHub page for this problem: https:\/\/github.com\/mickem\/nscp\/issues\/619<\/a><\/p>\n\n\n\n
<\/p>\n\n\n\n
Related Reading:<\/p>\n\n\n\n