search

unispeech / unimrcp

Open source cross-platform implementation of MRCP protocol
http://www.unimrcp.org
Apache License 2.0
380 stars 167 forks source link

Channel is being opened too slow #250

Closed Mert84 closed 5 years ago

Mert84 commented 5 years ago

Hi, System info : unimrcp 1.5.0 windows x64 build with WPAPoll enabled in unimrcpdeps

I am observing a much slower than expected kind of situation even though the flow of logs seems normal. I am lost and need some help about where I should check.

2019-09-25 13:43:13:880936 29808 [INFO] Create Session 0x19bc0839318 [uni2] 2019-09-25 13:43:13:880936 29808 [INFO] Remote SDP 0x19bc0839318 2019-09-25 13:43:21:162304 32044 [INFO] Receive Offer 0x19bc0839318 <561175d37ab0fc40> [c:1 a:1 v:0] 2019-09-25 13:43:22:165354 15612 [INFO] Media Path 0x19bc0839318 Source->[PCMU/8000/1]->Decoder->[LPCM/8000/1]->Bridge->[LPCM/8000/1]->Sink 2019-09-25 13:43:37:257129 32044 [INFO] Send Answer 0x19bc0839318 <561175d37ab0fc40> [c:1 a:1 v:0] Status OK 2019-09-25 13:43:37:257129 32044 [INFO] Local SDP 0x19bc0839318 <561175d37ab0fc40> 2019-09-25 13:43:37:259123 29808 [NOTICE] SIP Call State 0x19bc0839318 [completed] 2019-09-25 13:44:09:258756 29808 [NOTICE] SIP Call State 0x19bc0839318 [terminating] 2019-09-25 13:44:09:258756 29808 [NOTICE] SIP Call State 0x19bc0839318 [terminated] 2019-09-25 13:44:09:258756 32044 [INFO] Deactivate Session 0x19bc0839318 <561175d37ab0fc40> 2019-09-25 13:44:09:258756 32044 [INFO] Terminate Session 0x19bc0839318 <561175d37ab0fc40> 2019-09-25 13:44:09:311759 32044 [INFO] Session Terminated 0x19bc0839318 <561175d37ab0fc40>

As far as I understand there are multiple threads processing different kinds of events while opening an mrcp channel. Specially in the following 2 lines the system is just waiting abnormally long.

2019-09-25 13:43:13:880936 29808 [INFO] Remote SDP 0x19bc0839318 2019-09-25 13:43:21:162304 32044 [INFO] Receive Offer 0x19bc0839318 <561175d37ab0fc40> [c:1 a:1 v:0]

Note that this is an Mrcpv2 channel. In this specific case there are approximately 50 RTSP healthcheck sessions being opened and closed while this channel has still not been opened. Is there some kind of a message queue size limit I need to check? I would kindly need a push in the right direction.

Regards Mert Büyüktuncay

Mert84 commented 5 years ago

The following logs are from my own developer machine with sofiasip logs enabled. I am trying to understand exactly which steps are performed between "Remote SDP" log line and "Receive Offer " log line.

2019-10-01 07:55:14:987552 16992 [INFO] Create Session 0x1a220da4168 [uni2] 2019-10-01 07:55:14:987552 30512 [DEBUG] tport_vsend returned 972 2019-10-01 07:55:14:987552 16992 [INFO] Remote SDP 0x1a220da4168 v=0 o=SestekMrcpClient 0 0 IN IP4 0.0.0.0 s=- c=IN IP4 0.0.0.0 t=0 0 m=application 9 TCP/MRCPv2 1 a=sendonly a=setup:active a=connection:new a=resource:speechrecog a=cmid:1 m=audio 55155 RTP/AVP 0 96 a=rtpmap:0 PCMU/8000 a=rtpmap:96 telephone-event/8000 a=sendonly a=ptime:20 a=mid:1

2019-10-01 07:55:14:987552 30512 [DEBUG] nta_incoming_timer: 1/1 resent, 0/1 tout, 0/0 term, 0/2 free 2019-10-01 07:55:14:987552 30512 [DEBUG] nta: timer set next to 4000 ms 2019-10-01 07:55:14:987552 16992 [DEBUG] Signal Message to [MRCP Server] [0x1a220e136d0;1;0] 2019-10-01 07:55:14:987552 30512 [DEBUG] tport_wakeup_pri(000001A220CA6610): events IN 2019-10-01 07:55:14:987552 07536 [DEBUG] Process Message [MRCP Server] [0x1a220e136d0;1;0] 2019-10-01 07:55:14:987552 30512 [DEBUG] tport_recv_event(000001A220CA6610) 2019-10-01 07:55:14:987552 07536 [DEBUG] Dispatch Signaling Message [0] 2019-10-01 07:55:14:987552 30512 [DEBUG] tport(000001A220CA6610) msg 000001A220E3FB80 from (udp/192.168.50.95:9060) has 416 bytes, veclen = 1 2019-10-01 07:55:14:987552 07536 [NOTICE] Add Session <800fe1a2a1e3ad4f> 2019-10-01 07:55:14:987552 07536 [INFO] Receive Offer 0x1a220da4168 <800fe1a2a1e3ad4f> [c:1 a:1 v:0]

I guess other than the somewhat unrelated tport event all it does is switching from thread 16992 to thread 07536 . I understand the thread 07536 is responsible from Mrcp messages' pipeline. So what could make this execute this slowly? Is it likely to be a slowness issue on the server plugin side? I just learned that the customer is using a dns name in the sip messaging instead of using ip address directly. Could this possibly have an effect on this issue?

achaloyan commented 5 years ago

Looking at the timings of the two log statements you outlined,

2019-09-25 13:43:13:880936 29808 [INFO] Remote SDP 0x19bc0839318 2019-09-25 13:43:21:162304 32044 [INFO] Receive Offer 0x19bc0839318 <561175d37ab0fc40> [c:1 a:1 v:0]

I can tell that the main thread of UniMRCP server was blocked most likely in the context of a plugin call.

The first log statement is made from the thread context of the Sofia-SIP module. Afterwards, a new message is posted to the task queue of the main thread. The message should have been processed instantaneously, unless the main thread is blocked by your plugin. There are no other possibly blocking calls in between.

If you enable DEBUG logs, you should be able to determine when the main thread is back to waiting state. And if there is a delay, then check what is actually causing it to block.

Mert84 commented 5 years ago

I remember having a similar issue when our server plugin behaved slowly when closing a session.

This time though, I have not seen one single point the server has blocked the thread. Instead what I have observed is that when more than about 60 channels are being opened/closed simultaneously, the server plugin starts to destroy the session instances slower than usual. My current guess is that these small blocking operations -each of which could have been acceptable if they have occurred infrequently- accumulate and we start to see some events stay in queue for long times before being processed properly. I would be glad to get your opinion if this is an acceptable explanation for this behavior or should I really investigate this further and try to find a single huge blocking event on our server side(I have investigated this for the last week and failed to find anything of the sort)

To overcome this entirely I've tried decoupling the unimrcpserver plugin channel open/close events (handlers in mrcp_engine_channel_method_vtable_t) from our server business entirely. Now when a channel is opened or closed the server does nothing but send a signal to another thread/system. After doing this I've observed good improvements on the timings.