22 Nov
2005
22 Nov
'05
4:19 p.m.
Today we had an incident where SER (0.9.4) children drained all the CPUs
of one of our servers.
Top Showed:
PID USER PRI NI SIZE RSS SHARE STAT %CPU %MEM TIME CPU COMMAND
17925 root 25 0 5644 5644 3888 R 25.5 0.2 6:26 1 ser
17929 root 25 0 5672 5672 3880 R 24.7 0.2 6:48 0 ser
17928 root 25 0 5688 5688 3872 R 24.3 0.2 6:25 1 ser
17933 root 25 0 4540 4540 3740 R 22.8 0.2 6:00 0 ser
And ..
# ps -Al | grep ser
1 S 0 17901 1 0 85 0 - 14200 pause ? 00:00:00 ser
1 S 0 17916 17901 0 75 0 - 14200 pipe_w ? 00:00:00 ser
1 S 0 17917 17901 0 75 0 - 14418 schedu ? 00:00:22 ser
1 S 0 17918 17901 0 75 0 - 14422 schedu ? 00:00:23 ser
1 S 0 17919 17901 0 75 0 - 14423 schedu ? 00:00:24 ser
1 S 0 17920 17901 0 75 0 - 14447 schedu ? 00:00:22 ser
1 S 0 17921 17901 0 75 0 - 14421 schedu ? 00:00:22 ser
1 S 0 17922 17901 0 75 0 - 14424 schedu ? 00:00:22 ser
1 S 0 17923 17901 0 75 0 - 14428 schedu ? 00:00:21 ser
1 S 0 17924 17901 0 75 0 - 14424 schedu ? 00:00:22 ser
1 R 0 17925 17901 0 85 0 - 14448 - ? 00:06:22 ser
1 S 0 17926 17901 0 75 0 - 14457 schedu ? 00:00:49 ser
1 S 0 17927 17901 0 75 0 - 14453 schedu ? 00:00:50 ser
1 R 0 17928 17901 0 85 0 - 14477 - ? 00:06:20 ser
1 R 0 17929 17901 0 85 0 - 14455 - ? 00:06:44 ser
1 S 0 17930 17901 0 75 0 - 14452 schedu ? 00:00:50 ser
1 S 0 17931 17901 0 75 0 - 14448 schedu ? 00:00:50 ser
1 S 0 17932 17901 0 76 0 - 14448 schedu ? 00:00:49 ser
1 R 0 17933 17901 0 85 0 - 14235 - ? 00:05:55 ser
As you can see it looks like 4 children dropped out of the scheduler.
The only thing suspicious is that RTPProxy became non-responsive around
that time. At least thats the only thing the log shows:
Nov 22 15:56:17 /usr/local/sbin/ser[17931]: ERROR: send_rtpp_command:
timeout waiting reply from a RTP proxy
Any idea why these 4 children dropped out? Any hints on how to
troubleshoot this?
Thanks,
--
Andres
Network Admin
http://www.telesip.net
23 Nov
23 Nov
1:58 a.m.
Andres,
I believe I remember this issue being brought up a while back. If I remember
correctly, ser children locked up when communicating to a locked rtpproxy
over socket interface. The "solution" was to use udp over loopback to
communicate as this would fail that specific call, but not lock the ser
process.
g-)
----- Original Message -----
From: "Andres" <andres(a)telesip.net>
To: <serusers(a)lists.iptel.org>
Sent: Tuesday, November 22, 2005 10:19 PM
Subject: [Serusers] SER Children Misbehaving
Today we had an incident where SER (0.9.4) children
drained all the CPUs
of one of our servers.
Top Showed:
PID USER PRI NI SIZE RSS SHARE STAT %CPU %MEM TIME CPU COMMAND
17925 root 25 0 5644 5644 3888 R 25.5 0.2 6:26 1 ser
17929 root 25 0 5672 5672 3880 R 24.7 0.2 6:48 0 ser
17928 root 25 0 5688 5688 3872 R 24.3 0.2 6:25 1 ser
17933 root 25 0 4540 4540 3740 R 22.8 0.2 6:00 0 ser
And ..
# ps -Al | grep ser
1 S 0 17901 1 0 85 0 - 14200 pause ? 00:00:00 ser
1 S 0 17916 17901 0 75 0 - 14200 pipe_w ? 00:00:00 ser
1 S 0 17917 17901 0 75 0 - 14418 schedu ? 00:00:22 ser
1 S 0 17918 17901 0 75 0 - 14422 schedu ? 00:00:23 ser
1 S 0 17919 17901 0 75 0 - 14423 schedu ? 00:00:24 ser
1 S 0 17920 17901 0 75 0 - 14447 schedu ? 00:00:22 ser
1 S 0 17921 17901 0 75 0 - 14421 schedu ? 00:00:22 ser
1 S 0 17922 17901 0 75 0 - 14424 schedu ? 00:00:22 ser
1 S 0 17923 17901 0 75 0 - 14428 schedu ? 00:00:21 ser
1 S 0 17924 17901 0 75 0 - 14424 schedu ? 00:00:22 ser
1 R 0 17925 17901 0 85 0 - 14448 - ? 00:06:22 ser
1 S 0 17926 17901 0 75 0 - 14457 schedu ? 00:00:49 ser
1 S 0 17927 17901 0 75 0 - 14453 schedu ? 00:00:50 ser
1 R 0 17928 17901 0 85 0 - 14477 - ? 00:06:20 ser
1 R 0 17929 17901 0 85 0 - 14455 - ? 00:06:44 ser
1 S 0 17930 17901 0 75 0 - 14452 schedu ? 00:00:50 ser
1 S 0 17931 17901 0 75 0 - 14448 schedu ? 00:00:50 ser
1 S 0 17932 17901 0 76 0 - 14448 schedu ? 00:00:49 ser
1 R 0 17933 17901 0 85 0 - 14235 - ? 00:05:55 ser
As you can see it looks like 4 children dropped out of the scheduler. The
only thing suspicious is that RTPProxy became non-responsive around that
time. At least thats the only thing the log shows:
Nov 22 15:56:17 /usr/local/sbin/ser[17931]: ERROR: send_rtpp_command:
timeout waiting reply from a RTP proxy
Any idea why these 4 children dropped out? Any hints on how to
troubleshoot this?
Thanks,
--
Andres
Network Admin
http://www.telesip.net
_______________________________________________
Serusers mailing list
serusers(a)lists.iptel.org
http://lists.iptel.org/mailman/listinfo/serusers
10:15 a.m.
Hi Greger,
For this same reason we switched to a UDP interface about 6 months ago.
But as you can see we still managed to get 4 Children locked up. It
still was able to do millions of transaction since the last lockup (2
months ago) but we are still clueless about why this is happening. We
have rtpproxy running again in the foreground outputting all messages to
a file. Hopefully this will provide enough info to get to the bottom of
this.
Thanks,
--
Andres
Network Admin
http://www.telesip.net
Greger V. Teigre wrote:
Andres,
I believe I remember this issue being brought up a while back. If I
remember correctly, ser children locked up when communicating to a
locked rtpproxy over socket interface. The "solution" was to use udp
over loopback to communicate as this would fail that specific call,
but not lock the ser process.
g-)
----- Original Message ----- From: "Andres" <andres(a)telesip.net>
To: <serusers(a)lists.iptel.org>
Sent: Tuesday, November 22, 2005 10:19 PM
Subject: [Serusers] SER Children Misbehaving
Today we had an incident where SER (0.9.4)
children drained all the
CPUs of one of our servers.
Top Showed:
PID USER PRI NI SIZE RSS SHARE STAT %CPU %MEM TIME CPU COMMAND
17925 root 25 0 5644 5644 3888 R 25.5 0.2 6:26 1 ser
17929 root 25 0 5672 5672 3880 R 24.7 0.2 6:48 0 ser
17928 root 25 0 5688 5688 3872 R 24.3 0.2 6:25 1 ser
17933 root 25 0 4540 4540 3740 R 22.8 0.2 6:00 0 ser
And ..
# ps -Al | grep ser
1 S 0 17901 1 0 85 0 - 14200 pause ? 00:00:00 ser
1 S 0 17916 17901 0 75 0 - 14200 pipe_w ? 00:00:00 ser
1 S 0 17917 17901 0 75 0 - 14418 schedu ? 00:00:22 ser
1 S 0 17918 17901 0 75 0 - 14422 schedu ? 00:00:23 ser
1 S 0 17919 17901 0 75 0 - 14423 schedu ? 00:00:24 ser
1 S 0 17920 17901 0 75 0 - 14447 schedu ? 00:00:22 ser
1 S 0 17921 17901 0 75 0 - 14421 schedu ? 00:00:22 ser
1 S 0 17922 17901 0 75 0 - 14424 schedu ? 00:00:22 ser
1 S 0 17923 17901 0 75 0 - 14428 schedu ? 00:00:21 ser
1 S 0 17924 17901 0 75 0 - 14424 schedu ? 00:00:22 ser
1 R 0 17925 17901 0 85 0 - 14448 - ? 00:06:22 ser
1 S 0 17926 17901 0 75 0 - 14457 schedu ? 00:00:49 ser
1 S 0 17927 17901 0 75 0 - 14453 schedu ? 00:00:50 ser
1 R 0 17928 17901 0 85 0 - 14477 - ? 00:06:20 ser
1 R 0 17929 17901 0 85 0 - 14455 - ? 00:06:44 ser
1 S 0 17930 17901 0 75 0 - 14452 schedu ? 00:00:50 ser
1 S 0 17931 17901 0 75 0 - 14448 schedu ? 00:00:50 ser
1 S 0 17932 17901 0 76 0 - 14448 schedu ? 00:00:49 ser
1 R 0 17933 17901 0 85 0 - 14235 - ? 00:05:55 ser
As you can see it looks like 4 children dropped out of the
scheduler. The only thing suspicious is that RTPProxy became
non-responsive around that time. At least thats the only thing the
log shows:
Nov 22 15:56:17 /usr/local/sbin/ser[17931]: ERROR:
send_rtpp_command: timeout waiting reply from a RTP proxy
Any idea why these 4 children dropped out? Any hints on how to
troubleshoot this?
Thanks,
--
Andres
Network Admin
http://www.telesip.net
_______________________________________________
Serusers mailing list
serusers(a)lists.iptel.org
http://lists.iptel.org/mailman/listinfo/serusers
24 Nov
24 Nov
4:25 a.m.
Ah, of course you knew about that :-)
Well, then I cannot really see why the SER children locked up. Do you have
any SER logs right before locking up? You are sure it's related to a
non-responding rtpproxy?
I remember that Maxim was not able to reproduce the rtpproxy lockup, so
that's one hard bug to nail down. Hopefully you will get something useful
out of the debugging.
g-)
----- Original Message -----
From: "Andres" <andres(a)telesip.net>
To: "Greger V. Teigre" <greger(a)teigre.com>
Cc: <serusers(a)lists.iptel.org>
Sent: Wednesday, November 23, 2005 4:15 PM
Subject: Re: [Serusers] SER Children Misbehaving
Hi Greger,
For this same reason we switched to a UDP interface about 6 months ago.
But as you can see we still managed to get 4 Children locked up. It still
was able to do millions of transaction since the last lockup (2 months
ago) but we are still clueless about why this is happening. We have
rtpproxy running again in the foreground outputting all messages to a
file. Hopefully this will provide enough info to get to the bottom of
this.
Thanks,
--
Andres
Network Admin
http://www.telesip.net
Greger V. Teigre wrote:
Andres,
I believe I remember this issue being brought up a while back. If I
remember correctly, ser children locked up when communicating to a locked
rtpproxy over socket interface. The "solution" was to use udp over
loopback to communicate as this would fail that specific call, but not
lock the ser process.
g-)
----- Original Message ----- From: "Andres" <andres(a)telesip.net>
To: <serusers(a)lists.iptel.org>
Sent: Tuesday, November 22, 2005 10:19 PM
Subject: [Serusers] SER Children Misbehaving
Today we had an incident where SER (0.9.4)
children drained all the CPUs
of one of our servers.
Top Showed:
PID USER PRI NI SIZE RSS SHARE STAT %CPU %MEM TIME CPU COMMAND
17925 root 25 0 5644 5644 3888 R 25.5 0.2 6:26 1 ser
17929 root 25 0 5672 5672 3880 R 24.7 0.2 6:48 0 ser
17928 root 25 0 5688 5688 3872 R 24.3 0.2 6:25 1 ser
17933 root 25 0 4540 4540 3740 R 22.8 0.2 6:00 0 ser
And ..
# ps -Al | grep ser
1 S 0 17901 1 0 85 0 - 14200 pause ? 00:00:00 ser
1 S 0 17916 17901 0 75 0 - 14200 pipe_w ? 00:00:00 ser
1 S 0 17917 17901 0 75 0 - 14418 schedu ? 00:00:22 ser
1 S 0 17918 17901 0 75 0 - 14422 schedu ? 00:00:23 ser
1 S 0 17919 17901 0 75 0 - 14423 schedu ? 00:00:24 ser
1 S 0 17920 17901 0 75 0 - 14447 schedu ? 00:00:22 ser
1 S 0 17921 17901 0 75 0 - 14421 schedu ? 00:00:22 ser
1 S 0 17922 17901 0 75 0 - 14424 schedu ? 00:00:22 ser
1 S 0 17923 17901 0 75 0 - 14428 schedu ? 00:00:21 ser
1 S 0 17924 17901 0 75 0 - 14424 schedu ? 00:00:22 ser
1 R 0 17925 17901 0 85 0 - 14448 - ? 00:06:22 ser
1 S 0 17926 17901 0 75 0 - 14457 schedu ? 00:00:49 ser
1 S 0 17927 17901 0 75 0 - 14453 schedu ? 00:00:50 ser
1 R 0 17928 17901 0 85 0 - 14477 - ? 00:06:20 ser
1 R 0 17929 17901 0 85 0 - 14455 - ? 00:06:44 ser
1 S 0 17930 17901 0 75 0 - 14452 schedu ? 00:00:50 ser
1 S 0 17931 17901 0 75 0 - 14448 schedu ? 00:00:50 ser
1 S 0 17932 17901 0 76 0 - 14448 schedu ? 00:00:49 ser
1 R 0 17933 17901 0 85 0 - 14235 - ? 00:05:55 ser
As you can see it looks like 4 children dropped out of the scheduler.
The only thing suspicious is that RTPProxy became non-responsive around
that time. At least thats the only thing the log shows:
Nov 22 15:56:17 /usr/local/sbin/ser[17931]: ERROR: send_rtpp_command:
timeout waiting reply from a RTP proxy
Any idea why these 4 children dropped out? Any hints on how to
troubleshoot this?
Thanks,
--
Andres
Network Admin
http://www.telesip.net
_______________________________________________
Serusers mailing list
serusers(a)lists.iptel.org
http://lists.iptel.org/mailman/listinfo/serusers
11:46 a.m.
Greger V. Teigre wrote:
Ah, of course you knew about that :-)
Well, then I cannot really see why the SER children locked up. Do you
have any SER logs right before locking up?
I looked at them but there was really nothing. Only the errors
indicating the RTPPROXY stopped responding.
You are sure it's related to a non-responding
rtpproxy?
No, but its too much of a coincidence. We monitor the RTPPROXY from a
Nagios script every 5 minutes so we can confirm externally that it was
not responding around the same time as the 4 children locked up.
I remember that Maxim was not able to reproduce the
rtpproxy lockup,
so that's one hard bug to nail down. Hopefully you will get something
useful out of the debugging.
Yea I know. We left RTPROXY running in the foreground (to gather info
for Maxim) for like 2 months. Millions of calls and all was perfect.
We restarted it normally about 3 weeks ago and we got this problem. I
am starting to think its more stable running in the foreground.
Thanks,
--
Andres
Network Admin
http://www.telesip.net
26 Nov
26 Nov
3:41 a.m.
Hm. Strange indeed. I cannot really see why SER should lock up without an
error. It will be interesting to hear if you find anything.
g-)
----- Original Message -----
From: "Andres" <andres(a)telesip.net>
To: "Greger V. Teigre" <greger(a)teigre.com>
Cc: <serusers(a)lists.iptel.org>
Sent: Thursday, November 24, 2005 5:46 PM
Subject: Re: [Serusers] SER Children Misbehaving
Greger V. Teigre wrote:
Ah, of course you knew about that :-)
Well, then I cannot really see why the SER children locked up. Do you
have any SER logs right before locking up?
I looked at them but there was really nothing. Only the errors indicating
the RTPPROXY stopped responding.
You are sure it's related to a non-responding
rtpproxy?
No, but its too much of a coincidence. We monitor the RTPPROXY from a
Nagios script every 5 minutes so we can confirm externally that it was not
responding around the same time as the 4 children locked up.
I remember that Maxim was not able to reproduce
the rtpproxy lockup, so
that's one hard bug to nail down. Hopefully you will get something useful
out of the debugging.
Yea I know. We left RTPROXY running in the foreground (to gather info for
Maxim) for like 2 months. Millions of calls and all was perfect. We
restarted it normally about 3 weeks ago and we got this problem. I am
starting to think its more stable running in the foreground.
Thanks,
--
Andres
Network Admin
http://www.telesip.net
6983
days inactive
6987
days old
5 comments
2 participants
participants (2)
-
Andres -
Greger V. Teigre