[asterisk-bugs] [Asterisk 0017521]: Brief lagginess on IAX2 channels is fatal

Fri Jan 28 01:31:29 CST 2011

A NOTE has been added to this issue. 
====================================================================== 
https://issues.asterisk.org/view.php?id=17521 
====================================================================== 
Reported By:                jcovert
Assigned To:                
====================================================================== 
Project:                    Asterisk
Issue ID:                   17521
Category:                   Channels/chan_iax2
Reproducibility:            always
Severity:                   major
Priority:                   normal
Status:                     acknowledged
Asterisk Version:           1.6.2.8 
JIRA:                       SWP-1718 
Regression:                 No 
Reviewboard Link:            
SVN Branch (only for SVN checkouts, not tarball releases): N/A 
SVN Revision (number only!):  
Request Review:              
====================================================================== 
Date Submitted:             2010-06-17 10:32 CDT
Last Modified:              2011-01-28 01:31 CST
====================================================================== 
Summary:                    Brief lagginess on IAX2 channels is fatal
Description: 
The problem reported in issue https://issues.asterisk.org/view.php?id=15609 and
https://issues.asterisk.org/view.php?id=15900 continues:

[Jun 17 09:55:14] WARNING[15579]: channel.c:1044 __ast_queue_frame:
Exceptionally long voice queue length queuing to IAX2/x38-9660
[Jun 17 09:57:54] WARNING[15579]: channel.c:1044 __ast_queue_frame:
Exceptionally long voice queue length queuing to IAX2/x38-9660
[Jun 17 09:57:54] WARNING[15579]: channel.c:1044 __ast_queue_frame:
Exceptionally long voice queue length queuing to IAX2/x38-9660
[Jun 17 09:58:07] NOTICE[15579]: chan_iax2.c:11447 __iax2_poke_noanswer:
Peer 'x29' is now UNREACHABLE! Time: 2
[Jun 17 09:58:07] NOTICE[15579]: chan_iax2.c:11447 __iax2_poke_noanswer:
Peer 'jrclaptop' is now UNREACHABLE! Time: 4
[Jun 17 09:58:07] NOTICE[15579]: chan_iax2.c:11447 __iax2_poke_noanswer:
Peer 'x38' is now UNREACHABLE! Time: 136
[Jun 17 09:58:10] WARNING[15579]: channel.c:1044 __ast_queue_frame:
Exceptionally long voice queue length queuing to IAX2/x38-9660
[Jun 17 09:58:10] WARNING[15579]: channel.c:1044 __ast_queue_frame:
Exceptionally long voice queue length queuing to IAX2/x38-9660
[Jun 17 09:58:10] WARNING[15579]: channel.c:1044 __ast_queue_frame:
Exceptionally long voice queue length queuing to IAX2/x38-9660
    -- Hungup 'IAX2/x38-9660'
  == Spawn extension (dialstation, 38, 1) exited non-zero on
'SIP/x28-0000048b'
[Jun 17 09:58:12] NOTICE[15579]: chan_iax2.c:10418 socket_process: Peer
'x29' is now REACHABLE! Time: 2
[Jun 17 09:58:12] NOTICE[15579]: chan_iax2.c:10418 socket_process: Peer
'jrclaptop' is now REACHABLE! Time: 4
[Jun 17 09:58:12] NOTICE[15579]: chan_iax2.c:10418 socket_process: Peer
'x38' is now REACHABLE! Time: 137

This tends to reproduce for me only on transatlantic calls.

/john

======================================================================
Relationships       ID      Summary
----------------------------------------------------------------------
related to          0015609 [patch] WARNING[23025]: channel.c:952 _...
related to          0015900 Console flood &amp; CPU load 100% when ...
related to          0017625 &quot;I should never be called!&quot; m...
related to          0018511 [patch] Asterisk hangs with no calls be...
====================================================================== 

---------------------------------------------------------------------- 
 (0131157) jcovert (reporter) - 2011-01-28 01:31
 https://issues.asterisk.org/view.php?id=17521#c131157 
---------------------------------------------------------------------- 
To reproduce this problem, I'm pretty sure that you're going to have to get
the machine really busy.  I am convinced that in the changes from 1.6.1.6
to 1.6.2.6 a code change was introduced which created an n-squared (or
n-factorial or worse) inefficiency bug.

I have two different systems which are identical except for processor
speed.  I have been running my production PBX on the slower, older machine.
 The faster one is used for other work, and for pre-testing new releases of
asterisk before they are deployed into production.

I have been reporting this problem from the production machine.  It has
some 30 sip peers and 5 or six iax peers.  The problem happens ALL THE TIME
on the slower production machine.  On the faster test machine, simply doing
the originate command is not sufficient to cause the visible problem
(though IAX audio is very choppy and pretty unintelligible).

Consider the following CPU usage when the production asterisk is just
running "idle" -- doing nothing but processing registrations, qualifies,
ping/pongs, and other keepalives on sip and iax:

29189 asterisk     5.2% 12:18.40  36   721  1085  38.6M  25.0M  46.4M  
200M

Now, watch what happens when I start the test using the originate
command:

29189 asterisk   103.9% 13:15.61  >>   824  1291  40.8M+ 25.0M  48.6M+ 
224M+

Once stopped it drops back down:

29189 asterisk     5.6% 14:17.36  >>   821  1285  41.0M  25.0M  48.8M  
224M 

A similar thing happens on the faster machine, but it has enough headroom
that there are no messages unless some additional load (e.g. top sorted by
%usage).  Yet it is still choppy. 

Issue History 
Date Modified    Username       Field                    Change               
====================================================================== 
2011-01-28 01:31 jcovert        Note Added: 0131157                          
======================================================================