PHP Script Server Timeouts

sasifras · Post by **sasifras** » Fri Sep 25, 2009 7:50 am

I'm still working on the donation bit...I think my case is getting better each day

sasifras · Post by **sasifras** » Fri Sep 25, 2009 7:53 am

ok, this is FLIPPPING bizzare...

09/25/2009 07:48:51 AM - PHPSVR: Poller[0] WARNING: Script Server terminated with signal '15' in file:'/var/www/cacti-0.8.7d/scripts/ss_cisco_cbwfq.php', function:'ss_cisco_cbwfq', params:'<device> <string> 2 161 800 "" "" get qosdroppkts 7.mark-internetwork-control.2.1353.1357'
09/25/2009 07:47:50 AM - PHPSVR: Poller[0] WARNING: Script Server terminated with signal '15' in file:'/var/www/cacti-0.8.7d/scripts/ss_cisco_cbwfq.php', function:'ss_cisco_cbwfq', params:'<device> <string> 2 161 1000 "" "" get qosbyte 1.mark-scavenger-data.1.1129.1149'
09/25/2009 07:47:26 AM - PHPSVR: Poller[0] WARNING: Script Server terminated with signal '15' in file:'/var/www/cacti-0.8.7d/scripts/ss_cisco_cbwfq.php', function:'ss_cisco_cbwfq', params:'<device> <string> 2 161 1000 "" "" get qosbyte 1.mark-transactional-data.1.1129.1137'
09/25/2009 07:47:19 AM - SYSTEM THOLD STATS: Time:0.0530 Tholds:19 Hosts:0
09/25/2009 07:47:18 AM - SYSTEM STATS: Time:136.6092 Method:spine Processes:15 Threads:15 Hosts:1649 HostsPerProcess:110 DataSources:328415 RRDsProcessed:0
09/25/2009 07:47:06 AM - SPINE: Poller[0] WARNING: SS[2] The PHP Script Server did not respond in time and will therefore be restarted
09/25/2009 07:46:31 AM - SPINE: Poller[0] WARNING: SS[1] The PHP Script Server did not respond in time and will therefore be restarted
09/25/2009 07:46:21 AM - SPINE: Poller[0] WARNING: SS[3] The PHP Script Server did not respond in time and will therefore be restarted
09/25/2009 07:46:07 AM - SPINE: Poller[0] WARNING: SS[1] The PHP Script Server did not respond in time and will therefore be restarted
09/25/2009 07:46:06 AM - SPINE: Poller[0] WARNING: SS[0] The PHP Script Server did not respond in time and will therefore be restarted

all I did was download the new version of spine into my personal home dir, uncompress, and stage the patches (I haven't compiled it, installed it, etc). For sanity reasons...

[root@ul563 cacti-spine-0.8.7e]# spine -v
SPINE 0.8.7c

why the heck did this all the sudden start producing your logging?

Note: <device> <string> were inserted by me to protect information.

Post by **TheWitness** » Fri Sep 25, 2009 7:58 am

That's the new script server doing it's thing. So, your QOS polling is bogging down. You should see why that is. If it's what I'm thinking about, it's a nasty script with lot's of overhead that is not required. I offered to fix it for a fee a while ago, but no one bit.

TheWitness

sasifras · Post by **sasifras** » Fri Sep 25, 2009 8:00 am

Actually, I though this was the version you did fix (could be totally off - this isn't the original version, it is the 2nd that I'm aware of)...

So that would explain this?

root 17102 1 0 07:40 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 17455 1 0 07:40 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 17751 1 0 07:40 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 21348 1 0 07:41 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 21812 1 0 07:45 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 21823 1 0 07:45 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 21825 1 0 07:45 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 21831 1 0 07:45 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 21960 1 0 07:45 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 22332 1 0 07:45 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 26784 1 0 07:50 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 26938 1 0 07:50 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 26941 1 0 07:50 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 26948 1 0 07:50 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 27468 1 0 07:50 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 27631 1 0 07:50 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 31090 1 0 07:51 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 31109 1 0 07:51 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 32091 1 0 07:55 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 32092 1 0 07:55 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0

note the "start" times for these? lots of hanging around.

Post by **TheWitness** » Fri Sep 25, 2009 8:20 am

I downloaded the one from here just a few minutes ago. It's pretty clean, although the tab's are missing, so it's a bit hard to read.

I cleaned it up a little more. However, as is, it's about as clean as it will get. It's pretty efficient. So, now I go back and look at the spine code again. However, we have to understand why the devices are not responding. I did not review the script to make sure it's calls to our snmp functions are still correct. But for now, it's time to goto work.

TheWitness

sasifras · Post by **sasifras** » Fri Sep 25, 2009 8:26 am

I believe that is the one we are using (we had to extend it a bit to include 64-bit counters because I think it was set to 32-bit). I'm going to go download that one and just make sure it is what we are using... I'll also try the spine upgrade tomorrow night (can't really hurt anyway) and see where we get to. My main concern is we are graphing about 180+ devices (8 queues) with that script now and we have another 100 waiting to be added. Thanks again!

sasifras · Post by **sasifras** » Fri Sep 25, 2009 8:53 am

I did a quick look-see and it is the same script we are running. We've "extended" the code slightly to include interface speed (for the graph) and added drop packets for each class (cbQosCMDropPkt64). So it should be very similar. I'll get spine upgraded this weekend.

sasifras · Post by **sasifras** » Mon Sep 28, 2009 7:29 am

Upgraded to the latest spine/patches. Still seeing the errors (although I think the assumption is that I would based on the fact that I started seeing the debugging/error codes Friday). The device being impacted keeps changing (doesn't appear to be the same device more then once), and there are no other indications that those devices are slow to respond on that given poll (all other stats return normally from that device). Also, every one of the "errors" is a signal 15 error (for those reported, I do have the feeling that it isn't reporting them all).

09/28/2009 07:12:12 AM - PHPSVR: Poller[0] WARNING: Script Server terminated with signal '15' in file:'/var/www/cacti-0.8.7d/scripts/ss_cisco_cbwfq.php', function:'ss_cisco_cbwfq', params:'<dev1> <snmpstring> 2 161 1000 "" "" get qosbyte 19.class-default.2.1193.1227'
09/28/2009 07:09:01 AM - PHPSVR: Poller[0] WARNING: Script Server terminated with signal '15' in file:'/var/www/cacti-0.8.7d/scripts/ss_cisco_cbwfq.php', function:'ss_cisco_cbwfq', params:'<dev2> <snmpstring> 2 161 800 "" "" get qosdroppkts 6.mark-transactional-data.2.1121.1131'
09/28/2009 07:05:51 AM - SPINE: Poller[0] WARNING: SS[4] The PHP Script Server did not respond in time and will therefore be restarted
09/28/2009 07:01:08 AM - SPINE: Poller[0] WARNING: SS[5] The PHP Script Server did not respond in time and will therefore be restarted
09/28/2009 06:59:38 AM - PHPSVR: Poller[0] WARNING: Script Server terminated with signal '15' in file:'/var/www/cacti-0.8.7d/scripts/ss_cisco_cbwfq.php', function:'ss_cisco_cbwfq', params:'<dev3> <snmpstring> 2 161 500 "" "" get qosdroppkts 9.mark-bulk-data.2.1121.1143'
09/28/2009 06:59:13 AM - PHPSVR: Poller[0] WARNING: Script Server terminated with signal '15' in file:'/var/www/cacti-0.8.7d/scripts/ss_cisco_cbwfq.php', function:'ss_cisco_cbwfq', params:'<dev4> <snmpstring> 2 161 500 "" "" get qosdroppkts 10.mark-scavenger-data.2.1193.1221'
09/28/2009 06:57:10 AM - PHPSVR: Poller[0] WARNING: Script Server terminated with signal '15' in file:'/var/www/cacti-0.8.7d/scripts/ss_cisco_cbwfq.php', function:'ss_cisco_cbwfq', params:'<dev5> <snmpstring> 2 161 1000 "" "" get qosbyte 7.mark-transactional-data.2.2253.2263'
09/28/2009 06:56:06 AM - SPINE: Poller[0] WARNING: SS[4] The PHP Script Server did not respond in time and will therefore be restarted
09/28/2009 06:55:57 AM - SPINE: Poller[0] WARNING: SS[3] The PHP Script Server did not respond in time and will therefore be restarted

You still thinking the script is getting data it can't properly handle in some of these instances?

Post by **TheWitness** » Mon Sep 28, 2009 9:39 am

The signal 15 is spine requesting the script server to restart.

TheWitness

sasifras · Post by **sasifras** » Mon Sep 28, 2009 9:46 am

Because spine didn't get a response from the script server in "X" seconds (Where X = settings->poller->Script Server timeout value)? I guess I'm just trying to figure out if there are other reasons that it would send a sig15.

meralias · Post by **meralias** » Thu Oct 01, 2009 11:40 am

We're seeing a similar issue, were running spine 0.8.7d, upgraded to e + patches, now using the debug server php file.

I'm getting a large number of these lines a second:

10/01/2009 11:37:50 AM - SPINE: Poller[0] ERROR: SS[0] PHP Script Server communications lost. Restarting PHP Script Server
10/01/2009 11:37:50 AM - PHPSVR: Poller[0] WARNING: Script Server terminated with signal '15' in file:'', function:'', params:''

sasifras · Post by **sasifras** » Mon Oct 05, 2009 9:01 am

Just curious if there was any other information on why the signal 15 would be used (see previous post) - like I've said, I don't believe it is because the device is unresponsive since it seemingly changes devices every poll. I've also noticed our poller times have become VERY erratic.

Somewhat off-topic, but wasn't there a plug-in or something someone made to show you polling problems each cycle? I recall reading something about that but can't find it anywhere...

mcutting · Post by **mcutting** » Mon Oct 05, 2009 9:56 am

sasifras wrote:Just curious if there was any other information on why the signal 15 would be used (see previous post) - like I've said, I don't believe it is because the device is unresponsive since it seemingly changes devices every poll. I've also noticed our poller times have become VERY erratic.

Somewhat off-topic, but wasn't there a plug-in or something someone made to show you polling problems each cycle? I recall reading something about that but can't find it anywhere...

There used to be a plugin called "Pollperf" by Gandalf that could give you details like this.

sasifras · Post by **sasifras** » Wed Oct 07, 2009 10:42 am

Thanks for the pointer. I'll have to take a peek at that and see if it puts my systems into the ground

I'm thinking this script server stuff is what is causing some massively erratic poller times since we were rock-consistent before heavily moving in this direction (consistent with scripted processes, became inconsistent when we starting using script server processes).

Sasifras

toe_cutter · Post by **toe_cutter** » Thu Oct 08, 2009 2:00 am

Hi all,

Im also getting these Script Server timeouts :/ Im running TheWitness' edited script_server.php, but not getting any output. Running mysql -e "show processlist" prints out some sleeping NULL processes, but i cant say im too worried about them (TheWitness' shell-script didnt print out anything (just blinking commands occasionally)).

Ill be testing pollperf soon too...

Cacti+spine 0.8.7e, PA 2.5(the working one), weathermap 0.96a, realtime 0.4, aggregate 0.71, spikekill 1.0, boost 2.5.

Setup like BorisL's BIG setup, used his boost first (v2.0?) but then figured that his patches would have been incorporated by now and upgraded to boost 2.5.

So yeah, some coffee and then pollperf!

Edit:
Oh yeah, not only getting the warning, sometimes these others too:

Code: Select all

10/08/2009 03:08:00 AM - SPINE: Poller[0] ERROR: SS[0] An invalid file descriptor was given in one of the sets.  
10/08/2009 03:08:00 AM - SPINE: Poller[0] ERROR: Spine Timed Out While Processing Hosts Internal  
10/08/2009 03:07:30 AM - SPINE: Poller[0] WARNING: SS[0] The PHP Script Server did not respond in time and will therefore be restarted

The Edited script_server.php was running while this was printed.

PHP Script Server Timeouts

Who is online