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
