High CPU/Load on npcd

[cambevis]

Hello All,

For the last week, we've been experiencing high CPU/loads on our nagios server, with the attendant lines spamming my npcd.log file

[06-08-2015 08:36:07] NPCD: ERROR: Executed command exits with return code '2'
[06-08-2015 08:36:07] NPCD: ERROR: Command line was '/usr/local/nagios/libexec/process_perfdata.pl -n -b /usr/local/nagios/var/spool/perfdata//1433156650.perfdata.service'

Any ideas how I further debug this?

Thanks

Cam

[tmcdonald]

What version of XI are you using? What is the load on the server?

[cambevis]

Sorry, duh. I'm running 2014R2.7 on Centos 6.6

The CPU is pretty much maxed any time npcd is running and the load will be between 2 and 4.

I have turned on debug logging for npcd, but it means very little to me.

[root@nagiosxi var]# less npcd.log.debug
[06-08-2015 09:19:21] NPCD: npcd Daemon (0.4.14) started with PID=30133
[06-08-2015 09:19:21] NPCD: Please have a look at 'npcd -V' to get license information
[06-08-2015 09:19:21] NPCD: HINT: load_threshold is enabled - ('10.000000')
[06-08-2015 09:19:21] NPCD: Found 264761 files in /usr/local/nagios/var/spool/perfdata/
[06-08-2015 09:19:21] NPCD: DEBUG: load 0.130000/10.000000
[06-08-2015 09:19:21] NPCD: ThreadCounter 0/5 File is .
[06-08-2015 09:19:21] NPCD: DEBUG: load 0.130000/10.000000
[06-08-2015 09:19:21] NPCD: ThreadCounter 0/5 File is ..
[06-08-2015 09:19:21] NPCD: DEBUG: load 0.130000/10.000000
[06-08-2015 09:19:21] NPCD: ThreadCounter 0/5 File is 1343078689.perfdata.service-PID-1925
[06-08-2015 09:19:21] NPCD: File '1343078689.perfdata.service-PID-1925' is an already in process PNP file. Leaving it untouched.
[06-08-2015 09:19:21] NPCD: DEBUG: load 0.130000/10.000000
[06-08-2015 09:19:21] NPCD: ThreadCounter 0/5 File is 1345654160.perfdata.host-PID-2007
[06-08-2015 09:19:21] NPCD: File '1345654160.perfdata.host-PID-2007' is an already in process PNP file. Leaving it untouched.
[06-08-2015 09:19:21] NPCD: DEBUG: load 0.130000/10.000000
[06-08-2015 09:19:21] NPCD: ThreadCounter 0/5 File is 1381343061.perfdata.service-PID-21924
[06-08-2015 09:19:21] NPCD: File '1381343061.perfdata.service-PID-21924' is an already in process PNP file. Leaving it untouched.
[06-08-2015 09:19:21] NPCD: DEBUG: load 0.130000/10.000000
[06-08-2015 09:19:21] NPCD: ThreadCounter 0/5 File is 1431787362.perfdata.host
[06-08-2015 09:19:21] NPCD: Regular File: 1431787362.perfdata.host
[06-08-2015 09:19:21] NPCD: A thread was started on thread_counter = 0
[06-08-2015 09:19:21] NPCD: DEBUG: load 0.130000/10.000000
[06-08-2015 09:19:21] NPCD: Processing file 1431787362.perfdata.host with ID 139914028746496 - going to exec /usr/local/nagios/libexec/process_perfdata.pl -n -b /usr/local/nagios/var/spool/perfdata//1431787362.perfdata.host
[06-08-2015 09:19:21] NPCD: ThreadCounter 1/5 File is 1431787362.perfdata.service
[06-08-2015 09:19:21] NPCD: Processing file '1431787362.perfdata.host'
[06-08-2015 09:19:21] NPCD: Regular File: 1431787362.perfdata.service
[06-08-2015 09:19:21] NPCD: A thread was started on thread_counter = 1
[06-08-2015 09:19:21] NPCD: DEBUG: load 0.130000/10.000000
[06-08-2015 09:19:21] NPCD: ThreadCounter 2/5 File is 1431787377.perfdata.host
[06-08-2015 09:19:21] NPCD: Regular File: 1431787377.perfdata.host
[06-08-2015 09:19:21] NPCD: A thread was started on thread_counter = 2
[06-08-2015 09:19:21] NPCD: DEBUG: load 0.130000/10.000000
[06-08-2015 09:19:21] NPCD: ThreadCounter 3/5 File is 1431787377.perfdata.service
[06-08-2015 09:19:21] NPCD: Regular File: 1431787377.perfdata.service
[06-08-2015 09:19:21] NPCD: A thread was started on thread_counter = 3
[06-08-2015 09:19:21] NPCD: DEBUG: load 0.130000/10.000000
[06-08-2015 09:19:21] NPCD: ThreadCounter 4/5 File is 1431787392.perfdata.host
[06-08-2015 09:19:21] NPCD: Regular File: 1431787392.perfdata.host
[06-08-2015 09:19:21] NPCD: A thread was started on thread_counter = 4
[06-08-2015 09:19:21] NPCD: DEBUG: load 0.130000/10.000000
[06-08-2015 09:19:21] NPCD: ThreadCounter 5/5 File is 1431787392.perfdata.service
[06-08-2015 09:19:21] NPCD: Regular File: 1431787392.perfdata.service
[06-08-2015 09:19:21] NPCD: WARN: MAX Thread reached: 1431787392.perfdata.service comes later with ThreadCounter: 5
[06-08-2015 09:19:21] NPCD: DEBUG: Will wait for th['4']
[06-08-2015 09:19:21] NPCD: ERROR: Executed command exits with return code '2'
[06-08-2015 09:19:21] NPCD: ERROR: Command line was '/usr/local/nagios/libexec/process_perfdata.pl -n -b /usr/local/nagios/var/spool/perfdata//1431787362.perfdata.host'
[06-08-2015 09:19:21] NPCD: Processing file 1431787362.perfdata.service with ID 139914018256640 - going to exec /usr/local/nagios/libexec/process_perfdata.pl -n -b /usr/local/nagios/var/spool/perfdata//1431787362.perfdata.service
[06-08-2015 09:19:21] NPCD: Processing file '1431787362.perfdata.service'
[06-08-2015 09:19:21] NPCD: Processing file 1431787377.perfdata.service with ID 139913928374016 - going to exec /usr/local/nagios/libexec/process_perfdata.pl -n -b /usr/local/nagios/var/spool/perfdata//1431787377.perfdata.service
[06-08-2015 09:19:21] NPCD: Processing file '1431787377.perfdata.service'
[06-08-2015 09:19:21] NPCD: Processing file 1431787392.perfdata.host with ID 139913917884160 - going to exec /usr/local/nagios/libexec/process_perfdata.pl -n -b /usr/local/nagios/var/spool/perfdata//1431787392.perfdata.host
[06-08-2015 09:19:21] NPCD: Processing file '1431787392.perfdata.host'
[06-08-2015 09:19:21] NPCD: Processing file 1431787377.perfdata.host with ID 139914007766784 - going to exec /usr/local/nagios/libexec/process_perfdata.pl -n -b /usr/local/nagios/var/spool/perfdata//1431787377.perfdata.host
[06-08-2015 09:19:21] NPCD: Processing file '1431787377.perfdata.host'
[06-08-2015 09:19:21] NPCD: ERROR: Executed command exits with return code '2'
[06-08-2015 09:19:21] NPCD: ERROR: Command line was '/usr/local/nagios/libexec/process_perfdata.pl -n -b /usr/local/nagios/var/spool/perfdata//1431787362.perfdata.service'
[06-08-2015 09:19:21] NPCD: ERROR: Executed command exits with return code '2'
[06-08-2015 09:19:21] NPCD: ERROR: Command line was '/usr/local/nagios/libexec/process_perfdata.pl -n -b /usr/local/nagios/var/spool/perfdata//1431787392.perfdata.host'
[06-08-2015 09:19:21] NPCD: ERROR: Executed command exits with return code '2'
[06-08-2015 09:19:21] NPCD: ERROR: Command line was '/usr/local/nagios/libexec/process_perfdata.pl -n -b /usr/local/nagios/var/spool/perfdata//1431787377.perfdata.service'

[abrist]

Well, I don't actually think your issues is with npcd load usage, as it looks quite low in those logs. Could you enable and increase the debug level for process_perfdata:
https://support.nagios.com/wiki/index.p ... h_Problems
And then post a large tail of the perfdata log:

Code: Select all

tail -50 /usr/local/nagios/var/perfdata.log

[cambevis]

Done, sir. But the whole log looks pretty much like this, unremarkable (shrug)..

Thanks!

Cam


2015-06-08 13:32:32 [19578] [2] searching for /usr/local/nagios/var/spool/perfdata//1431822702.perfdata.host
2015-06-08 13:32:32 [19578] [2] renaming /usr/local/nagios/var/spool/perfdata//1431822702.perfdata.host to /usr/local/nagios/var/spool/perfdata//1431822702.perfdata.host-PID-19578 for bulk update
2015-06-08 13:32:32 [19580] [2] Using Config File /usr/local/nagios/etc/pnp/process_perfdata.cfg parameters
2015-06-08 13:32:32 [19579] [2] Using Config File /usr/local/nagios/etc/pnp/process_perfdata.cfg parameters
2015-06-08 13:32:32 [19580] [1] process_perfdata.pl-0.4.14 starting in BULK Mode called by NPCD
2015-06-08 13:32:32 [19580] [2] searching for /usr/local/nagios/var/spool/perfdata//1431822717.perfdata.host
2015-06-08 13:32:32 [19580] [2] renaming /usr/local/nagios/var/spool/perfdata//1431822717.perfdata.host to /usr/local/nagios/var/spool/perfdata//1431822717.perfdata.host-PID-19580 for bulk update
2015-06-08 13:32:32 [19579] [1] process_perfdata.pl-0.4.14 starting in BULK Mode called by NPCD
2015-06-08 13:32:32 [19579] [2] searching for /usr/local/nagios/var/spool/perfdata//1431822702.perfdata.service
2015-06-08 13:32:32 [19579] [2] renaming /usr/local/nagios/var/spool/perfdata//1431822702.perfdata.service to /usr/local/nagios/var/spool/perfdata//1431822702.perfdata.service-PID-19579 for bulk update
2015-06-08 13:32:32 [19588] [2] Using Config File /usr/local/nagios/etc/pnp/process_perfdata.cfg parameters
2015-06-08 13:32:32 [19588] [1] process_perfdata.pl-0.4.14 starting in BULK Mode called by NPCD
2015-06-08 13:32:32 [19588] [2] searching for /usr/local/nagios/var/spool/perfdata//1431822732.perfdata.service
2015-06-08 13:32:32 [19588] [2] renaming /usr/local/nagios/var/spool/perfdata//1431822732.perfdata.service to /usr/local/nagios/var/spool/perfdata//1431822732.perfdata.service-PID-19588 for bulk update
2015-06-08 13:32:32 [19589] [2] Using Config File /usr/local/nagios/etc/pnp/process_perfdata.cfg parameters
2015-06-08 13:32:32 [19589] [1] process_perfdata.pl-0.4.14 starting in BULK Mode called by NPCD
2015-06-08 13:32:32 [19589] [2] searching for /usr/local/nagios/var/spool/perfdata//1431822747.perfdata.host
2015-06-08 13:32:32 [19589] [2] renaming /usr/local/nagios/var/spool/perfdata//1431822747.perfdata.host to /usr/local/nagios/var/spool/perfdata//1431822747.perfdata.host-PID-19589 for bulk update
2015-06-08 13:32:32 [19585] [2] Using Config File /usr/local/nagios/etc/pnp/process_perfdata.cfg parameters
2015-06-08 13:32:32 [19584] [2] Using Config File /usr/local/nagios/etc/pnp/process_perfdata.cfg parameters
2015-06-08 13:32:32 [19585] [1] process_perfdata.pl-0.4.14 starting in BULK Mode called by NPCD
2015-06-08 13:32:32 [19585] [2] searching for /usr/local/nagios/var/spool/perfdata//1431822732.perfdata.host
2015-06-08 13:32:32 [19585] [2] renaming /usr/local/nagios/var/spool/perfdata//1431822732.perfdata.host to /usr/local/nagios/var/spool/perfdata//1431822732.perfdata.host-PID-19585 for bulk update
2015-06-08 13:32:32 [19584] [1] process_perfdata.pl-0.4.14 starting in BULK Mode called by NPCD
2015-06-08 13:32:32 [19584] [2] searching for /usr/local/nagios/var/spool/perfdata//1431822717.perfdata.service
2015-06-08 13:32:32 [19584] [2] renaming /usr/local/nagios/var/spool/perfdata//1431822717.perfdata.service to /usr/local/nagios/var/spool/perfdata//1431822717.perfdata.service-PID-19584 for bulk update
2015-06-08 13:32:32 [19590] [2] Using Config File /usr/local/nagios/etc/pnp/process_perfdata.cfg parameters
2015-06-08 13:32:32 [19590] [1] process_perfdata.pl-0.4.14 starting in BULK Mode called by NPCD
2015-06-08 13:32:32 [19590] [2] searching for /usr/local/nagios/var/spool/perfdata//1431822747.perfdata.service
2015-06-08 13:32:32 [19590] [2] renaming /usr/local/nagios/var/spool/perfdata//1431822747.perfdata.service to /usr/local/nagios/var/spool/perfdata//1431822747.perfdata.service-PID-19590 for bulk update
2015-06-08 13:32:32 [19594] [2] Using Config File /usr/local/nagios/etc/pnp/process_perfdata.cfg parameters
2015-06-08 13:32:32 [19594] [1] process_perfdata.pl-0.4.14 starting in BULK Mode called by NPCD
2015-06-08 13:32:32 [19594] [2] searching for /usr/local/nagios/var/spool/perfdata//1431822762.perfdata.host
2015-06-08 13:32:32 [19594] [2] renaming /usr/local/nagios/var/spool/perfdata//1431822762.perfdata.host to /usr/local/nagios/var/spool/perfdata//1431822762.perfdata.host-PID-19594 for bulk update
2015-06-08 13:32:32 [19595] [2] Using Config File /usr/local/nagios/etc/pnp/process_perfdata.cfg parameters
2015-06-08 13:32:32 [19595] [1] process_perfdata.pl-0.4.14 starting in BULK Mode called by NPCD
2015-06-08 13:32:32 [19595] [2] searching for /usr/local/nagios/var/spool/perfdata//1431822762.perfdata.service
2015-06-08 13:32:32 [19595] [2] renaming /usr/local/nagios/var/spool/perfdata//1431822762.perfdata.service to /usr/local/nagios/var/spool/perfdata//1431822762.perfdata.service-PID-19595 for bulk update
2015-06-08 13:32:32 [19598] [2] Using Config File /usr/local/nagios/etc/pnp/process_perfdata.cfg parameters
2015-06-08 13:32:32 [19598] [1] process_perfdata.pl-0.4.14 starting in BULK Mode called by NPCD
2015-06-08 13:32:32 [19598] [2] searching for /usr/local/nagios/var/spool/perfdata//1431822777.perfdata.host
2015-06-08 13:32:32 [19598] [2] renaming /usr/local/nagios/var/spool/perfdata//1431822777.perfdata.host to /usr/local/nagios/var/spool/perfdata//1431822777.perfdata.host-PID-19598 for bulk update
2015-06-08 13:32:32 [19600] [2] Using Config File /usr/local/nagios/etc/pnp/process_perfdata.cfg parameters
2015-06-08 13:32:32 [19599] [2] Using Config File /usr/local/nagios/etc/pnp/process_perfdata.cfg parameters
2015-06-08 13:32:32 [19600] [1] process_perfdata.pl-0.4.14 starting in BULK Mode called by NPCD
2015-06-08 13:32:32 [19600] [2] searching for /usr/local/nagios/var/spool/perfdata//1431822792.perfdata.host
2015-06-08 13:32:32 [19600] [2] renaming /usr/local/nagios/var/spool/perfdata//1431822792.perfdata.host to /usr/local/nagios/var/spool/perfdata//1431822792.perfdata.host-PID-19600 for bulk update
2015-06-08 13:32:32 [19599] [1] process_perfdata.pl-0.4.14 starting in BULK Mode called by NPCD
2015-06-08 13:32:32 [19599] [2] searching for /usr/local/nagios/var/spool/perfdata//1431822777.perfdata.service
2015-06-08 13:32:32 [19599] [2] renaming /usr/local/nagios/var/spool/perfdata//1431822777.perfdata.service to /usr/local/nagios/var/spool/perfdata//1431822777.perfdat

[tmcdonald]

Back to basics perhaps, but what is top showing for processes?

[cambevis]

Nothing get above 5 (mysqld, httpd, etc) until I start up npcd, then npcd goes nuts. I was hoping I'd be able to track it back to a piece of bad data, but no such luck.

[tgriep]

Could you run the following and post the output here?

Code: Select all

ls /usr/local/nagios/var/spool/xidpe | wc -l
ls /usr/local/nagios/var/spool/perfdata | wc -l
ls /usr/local/nagios/var/spool/checkresults | wc -l

[cambevis]

Looks like there's a lot of perfdata!

[root@nagiosxi ~]# ls /usr/local/nagios/var/spool/xidpe | wc -l
0
[root@nagiosxi ~]# ls /usr/local/nagios/var/spool/perfdata | wc -l
287227
[root@nagiosxi ~]# ls /usr/local/nagios/var/spool/checkresults | wc -l
0

[tgriep]

When the npcd daemon isn't running, the performance data gets spooled in this folder

Code: Select all

/usr/local/nagios/var/spool/perfdata

and when it is restarted, it has to go through all of the files in that folder and since you have a lot of files in it, it will load the system until they are all processed.

You can either let the npcd process run through all of the files which could take a while or if you can delete them and start the npcd daemon but if you do this, you will lose the performance data that is in those files.