[OpenSIPS-Users] opensips-1.11.4: exec_msg_threshold warning logged showing delayes in unexpected places

[Michael Ulitskiy]

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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/users/attachments/20151202/df334afc/attachment.htm>