PHP Script Server Timeouts

sasifras · Post by **sasifras** » Wed Sep 23, 2009 7:57 am

My log files generally contain a fair number of entries such as these:

09/23/2009 07:42:21 AM - SPINE: Poller[0] WARNING: SS[7] The PHP Script Server did not respond in time and will therefore be restarted
09/23/2009 07:41:54 AM - SPINE: Poller[0] WARNING: SS[7] The PHP Script Server did not respond in time and will therefore be restarted
09/23/2009 07:41:14 AM - SPINE: Poller[0] WARNING: SS[6] The PHP Script Server did not respond in time and will therefore be restarted
09/23/2009 07:41:10 AM - SPINE: Poller[0] WARNING: SS[0] The PHP Script Server did not respond in time and will therefore be restarted
09/23/2009 07:40:57 AM - SPINE: Poller[0] WARNING: SS[2] The PHP Script Server did not respond in time and will therefore be restarted

My question is should I be concerned with these logged entries (my guess is yes)? We heavily utilize the script server (>7K objects per poll pass) and need to add even more to it if we find it running in a healthy state. I've reviewed several posts/docs on "troubleshooting" PHP script server stuff, but none seem to address the timeouts. We know our script runs clean (it is heavily based on the Cisco CBWFQ SS template) when the far-end device is alive.

Could these timeouts be the result of the far-end device just not responding within the script server timeout (currently 25 seconds)?

Would adding more script servers help (not likely, but figured I'd ask) (currently set to 10 which is described as the max)?

Is there any way to get more insight into what the/that script server was doing before it timed out?

Any ideas would be helpful to us. Thanks!

Sasifras

Post by **TheWitness** » Wed Sep 23, 2009 8:00 pm

Try reducing the number of script servers. I have seen this issue lately and it may be an issue with the fork command in Linux. I don't have too much time, but FD's may be getting hosed. I had not seen this until recently. However, my time is limited right now to debug.

TheWitness

sasifras · Post by **sasifras** » Thu Sep 24, 2009 7:43 am

I will try to reduce the number of PHP script servers a few at a time over a period of time to see if that "helps" without negatively impacting poller times and I will report back. So far I've reduced from 10 to 7 and seen no negative impacts, but no positive ones either (still seeing the errors).

09/24/2009 07:37:26 AM - SPINE: Poller[0] WARNING: SS[2] The PHP Script Server did not respond in time and will therefore be restarted
09/24/2009 07:37:07 AM - SPINE: Poller[0] WARNING: SS[5] The PHP Script Server did not respond in time and will therefore be restarted
09/24/2009 07:36:59 AM - SPINE: Poller[0] WARNING: SS[2] The PHP Script Server did not respond in time and will therefore be restarted
09/24/2009 07:36:16 AM - SPINE: Poller[0] WARNING: SS[2] The PHP Script Server did not respond in time and will therefore be restarted
09/24/2009 07:35:49 AM - SPINE: Poller[0] WARNING: SS[2] The PHP Script Server did not respond in time and will therefore be restarted

Post by **TheWitness** » Thu Sep 24, 2009 8:04 am

Write a simple watch script that does the following, to see if there are MySQL delays that are causing problems in polling:

Code: Select all

#!/bin/bash
while [ 1 ]; do
  clear
  mysql -e "show processlist" | grep -v NULL | grep -v Sleep"
  sleep 1
done

Also, I have a modified script server that will tell us what is timing out. However, it's not in SVN presently. Something is either timing out, or written poorly aka returning results with an echo or a print instead of a return.

TheWitness

sasifras · Post by **sasifras** » Thu Sep 24, 2009 10:11 am

When running the script through a poll cycle the ends with errors I don't see anything that to me looks like a problem (each second the screen refreshes, new lines on it, etc etc). I don't, for instance, see a screen loaded with locks/etc). The highest command time I see is usually 1, sometimes (rarely) a 2.

I just started noticing these, but they could have been happening for a long time so I'm not sure without some output to tell me which instance died running which script I'm not sure I can do much more deduction. I'm going to lean towards it not being the echo/print issue since we use one of about 3 different script server scripts on thousands of objects and I would think it if was because of an echo/print, the data wouldn't be graphing properly (maybe that is a bad assumption).

I've gotten down to 3 script servers and I don't think I can go any lower (poll time is up to about 250 seconds). Also, my gut feeling is that the errors are INCREASING as I've reduced the script server counts, not decreasing....

09/24/2009 10:02:46 AM - SPINE: Poller[0] WARNING: SS[1] The PHP Script Server did not respond in time and will therefore be restarted
09/24/2009 10:02:09 AM - SPINE: Poller[0] WARNING: SS[0] The PHP Script Server did not respond in time and will therefore be restarted
09/24/2009 10:01:57 AM - SPINE: Poller[0] WARNING: SS[0] The PHP Script Server did not respond in time and will therefore be restarted
09/24/2009 10:01:37 AM - SPINE: Poller[0] WARNING: SS[1] The PHP Script Server did not respond in time and will therefore be restarted
09/24/2009 10:01:31 AM - SPINE: Poller[0] WARNING: SS[2] The PHP Script Server did not respond in time and will therefore be restarted
09/24/2009 10:01:05 AM - SPINE: Poller[0] WARNING: SS[1] The PHP Script Server did not respond in time and will therefore be restarted
09/24/2009 10:01:05 AM - SPINE: Poller[0] WARNING: SS[2] The PHP Script Server did not respond in time and will therefore be restarted
09/24/2009 10:00:46 AM - SPINE: Poller[0] WARNING: SS[1] The PHP Script Server did not respond in time and will therefore be restarted
09/24/2009 10:00:46 AM - SPINE: Poller[0] WARNING: SS[1] The PHP Script Server did not respond in time and will therefore be restarted
09/24/2009 10:00:40 AM - SPINE: Poller[0] WARNING: SS[0] The PHP Script Server did not respond in time and will therefore be restarted
09/24/2009 10:00:40 AM - SPINE: Poller[0] WARNING: SS[1] The PHP Script Server did not respond in time and will therefore be restarted

I think I need to hangout until you get a chance to put the other script server code up (btw, we're still running 0.8.7d in case that matters on this one).

Post by **TheWitness** » Thu Sep 24, 2009 7:08 pm

Ok, bump them back up again. I will attache the patched script server for reference. Please give it another name and test before you deploy.

TheWitness

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

I put the new script into place (thank you by the way). It didn't appear to be running the "correct" version at first, so I went looking and found this hanging around:

root 18974 1 0 07:10 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0

My understanding was that all these should "close" out after the poller completes it cycle, that wasn't the case and might have been why the newer version wasn't/isn't being run (from what I can tell I should be getting a different msg in my logfiles now and I'm not). I did kill (had to kill -9 that) that process to ensure the system started off all new ones.

I also noticed this with the new code (didn't look with the "old" but I can't see how this part would be different):

root 24006 24005 6 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24009 24008 7 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24012 24011 9 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24017 24005 10 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24018 24016 10 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24019 24008 10 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24022 24011 6 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24023 24021 8 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24026 24005 8 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24027 24016 7 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24028 24008 7 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24039 24011 7 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24048 24021 9 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24049 24047 8 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24082 24079 8 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24155 24143 14 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24159 24157 14 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24160 24016 14 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24161 24008 15 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24162 24005 14 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24163 24011 14 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24164 24016 14 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24165 24008 14 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24166 24005 14 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24169 24016 14 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24170 24008 0 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24171 24011 0 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24172 24005 0 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24173 24047 0 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24174 24021 0 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24175 24016 0 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24176 24011 0 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24177 24008 0 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24178 24005 0 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24179 24047 0 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24180 24079 0 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24181 24143 0 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0
root 24182 24157 0 07:15 ? 00:00:00 /usr/bin/php -q /var/www/cacti-0.8.7d/script_server.php spine 0

I have the system configured for 10 script servers, I counted 38 here and I think there were actually more (if I'm reading that right).

Did I need to do something "special" to get the new logging to appear?

I am still getting the "generic" log msgs:

09/25/2009 07:16:27 AM - SPINE: Poller[0] WARNING: SS[0] The PHP Script Server did not respond in time and will therefore be restarted

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

Hmm, what version of Spine again? Do you have patches? Something is timing out. The new script server generates log's when scripts have issues like timeouts. They should appear in your log.

TheWitness

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

That's what I was thinking too... but I'm not seeing anything different (it looked like they were standard "warning" level messages which I should see with this level of logging).

SPINE 0.8.7c

edit:
It "feels" like something is cached - which is why I killed off the carry-over script server processes but I can't figure out what would have this stuff cached at this point. Also, I was going to mod the generic error: The PHP Script Server did not respond in time and will therefore be restarted to be "slightly" different so I could see if it was running the correct version, but that error doesn't seem to be inside the script_server code itself so.....

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

Don't use that version. Use 0.8.7e + patches. The patches for don't apply for Windows if you just want to use the binary. I think you will find the processes that are hanging around will go away on Windows.

TheWitness

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

Sorry, slet the "Windows" comment. That was the last post

TheWitness

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

I'm not fully sure I understand what the windows comments mean (since we are a unix shop), but it sounds like I need to move up to 8.7e+patches spine. No worries about running 8.7e spine and 8.7d cacti, right?

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

No there are no issues. And if you read the post I posted right after my last post you would see that I'm having issues going from post to post. I guess I just have Windows on the brain right now.

When spine signals those processes to kill, with the new script server, they should log first to the Cacti log. Let's make sure that is happening. Once you do that, you will at least know the script that is timing out.

TheWitness

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

I saw your post, just didn't go back and edit mine (it did look like 2 different thoughts

). I won't be able to swap spine out today because of prod use, but I have some maintenance I need to do tomorrow night and I'll try to do it then.

Thanks for all your help...I have no idea how you do all this,

Sasifras

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

I have "no" personal life. I live to code. I will die with my hands on a keyboard somewhere. (Well, it's just a little overstated. Tonight I take the kids to dinner). A little donation to the Cacti Group would help me pay for it. Well, actually not, but it will pay for beer next year at our annual meeting of the Cacti Group

TheWitness

PHP Script Server Timeouts

PHP Script Server Timeouts

Who is online