<html>
<head>
<meta content="text/html; charset=windows-1252"
http-equiv="Content-Type">
</head>
<body bgcolor="#FFFFFF" text="#000000">
<tt>Hi Michael,<br>
<br>
The subst() warning is very interesting, since it's not doing I/O
at all (bonus: it's not even allocating shared memory!).<br>
<br>
So first thing that comes to mind is some excessive CPU usage
happening on your machine. Some cron job or daemon which may be
CPU starving the OpenSIPS workers from time to time?<br>
<br>
Best regards,<br>
</tt>
<pre class="moz-signature" cols="72">Liviu Chircu
OpenSIPS Developer
<a class="moz-txt-link-freetext" href="http://www.opensips-solutions.com">http://www.opensips-solutions.com</a></pre>
<div class="moz-cite-prefix">On 02.12.2015 17:46, Michael Ulitskiy
wrote:<br>
</div>
<blockquote cite="mid:4673544.Jhr1IflsyW@x-files" type="cite">
<meta name="qrichtext" content="1">
<style type="text/css">
p, li { white-space: pre-wrap; }
</style>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">Hello</p>
<p style="-qt-paragraph-type:empty; margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; "> </p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">I have opensips-1.11.4 running as frontend proxy/registrar to a cluster of asterisk servers.</p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">It currently works under low load - around 50 messages per second.</p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">Nonetheless several times a day I'm receiving exec_msg_threshold warnings showing</p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">delays in the very unexpected places. exec_msg_threshold is set to 100ms (100000 microseconds).</p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">Here's a few examples:</p>
<p style="-qt-paragraph-type:empty; margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; "> </p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">Dec 2 00:56:31 csp-p1n1 csp1[19102]: WARNING:core:log_expiry: threshold exceeded : msg processing took too long - 148931 us.Source : NOTIFY sip:srv.csp1.example.com SIP/2.0 </p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">Dec 2 00:56:31 csp-p1n1 csp1[19102]: WARNING:core:log_expiry: #1 is a module action : pv_proxy_authorize - 148529us - line 1433 </p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">Dec 2 00:56:31 csp-p1n1 csp1[19102]: WARNING:core:log_expiry: #2 is a module action : t_relay - 78us - line 1116 </p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">Dec 2 00:56:31 csp-p1n1 csp1[19102]: WARNING:core:log_expiry: #3 is a module action : avp_subst - 32us - line 907 </p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">Dec 2 00:56:31 csp-p1n1 csp1[19102]: WARNING:core:log_expiry: #4 is a core action : 69 - 11us - line 943 </p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">Dec 2 00:56:31 csp-p1n1 csp1[19102]: WARNING:core:log_expiry: #5 is a module action : record_route - 8us - line 455 </p>
<p style="-qt-paragraph-type:empty; margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; "> </p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">pv_proxy_authorize() took 148ms. the code in question: </p>
<p style="-qt-paragraph-type:empty; margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; "> </p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">if (!pv_proxy_authorize("example.com")) {</p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;"> ...</p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">}</p>
<p style="-qt-paragraph-type:empty; margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; "> </p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">Another example:</p>
<p style="-qt-paragraph-type:empty; margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; "> </p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">Dec 2 01:10:24 csp-p1n1 csp1[19104]: WARNING:core:log_expiry: threshold exceeded : msg processing took too long - 148508 us.Source : REGISTER sip:csp1.example.com:5060 SIP/2.0 </p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">Dec 2 01:10:24 csp-p1n1 csp1[19104]: WARNING:core:log_expiry: #1 is a module action : subst - 147958us - line 1308 </p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">Dec 2 01:10:24 csp-p1n1 csp1[19104]: WARNING:core:log_expiry: #2 is a module action : t_replicate - 85us - line 1310 </p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">Dec 2 01:10:24 csp-p1n1 csp1[19104]: WARNING:core:log_expiry: #3 is a module action : save - 75us - line 1291 </p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">Dec 2 01:10:24 csp-p1n1 csp1[19104]: WARNING:core:log_expiry: #4 is a module action : avp_subst - 45us - line 907 </p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">Dec 2 01:10:24 csp-p1n1 csp1[19104]: WARNING:core:log_expiry: #5 is a module action : pv_www_authorize - 20us - line 1254</p>
<p style="-qt-paragraph-type:empty; margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; "> </p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">Here's subst() took 148ms. the code in question:</p>
<p style="-qt-paragraph-type:empty; margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; "> </p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">subst('/^To: .*sip:(.+)@.+/To: sip:\1@$rd/i');</p>
<p style="-qt-paragraph-type:empty; margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; "> </p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">Yet another example:</p>
<p style="-qt-paragraph-type:empty; margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; "> </p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">Dec 2 04:37:47 csp-p1n1 csp1[19119]: WARNING:core:log_expiry: threshold exceeded : msg processing took too long - 146908 us.Source : REGISTER sip:srv.csp1.example.com SIP/2.0</p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">Dec 2 04:37:47 csp-p1n1 csp1[19119]: WARNING:core:log_expiry: #1 is a module action : www_challenge - 146535us - line 1272</p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">Dec 2 04:37:47 csp-p1n1 csp1[19119]: WARNING:core:log_expiry: #2 is a module action : avp_subst - 57us - line 907</p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">Dec 2 04:37:47 csp-p1n1 csp1[19119]: WARNING:core:log_expiry: #3 is a module action : sipmsg_validate - 22us - line 1002</p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">Dec 2 04:37:47 csp-p1n1 csp1[19119]: WARNING:core:log_expiry: #4 is a module action : pv_www_authorize - 15us - line 1254</p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">Dec 2 04:37:47 csp-p1n1 csp1[19119]: WARNING:core:log_expiry: #5 is a module action : nat_uac_test - 11us - line 1202</p>
<p style="-qt-paragraph-type:empty; margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; "> </p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">www_challenge() took 146ms. the code is:</p>
<p style="-qt-paragraph-type:empty; margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; "> </p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">www_challenge("example.com","1");</p>
<p style="-qt-paragraph-type:empty; margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; "> </p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">I've seen it in all kind of places including pure core operations, like pseudo-variables assignments.</p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">Does anybody have any idea what might be causing this?</p>
<p style="-qt-paragraph-type:empty; margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; "> </p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">Thanks,</p>
<p style=" margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; -qt-user-state:0;">Michael</p>
<p style="-qt-paragraph-type:empty; margin-top:0px; margin-bottom:0px; margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; "> </p>
<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>