<html>
<head>
<meta http-equiv="Content-Type" content="text/html; charset=utf-8">
</head>
<body bgcolor="#FFFFFF" text="#000000">
<tt>Hi Royee,<br>
<br>
what are the time values reported for 't_relay' and 'save' ? the
50ms threashold may not be so relevant for explaining delays of
seconds. <br>
<br>
Best regards,<br>
</tt>
<pre class="moz-signature" cols="72">Bogdan-Andrei Iancu
OpenSIPS Founder and Developer
<a class="moz-txt-link-freetext" href="http://www.opensips-solutions.com">http://www.opensips-solutions.com</a>
OpenSIPS Summit 2018
<a class="moz-txt-link-freetext" href="http://www.opensips.org/events/Summit-2018Amsterdam">http://www.opensips.org/events/Summit-2018Amsterdam</a>
</pre>
<div class="moz-cite-prefix">On 02/05/2018 02:09 PM, Royee Tichauer
via Users wrote:<br>
</div>
<blockquote type="cite"
cite="mid:CAFrVV=xdPnJjYTedQo=q6Dszjr0R-QND7RZM-GC6+NHB9wi+cA@mail.gmail.com">
<div dir="ltr">Hi,
<div><br>
</div>
<div>We are using opensips 2.1 as an SBC component and we see
that we have loss of registrations happening once in a while.
When we captured SIP we saw that some messages are being
delayed by a couple of seconds. We enabled
'exec_execute_message=50000' and saw in the logs that opensips
core methods like 't_realy' and 'save' . I looked at SAR
during this time and there are no indications of CPU running
high during this time. </div>
<div><br>
</div>
<div>Can you help me figure out this issue?<br>
</div>
<div><br>
</div>
<div>Thanks,</div>
<div>Royee</div>
<div><br>
</div>
<div>Logs:</div>
<div><br>
</div>
<div>
<p
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1"
style="color:rgb(33,33,33);font-size:13px"><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-Apple-converted-space"> </span>4
17:07:23 <a href="http://amz1vpsbc2.amz1.vocalocity.com/"
style="outline:transparent solid 1px" target="_blank"
moz-do-not-send="true">sbc.company.com</a> /usr/sbin/opensips[29827]: </span><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">:core:log_expiry:
threshold exceeded : msg processing took too long -
8912776 us.Source : SIP/2.0 200 OK#015#012Via: SIP/2.0/UDP
<ip>5060;received=<ip>;rport=5060;branch=z9hG4bK7eec.23d21053.0#015#012Via:
SIP/2.0/UDP
<ip>:5060;rport=5060;received=<ip>;branch=z9hG4bK2715962793#015#012From:
"" <<a
href="http://sip:VH2677991@sip-190913.accounts.vocalocity.com:5060/"
target="_blank" moz-do-not-send="true">sip:<sip_id>@<account>.company.com:5060</a>>;tag=646749010#015#012To:
"###" <<a
href="http://sip:VH2677991@sip-190913.accounts.vocalocity.com:5060/"
target="_blank" moz-do-not-send="true">sip:#####@sip-#####.accounts.COMPANY.com:5060</a>>;tag=8b4547f60a700f827fe775c80b65be1b.efed#015#012Call-ID: <a
href="http://0_2258842442@192.168.0.3/#015%23012CSeq"
target="_blank" moz-do-not-send="true">0_2258842442@<ip>#015#012CSeq</a>:
3575 REGISTER#015#012Contact: <<a
href="http://sip:VH2677991@97.96.230.47:5060/"
target="_blank" moz-do-not-send="true">sip:######@<ip>:5060</a>>;expires=45;received="sip:<a
href="http://52.7.62.159:5060/" target="_blank"
moz-do-not-send="true"><ip>:5060</a>"#015#012Server:
Vonage#015#012Content-Length: 0#015#012#015#012</span></p>
<p
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1"
style="color:rgb(33,33,33);font-size:13px"><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-Apple-converted-space"> </span>4
17:07:23 <a href="http://amz1vpsbc2.amz1.vocalocity.com/"
target="_blank" moz-do-not-send="true">sbc.amz1.company.com</a> /usr/sbin/opensips[29827]: </span><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">:core:log_expiry:
#1 is a module action : <font color="#ff0000">save -
8912725us</font> - line 914</span></p>
<p
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1"
style="color:rgb(33,33,33);font-size:13px"><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-Apple-converted-space"> </span>4
17:07:23 <a href="http://amz1vpsbc2.amz1.vocalocity.com/"
style="outline:transparent solid 1px" target="_blank"
moz-do-not-send="true">sbc.amz1.company.com</a> /usr/sbin/opensips[29827]: </span><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">:core:log_expiry:
#2 is a core action : 80 - 17us - line 1103</span></p>
<p
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1"
style="color:rgb(33,33,33);font-size:13px"><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-Apple-converted-space"> </span>4
17:07:23 <a href="http://amz1vpsbc2.amz1.vocalocity.com/"
style="outline:transparent solid 1px" target="_blank"
moz-do-not-send="true">sbc.amz1.company.com</a> /usr/sbin/opensips[29827]: </span><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">:core:log_expiry:
#3 is a core action : 72 - 5us - line 887</span></p>
<p
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1"
style="color:rgb(33,33,33);font-size:13px"><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-Apple-converted-space"> </span>4
17:07:23 <a href="http://amz1vpsbc2.amz1.vocalocity.com/"
style="outline:transparent solid 1px" target="_blank"
moz-do-not-send="true">sbc.amz1.company.com</a> /usr/sbin/opensips[29820]: </span><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">:core:log_expiry:
threshold exceeded : msg processing took too long -
5355695 us.Source : REGISTER <a class="moz-txt-link-freetext" href="sip:####">sip:####</a><a
href="http://sip-190913.accounts.vocalocity.com:5060/"
target="_blank" moz-do-not-send="true">.accounts.company.com:5060</a> SIP/2.0#015#012Via:
SIP/2.0/UDP
<ip>:5060;branch=z9hG4bK2715962793#015#012From:
"###" <<a
href="http://sip:VH2677991@sip-190913.accounts.vocalocity.com:5060/"
target="_blank" moz-do-not-send="true">sip:#####@sip-####.accounts.company.com:5060</a>>;tag=646749010#015#012To:
"####" <<a
href="http://sip:VH2677991@sip-190913.accounts.vocalocity.com:5060/"
target="_blank" moz-do-not-send="true">sip:####@sip-#####.accounts.company.com:5060</a>>#015#012Call-ID: <a
href="http://0_2258842442@192.168.0.3/#015%23012CSeq"
target="_blank" moz-do-not-send="true">0_2258842442@######015#012CSeq</a>:
3575 REGISTER#015#012Contact: <<a
href="http://sip:VH2677991@97.96.230.47:5060/"
target="_blank" moz-do-not-send="true">####@<ip>:5060</a>>#015#012Authorization:
Digest username="####", realm="<a
href="http://sip-190913.accounts.vocalocity.com/"
target="_blank" moz-do-not-send="true">####.accounts.company.com</a>",
nonce="5a773de000000b19dc7d21205f1edfda504fac90296b04fb",
uri="sip:<a
href="http://sip-190913.accounts.vocalocity.com:5060/"
target="_blank" moz-do-not-send="true">sip-#######.accounts.company.com:5060</a>",
response="df8d6cbfd178a36913a1464920da3f06",
algorithm=MD5#015#012Allow: INVITE, INFO, PRACK, ACK, BYE,
CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER,
PUBLISH, UPDATE, MESSAGE#015#012Max-Forwards:
69#015#012User-Agent: #########015#012Expires:
3600#015#012Allow-Events:
talk,hold,conference,refer,check-sync#015#012Content-Length:
0#015#012#015#012</span></p>
<p
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1"
style="color:rgb(33,33,33);font-size:13px"><br>
</p>
<p
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1"
style="color:rgb(33,33,33);font-size:13px"><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-Apple-converted-space"> </span>4
17:07:23 </span><a
href="http://amz1vpsbc2.amz1.vocalocity.com/"
target="_blank" style="outline:transparent solid 1px"
moz-do-not-send="true">sbc.amz1.company.com</a> <span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1"> /usr/sbin/opensips[29827]: </span><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">:core:log_expiry:
#4 is a core action : 72 - 5us - line 1086</span></p>
<p
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1"
style="color:rgb(33,33,33);font-size:13px"><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-Apple-converted-space"> </span>4
17:07:23 <a href="http://amz1vpsbc2.amz1.vocalocity.com/"
target="_blank" style="outline:transparent solid 1px"
moz-do-not-send="true">sbc.amz1.company.com</a> /usr/sbin/opensips[29820]: </span><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">:core:log_expiry:
#1 is a module action : <font color="#ff0000">t_relay -
5355333us</font> - line 465</span></p>
<p
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1"
style="color:rgb(33,33,33);font-size:13px"><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-Apple-converted-space"> </span>4
17:07:23 <a href="http://amz1vpsbc2.amz1.vocalocity.com/"
target="_blank" style="outline:transparent solid 1px"
moz-do-not-send="true">sbc.amz1.company.com</a> /usr/sbin/opensips[29827]: </span><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">:core:log_expiry:
#5 is a module action : ds_is_in_list - 4us - line 943</span></p>
<p
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1"
style="color:rgb(33,33,33);font-size:13px"><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-Apple-converted-space"> </span>4
17:07:23 <a href="http://amz1vpsbc2.amz1.vocalocity.com/"
target="_blank" style="outline:transparent solid 1px"
moz-do-not-send="true">sbc.amz1.company.com</a> /usr/sbin/opensips[29817]: </span><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">:core:log_expiry:
#1 is a module action : t_relay - 7375370us - line 465</span></p>
<p
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1"
style="color:rgb(33,33,33);font-size:13px"><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-Apple-converted-space"> </span>4
17:07:23 <a href="http://amz1vpsbc2.amz1.vocalocity.com/"
target="_blank" style="outline:transparent solid 1px"
moz-do-not-send="true">sbc.amz1.company.com</a> /usr/sbin/opensips[29820]: </span><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">:core:log_expiry:
#2 is a core action : 78 - 105us - line 604</span></p>
<p
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1"
style="color:rgb(33,33,33);font-size:13px"><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-Apple-converted-space"> </span>4
17:07:23 <a href="http://amz1vpsbc2.amz1.vocalocity.com/"
target="_blank" style="outline:transparent solid 1px"
moz-do-not-send="true">sbc.amz1.company.com</a> /usr/sbin/opensips[29817]: </span><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">:core:log_expiry:
#2 is a core action : 78 - 100us - line 604</span></p>
<p
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1"
style="color:rgb(33,33,33);font-size:13px"><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-Apple-converted-space"> </span>4
17:07:23 <a href="http://amz1vpsbc2.amz1.vocalocity.com/"
target="_blank" style="outline:transparent solid 1px"
moz-do-not-send="true">sbc.amz1.company.com</a> /usr/sbin/opensips[29820]: </span><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">:core:log_expiry:
#3 is a core action : 78 - 99us - line 635</span></p>
<p
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1"
style="color:rgb(33,33,33);font-size:13px"><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-Apple-converted-space"> </span>4
17:07:23 <a href="http://amz1vpsbc2.amz1.vocalocity.com/"
target="_blank" style="outline:transparent solid 1px"
moz-do-not-send="true">sbc.amz1.company.com</a> /usr/sbin/opensips[29817]: </span><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span
class="m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">:core:log_expiry:
#3 is a core action : 78 - 98us - line 635</span></p>
</div>
</div>
<br>
<fieldset class="mimeAttachmentHeader"></fieldset>
<br>
<pre wrap="">_______________________________________________
Users mailing list
<a class="moz-txt-link-abbreviated" href="mailto:Users@lists.opensips.org">Users@lists.opensips.org</a>
<a class="moz-txt-link-freetext" href="http://lists.opensips.org/cgi-bin/mailman/listinfo/users">http://lists.opensips.org/cgi-bin/mailman/listinfo/users</a>
</pre>
</blockquote>
<br>
</body>
</html>