search

mickem / nscp

NSClient++
http://nsclient.org
GNU General Public License v2.0
239 stars 94 forks source link

CheckSystem causes system hang every ~20 minutes. #619

Open crossan007 opened 5 years ago

crossan007 commented 5 years ago

Issue and Steps to Reproduce

When CheckSystem=enabled is set in nsclient.ini, the system will encounter noticeable performance issues for a few minutes every 20 minutes.

Steps to reproduce: Start NSCP. No external monitoring or remote access is necessary to reproduce

.\nscp.exe test

Expected Behavior

NSCP should not cause system-wide performance issues.

Actual Behavior

The performance issues are most noticed in response times for IIS web pages (identified by the timeTaken field in the IIS logs).

These performance issues can be exactly correlated with ~3% CPU utilization by WmiPrvSe.exe, and this line in the Microsoft-Windows-WMI-Activity/Operational log:

WMIProv provider started with result code 0x0. HostProcess = wmiprvse.exe; ProcessID = 3296; ProviderPath = %systemroot%\system32\wbem\wmiprov.dll

Having enabled WMI trace logging (https://docs.microsoft.com/en-us/windows/desktop/WmiSdk/tracing-wmi-activity) via Wevtutil.exe sl Microsoft-Windows-WMI-Activity/Trace /e:true it does not appear that a large number of WMI queries are being executed during these times. The only notable queries in the trace logs pertain to network interfaces (executed by the ClientProcessId owned by nscp.exe)

This appears to be the same scenarios as described here: https://github.com/martinlindhe/wmi_exporter/issues/89

According to that thread, it looks like the PDH queries should not cause this lag, but only WMI queries will. The NSCP source code seems to use PDH for most counters, but the networking counters still appear to use WMI.

I don't see an easy way to disable network counters from the CheckSystem module, but this would be my first guess as to diagnosing this issue.

Details

Additional Details

NSClient++ log:

2019-06-03 10:49:18: debug:c:\source\master\service\NSClient++.cpp:150: NSClient++ 0.5.2.39 2018-02-04 x64 Loading settings and logger...
2019-06-03 10:49:18: debug:c:\source\master\service\path_manager.cpp:175: Settings not ready so we cant lookup: base-path
2019-06-03 10:49:18: debug:c:\source\master\service\path_manager.cpp:175: Settings not ready so we cant lookup: exe-path
2019-06-03 10:49:18: debug:c:\source\master\libs\settings_manager\settings_manager_impl.cpp:164: Boot.ini found in: C:\Program Files\NSClient++/boot.ini
2019-06-03 10:49:18: debug:c:\source\master\service\path_manager.cpp:175: Settings not ready so we cant lookup: shared-path
2019-06-03 10:49:18: debug:c:\source\master\libs\settings_manager\settings_manager_impl.cpp:182: Activating: ini://${shared-path}/nsclient.ini
2019-06-03 10:49:18: debug:c:\source\master\libs\settings_manager\settings_manager_impl.cpp:83: Creating instance for: ini://${shared-path}/nsclient.ini
2019-06-03 10:49:18: debug:c:\source\master\service\path_manager.cpp:175: Settings not ready so we cant lookup: shared-path
2019-06-03 10:49:18: debug:c:\source\master\include\settings/impl/settings_ini.hpp:299: Loading: C:\Program Files\NSClient++/nsclient.ini
2019-06-03 10:49:18: debug:c:\source\master\service\NSClient++.cpp:158: NSClient++ 0.5.2.39 2018-02-04 x64 booting...
2019-06-03 10:49:18: debug:c:\source\master\service\NSClient++.cpp:159: Booted settings subsystem...
2019-06-03 10:49:18: debug:c:\source\master\service\NSClient++.cpp:219: On crash: restart: NSCP
2019-06-03 10:49:18: debug:c:\source\master\service\NSClient++.cpp:231: Archiving crash dumps in: C:\Program Files\NSClient++/crash-dumps
2019-06-03 10:49:18: debug:c:\source\master\service\plugin_manager.cpp:150: Found: CheckDisk
2019-06-03 10:49:18: debug:c:\source\master\service\plugin_manager.cpp:150: Found: CheckEventLog
2019-06-03 10:49:18: debug:c:\source\master\service\plugin_manager.cpp:150: Found: CheckExternalScripts
2019-06-03 10:49:18: debug:c:\source\master\service\plugin_manager.cpp:150: Found: CheckHelpers
2019-06-03 10:49:18: debug:c:\source\master\service\plugin_manager.cpp:150: Found: CheckNSCP
2019-06-03 10:49:18: debug:c:\source\master\service\plugin_manager.cpp:150: Found: CheckSystem
2019-06-03 10:49:18: debug:c:\source\master\service\plugin_manager.cpp:150: Found: NRPEServer
2019-06-03 10:49:18: debug:c:\source\master\service\plugin_manager.cpp:150: Found: WEBSErver
2019-06-03 10:49:18: debug:c:\source\master\service\plugin_manager.cpp:150: Found: allow arguments
2019-06-03 10:49:18: debug:c:\source\master\service\plugin_manager.cpp:306: Loading module C:\Program Files\NSClient++\modules\CheckDisk.dll ()
2019-06-03 10:49:18: debug:c:\source\master\service\plugin_manager.cpp:306: Loading module C:\Program Files\NSClient++\modules\CheckEventLog.dll ()
2019-06-03 10:49:18: debug:c:\source\master\service\plugin_manager.cpp:306: Loading module C:\Program Files\NSClient++\modules\CheckExternalScripts.dll ()
2019-06-03 10:49:18: debug:c:\source\master\service\plugin_manager.cpp:306: Loading module C:\Program Files\NSClient++\modules\CheckHelpers.dll ()
2019-06-03 10:49:18: debug:c:\source\master\service\plugin_manager.cpp:306: Loading module C:\Program Files\NSClient++\modules\CheckNSCP.dll ()
2019-06-03 10:49:18: debug:c:\source\master\service\plugin_manager.cpp:306: Loading module C:\Program Files\NSClient++\modules\CheckSystem.dll ()
2019-06-03 10:49:18: debug:c:\source\master\service\plugin_manager.cpp:306: Loading module C:\Program Files\NSClient++\modules\NRPEServer.dll ()
2019-06-03 10:49:18: debug:c:\source\master\service\plugin_manager.cpp:306: Loading module C:\Program Files\NSClient++\modules\WEBSErver.dll ()
2019-06-03 10:49:19: error:c:\source\master\service\plugin_manager.cpp:296: Failed to find plugin: allow arguments in C:\Program Files\NSClient++\modules
2019-06-03 10:49:19: debug:c:\source\master\service\plugin_manager.cpp:227: Loading plugin: CheckDisk
2019-06-03 10:49:19: debug:c:\source\master\service\plugin_manager.cpp:227: Loading plugin: CheckEventLog
2019-06-03 10:49:19: debug:c:\source\master\service\plugin_manager.cpp:227: Loading plugin: CheckExternalScripts
2019-06-03 10:49:19: debug:c:\source\master\modules\CheckExternalScripts\CheckExternalScripts.cpp:127: No aliases found (adding default)
2019-06-03 10:49:19: debug:c:\source\master\service\plugin_manager.cpp:227: Loading plugin: CheckHelpers
2019-06-03 10:49:19: debug:c:\source\master\service\plugin_manager.cpp:227: Loading plugin: CheckNSCP
2019-06-03 10:49:19: debug:c:\source\master\modules\CheckNSCP\CheckNSCP.cpp:51: Crash folder is: C:\Program Files\NSClient++/crash-dumps
2019-06-03 10:49:19: debug:c:\source\master\service\plugin_manager.cpp:227: Loading plugin: CheckSystem
2019-06-03 10:49:19: debug:c:\source\master\service\plugin_manager.cpp:227: Loading plugin: NRPEServer
2019-06-03 10:49:19: debug:c:\source\master\modules\NRPEServer\NRPEServer.cpp:126: Allowed hosts definition: <IP ADDRESS REDACTED>>
2019-06-03 10:49:19: debug:c:\source\master\modules\NRPEServer\NRPEServer.cpp:127: Server config: address: :5666, ssl enabled: none, no certificate, dh: C:\Program Files\NSClient++/security/nrpe_dh_512.pem, ciphers: ADH, ca: C:\Program Files\NSClient++/security/ca.pem, options: 
2019-06-03 10:49:19: debug:c:\source\master\include\socket/server.hpp:111: Binding to: [::]:5666(ipv6)
2019-06-03 10:49:19: debug:c:\source\master\include\socket/server.hpp:214: Attempting to bind to: [::]:5666(ipv6)
2019-06-03 10:49:19: debug:c:\source\master\include\socket/server.hpp:107: Binding to: 0.0.0.0:5666(ipv4), reopen: true, reuse: true
2019-06-03 10:49:19: debug:c:\source\master\include\socket/server.hpp:214: Attempting to bind to: 0.0.0.0:5666(ipv4)
2019-06-03 10:49:19: debug:c:\source\master\service\plugin_manager.cpp:227: Loading plugin: WEBSErver
2019-06-03 10:49:19: debug:c:\source\master\modules\WEBServer\WEBServer.cpp:161: Using certificate: C:\Program Files\NSClient++/security/certificate.pem
2019-06-03 10:49:19: debug:c:\source\master\modules\WEBServer\WEBServer.cpp:185: Loading webserver on port: 8443
2019-06-03 10:49:19: debug:c:\source\master\service\NSClient++.cpp:317: NSClient++ - 0.5.2.39 2018-02-04 Started!
2019-06-03 10:49:19: debug:c:\source\master\service\plugin_manager.cpp:306: Loading module C:\Program Files\NSClient++\modules\CommandClient.dll ()
2019-06-03 10:49:19: debug:c:\source\master\service\plugin_manager.cpp:525: Loading plugin: CommandClient...
2019-06-03 10:49:19: debug:c:\source\master\modules\CommandClient\CommandClient.cpp:133: Enter command to execute, help for help or exit to exit...
2019-06-03 10:49:19: debug:c:\source\master\modules\CheckSystem\pdh_thread.cpp:169: Loading counter: disk_queue_length_0 C: = \\<<HOSTNAME_REDACTED>>\PhysicalDisk(0 C:)\% Disk Time
2019-06-03 10:49:19: debug:c:\source\master\modules\CheckSystem\pdh_thread.cpp:169: Loading counter: disk_queue_length_1 E: = \\<<HOSTNAME_REDACTED>>\PhysicalDisk(1 E:)\% Disk Time
2019-06-03 10:49:19: debug:c:\source\master\modules\CheckSystem\pdh_thread.cpp:169: Loading counter: disk_queue_length__Total = \\<<HOSTNAME_REDACTED>>\PhysicalDisk(_Total)\% Disk Time
2019-06-03 11:18:19: info:c:\source\master\modules\CommandClient\CommandClient.cpp:116: Ctrl+c is not exit...
2019-06-03 11:18:19: debug:c:\source\master\service\NSClient++.cpp:323: Attempting to stop all plugins
2019-06-03 11:18:19: debug:c:\source\master\service\NSClient++.cpp:325: Stopping all plugins
2019-06-03 11:18:19: debug:c:\source\master\service\plugin_manager.cpp:259: Unloading plugin: CheckDisk...
2019-06-03 11:18:19: debug:c:\source\master\service\plugin_manager.cpp:259: Unloading plugin: CheckEventLog...
2019-06-03 11:18:19: debug:c:\source\master\service\plugin_manager.cpp:259: Unloading plugin: CheckExternalScripts...
2019-06-03 11:18:19: debug:c:\source\master\service\plugin_manager.cpp:259: Unloading plugin: CheckHelpers...
2019-06-03 11:18:19: debug:c:\source\master\service\plugin_manager.cpp:259: Unloading plugin: CheckNSCP...
2019-06-03 11:18:19: debug:c:\source\master\service\plugin_manager.cpp:259: Unloading plugin: CheckSystem...
2019-06-03 11:18:19: debug:c:\source\master\service\plugin_manager.cpp:259: Unloading plugin: NRPEServer...
2019-06-03 11:18:19: debug:c:\source\master\service\plugin_manager.cpp:259: Unloading plugin: WEBSErver...
2019-06-03 11:18:19: debug:c:\source\master\service\plugin_manager.cpp:259: Unloading plugin: CommandClient...
2019-06-03 11:18:19: debug:c:\source\master\service\NSClient++.cpp:333: Stopping: COM helper
2019-06-03 11:18:19: debug:c:\source\master\service\NSClient++.cpp:342: Stopping: Settings instance
crossan007 commented 5 years ago

I just discovered the disable option for CheckSystem, so I am trying to disable network now via:

[/settings/system/windows]
# Disable automatic checks
disable=network

https://docs.nsclient.org/reference/windows/CheckSystem/#disable-automatic-checks