Intermittent Poller Sync issues

[Netcooler]

Folks,

I noticed today on a fresh cacti installation of 87i that I am intermittently getting:

02/29/2012 07:00:48 AM - POLLER: Poller[0] WARNING: Cron is out of sync with the Poller Interval! The Poller Interval is '300' seconds, with a maximum of a '300' second Cron, but 347 seconds have passed since the last poll!


It is not every cycle but maybe once or twice an hour or two. I am running Spine on RHEL and only have 1 single device right now which is the local host.

Here is more of my Log File:

02/29/2012 07:20:02 AM - SYSTEM THOLD STATS: Time:0.0021 Tholds:0 DownHosts:0
02/29/2012 07:20:02 AM - SYSTEM STATS: Time:0.4271 Method:spine Processes:1 Threads:1 Hosts:2 HostsPerProcess:2 DataSources:13 RRDsProcessed:9
02/29/2012 07:15:02 AM - SYSTEM THOLD STATS: Time:0.1078 Tholds:0 DownHosts:0
02/29/2012 07:15:02 AM - SYSTEM STATS: Time:0.8532 Method:spine Processes:1 Threads:1 Hosts:2 HostsPerProcess:2 DataSources:13 RRDsProcessed:9
02/29/2012 07:10:02 AM - SYSTEM THOLD STATS: Time:0.0024 Tholds:0 DownHosts:0
02/29/2012 07:10:02 AM - SYSTEM STATS: Time:0.4317 Method:spine Processes:1 Threads:1 Hosts:2 HostsPerProcess:2 DataSources:13 RRDsProcessed:9
02/29/2012 07:05:02 AM - SYSTEM THOLD STATS: Time:0.0026 Tholds:0 DownHosts:0
02/29/2012 07:05:02 AM - SYSTEM STATS: Time:1.0293 Method:spine Processes:1 Threads:1 Hosts:2 HostsPerProcess:2 DataSources:13 RRDsProcessed:9
02/29/2012 07:01:04 AM - SYSTEM THOLD STATS: Time:0.0017 Tholds:0 DownHosts:0
02/29/2012 07:01:04 AM - SYSTEM STATS: Time:16.5959 Method:spine Processes:1 Threads:1 Hosts:2 HostsPerProcess:2 DataSources:13 RRDsProcessed:9
02/29/2012 07:00:48 AM - POLLER: Poller[0] WARNING: Cron is out of sync with the Poller Interval! The Poller Interval is '300' seconds, with a maximum of a '300' second Cron, but 347 seconds have passed since the last poll! 02/29/2012 06:55:04 AM - SYSTEM THOLD STATS: Time:0.0022 Tholds:0 DownHosts:0
02/29/2012 06:55:04 AM - SYSTEM STATS: Time:2.9299 Method:spine Processes:1 Threads:1 Hosts:2 HostsPerProcess:2 DataSources:13 RRDsProcessed:9
02/29/2012 06:50:04 AM - SYSTEM THOLD STATS: Time:0.0020 Tholds:0 DownHosts:0
02/29/2012 06:50:04 AM - SYSTEM STATS: Time:3.0073 Method:spine Processes:1 Threads:1 Hosts:2 HostsPerProcess:2 DataSources:13 RRDsProcessed:9
02/29/2012 06:45:03 AM - SYSTEM THOLD STATS: Time:0.0014 Tholds:0 DownHosts:0
02/29/2012 06:45:03 AM - SYSTEM STATS: Time:1.4605 Method:spine Processes:1 Threads:1 Hosts:2 HostsPerProcess:2 DataSources:13 RRDsProcessed:9
02/29/2012 06:40:04 AM - SYSTEM THOLD STATS: Time:0.0023 Tholds:0 DownHosts:0
02/29/2012 06:40:04 AM - SYSTEM STATS: Time:2.3250 Method:spine Processes:1 Threads:1 Hosts:2 HostsPerProcess:2 DataSources:13 RRDsProcessed:9
02/29/2012 06:35:23 AM - SYSTEM THOLD STATS: Time:0.0100 Tholds:0 DownHosts:0
02/29/2012 06:35:23 AM - SYSTEM STATS: Time:10.4937 Method:spine Processes:1 Threads:1 Hosts:2 HostsPerProcess:2 DataSources:13 RRDsProcessed:9
02/29/2012 06:30:47 AM - SYSTEM THOLD STATS: Time:0.0031 Tholds:0 DownHosts:0
02/29/2012 06:30:47 AM - SYSTEM STATS: Time:15.6387 Method:spine Processes:1 Threads:1 Hosts:2 HostsPerProcess:2 DataSources:13 RRDsProcessed:9
02/29/2012 06:30:31 AM - POLLER: Poller[0] WARNING: Cron is out of sync with the Poller Interval! The Poller Interval is '300' seconds, with a maximum of a '300' second Cron, but 330 seconds have passed since the last poll!


What I see is SYSTEM STATS taking much longer during that Cycle. As I review the CRON LOG it appears to fire off my poller every 5 minutes:

Feb 29 06:35:01 q4usc1syu0169 crond[26011]: (cacti) CMD (/usr/bin/php /opt1/cacti/poller.php > /dev/null 2>&1)
Feb 29 06:40:01 q4usc1syu0169 crond[26221]: (cacti) CMD (/usr/bin/php /opt1/cacti/poller.php > /dev/null 2>&1)
Feb 29 06:45:01 q4usc1syu0169 crond[26431]: (cacti) CMD (/usr/bin/php /opt1/cacti/poller.php > /dev/null 2>&1)
Feb 29 06:50:01 q4usc1syu0169 crond[26641]: (cacti) CMD (/usr/bin/php /opt1/cacti/poller.php > /dev/null 2>&1)
Feb 29 06:55:01 q4usc1syu0169 crond[26851]: (cacti) CMD (/usr/bin/php /opt1/cacti/poller.php > /dev/null 2>&1)
Feb 29 07:00:04 q4usc1syu0169 crond[27040]: (cacti) CMD (/usr/bin/php /opt1/cacti/poller.php > /dev/null 2>&1)
Feb 29 07:01:02 q4usc1syu0169 crond[27100]: (root) CMD (run-parts /etc/cron.hourly)
Feb 29 07:05:01 q4usc1syu0169 crond[27261]: (cacti) CMD (/usr/bin/php /opt1/cacti/poller.php > /dev/null 2>&1)
Feb 29 07:10:01 q4usc1syu0169 crond[27541]: (cacti) CMD (/usr/bin/php /opt1/cacti/poller.php > /dev/null 2>&1)
Feb 29 07:15:01 q4usc1syu0169 crond[27771]: (cacti) CMD (/usr/bin/php /opt1/cacti/poller.php > /dev/null 2>&1)
Feb 29 07:20:01 q4usc1syu0169 crond[27969]: (cacti) CMD (/usr/bin/php /opt1/cacti/poller.php > /dev/null 2>&1)



Poller Information
Interval 300
Type SPINE 0.8.7i Copyright 2002-2011 by The Cacti Group
Items Action[0]: 4
Action[1]: 9
Total: 13

Date Wed, 29 Feb 2012 07:34:35 -0600
Cacti Version 0.8.7i
Cacti OS unix
SNMP Version NET-SNMP version: 5.3.2.2
RRDTool Version RRDTool 1.4.x
Hosts 1
Graphs 8
Data Sources Script/Command: 5
SNMP Query: 2
Script Query: 2
Total: 9

Plugin Management (Cacti Version: 0.8.7i, Plugin Architecture Version: 3.1)
Settings 0.71 Global Plugin Settings System Active Jimmy Conner
Domains 0.1 Multiple User Domains for Cacti General Active The Cacti Group
Ugroup 0.2 Multiple User Groups for Cacti General Active The Cacti Group
Thold 0.4.9 Thresholds General Active Jimmy Conner


cron int /etc/cron.d and named cacti
vi of cacti
*/5 * * * * cacti /usr/bin/php /opt1/cacti/poller.php > /dev/null 2>&1

[gandalf]

Is there any hourly process consuming resources?
R.

[Netcooler]

I thought about that but it is not just on the hour sometimes at the 20 minute mark - and so on and completely INCONSISTENT.

Gonna keep watching it.. and wish it away

will post anything

[gandalf]

Perhaps running spine with verbosity=3 helps identifying the host that consumes too much time.
Not too sure, that this will help, as the start phase of polling seems to have that issue.
R.

[Netcooler]

Sadly it is only 1 host...

I think i may have had too much memory in the php.ini.. reduced it to 512 to see if that helps at all. Will let you know

[yoda987]

Ive a similar issue cept mine is constant.

03/01/2012 03:10:00 AM - POLLER: Poller[0] Maximum runtime of 298 seconds exceeded. Exiting.
03/01/2012 03:10:00 AM - SYSTEM STATS: Time:298.7728 Method:spine Processes:1 Threads:4 Hosts:270 HostsPerProcess:270 Dat$
03/01/2012 03:10:00 AM - POLLER: Poller[0] Maximum runtime of 298 seconds exceeded. Exiting.
03/01/2012 03:10:00 AM - SYSTEM STATS: Time:0.1075 Method:spine Processes:1 Threads:4 Hosts:270 HostsPerProcess:270 DataS$
03

CentOS
Poller running every 5 verified in cronlog.

Cacti Version 0.8.7i
Cacti OS unix
SNMP Version NET-SNMP version: 5.5
RRDTool Version RRDTool 1.3.x
Hosts 269
Graphs 345
Data Sources Script/Command: 9
SNMP: 345
SNMP Query: 2
Total: 356

Interval 60
Type Unknown
Items Action[0]: 347
Action[1]: 9
Total: 356
Concurrent Processes 1
Max Threads 4
PHP Servers 1
Script Timeout 25
Max OID 10
Last Run Statistics Time:0.1077 Method:spine Processes:1 Threads:4 Hosts:270 HostsPerProcess:270 DataSources:344 RRDsProcessed:0

[Netcooler]

Yeah - your is a bit different. Mine shows a slight lag between the 5 minute cycles so it may start at 8:00 and the 8:05 and 20 seconds and thats my message. it doesnt happen all the time but there is somethng that causes that poller to delay a bit resource wise like Gandalph indicates.


Yours means your poller is taking WAY to long. - you probably need to invest some time in the Spine Poller (like 5 minutes). It will improve your polling of the 270 hosts significantly and very easy to compile for CentOS

OR you need to ID the hosts that are killing you and bringing you down. I think you go to spine and see how that does

1. download the spine binaries to a tmp location

Credit Thomas Urban (phalek) with the following:
2. do a yum update to get: gcc, mysql-devel, net-snmp-devel, autoconf, automake, libtool

yum install gcc mysql-devel net-snmp-devel autoconf automake libtool

3. unzip and untar the binaries
4. change to that new directory
5. ./bootstrap
6. ./configure
7. make
8. make install
9. cp /usr/local/spine/etc/spine.conf.dist /etc/spine.conf
10. vi /etc/spine.conf and match your DB info
11. then go into cacti web interface nd change poller from cmd to spine


You should see HUGE improvements... HUGE and I hope this helps

[yoda987]

This is running under spine

Type Unknown

Thats a problem as I dont know why it says unknown. But it is spine.

Which set of logs do I need to see which hosts its polling to see if one is killing it?

[Netcooler]

Look at Gandalphs post Above:

"Perhaps running spine with verbosity=3 helps identifying the host that consumes too much time.
Not too sure, that this will help, as the start phase of polling seems to have that issue.
R."

Set your poller to output to /tmp/poller.log instead of dev null (in cron ) so you can see what the poller is doing?

[yoda987]

kk. Where do you change verbosity as well?

[Netcooler]

So - disable the poller in cron..

then run via command line

/PATHTOSPINE/spine/bin/spine --verbosity=X where X is the level