Maximum runtime exceeded due to excessive SQL Assoc cmds

daemon · Post by **daemon** » Fri Mar 24, 2006 11:15 am

I've noticed quite a few "Maximum runtime of X seconds exceeded" messages in my log lately, so I did a debug to try and figure out what's going on. here's an a snippet from a good polling period:

Code: Select all

03/24/2006 09:56:15 AM - CACTID: Poller[0] Host[1731] DEBUG: HOST COMPLETE: About to Exit Host Polling Thread Function
03/24/2006 09:56:15 AM - CACTID: Poller[0] DEBUG: The Value of Active Threads is 1
03/24/2006 09:56:15 AM - CACTID: Poller[0] DEBUG: The Value of Active Threads is 0
03/24/2006 09:56:15 AM - CACTID: Poller[0] DEBUG: The Value of Active Threads is 0
03/24/2006 09:56:16 AM - CMDPHP: Poller[0] DEBUG: SQL Assoc: "select poller_id,end_time from poller_time where poller_id = 0"
03/24/2006 09:56:16 AM - CMDPHP: Poller[0] DEBUG: SQL Assoc: "select  poller_output.output,  poller_output.time,  poller_output.local_data_id,  poller_item.rrd_path,  poller_item.rrd_name,  poller_item.rrd_num  from (poller_output,poller_item)  where (poller_output.local_data_id=poller_item.local_data_id and poller_output.rrd_name=poller_item.rrd_name)"
3/24/2006 09:56:16 AM - CMDPHP: Poller[0] DEBUG: SQL Exec: "delete from poller_output where local_data_id='21146' and rrd_name='cisco_memfree' and time='2006-03-24 09:55:08'"
03/24/2006 09:56:16 AM - CMDPHP: Poller[0] DEBUG: SQL Exec: "delete from poller_output where local_data_id='21147' and rrd_name='cisco_memused' and time='2006-03-24 09:55:08'"
03/24/2006 09:56:16 AM - CMDPHP: Poller[0] DEBUG: SQL Exec: "delete from poller_output where local_data_id='21145' and rrd_name='5min_cpu' and time='2006-03-24 09:55:08'"
03/24/2006 09:56:16 AM - POLLER: Poller[0] CACTI2RRD: /usr/bin/rrdtool update /www/htdocs/cacti-0.8.6h/rra/boxname_cisco_memfree_21146.rrd --template cisco_memfree 1143212108:2698104
03/24/2006 09:56:16 AM - POLLER: Poller[0] CACTI2RRD: /usr/bin/rrdtool update /www/htdocs/cacti-0.8.6h/rra/boxname_cisco_memused_21147.rrd --template cisco_memused 1143212108:2171284
03/24/2006 09:56:16 AM - POLLER: Poller[0] CACTI2RRD: /usr/bin/rrdtool update /www/htdocs/cacti-0.8.6h/rra/boxname_5min_cpu_21145.rrd --template 5min_cpu 1143212108:1
03/24/2006 09:56:16 AM - CACTID: Poller[0] DEBUG: SQLCMD: replace into settings (name,value) values ('date',NOW())
03/24/2006 09:56:16 AM - CACTID: Poller[0] DEBUG: SQLCMD: insert into poller_time (poller_id, start_time, end_time) values (0, NOW(), NOW())
03/24/2006 09:56:16 AM - CACTID: Poller[0] DEBUG: Thread Cleanup Complete
03/24/2006 09:56:16 AM - CACTID: Poller[0] DEBUG: PHP Script Server Pipes Closed
03/24/2006 09:56:16 AM - CACTID: Poller[0] DEBUG: Allocated Variable Memory Freed
03/24/2006 09:56:16 AM - CACTID: Poller[0] CACTID: Shutting down Net-SNMP API
03/24/2006 09:56:16 AM - CACTID: Poller[0] DEBUG: MYSQL Free & Close Completed
03/24/2006 09:56:16 AM - CACTID: Poller[0] Time: 67.7004 s, Threads: 40, Hosts: 163
03/24/2006 09:56:17 AM - CMDPHP: Poller[0] DEBUG: SQL Assoc: "select poller_id,end_time from poller_time where poller_id = 0"
03/24/2006 09:56:17 AM - CMDPHP: Poller[0] DEBUG: SQL Assoc: "select  poller_output.output,  poller_output.time,  poller_output.local_data_id,  poller_item.rrd_path,  poller_item.rrd_name,  poller_item.rrd_num  from (poller_output,poller_item)  where (poller_output.local_data_id=poller_item.local_data_id and poller_output.rrd_name=poller_item.rrd_name)"
03/24/2006 09:56:17 AM - SYSTEM STATS: Time:75.7471 Method:cactid Processes:8 Threads:40 Hosts:1296 HostsPerProcess:162 DataSources:3843 RRDsProcessed:3837
03/24/2006 09:56:17 AM - CMDPHP: Poller[0] DEBUG: SQL Exec: "replace into settings (name,value) values ('stats_poller','Time:75.7471 Method:cactid Processes:8 Threads:40 Hosts:1296 HostsPerProcess:162 DataSources:3843 RRDsProcessed:3837')"
03/24/2006 09:56:17 AM - CMDPHP: Poller[0] DEBUG: SQL Exec: "truncate table poller_output"
03/24/2006 09:56:17 AM - CMDPHP: Poller[0] DEBUG: SQL Cell: "select count(*) from poller_command"
03/24/2006 09:56:17 AM - POLLER: Poller[0] DEBUG: About to Spawn a Remote Process [CMD: /www/php/bin/php, ARGS: -q /www/htdocs/cacti-0.8.6h/poller_export.php]

and here's one of the "exceeded" ones:

Code: Select all

03/24/2006 10:01:15 AM - CACTID: Poller[0] Host[1731] DEBUG: HOST COMPLETE: About to Exit Host Polling Thread Function
03/24/2006 10:01:15 AM - CACTID: Poller[0] DEBUG: The Value of Active Threads is 1
03/24/2006 10:01:15 AM - CACTID: Poller[0] DEBUG: The Value of Active Threads is 0
03/24/2006 10:01:15 AM - CACTID: Poller[0] DEBUG: The Value of Active Threads is 0
03/24/2006 10:01:16 AM - CMDPHP: Poller[0] DEBUG: SQL Assoc: "select poller_id,end_time from poller_time where poller_id = 0"
03/24/2006 10:01:16 AM - CMDPHP: Poller[0] DEBUG: SQL Assoc: "select  poller_output.output,  poller_output.time,  poller_output.local_data_id,  poller_item.rrd_path,  poller_item.rrd_name,  poller_item.rrd_num  from (poller_output,poller_item)  where (poller_output.local_data_id=poller_item.local_data_id and poller_output.rrd_name=poller_item.rrd_name)"
03/24/2006 10:01:16 AM - CMDPHP: Poller[0] DEBUG: SQL Exec: "delete from poller_output where local_data_id='21146' and rrd_name='cisco_memfree' and time='2006-03-24 10:00:08'"
03/24/2006 10:01:16 AM - CMDPHP: Poller[0] DEBUG: SQL Exec: "delete from poller_output where local_data_id='21147' and rrd_name='cisco_memused' and time='2006-03-24 10:00:08'"
03/24/2006 10:01:16 AM - CMDPHP: Poller[0] DEBUG: SQL Exec: "delete from poller_output where local_data_id='21145' and rrd_name='5min_cpu' and time='2006-03-24 10:00:08'"
03/24/2006 10:01:16 AM - POLLER: Poller[0] CACTI2RRD: /usr/bin/rrdtool update /www/htdocs/cacti-0.8.6h/rra/boxname_cisco_memfree_21146.rrd --template cisco_memfree 1143212408:2698080
03/24/2006 10:01:16 AM - POLLER: Poller[0] CACTI2RRD: /usr/bin/rrdtool update /www/htdocs/cacti-0.8.6h/rra/boxname_cisco_memused_21147.rrd --template cisco_memused 1143212408:2171308
03/24/2006 10:01:16 AM - POLLER: Poller[0] CACTI2RRD: /usr/bin/rrdtool update /www/htdocs/cacti-0.8.6h/rra/boxname_5min_cpu_21145.rrd --template 5min_cpu 1143212408:1
03/24/2006 10:01:16 AM - CACTID: Poller[0] DEBUG: SQLCMD: replace into settings (name,value) values ('date',NOW())
03/24/2006 10:01:16 AM - CACTID: Poller[0] DEBUG: SQLCMD: insert into poller_time (poller_id, start_time, end_time) values (0, NOW(), NOW())
03/24/2006 10:01:16 AM - CACTID: Poller[0] DEBUG: Thread Cleanup Complete
03/24/2006 10:01:16 AM - CACTID: Poller[0] DEBUG: PHP Script Server Pipes Closed
03/24/2006 10:01:16 AM - CACTID: Poller[0] DEBUG: Allocated Variable Memory Freed
03/24/2006 10:01:16 AM - CACTID: Poller[0] CACTID: Shutting down Net-SNMP API
03/24/2006 10:01:16 AM - CACTID: Poller[0] DEBUG: MYSQL Free & Close Completed
03/24/2006 10:01:16 AM - CACTID: Poller[0] Time: 67.7478 s, Threads: 40, Hosts: 163
03/24/2006 10:01:17 AM - CMDPHP: Poller[0] DEBUG: SQL Assoc: "select poller_id,end_time from poller_time where poller_id = 0"
03/24/2006 10:01:17 AM - CMDPHP: Poller[0] DEBUG: SQL Assoc: "select  poller_output.output,  poller_output.time,  poller_output.local_data_id,  poller_item.rrd_path,  poller_item.rrd_name,  poller_item.rrd_num  from (poller_output,poller_item)  where (poller_output.local_data_id=poller_item.local_data_id and poller_output.rrd_name=poller_item.rrd_name)"
03/24/2006 10:01:18 AM - CMDPHP: Poller[0] DEBUG: SQL Assoc: "select poller_id,end_time from poller_time where poller_id = 0"

…

03/24/2006 10:04:53 AM - CMDPHP: Poller[0] DEBUG: SQL Assoc: "select  poller_output.output,  poller_output.time,  poller_output.local_data_id,  poller_item.rrd_path,  poller_item.rrd_name,  poller_item.rrd_num  from (poller_output,poller_item)  where (poller_output.local_data_id=poller_item.local_data_id and poller_output.rrd_name=poller_item.rrd_name)"
03/24/2006 10:04:54 AM - CMDPHP: Poller[0] DEBUG: SQL Assoc: "select poller_id,end_time from poller_time where poller_id = 0"
03/24/2006 10:04:54 AM - CMDPHP: Poller[0] DEBUG: SQL Assoc: "select  poller_output.output,  poller_output.time,  poller_output.local_data_id,  poller_item.rrd_path,  poller_item.rrd_name,  poller_item.rrd_num  from (poller_output,poller_item)  where (poller_output.local_data_id=poller_item.local_data_id and poller_output.rrd_name=poller_item.rrd_name)"
03/24/2006 10:04:54 AM - POLLER: Poller[0] Maximum runtime of 292 seconds exceeded. Exiting.
03/24/2006 10:04:54 AM - SYSTEM STATS: Time:293.4171 Method:cactid Processes:8 Threads:40 Hosts:1296 HostsPerProcess:162 DataSources:3843 RRDsProcessed:3603
03/24/2006 10:04:54 AM - CMDPHP: Poller[0] DEBUG: SQL Exec: "replace into settings (name,value) values ('stats_poller','Time:293.4171 Method:cactid Processes:8 Threads:40 Hosts:1296 HostsPerProcess:162 DataSources:3843 RRDsProcessed:3603')"

where I put the elipses (...) there are nothing but those "SQL Assoc" commands. any idea what might be causing all of them? I actually have an identical box that I exported to the box that is now having these problems, but the original box wasn't doing this. I have done some things in the meantime, like adding hosts, but can't remember doing anything that might have caused this.

any ideas would be appreciated.
thanks!
-brian

Post by **rony** » Sat Mar 25, 2006 8:04 pm

What version of mysql are you running?

daemon · Post by **daemon** » Sat Mar 25, 2006 10:01 pm

sorry, it's all in my sig but somehow it didn't make it to this post. it's 4.1.16.

daemon · Post by **daemon** » Wed Mar 29, 2006 6:37 pm

any ideas on this? it's still going on. looks like it might have something to do with this section in poller.php:

Code: Select all

        while (1) {
                $polling_items = db_fetch_assoc("select poller_id,end_time from poller_time where poller_id = 0");

                if (sizeof($polling_items) == $process_file_number) {
                        $rrds_processed = $rrds_processed + process_poller_output($rrdtool_pipe);

                        /* take time and log performance data */
                        list($micro,$seconds) = split(" ", microtime());
                        $end = $seconds + $micro;

                        $cacti_stats = sprintf(
                                "Time:%01.4f " .
                                "Method:%s " .
                                "Processes:%s " .
                                "Threads:%s " .
                                "Hosts:%s " .
                                "HostsPerProcess:%s " .
                                "DataSources:%s " .

daemon · Post by **daemon** » Fri Mar 31, 2006 5:00 pm

I'm going to give this one more shot in the hopes that this additional info sheds some light on the problem...

I added a couple of lines to the poller.php to print out the values, because it seemed that sizeof($polling_items) was never equal to $process_file_number. and, in fact, that's what I found, because these lines appeared in the log until MAX_POLLER_RUNTIME was reached:
=================================================================
03/30/2006 10:33:31 AM - CMDPHP: Poller[0] ****size of polling items is 3, process file number is 4****
03/30/2006 10:33:32 AM - CMDPHP: Poller[0] ****size of polling items is 3, process file number is 4****
03/30/2006 10:33:33 AM - CMDPHP: Poller[0] ****size of polling items is 3, process file number is 4**** =================================================================
here's what the SQL query looked like when I ran it manually while this was going on:

Code: Select all

mysql> select poller_id,end_time from poller_time where poller_id = 0;
+-----------+---------------------+
| poller_id | end_time            |
+-----------+---------------------+
|         0 | 2006-03-30 10:31:10 |
|         0 | 2006-03-30 10:31:11 |
|         0 | 2006-03-30 10:31:12 |
+-----------+---------------------+
3 rows in set (0.00 sec)

it looks like one of the cactid processes is dying prior to the others and not reporting itself as having ended. so, when poller.php does its SQL query to see if all the processes have ended, that one isn't showing up. this is why the number of polling items is always 3. here's a couple of process listings showing the same bahaviour.

Code: Select all

first run, all processes are still running
501       8381     1  0 16:30 ?        00:00:00 /usr/local/cactid/bin/cactid 0 724
501       8398     1  0 16:30 ?        00:00:00 /usr/local/cactid/bin/cactid 725 1053
501       8422     1  0 16:30 ?        00:00:00 /usr/local/cactid/bin/cactid 1054 1380
501       8456     1  0 16:30 ?        00:00:00 /usr/local/cactid/bin/cactid 1381 1726

second run, cactid 0 724 is now gone
501       8398     1  0 16:30 ?        00:00:00 /usr/local/cactid/bin/cactid 725 1053
501       8422     1  0 16:30 ?        00:00:00 /usr/local/cactid/bin/cactid 1054 1380
501       8456     1  0 16:30 ?        00:00:00 /usr/local/cactid/bin/cactid 1381 1726

when those 3 processes end, their endtimes are added to the databases but the first one never is because, I'm assuming, it's exiting abnormally.

any help would be most appreciated.
thanks!

daemon · Post by **daemon** » Fri Mar 31, 2006 7:18 pm

assuming anyone actually cares, I think I was able to fix it.

I went on another box of mine and noticed the cactid was a different file size, even though it was the same version. the one on the problem box has this output:

Code: Select all

CACTID 0.8.6f  Copyright 2002-2005 by The Cacti Group

Usage: cactid [start_host_id end_host_id]

If you do not specify [start_host_id end_host_id], Cactid will poll all hosts.

Cactid relies on the cactid.conf file that can exist in multiple locations.
The first location checked is the current directory.  Optionally, it can be
placed in the '/etc' directory.

Cactid is distributed under the Terms of the GNU General
Public License Version 2. (www.gnu.org/copyleft/gpl.html)

For more information, see http://www.cacti.net

while the other one, that seems to have fixed the problem, looks like this:

Code: Select all

CACTID 0.8.6f  Copyright 2002-2005 by The Cacti Group

Usage: cactid [options] [firstid lastid]

Options:

  -h/--help          Show this brief help listing
  -f/--first=X       Start polling with host X
  -l/--last=X        End polling with host X
  -p/--poller=X      Poller ID = X
  -C/--conf=F        Read Cactid configuration from file F
  -O/--option=S:V    Override DB settings 'set' with value 'V'
  -R/--readonly      This Cactid run is readonly with respect to the database
  -S/--stdout        Logging is performed to the standard output
  -V/--verbosity=V   Set logging verbosity to <V>
  --snmponly         Only do SNMP polling: no script stuff

Either both of --first/--last must be provided, or neither can be,
and in their absense, all hosts are processed.

Without the --conf parameter, cactid searches for its cactid.conf
file in the usual places.

Verbosity is one of NONE/LOW/MEDIUM/HIGH/DEBUG or 1..5

Runtime options are read from the 'settings' table in the Cacti
database, but they can be overridden with the --option=S:V
parameter.

Cactid is distributed under the Terms of the GNU General
Public License Version 2. (www.gnu.org/copyleft/gpl.html)
For more information, see http://www.cacti.net

I'm assuming the one is 0.8.6f and the other is 0.8.6f-1, that I see mentioned in the cactid changelog. at any rate, things are looking good now, so I'll try to leave everyone alone for at least a week or so.

Post by **rony** » Fri Mar 31, 2006 9:08 pm

Later one is accually 0.8.6g, the version wasn't updated properly.

Post by **TheWitness** » Fri Mar 31, 2006 10:34 pm

Your issue is caused by a Cactid segfault. Grab the latest SVN of branch_0_8_6 and try that. Just download the *.c and *.h files and remake.

Thanks,

TheWitness

daemon · Post by **daemon** » Tue Apr 04, 2006 12:55 pm

TheWitness wrote:Your issue is caused by a Cactid segfault. Grab the latest SVN of branch_0_8_6 and try that. Just download the *.c and *.h files and remake.

I appreciate the reply as the problem has resurfaced. I downloaded the branch that you mentioned with svn, copied it over the source for 0.8.6g and then configured it, made it and installed it. after doing this, though, I'm still seeing the same thing. one or more of the cactid process will die, leaving poller.php thinking that they haven't all completed yet. hopefully I did something obviously dumb.

Post by **TheWitness** » Tue Apr 04, 2006 8:59 pm

You should send me a full debug log and also send me a database dump so that I can analyze.

TheWitness

Post by **TheWitness** » Tue Apr 04, 2006 9:00 pm

Oh, also, please upgrade from PHP 5.1.1, very buggy. This may be leading to the segfaults.

TheWitness

daemon · Post by **daemon** » Wed Apr 05, 2006 3:50 pm

did the 5.1.2 upgrade and it didn't seem to make any difference. just e-mailed you the files you requested.
thanks!

daemon · Post by **daemon** » Fri Apr 07, 2006 9:34 am

ok, with help from the witness it looks like this problem has finally been fixed...for real this time.

turns out that MYSQL was getting too many connections and cactid was failing, as evidenced by these entries below:

Code: Select all

04/05/2006 03:45:58 PM - CACTID: Poller[0] MYSQL: Connection Failed: Too many connections
04/05/2006 03:45:58 PM - CACTID: Poller[0] FATAL: Cactid Fork process encountered a FATAL error and must exit

so, I had to edit /etc/my.cnf and add the following line under [mysqld]:
set-variable=max_connections=2000

and then restart mysqld. after that, all is well!
thanks much to larry and all who looked at this thread.

lorcs · Post by **lorcs** » Mon Apr 10, 2006 1:09 pm

daemon wrote:ok, with help from the witness it looks like this problem has finally been fixed...for real this time.

turns out that MYSQL was getting too many connections and cactid was failing, as evidenced by these entries below:
Code: Select all
04/05/2006 03:45:58 PM - CACTID: Poller[0] MYSQL: Connection Failed: Too many connections
04/05/2006 03:45:58 PM - CACTID: Poller[0] FATAL: Cactid Fork process encountered a FATAL error and must exit
so, I had to edit /etc/my.cnf and add the following line under [mysqld]:
set-variable=max_connections=2000

and then restart mysqld. after that, all is well!
thanks much to larry and all who looked at this thread.

Hi,

I also have similar problem as the CACTID run time exceeding 292s. I see two poller processes are forked. However, with your method of adding additional statement in my.cnf, my problem still persists. Do you have any other things that also need to be done to get the problem fixed

Best Regards

Raymond Lo

daemon · Post by **daemon** » Mon Apr 10, 2006 1:14 pm

lorcs wrote: Hi,

I also have similar problem as the CACTID run time exceeding 292s. I see two poller processes are forked. However, with your method of adding additional statement in my.cnf, my problem still persists. Do you have any other things that also need to be done to get the problem fixed

Best Regards

Raymond Lo

I would turn on debug to see exactly what it is doing during that time. it could be any number of things not necessarily related to the SQL connections.
-brian

Maximum runtime exceeded due to excessive SQL Assoc cmds

Maximum runtime exceeded due to excessive SQL Assoc cmds

Who is online