poller over run

[lard]

hello,

I have a strange issue with gaps in graphs e.t.c. - looking through the stats I'm seeing the following:

06/10/2008 11:59:34 AM - SYSTEM STATS: Time:93.4989 Method:cmd.php Processes:15 Threads:N/A Hosts:240 HostsPerProcess:16 DataSources:9887 RRDsProcessed:4720
06/10/2008 11:54:29 AM - SYSTEM STATS: Time:86.9125 Method:cmd.php Processes:15 Threads:N/A Hosts:240 HostsPerProcess:16 DataSources:9887 RRDsProcessed:4720
06/10/2008 11:47:05 AM - SYSTEM STATS: Time:91.4516 Method:cmd.php Processes:15 Threads:N/A Hosts:240 HostsPerProcess:16 DataSources:9887 RRDsProcessed:4720
06/10/2008 11:39:30 AM - SYSTEM STATS: Time:89.9123 Method:cmd.php Processes:15 Threads:N/A Hosts:240 HostsPerProcess:16 DataSources:9887 RRDsProcessed:4707
06/10/2008 11:35:55 AM - SYSTEM STATS: Time:105.4380 Method:cmd.php Processes:15 Threads:N/A Hosts:240 HostsPerProcess:16 DataSources:9887 RRDsProcessed:4720
06/10/2008 11:29:49 AM - SYSTEM STATS: Time:108.8467 Method:cmd.php Processes:15 Threads:N/A Hosts:240 HostsPerProcess:16 DataSources:9887 RRDsProcessed:4720

From the timings it's showing that the poll takes about 5 minutes yet the stats show approx 100 seconds - is it reasonable to assume that the reason for the time discrepancy is that the poll's finish but then it's rrdtool updating the datasources that is pushing this over the 5 minute period?

I've tried both Spine and CMD and both have this problem - is there any way to have multiple rrdtool processes running to update the data sources? or will boost perhaps improve things?

I've disabled thold & weathermap thinking that this was adding to the polling time (but not being accounted for in the logs) - not sure of how to find out what is pushing the poll over 5 minutes?

of course - I could just be having a senior moment and not interpretting the stats output correctly!

info:

OS: windows 2000
Cacti: 0.8.7a
PHP: 5.2.5
MySQL: 4.1
Spine: 0.8.7

Thanks,

Larry

[Linegod]

The poller is only taking ~90 seconds to complete.

The poller _runs_ every 5 minutes.

[lard]

The more I think about it the more I think it's me being daft!

but to confirm:

06/10/2008 11:54:29 AM - SYSTEM STATS: Time:86.9125 Method:cmd.php Processes:15 Threads:N/A Hosts:240 HostsPerProcess:16 DataSources:9887 RRDsProcessed:4720
06/10/2008 11:47:05 AM - SYSTEM STATS: Time:91.4516 Method:cmd.php Processes:15 Threads:N/A Hosts:240 HostsPerProcess:16 DataSources:9887 RRDsProcessed:4720

Poller completed 11:47:05 - runtime of 91 seconds = 11:45:34 start

Poller completed 11:54:29 - runtime of 86 seconds = 11:53:04 start

That's 3 minutes unaccounted for?

And more recently:

06/10/2008 03:18:25 PM - SYSTEM STATS: Time:93.0368 Method:cmd.php Processes:15 Threads:N/A Hosts:240 HostsPerProcess:16 DataSources:9887 RRDsProcessed:4720
06/10/2008 03:09:48 PM - SYSTEM STATS: Time:108.3359 Method:cmd.php Processes:15 Threads:N/A Hosts:240 HostsPerProcess:16 DataSources:9887 RRDsProcessed:4720

There's a difference of 9 minutes between polls completing - this would explain my graph gaps and also this message:

06/10/2008 03:16:52 PM - POLLER: Poller[0] WARNING: Scheduled Task is out of sync with the Poller Interval! The Poller Interval is '300' seconds, with a maximum of a '300' second Scheduled Task, but 532 seconds have passed since the last poll!

I think this is because the scheduled task is taking longer to complete than the stats indicate?

[Linegod]

Could it be that you have multiple scheduled tasks for poller.php?

[lard]

That would explain it - though I've been through and only have the one scheduled task for poller.php

From watching the poller in the past doesn't it collect all the polling results then pass to rrdtool to update data sources - are you aware if this rrdtool update is counted towards the reported poller time?

[Linegod]

The 'SYSTEM STATS: Time:' is the complete time of the entire process (collection, storage, rrd creation/updating). When in debug, you can see the CACTI2RRD processes, if you want further verification.

Putting things in order:

Code: Select all

06/10/2008 03:18:25 PM - SYSTEM STATS: Time:93.0368 
06/10/2008 03:16:52 PM - POLLER: Poller[0] WARNING: Scheduled Task is out of sync 
06/10/2008 03:09:48 PM - SYSTEM STATS: Time:108.3359 

That would mean that the poller ran at 03:08, failed at ~03:13 and ran at 03:17.

Unless there are other stats in there, the timing of the scheduler appears off (but then Windows is not my area at all....)

[lard]

yep - seems to be - though the windows scheduled task is simple enough (from what I see) - just repeat task every 5 minutes and away you go, checking the server shows last run time and next run time exactly 5 minutes apart.

I'll run the debug and see the increased info for some clues!

Thanks for your input so far

Larry

[lard]

o.k - a debug poller run shows:

Starting:

06/10/2008 04:38:00 PM - POLLER: Poller[0] NOTE: Poller Int: '300', Scheduled Task Int: '300', Time Since Last: '270', Max Runtime '298', Poller Runs: '1'
06/10/2008 04:38:00 PM - CMDPHP: Poller[0] DEBUG: SQL Exec: "replace into settings (name,value) values ('poller_lastrun',1213112280)"
06/10/2008 04:38:00 PM - CMDPHP: Poller[0] DEBUG: SQL Assoc: "select id from host where disabled = '' order by id"
06/10/2008 04:38:00 PM - CMDPHP: Poller[0] DEBUG: SQL Exec: "replace into settings (name,value) values ('path_webroot','e:/Apache2/htdocs/cacti')"
06/10/2008 04:38:00 PM - CMDPHP: Poller[0] DEBUG: SQL Exec: "TRUNCATE TABLE poller_time"
06/10/2008 04:38:00 PM - CMDPHP: Poller[0] DEBUG: SQL Assoc: "SELECT local_data_id, rrd_name FROM poller_output"
06/10/2008 04:38:00 PM - POLLER: Poller[0] DEBUG: About to Spawn a Remote Process [CMD: e:\php\php.exe, ARGS: -q e:/apache2/htdocs/cacti/cmd.php 0 80]
06/10/2008 04:38:00 PM - POLLER: Poller[0] DEBUG: About to Spawn a Remote Process [CMD: e:\php\php.exe, ARGS: -q e:/apache2/htdocs/cacti/cmd.php 81 107]
06/10/2008 04:38:00 PM - POLLER: Poller[0] DEBUG: About to Spawn a Remote Process [CMD: e:\php\php.exe, ARGS: -q e:/apache2/htdocs/cacti/cmd.php 108 140]
06/10/2008 04:38:01 PM - POLLER: Poller[0] DEBUG: About to Spawn a Remote Process [CMD: e:\php\php.exe, ARGS: -q e:/apache2/htdocs/cacti/cmd.php 141 165]
06/10/2008 04:38:01 PM - CMDPHP: Poller[0] DEBUG: SQL Assoc: " SELECT * FROM host WHERE (disabled = '' AND id >= 0 AND id <= 80) ORDER by id"
06/10/2008 04:38:01 PM - CMDPHP: Poller[0] DEBUG: SQL Assoc: "SELECT * FROM poller_item WHERE (host_id >= 0 AND host_id <= 80 AND rrd_next_step <= 0) ORDER by host_id"
06/10/2008 04:38:01 PM - POLLER: Poller[0] DEBUG: About to Spawn a Remote Process [CMD: e:\php\php.exe, ARGS: -q e:/apache2/htdocs/cacti/cmd.php 166 186]
06/10/2008 04:38:01 PM - CMDPHP: Poller[0] DEBUG: SQL Cell: "SELECT count(*) FROM poller_item WHERE (action=2 AND host_id >= 0 AND host_id <= 80 AND rrd_next_step <= 0)"
06/10/2008 04:38:01 PM - POLLER: Poller[0] DEBUG: About to Spawn a Remote Process [CMD: e:\php\php.exe, ARGS: -q e:/apache2/htdocs/cacti/cmd.php 187 209]

e.t.c.

Then the end of one run and beginning of another:

06/10/2008 04:41:18 PM - POLLER: Poller[0] CACTI2RRD: E:\rrdtool\rrdtool.exe update E:\Apache2\htdocs\cacti\rra\redbus300501_errors_in_7415.rrd --template errors_out:errors_in:discards_out:discards_in 1213112475:0:0:0:2489
06/10/2008 04:41:18 PM - POLLER: Poller[0] CACTI2RRD: E:\rrdtool\rrdtool.exe update E:\Apache2\htdocs\cacti\rra\redbus300501_errors_in_7414.rrd --template errors_in:discards_out:errors_out:discards_in 1213112475:0:0:0:26061
06/10/2008 04:41:18 PM - SYSTEM STATS: Time:198.1092 Method:cmd.php Processes:15 Threads:N/A Hosts:240 HostsPerProcess:16 DataSources:9887 RRDsProcessed:4720
06/10/2008 04:41:18 PM - CMDPHP: Poller[0] DEBUG: SQL Exec: "replace into settings (name,value) values ('stats_poller','Time:198.1092 Method:cmd.php Processes:15 Threads:N/A Hosts:240 HostsPerProcess:16 DataSources:9887 RRDsProcessed:4720')"
06/10/2008 04:41:18 PM - CMDPHP: Poller[0] DEBUG: SQL Cell: "select count(*) from poller_command"
06/10/2008 04:41:18 PM - CMDPHP: Poller[0] DEBUG: SQL Assoc: "show tables from `cacti`"
06/10/2008 04:41:20 PM - CMDPHP: Poller[0] DEBUG: SQL Cell: "select cacti from version"
06/10/2008 04:41:20 PM - CMDPHP: Poller[0] DEBUG: SQL Cell: "select id from user_auth where username='0'"
06/10/2008 04:41:20 PM - CMDPHP: Poller[0] DEBUG: SQL Assoc: "select user_auth_realm.realm_id from user_auth_realm where user_auth_realm.user_id='1' and user_auth_realm.realm_id='15'"
06/10/2008 04:41:20 PM - CMDPHP: Poller[0] DEBUG: SQL Cell: "select username from user_auth where id=1"
06/10/2008 04:41:20 PM - CMDPHP: Poller[0] DEBUG: SQL Assoc: "select realm_id from user_auth_realm where user_id=1"
06/10/2008 04:45:04 PM - CMDPHP: Poller[0] DEBUG: SQL Cell: "select cacti from version"
06/10/2008 04:45:04 PM - CMDPHP: Poller[0] DEBUG: SQL Cell: "select id from user_auth where username='0'"
06/10/2008 04:45:04 PM - CMDPHP: Poller[0] DEBUG: SQL Assoc: "select user_auth_realm.realm_id from user_auth_realm where user_auth_realm.user_id='1' and user_auth_realm.realm_id='15'"
06/10/2008 04:45:04 PM - CMDPHP: Poller[0] DEBUG: SQL Cell: "select username from user_auth where id=1"
06/10/2008 04:45:04 PM - CMDPHP: Poller[0] DEBUG: SQL Assoc: "select realm_id from user_auth_realm where user_id=1"
06/10/2008 04:45:04 PM - CMDPHP: Poller[0] DEBUG: SQL Cell: "select cacti from version"
06/10/2008 04:45:04 PM - CMDPHP: Poller[0] DEBUG: SQL Cell: "select id from user_auth where username='0'"
06/10/2008 04:45:04 PM - CMDPHP: Poller[0] DEBUG: SQL Assoc: "select user_auth_realm.realm_id from user_auth_realm where user_auth_realm.user_id='1' and user_auth_realm.realm_id='15'"
06/10/2008 04:45:05 PM - CMDPHP: Poller[0] DEBUG: SQL Cell: "select username from user_auth where id=1"
06/10/2008 04:45:05 PM - CMDPHP: Poller[0] DEBUG: SQL Assoc: "select realm_id from user_auth_realm where user_id=1"
06/10/2008 04:45:05 PM - CMDPHP: Poller[0] DEBUG: SQL Cell: "select count(*) from poller_item where rrd_next_step<=0"
06/10/2008 04:45:05 PM - POLLER: Poller[0] NOTE: Poller Int: '300', Scheduled Task Int: '300', Time Since Last: '425', Max Runtime '298', Poller Runs: '1'
06/10/2008 04:45:05 PM - POLLER: Poller[0] WARNING: Scheduled Task is out of sync with the Poller Interval! The Poller Interval is '300' seconds, with a maximum of a '300' second Scheduled Task, but 425 seconds have passed since the last poll!
06/10/2008 04:45:05 PM - CMDPHP: Poller[0] DEBUG: SQL Exec: "replace into settings (name,value) values ('poller_lastrun',1213112705)"

So it's almost as if the poller is 2 minutes late in running? - bizzare as the scheduled task seems fine - might look at a non windows os task scheduler to see if this solves it?

[Linegod]

It would appear so. Could there be any higher priority tasks pushing the poller down in the queue?

[lard]

not that I can see (as far as priority goes) - though I am also running howies weathermap creation task every 12 minutes that also uses rrdtool (it was every 5 minutes but I had suspicions that it was clashing so increased it)

I'm going to stop this task overnight and see if it solves the problem,

Thanks,

Larry

[lard]

Well - stopped weathermap and also disabled thold to see if this was backing up the poller and it made no difference

From last night:



Strangely I've just watched this and see the following:

EDIT: Annoyingly between me getting the screenshot it changed! - did say last run 10:28 next run 10:38



So it looks like you are spot on - that the server for some bizzare reason goes to run it and it fails?!

I'll run it manually and see what the error may be

Thanks!

Larry

Mod: may need moving to windows specific forum

[lard]

looks like completely a windows issue,

Ran the poller manually and it just sits there in a CMD window - in fact I can't even browse to the drive that apache e.t.c. is installed on - then when the server reacts the CMD just goes back to a prompt with no launch of the cactipoller windows - so I assume it goes past the php script timeout window

Looks like explorer is the cause for this on the server,

Thanks for your pointers with this - I'm off to give this server a good kicking now!