<div dir="ltr">Hi Bogdan, as the logs show:<div><br><div><span style="font-size:13px">save - 8912725us</span></div><div><span style="font-size:13px">t_relay - 5355333us</span></div><div><span style="font-size:13px"><br></span></div><div><span style="font-size:13px">Let me know if you have any ideas,</span></div><div><span style="font-size:13px">Thanks,</span></div><div><span style="font-size:13px">Royee</span></div><div><span style="font-size:13px"><br></span></div><div><br></div><div><br></div><br><div class="gmail_quote"><div dir="ltr">On Mon, Feb 5, 2018 at 5:50 PM Bogdan-Andrei Iancu <<a href="mailto:bogdan@opensips.org" target="_blank">bogdan@opensips.org</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
<div 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="m_5607116917498711912m_-3685039611660924341moz-signature" cols="72">Bogdan-Andrei Iancu
OpenSIPS Founder and Developer
<a class="m_5607116917498711912m_-3685039611660924341moz-txt-link-freetext" href="http://www.opensips-solutions.com" target="_blank">http://www.opensips-solutions.com</a>
OpenSIPS Summit 2018
<a class="m_5607116917498711912m_-3685039611660924341moz-txt-link-freetext" href="http://www.opensips.org/events/Summit-2018Amsterdam" target="_blank">http://www.opensips.org/events/Summit-2018Amsterdam</a>
</pre></div><div bgcolor="#FFFFFF" text="#000000">
<div class="m_5607116917498711912m_-3685039611660924341moz-cite-prefix">On 02/05/2018 02:09 PM, Royee Tichauer
via Users wrote:<br>
</div>
</div><div bgcolor="#FFFFFF" text="#000000"><blockquote type="cite">
<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_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1" style="color:rgb(33,33,33);font-size:13px"><span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span class="m_5607116917498711912m_-3685039611660924341m_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">sbc.company.com</a> /usr/sbin/opensips[29827]: </span><span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span class="m_5607116917498711912m_-3685039611660924341m_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">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">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">0_2258842442@<ip>#015#012CSeq</a>:
3575 REGISTER#015#012Contact: <<a href="http://sip:VH2677991@97.96.230.47:5060/" target="_blank">sip:######@<ip>:5060</a>>;expires=45;received="sip:<a href="http://52.7.62.159:5060/" target="_blank"><ip>:5060</a>"#015#012Server:
Vonage#015#012Content-Length: 0#015#012#015#012</span></p>
<p class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1" style="color:rgb(33,33,33);font-size:13px"><span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-Apple-converted-space"> </span>4
17:07:23 <a href="http://amz1vpsbc2.amz1.vocalocity.com/" target="_blank">sbc.amz1.company.com</a> /usr/sbin/opensips[29827]: </span><span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span class="m_5607116917498711912m_-3685039611660924341m_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_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1" style="color:rgb(33,33,33);font-size:13px"><span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span class="m_5607116917498711912m_-3685039611660924341m_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">sbc.amz1.company.com</a> /usr/sbin/opensips[29827]: </span><span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">:core:log_expiry:
#2 is a core action : 80 - 17us - line 1103</span></p>
<p class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1" style="color:rgb(33,33,33);font-size:13px"><span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span class="m_5607116917498711912m_-3685039611660924341m_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">sbc.amz1.company.com</a> /usr/sbin/opensips[29827]: </span><span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">:core:log_expiry:
#3 is a core action : 72 - 5us - line 887</span></p>
<p class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1" style="color:rgb(33,33,33);font-size:13px"><span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span class="m_5607116917498711912m_-3685039611660924341m_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">sbc.amz1.company.com</a> /usr/sbin/opensips[29820]: </span><span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">:core:log_expiry:
threshold exceeded : msg processing took too long -
5355695 us.Source : REGISTER <a class="m_5607116917498711912m_-3685039611660924341moz-txt-link-freetext">sip:####</a><a href="http://sip-190913.accounts.vocalocity.com:5060/" target="_blank">.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">sip:#####@sip-####.accounts.company.com:5060</a>>;tag=646749010#015#012To:
"####" <<a href="http://sip:VH2677991@sip-190913.accounts.vocalocity.com:5060/" target="_blank">sip:####@sip-#####.accounts.company.com:5060</a>>#015#012Call-ID: <a href="http://0_2258842442@192.168.0.3/#015%23012CSeq" target="_blank">0_2258842442@######015#012CSeq</a>:
3575 REGISTER#015#012Contact: <<a href="http://sip:VH2677991@97.96.230.47:5060/" target="_blank">####@<ip>:5060</a>>#015#012Authorization:
Digest username="####", realm="<a href="http://sip-190913.accounts.vocalocity.com/" target="_blank">####.accounts.company.com</a>",
nonce="5a773de000000b19dc7d21205f1edfda504fac90296b04fb",
uri="sip:<a href="http://sip-190913.accounts.vocalocity.com:5060/" target="_blank">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_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1" style="color:rgb(33,33,33);font-size:13px"><br>
</p>
<p class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1" style="color:rgb(33,33,33);font-size:13px"><span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-Apple-converted-space"> </span>4
17:07:23 </span><a href="http://amz1vpsbc2.amz1.vocalocity.com/" style="outline:transparent solid 1px" target="_blank">sbc.amz1.company.com</a> <span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1"> /usr/sbin/opensips[29827]: </span><span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">:core:log_expiry:
#4 is a core action : 72 - 5us - line 1086</span></p>
<p class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1" style="color:rgb(33,33,33);font-size:13px"><span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span class="m_5607116917498711912m_-3685039611660924341m_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">sbc.amz1.company.com</a> /usr/sbin/opensips[29820]: </span><span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span class="m_5607116917498711912m_-3685039611660924341m_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_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1" style="color:rgb(33,33,33);font-size:13px"><span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span class="m_5607116917498711912m_-3685039611660924341m_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">sbc.amz1.company.com</a> /usr/sbin/opensips[29827]: </span><span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span class="m_5607116917498711912m_-3685039611660924341m_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_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1" style="color:rgb(33,33,33);font-size:13px"><span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span class="m_5607116917498711912m_-3685039611660924341m_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">sbc.amz1.company.com</a> /usr/sbin/opensips[29817]: </span><span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span class="m_5607116917498711912m_-3685039611660924341m_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_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1" style="color:rgb(33,33,33);font-size:13px"><span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span class="m_5607116917498711912m_-3685039611660924341m_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">sbc.amz1.company.com</a> /usr/sbin/opensips[29820]: </span><span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">:core:log_expiry:
#2 is a core action : 78 - 105us - line 604</span></p>
<p class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1" style="color:rgb(33,33,33);font-size:13px"><span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span class="m_5607116917498711912m_-3685039611660924341m_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">sbc.amz1.company.com</a> /usr/sbin/opensips[29817]: </span><span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">:core:log_expiry:
#2 is a core action : 78 - 100us - line 604</span></p>
<p class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1" style="color:rgb(33,33,33);font-size:13px"><span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span class="m_5607116917498711912m_-3685039611660924341m_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">sbc.amz1.company.com</a> /usr/sbin/opensips[29820]: </span><span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">:core:log_expiry:
#3 is a core action : 78 - 99us - line 635</span></p>
<p class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-p1" style="color:rgb(33,33,33);font-size:13px"><span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s1">Feb<span class="m_5607116917498711912m_-3685039611660924341m_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">sbc.amz1.company.com</a> /usr/sbin/opensips[29817]: </span><span class="m_5607116917498711912m_-3685039611660924341m_2704548187974995081m_3087077431777231565inbox-inbox-m_6425236171007866397inbox-inbox-s4">WARNING</span><span class="m_5607116917498711912m_-3685039611660924341m_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="m_5607116917498711912m_-3685039611660924341mimeAttachmentHeader"></fieldset>
<br>
</blockquote></div><div bgcolor="#FFFFFF" text="#000000"><blockquote type="cite"><pre>_______________________________________________
Users mailing list
<a class="m_5607116917498711912m_-3685039611660924341moz-txt-link-abbreviated" href="mailto:Users@lists.opensips.org" target="_blank">Users@lists.opensips.org</a>
<a class="m_5607116917498711912m_-3685039611660924341moz-txt-link-freetext" href="http://lists.opensips.org/cgi-bin/mailman/listinfo/users" target="_blank">http://lists.opensips.org/cgi-bin/mailman/listinfo/users</a>
</pre>
</blockquote>
<br>
</div>
</blockquote></div></div></div>