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 <mailto: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 <mailto: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:
Feb4 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
Feb4 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
Feb4 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
Feb4 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
Feb4 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
Feb4 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
Feb4 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
Feb4 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
Feb4 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
Feb4 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
Feb4 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
Feb4 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
Feb4 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 list
Users@lists.opensips.org <mailto:Users@lists.opensips.org>
http://lists.opensips.org/cgi-bin/mailman/listinfo/users
_______________________________________________
Users mailing list
Users@lists.opensips.org
http://lists.opensips.org/cgi-bin/mailman/listinfo/users
