[OpenSIPS-Users] opensips-1.11.4: exec_msg_threshold warning logged showing delayes in unexpected places
Michael Ulitskiy
mulitskiy at acedsl.com
Wed Dec 2 20:47:02 CET 2015
Hi Liviu,
That's the first thing I thought, but I can't imagine what that could be.
The machine is dedicated to opensips and doesn't have any other services.
It's running opensips under pacemaker CRM control (it's actually a cluster of 2 machines with floating ip)
and mysql db for usrloc persistence. mysql db is tiny (970 location entries at the moment) and
shouldn't cause any noticable delay. The only existing cron job is hourly log parsing/reporting.
I don't think it's related to any periodic activity, because the occurence is totally random.
The machine is basically idle in both cpu and io:
root at csp-p1n1:~# vmstat 1
procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
r b swpd free buff cache si so bi bo in cs us sy id wa
0 0 62108 229512 321196 2008736 0 0 2 53 0 0 1 0 99 0
2 0 62108 230072 321196 2008740 0 0 0 1 751 830 1 0 99 0
0 0 62108 230000 321196 2008740 0 0 0 10426 935 1223 1 0 95 4
0 0 62108 229952 321196 2008740 0 0 0 0 532 673 1 0 99 0
0 0 62108 229952 321196 2008744 0 0 0 6 498 669 0 0 99 0
0 0 62108 230076 321196 2008884 0 0 0 46 1377 1133 1 1 98 0
0 0 62108 229632 321196 2008744 0 0 0 0 673 839 1 1 99 0
1 0 62108 229712 321196 2008744 0 0 0 5 477 656 1 0 99 0
1 0 62108 229588 321196 2008744 0 0 0 9 470 682 0 0 99 0
0 0 62108 229588 321196 2008744 0 0 0 0 403 599 0 0 100 0
I'm not sure what else to look at and could use a hint.
Thanks,
Michael
On Wednesday, December 02, 2015 07:19:06 PM Liviu Chircu wrote:
> 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
> > Users at lists.opensips.org
> > http://lists.opensips.org/cgi-bin/mailman/listinfo/users
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/users/attachments/20151202/308dafad/attachment-0001.htm>
More information about the Users
mailing list