Hi Michael,
The subst() warning is very interesting, since it's not doing I/O at all
(bonus: it's not even allocating shared memory!).
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?
Best regards,
Liviu Chircu
OpenSIPS Developer
http://www.opensips-solutions.com
On 02.12.2015 17:46, Michael Ulitskiy wrote:
Hello
I have opensips-1.11.4 running as frontend proxy/registrar to a
cluster of asterisk servers.
It currently works under low load - around 50 messages per second.
Nonetheless several times a day I'm receiving exec_msg_threshold
warnings showing
delays in the very unexpected places. exec_msg_threshold is set to
100ms (100000 microseconds).
Here's a few examples:
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
Dec 2 00:56:31 csp-p1n1 csp1[19102]: WARNING:core:log_expiry: #1 is a
module action : pv_proxy_authorize - 148529us - line 1433
Dec 2 00:56:31 csp-p1n1 csp1[19102]: WARNING:core:log_expiry: #2 is a
module action : t_relay - 78us - line 1116
Dec 2 00:56:31 csp-p1n1 csp1[19102]: WARNING:core:log_expiry: #3 is a
module action : avp_subst - 32us - line 907
Dec 2 00:56:31 csp-p1n1 csp1[19102]: WARNING:core:log_expiry: #4 is a
core action : 69 - 11us - line 943
Dec 2 00:56:31 csp-p1n1 csp1[19102]: WARNING:core:log_expiry: #5 is a
module action : record_route - 8us - line 455
pv_proxy_authorize() took 148ms. the code in question:
if (!pv_proxy_authorize("example.com")) {
...
}
Another example:
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
Dec 2 01:10:24 csp-p1n1 csp1[19104]: WARNING:core:log_expiry: #1 is a
module action : subst - 147958us - line 1308
Dec 2 01:10:24 csp-p1n1 csp1[19104]: WARNING:core:log_expiry: #2 is a
module action : t_replicate - 85us - line 1310
Dec 2 01:10:24 csp-p1n1 csp1[19104]: WARNING:core:log_expiry: #3 is a
module action : save - 75us - line 1291
Dec 2 01:10:24 csp-p1n1 csp1[19104]: WARNING:core:log_expiry: #4 is a
module action : avp_subst - 45us - line 907
Dec 2 01:10:24 csp-p1n1 csp1[19104]: WARNING:core:log_expiry: #5 is a
module action : pv_www_authorize - 20us - line 1254
Here's subst() took 148ms. the code in question:
subst('/^To: .*sip:(.+)@.+/To: sip:\1@$rd/i');
Yet another example:
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
Dec 2 04:37:47 csp-p1n1 csp1[19119]: WARNING:core:log_expiry: #1 is a
module action : www_challenge - 146535us - line 1272
Dec 2 04:37:47 csp-p1n1 csp1[19119]: WARNING:core:log_expiry: #2 is a
module action : avp_subst - 57us - line 907
Dec 2 04:37:47 csp-p1n1 csp1[19119]: WARNING:core:log_expiry: #3 is a
module action : sipmsg_validate - 22us - line 1002
Dec 2 04:37:47 csp-p1n1 csp1[19119]: WARNING:core:log_expiry: #4 is a
module action : pv_www_authorize - 15us - line 1254
Dec 2 04:37:47 csp-p1n1 csp1[19119]: WARNING:core:log_expiry: #5 is a
module action : nat_uac_test - 11us - line 1202
www_challenge() took 146ms. the code is:
www_challenge("example.com","1");
I've seen it in all kind of places including pure core operations,
like pseudo-variables assignments.
Does anybody have any idea what might be causing this?
Thanks,
Michael
_______________________________________________
Users mailing list
[email protected]
http://lists.opensips.org/cgi-bin/mailman/listinfo/users
_______________________________________________
Users mailing list
[email protected]
http://lists.opensips.org/cgi-bin/mailman/listinfo/users
