Thanks for lead Bogdan we will look into it. Do you also have any idea why the t_relay was blocking for so long?
Royee On Mon, Feb 5, 2018 at 7:23 PM Bogdan-Andrei Iancu <bog...@opensips.org> wrote: > Hi Royee, > > I don't think it is related to xmlrpc - there are separate connection, > separate processes for this. > > I would rather suspect the event routes - the event is in-line handled in > usrloc, so the save() will cover the delivery/handling of the contact > related events. And if you do something time consuming in > event_route[E_UL_CONTACT_INSERT] lets say, this will reflect as processing > time for the save() function. > > Regards, > > Bogdan-Andrei Iancu > > OpenSIPS Founder and Developer > http://www.opensips-solutions.com > OpenSIPS Summit 2018 > http://www.opensips.org/events/Summit-2018Amsterdam > > On 02/05/2018 06:44 PM, Royee Tichauer wrote: > > Bogdan, > > Not sure I follow about breaking each function. What do you mean by > 'actual internal save()'? > > DB insert is not used. > > We use: > > event_route[E_UL_CONTACT_UPDATE] > > event_route[E_UL_CONTACT_DELETE] > > event_route[E_UL_CONTACT_INSERT] > > btw, we also use the mi_xmlrpc_ng constantly for monitoring if that might > have something to do with it (I saw a comment on opensips 1.6 that there > was an opensips blocking issue in some cases). > > Royee > > > > On Mon, Feb 5, 2018 at 6:34 PM Bogdan-Andrei Iancu <bog...@opensips.org> > wrote: > >> Hi Royee, >> >> Well, you need to break for each function the possible types of actions. >> Like for save(): >> - actual internal save() >> - DB insert if realtime mode used >> - potential events triggering - do you use any usrloc related events ? >> >> Regards, >> >> >> Bogdan-Andrei Iancu >> >> OpenSIPS Founder and Developer >> http://www.opensips-solutions.com >> OpenSIPS Summit 2018 >> http://www.opensips.org/events/Summit-2018Amsterdam >> >> On 02/05/2018 06:20 PM, Royee Tichauer wrote: >> >> Hi Bogdan, as the logs show: >> >> save - 8912725us >> t_relay - 5355333us >> >> Let me know if you have any ideas, >> Thanks, >> Royee >> >> >> >> >> On Mon, Feb 5, 2018 at 5:50 PM Bogdan-Andrei Iancu <bog...@opensips.org> >> wrote: >> >>> Hi Royee, >>> >>> what are the time values reported for 't_relay' and 'save' ? the 50ms >>> threashold may not be so relevant for explaining delays of seconds. >>> >>> Best regards, >>> >>> Bogdan-Andrei Iancu >>> >>> OpenSIPS Founder and Developer >>> http://www.opensips-solutions.com >>> OpenSIPS Summit 2018 >>> http://www.opensips.org/events/Summit-2018Amsterdam >>> >>> On 02/05/2018 02:09 PM, Royee Tichauer via Users wrote: >>> >>> Hi, >>> >>> We are using opensips 2.1 as an SBC component and we see that we have >>> loss of registrations happening once in a while. When we captured SIP we >>> saw that some messages are being delayed by a couple of seconds. We enabled >>> 'exec_execute_message=50000' and saw in the logs that opensips core methods >>> like 't_realy' and 'save' . I looked at SAR during this time and there are >>> no indications of CPU running high during this time. >>> >>> Can you help me figure out this issue? >>> >>> Thanks, >>> Royee >>> >>> Logs: >>> >>> Feb 4 17:07:23 sbc.company.com <http://amz1vpsbc2.amz1.vocalocity.com/> >>> /usr/sbin/opensips[29827]: WARNING:core:log_expiry: threshold exceeded >>> : msg processing took too long - 8912776 us.Source : SIP/2.0 200 >>> OK#015#012Via: SIP/2.0/UDP >>> <ip>5060;received=<ip>;rport=5060;branch=z9hG4bK7eec.23d21053.0#015#012Via: >>> SIP/2.0/UDP >>> <ip>:5060;rport=5060;received=<ip>;branch=z9hG4bK2715962793#015#012From: "" >>> <sip:<sip_id>@<account>.company.com:5060 >>> <http://sip:vh2677...@sip-190913.accounts.vocalocity.com:5060/>>;tag=646749010#015#012To: >>> "###" <sip:#####@sip-#####.accounts.COMPANY.com:5060 >>> <http://sip:vh2677...@sip-190913.accounts.vocalocity.com:5060/> >>> >;tag=8b4547f60a700f827fe775c80b65be1b.efed#015#012Call-ID: >>> 0_2258842442@<ip>#015#012CSeq >>> <http://0_2258842442@192.168.0.3/#015%23012CSeq>: 3575 >>> REGISTER#015#012Contact: <sip:######@<ip>:5060 >>> <http://sip:VH2677991@97.96.230.47:5060/>>;expires=45;received="sip: >>> <ip>:5060 <http://52.7.62.159:5060/>"#015#012Server: >>> Vonage#015#012Content-Length: 0#015#012#015#012 >>> >>> Feb 4 17:07:23 sbc.amz1.company.com >>> <http://amz1vpsbc2.amz1.vocalocity.com/> /usr/sbin/opensips[29827]: >>> WARNING:core:log_expiry: #1 is a module action : save - 8912725us - >>> line 914 >>> >>> Feb 4 17:07:23 sbc.amz1.company.com >>> <http://amz1vpsbc2.amz1.vocalocity.com/> /usr/sbin/opensips[29827]: >>> WARNING:core:log_expiry: #2 is a core action : 80 - 17us - line 1103 >>> >>> Feb 4 17:07:23 sbc.amz1.company.com >>> <http://amz1vpsbc2.amz1.vocalocity.com/> /usr/sbin/opensips[29827]: >>> WARNING:core:log_expiry: #3 is a core action : 72 - 5us - line 887 >>> >>> Feb 4 17:07:23 sbc.amz1.company.com >>> <http://amz1vpsbc2.amz1.vocalocity.com/> /usr/sbin/opensips[29820]: >>> WARNING:core:log_expiry: threshold exceeded : msg processing took too >>> long - 5355695 us.Source : REGISTER sip:####.accounts.company.com:5060 >>> <http://sip-190913.accounts.vocalocity.com:5060/> SIP/2.0#015#012Via: >>> SIP/2.0/UDP <ip>:5060;branch=z9hG4bK2715962793#015#012From: "###" < >>> sip:#####@sip-####.accounts.company.com:5060 >>> <http://sip:vh2677...@sip-190913.accounts.vocalocity.com:5060/>>;tag=646749010#015#012To: >>> "####" <sip:####@sip-#####.accounts.company.com:5060 >>> <http://sip:vh2677...@sip-190913.accounts.vocalocity.com:5060/> >>> >#015#012Call-ID: 0_2258842442@######015#012CSeq >>> <http://0_2258842442@192.168.0.3/#015%23012CSeq>: 3575 >>> REGISTER#015#012Contact: <####@<ip>:5060 >>> <http://sip:VH2677991@97.96.230.47:5060/>>#015#012Authorization: Digest >>> username="####", realm="####.accounts.company.com >>> <http://sip-190913.accounts.vocalocity.com/>", >>> nonce="5a773de000000b19dc7d21205f1edfda504fac90296b04fb", uri="sip: >>> sip-#######.accounts.company.com:5060 >>> <http://sip-190913.accounts.vocalocity.com:5060/>", >>> response="df8d6cbfd178a36913a1464920da3f06", algorithm=MD5#015#012Allow: >>> INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, >>> SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE#015#012Max-Forwards: >>> 69#015#012User-Agent: #########015#012Expires: 3600#015#012Allow-Events: >>> talk,hold,conference,refer,check-sync#015#012Content-Length: >>> 0#015#012#015#012 >>> >>> >>> Feb 4 17:07:23 sbc.amz1.company.com >>> <http://amz1vpsbc2.amz1.vocalocity.com/> /usr/sbin/opensips[29827]: >>> WARNING:core:log_expiry: #4 is a core action : 72 - 5us - line 1086 >>> >>> Feb 4 17:07:23 sbc.amz1.company.com >>> <http://amz1vpsbc2.amz1.vocalocity.com/> /usr/sbin/opensips[29820]: >>> WARNING:core:log_expiry: #1 is a module action : t_relay - 5355333us - >>> line 465 >>> >>> Feb 4 17:07:23 sbc.amz1.company.com >>> <http://amz1vpsbc2.amz1.vocalocity.com/> /usr/sbin/opensips[29827]: >>> WARNING:core:log_expiry: #5 is a module action : ds_is_in_list - 4us - >>> line 943 >>> >>> Feb 4 17:07:23 sbc.amz1.company.com >>> <http://amz1vpsbc2.amz1.vocalocity.com/> /usr/sbin/opensips[29817]: >>> WARNING:core:log_expiry: #1 is a module action : t_relay - 7375370us - >>> line 465 >>> >>> Feb 4 17:07:23 sbc.amz1.company.com >>> <http://amz1vpsbc2.amz1.vocalocity.com/> /usr/sbin/opensips[29820]: >>> WARNING:core:log_expiry: #2 is a core action : 78 - 105us - line 604 >>> >>> Feb 4 17:07:23 sbc.amz1.company.com >>> <http://amz1vpsbc2.amz1.vocalocity.com/> /usr/sbin/opensips[29817]: >>> WARNING:core:log_expiry: #2 is a core action : 78 - 100us - line 604 >>> >>> Feb 4 17:07:23 sbc.amz1.company.com >>> <http://amz1vpsbc2.amz1.vocalocity.com/> /usr/sbin/opensips[29820]: >>> WARNING:core:log_expiry: #3 is a core action : 78 - 99us - line 635 >>> >>> Feb 4 17:07:23 sbc.amz1.company.com >>> <http://amz1vpsbc2.amz1.vocalocity.com/> /usr/sbin/opensips[29817]: >>> WARNING:core:log_expiry: #3 is a core action : 78 - 98us - line 635 >>> >>> >>> _______________________________________________ >>> Users mailing >>> listUsers@lists.opensips.orghttp://lists.opensips.org/cgi-bin/mailman/listinfo/users >>> >>> >>> >> >
_______________________________________________ Users mailing list Users@lists.opensips.org http://lists.opensips.org/cgi-bin/mailman/listinfo/users
