[asterisk-dev] realtime architecture blocks iax network thread

[Dawid Mielnik]

Hi,

We are using asterisk (ver 1.2.9.1) interfaced via realtime (mysql via 
res_odbc or res_mysql) with a pretty large database for user authentication. 
Recently we have started to observe quite severe call quality issues which 
at first looked like network related problems - jitter, etc. After more 
intense debugging and adding a few more debug options in chan_iax we have 
noticed that realtime manages to effectively block iax's main thread on 
database queries. We have started timing execution time of socet_read() in 
iax and to our surprise, some unfortunate registration requests manage to 
block the thread for couple hundred milliseconds - example below:

Jun 23 20:00:30.029201 DEBUG[32099] chan_iax2.c: Starting processing 
'socket_read' (--NOW--)
Jun 23 20:00:30.029230 VERBOSE[32099] logger.c: Rx-Frame Retry[ No] --  
OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: REGREQ
Jun 23 20:00:30.029259 VERBOSE[32099] logger.c:    Timestamp: 00003ms 
SCall: 10810  DCall: 00000 [83.15.91.90:3888]
Jun 23 20:00:30.029283 VERBOSE[32099] logger.c:    USERNAME        : 3764
Jun 23 20:00:30.029309 VERBOSE[32099] logger.c:    REFRESH         : 60
Jun 23 20:00:30.029326 VERBOSE[32099] logger.c:
Jun 23 20:00:30.243007 DEBUG[32093] res_musiconhold.c: Only wrote -1 of 640 
bytes to pipe
Jun 23 20:00:30.243031 DEBUG[32093] res_musiconhold.c: Only wrote -1 of 640 
bytes to pipe
Jun 23 20:00:30.258157 DEBUG[32099] chan_iax2.c: realtime_peer: Registration 
for '3764' still active (60/1151085570/1151085630)!
Jun 23 20:00:30.260894 DEBUG[32099] chan_iax2.c: New max nontrunk callno is 
13
Jun 23 20:00:30.260926 DEBUG[32099] chan_iax2.c: Creating new call structure 
4
Jun 23 20:00:30.260951 DEBUG[32099] chan_iax2.c: Received packet 0, (6, 13)
Jun 23 20:00:30.260969 DEBUG[32099] chan_iax2.c: IAX subclass 13 received
Jun 23 20:00:30.260983 DEBUG[32099] chan_iax2.c: For call=4, set last=3
Jun 23 20:00:30.283004 DEBUG[32093] res_musiconhold.c: Only wrote -1 of 640 
bytes to pipe
Jun 23 20:00:30.283022 DEBUG[32093] res_musiconhold.c: Only wrote -1 of 640 
bytes to pipe
Jun 23 20:00:30.323000 DEBUG[32093] res_musiconhold.c: Only wrote -1 of 640 
bytes to pipe
Jun 23 20:00:30.323016 DEBUG[32093] res_musiconhold.c: Only wrote -1 of 640 
bytes to pipe
Jun 23 20:00:30.362997 DEBUG[32093] res_musiconhold.c: Only wrote -1 of 640 
bytes to pipe
Jun 23 20:00:30.363013 DEBUG[32093] res_musiconhold.c: Only wrote -1 of 640 
bytes to pipe
Jun 23 20:00:30.402995 DEBUG[32093] res_musiconhold.c: Only wrote -1 of 640 
bytes to pipe
Jun 23 20:00:30.403010 DEBUG[32093] res_musiconhold.c: Only wrote -1 of 640 
bytes to pipe
Jun 23 20:00:30.443098 DEBUG[32093] res_musiconhold.c: Only wrote -1 of 640 
bytes to pipe
Jun 23 20:00:30.443127 DEBUG[32093] res_musiconhold.c: Only wrote -1 of 640 
bytes to pipe
Jun 23 20:00:30.483001 DEBUG[32093] res_musiconhold.c: Only wrote -1 of 640 
bytes to pipe
Jun 23 20:00:30.483017 DEBUG[32093] res_musiconhold.c: Only wrote -1 of 640 
bytes to pipe
Jun 23 20:00:30.522996 DEBUG[32093] res_musiconhold.c: Only wrote -1 of 640 
bytes to pipe
Jun 23 20:00:30.523012 DEBUG[32093] res_musiconhold.c: Only wrote -1 of 640 
bytes to pipe
Jun 23 20:00:30.562994 DEBUG[32093] res_musiconhold.c: Only wrote -1 of 640 
bytes to pipe
Jun 23 20:00:30.563036 DEBUG[32093] res_musiconhold.c: Only wrote -1 of 640 
bytes to pipe
Jun 23 20:00:30.596691 DEBUG[32099] chan_iax2.c: realtime_peer: Registration 
for '3764' still active (60/1151085570/1151085630)!
Jun 23 20:00:30.596740 DEBUG[32092] chan_iax2.c: Checking device state for 
device 3764
Jun 23 20:00:30.597436 DEBUG[32092] chan_iax2.c: realtime_peer: Registration 
for '3764' still active (60/1151085570/1151085630)!
Jun 23 20:00:30.597455 DEBUG[32092] chan_iax2.c: iax2_devicestate(3764): 
Found peer. What's device state of 3764? addr=1515917139, defaddr=0 maxms=0, 
lastms=0
Jun 23 20:00:30.599940 DEBUG[32099] chan_iax2.c: realtime_peer: Registration 
for '3764' still active (60/1151085570/1151085630)!
Jun 23 20:00:30.602617 DEBUG[32099] chan_iax2.c: Finished processing 
'socket_read' (duration: 573 ms)

When we discovered it was the database interface causing all the problems we 
have tried using realtime caching in iax, but the current caching 
implementation isn't very effective. We have gained something like five 
database requests during a call instead of six. What we have done eventually 
is we have developed some quick work arounds by extending iax's realtime 
caching. We have taken out realtime_update_peer() into a seperate thread 
(database updates hurt the most), added a friend option to 
ast_load_realtime() which instead of only building a peer also builds a user 
and adds him to the user list, etc. In the end we have managed to cut 
database interaction down to just one request per user (during 
register_verify()) and from then on its all cached. We still have problems 
with the one request that's left during first registration (in 
register_verify()) since optimally it should be handled asynchronously to 
the network thread but we havent managed to properly get inbound 
registration out into a seperate thread - there are too many dependancies 
there and we always end up in some dead-lock.

Is there anyone who noticed these problems ?
Clearly the current iax realtime implementation is bad and any 'large' iax 
installation will run into problems. Database queries should not be handled 
by the same thread that processes incoming iax voice frames.

Does this qualify for the bug tracker ? / Or is there anyone interested in 
helping us fine brush iax realtime caching and work out a proper patch to 
handle database interaction ? Our workarounds are ok in our arrangement 
(although we still notice some problems), where all of our iax clients are 
users and peers at the same time ..but in order to properly implement the 
changes something that would take core iax developer a day or two would take 
us a couple of weeks probably.

Thanks,

Dawid