ASTERISK-15360: Exceptionally long voice queue length with chan_iax2 + res_timing

[Home]

Summary: ASTERISK-15360: Exceptionally long voice queue length with chan_iax2 + res_timing_pthread causes high CPU usage

Reporter: Marcello Ceschia (marcelloceschia) Labels:

Date Opened: 2009-12-23 04:58:13.000-0600 Date Closed: 2010-06-17 13:34:18

Priority: Major Regression? Yes

Status: Closed/Complete Components: Channels/chan_iax2

Versions: Frequency of
Occurrence

Related
Issues:

Environment: Attachments: ( 0) gdb.txt

Description: When making a call using iax channel, i have a high cpu usage ~97%
This does not only happens while transcoding audio, also with the same codecs on both sides.

after a short time, i get the following cli output:

[Dec 23 11:45:29] WARNING[12300]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/diax-6892

Calling sip2sip has a cpu usage about 1.5% per call

****** ADDITIONAL INFORMATION ******

OS: openSuSE 11.2
Kernel: 2.6.31.5-0.1-default
Arch: i686

Comments: By: Leif Madsen (lmadsen) 2010-01-04 12:54:33.000-0600

This looks to be a duplicate of 15609
By: Marcello Ceschia (marcelloceschia) 2010-01-30 09:47:28.000-0600

this problem is still alive in 1.6.2.1 when compiling with DEBUG_CHANNEL_LOCKS flag
By: Marcello Ceschia (marcelloceschia) 2010-02-01 06:43:59.000-0600

some output with asterisk 1.6.2.1 and DEBUG CHANNEL LOCKS flag:

[Feb 1 13:41:39] WARNING[4536]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/asterisk01-2469
[Feb 1 13:41:39] WARNING[13421]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/asterisk01-2469
[Feb 1 13:41:39] WARNING[13423]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/asterisk01-2469
[Feb 1 13:41:39] WARNING[4537]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/asterisk01-2469
asterisk03*CLI> core show locks
[Feb 1 13:41:39] WARNING[13426]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/asterisk01-2469
asterisk03*CLI>
=======================================================================
=== Currently Held Locks ==============================================
=======================================================================
===
=== <pending> <lock#> (<file>): <lock type> <line num> <function> <lock name> <lock addr> (times locked)
===
=== Thread ID: -1299924112 (iax2_process_thread started at [11713] chan_iax2.c start_network_thread())
=== ---> Waiting for Lock #0 (chan_iax2.c): MUTEX 9629 socket_process &iaxsl[fr->callno] 0xb34a6a48 (1)
/usr/sbin/asterisk(ast_bt_get_addresses+0x1a) [0x814795a]
/usr/lib/asterisk/modules/chan_iax2.so [0xb3070c6e]
/usr/lib/asterisk/modules/chan_iax2.so [0xb30a583a]
/usr/lib/asterisk/modules/chan_iax2.so [0xb30b25d2]
/usr/sbin/asterisk [0x81e151e]
/lib/libpthread.so.0 [0xb72916e5]
/lib/libpthread.so.0 [0xb7291600]
=== --- ---> Locked Here: chan_iax2.c line 9629 (socket_process)
=== -------------------------------------------------------------------
===
=== Thread ID: -1306244240 (pbx_thread started at [ 4563] pbx.c ast_pbx_start())
=== ---> Lock #0 (channel.c): MUTEX 3386 ast_write (channel lock) 0xc41dc2c (1)
/usr/sbin/asterisk(ast_bt_get_addresses+0x1a) [0x814795a]
/usr/sbin/asterisk [0x80bd4ae]
/usr/sbin/asterisk(ast_write+0xfe) [0x80c699e]
/usr/sbin/asterisk(ast_channel_bridge+0xa4f) [0x80caddf]
/usr/sbin/asterisk(ast_bridge_call+0x30c) [0x8111dec]
/usr/lib/asterisk/modules/app_dial.so [0xb62c4531]
/usr/lib/asterisk/modules/app_dial.so [0xb62c780d]
/usr/sbin/asterisk(pbx_exec+0xf5) [0x816c085]
/usr/sbin/asterisk [0x817a358]
/usr/sbin/asterisk [0x817c321]
/usr/sbin/asterisk [0x817db16]
/usr/sbin/asterisk [0x81e151e]
/lib/libpthread.so.0 [0xb72916e5]
/lib/libpthread.so.0 [0xb7291600]
=== ---> Waiting for Lock #1 (chan_iax2.c): MUTEX 7104 iax2_write &iaxsl[callno] 0xb34a6a48 (1)
/usr/sbin/asterisk(ast_bt_get_addresses+0x1a) [0x814795a]
/usr/lib/asterisk/modules/chan_iax2.so [0xb3070c6e]
/usr/lib/asterisk/modules/chan_iax2.so [0xb30a583a]
/usr/lib/asterisk/modules/chan_iax2.so [0xb30b25d2]
/usr/sbin/asterisk [0x81e151e]
/lib/libpthread.so.0 [0xb72916e5]
/lib/libpthread.so.0 [0xb7291600]
=== --- ---> Locked Here: chan_iax2.c line 9629 (socket_process)
=== -------------------------------------------------------------------
===
=== Thread ID: -1309439120 (iax2_process_thread started at [ 1308] chan_iax2.c find_idle_thread())
=== ---> Waiting for Lock #0 (chan_iax2.c): MUTEX 9629 socket_process &iaxsl[fr->callno] 0xb34a6a48 (1)
/usr/sbin/asterisk(ast_bt_get_addresses+0x1a) [0x814795a]
/usr/lib/asterisk/modules/chan_iax2.so [0xb3070c6e]
/usr/lib/asterisk/modules/chan_iax2.so [0xb30a583a]
/usr/lib/asterisk/modules/chan_iax2.so [0xb30b25d2]
/usr/sbin/asterisk [0x81e151e]
/lib/libpthread.so.0 [0xb72916e5]
/lib/libpthread.so.0 [0xb7291600]
=== --- ---> Locked Here: chan_iax2.c line 9629 (socket_process)
=== -------------------------------------------------------------------
===
=======================================================================

[Feb 1 13:41:39] WARNING[13440]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/asterisk01-2469
[Feb 1 13:41:39] WARNING[4532]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/asterisk01-2469
[Feb 1 13:41:39] WARNING[4530]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/asterisk01-2469
[Feb 1 13:41:39] WARNING[4529]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/asterisk01-2469
[Feb 1 13:41:39] WARNING[4528]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/asterisk01-2469
[Feb 1 13:41:39] WARNING[4534]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/asterisk01-2469
[Feb 1 13:41:40] WARNING[4529]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/asterisk01-2469
[Feb 1 13:41:40] WARNING[4537]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/asterisk01-2469
[Feb 1 13:41:40] WARNING[13424]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/asterisk01-2469
[Feb 1 13:41:40] WARNING[13425]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/asterisk01-2469
[Feb 1 13:41:40] WARNING[4536]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/asterisk01-2469
[Feb 1 13:41:40] WARNING[4531]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/asterisk01-2469
[Feb 1 13:41:40] WARNING[13416]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/asterisk01-2469
[Feb 1 13:41:40] WARNING[13422]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/asterisk01-2469
[Feb 1 13:41:40] WARNING[13427]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/asterisk01-2469
[Feb 1 13:41:40] WARNING[4530]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/asterisk01-2469
[Feb 1 13:41:40] WARNING[4532]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/asterisk01-2469
[Feb 1 13:41:40] WARNING[4535]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/asterisk01-2469
[Feb 1 13:41:40] WARNING[4528]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/asterisk01-2469
[Feb 1 13:41:40] WARNING[4536]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/asterisk01-2469
By: capouch (capouch) 2010-02-06 18:05:56.000-0600

I'm seeing the same behavior on trunk, r243077. Same behavior, including the fact that it's not transcoding. I've tried w/jitterbuffer on and off, tried talking to both older and newer versions of Asterisk, and the result is the same.

I will note that it doesn't always happen quickly, but it does always happen eventually.
By: Leif Madsen (lmadsen) 2010-02-16 13:26:11.000-0600

Can you guys test after revision 244071? There is a related commit at that revision.
By: Marcello Ceschia (marcelloceschia) 2010-02-17 02:17:07.000-0600

ok, i checked out Asterisk SVN-branch-1.6.2-r246989 and build it with:

DEBUG_THREADS
LOADABLE_MODULES
DEBUG_FD_LEAKS
DEBUG_CHANNEL_LOCKS
MALLOC_DEBUG

the behavior is the same as bevore; cpu load about 98% and warnings with "Exceptionally long voice queue length queuing"

By: Andrey Sofronov (andrey sofronov) 2010-04-01 03:42:09

I have the same problem (Asterisk 1.6.1.18 / Asterisk 1.6.2.6) couple times a week.

Scheme:
PBX Panasonic TDA -> PRI-30 -> WCTE12XP -> asterisk 1.6.1.18 -> IAX2 | internet | -> IAX2 -> asterisk 1.6.1.18 -> ....

CPU load ~100% and Exceptionally long voice queue length queuing to IAX2/...
By: Andrey Sofronov (andrey sofronov) 2010-04-27 04:35:43

Downgraded to Asterisk 1.6.2.2. It works fine about 3 weeks!
By: Victor Toofic (toofic) 2010-05-01 09:51:08

I've downgraded to 1.6.2.2 and still getting "Exceptionally long voice queue length queuing to IAX2..." and coredumped several times a day.
By: Paul Belanger (pabelanger) 2010-05-01 11:34:31

If you are getting coredumps please upload a non optimized backtrace (see below).
--
Thank you for your bug report. In order to move your issue forward, we require a backtrace from the core file produced after the crash. Please see the doc/backtrace.txt file in your Asterisk source directory.

Also, be sure you have DONT_OPTIMIZE enabled in menuselect within the Compiler Flags section, then:

make install

after enabling, reproduce the crash, and then execute the instructions in doc/backtrace.txt.

When complete, attach that file to this issue report. Thanks!
By: Victor Toofic (toofic) 2010-05-03 14:55:44

I've attached all threads bt. A single bt gives: "Cannot access memory at address 0xa".

This the output of gdb:

Core was generated by `/usr/local/asterisk/asterisk-1.6.2.2.stable/sbin/asterisk -f -vvvg -c'.
Program terminated with signal 11, Segmentation fault.
#0 pthread_timer_disable_continuous (handle=Cannot access memory at address 0xffffffffffffffee
) at res_timing_pthread.c:240
240 ao2_unlock(timer);

Thnks!
By: Leif Madsen (lmadsen) 2010-05-04 15:35:47

@toofic: are you using res_timing_pthreads? If so, you might want to disable that module and use the timing from DAHDI as that is more stable at this time.
By: Victor Toofic (toofic) 2010-05-06 15:56:35

That seems to work!!

Using res_timing_dahdi with dahdi_dummy solved the crashes, the high cpu load and the "Exceptionally long voice queue length queuing to IAX2..." messages.

At least it has been running for 2 days without any problems, that's a relief!! as it was crashing several times per day.

Thnks!
By: Leif Madsen (lmadsen) 2010-05-10 11:17:28

@toofic: thanks for the feedback! This will be dealt with as time and resources allow.
By: Mikko Korkalo (keitsi) 2010-05-21 06:29:56

Hi,

I had a very, very similar issue.
I don't know if it should be reported as a seperate bug or not, but definitely it seems related!

The errors shown in CLI were:

------------------------
voip2*CLI>
[May 21 03:28:35] WARNING[26473]: chan_iax2.c:3330 __attempt_transmit: Max retries exceeded to host 10.240.100.34 on IAX2/someiaxclient-7248 (type = 6, subclass = 2, ts=1320274, seqno=76)
== Spawn extension (innovaphone-5, 0400998371, 1) exited non-zero on 'IAX2/someiaxclient-7248'
-- Hungup 'IAX2/someiaxclient-7248'
[May 21 03:28:39] WARNING[26473]: chan_iax2.c:3330 __attempt_transmit: Max retries exceeded to host 10.240.100.123 on IAX2/anotheriaxclient-1822 (type = 6, subclass = 11, ts=374302, seqno=100)
[May 21 03:28:39] WARNING[26832]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/anotheriaxclient-1822
[May 21 03:28:39] WARNING[26826]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/anotheriaxclient-1822
[May 21 03:28:39] WARNING[26854]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/anotheriaxclient-1822
[May 21 03:28:39] WARNING[26810]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/anotheriaxclient-1822
[May 21 03:28:39] WARNING[26857]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/anotheriaxclient-1822
[May 21 03:28:39] WARNING[26822]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/anotheriaxclient-1822
[May 21 03:28:39] WARNING[26817]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/anotheriaxclient-1822
[May 21 03:28:39] WARNING[26852]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/anotheriaxclient-1822
[May 21 03:28:39] WARNING[26807]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/anotheriaxclient-1822
[May 21 03:28:39] WARNING[26811]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/anotheriaxclient-1822
[May 21 03:28:39] WARNING[26819]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/anotheriaxclient-1822
[May 21 03:28:39] WARNING[26802]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/anotheriaxclient-1822
[May 21 03:28:39] WARNING[26806]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/anotheriaxclient-1822
[May 21 03:28:39] WARNING[26796]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/anotheriaxclient-1822
-- Registered IAX2 'anotheriaxclient' (AUTHENTICATED) at 10.240.100.123:4569
== Spawn extension (innovaphone-4, 0400998371, 1) exited non-zero on 'IAX2/anotheriaxclient-1822'
-- Hungup 'IAX2/anotheriaxclient-1822'
-- Registered IAX2 'someiaxclient' (AUTHENTICATED) at 10.240.100.34:4569
-- Registered IAX2 'someiaxclient' (AUTHENTICATED) at 10.240.100.123:4176
-- Registered IAX2 'someiaxclient' (AUTHENTICATED) at 10.240.100.34:4569
------------------------

With just 2 calls, I could get CPU usage 40 - 80% with P4 processor, loads 1-2.
3 calls, loads were about ~8 and CPU at max (95%+).
4 calls, loads were about ~20+ and CPU at max (95%+), calls drop eventually.

I tried other timing settings, but they didn't change anything.
I added noload => res_timing_pthreads.so and load => res_timing_dahdi.so to modules.conf, and also tried changing internal_timing in asterisk.conf (both yes and no). No help here.

The setup was:
custom iax2 client software --- iax2+speex --- asterisk iax2 server --- asterisk h323 server --- ulaw/h323 --- h323 client --- GSM modem --- GSM network

Resolution:
I switched the h323 codec from ulaw to alaw, and bam, NO MORE PROBLEMS!
Speex was used in iax side, but on h323 side ulaw was used.
Loads were then near zero, and CPU usage less than 10% all the way up to 6 calls.
My guess is that it's some kind of thread locking issue related to ulaw and/or h323/iax2.

System information:
Distro: Ubuntu 10.04
Asterisk: Stock 1.6.2.5 with ubuntu 10.04 LTS patches (1.6.2.5-0ubuntu1)
HW: P4 with 512MB RAM
Kernel: 2.6.32-21-generic-pae ASTERISK-28-Ubuntu SMP

root@voip2:~# dpkg -l|grep asterisk
ii asterisk 1:1.6.2.5-0ubuntu1 Open Source Private Branch Exchange (PBX)
ii asterisk-chan-sebi 0.0.20100520-1 chan_sebi for asterisk
ii asterisk-config 1:1.6.2.5-0ubuntu1 Configuration files for Asterisk
ii asterisk-dev 1:1.6.2.5-0ubuntu1 Development files for Asterisk
ii asterisk-h323 1:1.6.2.5-0ubuntu1 H.323 protocol support for Asterisk
ii asterisk-sounds-main 1:1.6.2.5-0ubuntu1 Core Sound files for Asterisk (English)
root@voip2:~# uname -a
Linux voip2 2.6.32-21-generic-pae ASTERISK-28-Ubuntu SMP Fri Apr 16 09:39:35 UTC 2010 i686 GNU/Linux
root@voip2:~# cat /proc/cpuinfo
processor : 0
vendor_id : GenuineIntel
cpu family : 15
model : 2
model name : Intel(R) Pentium(R) 4 CPU 2.66GHz
stepping : 9
cpu MHz : 2660.292
cache size : 512 KB
fdiv_bug : no
hlt_bug : no
f00f_bug : no
coma_bug : no
fpu : yes
fpu_exception : yes
cpuid level : 2
wp : yes
flags : fpu vme de pse tsc msr pae mce cx8 apic mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe up pebs bts cid xtpr
bogomips : 5320.58
clflush size : 64
cache_alignment : 128
address sizes : 36 bits physical, 32 bits virtual
power management:

root@voip2:~# lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description: Ubuntu 10.04 LTS
Release: 10.04
Codename: lucid
By: Leif Madsen (lmadsen) 2010-06-17 13:34:17

I'm closing this issue as it appears ASTERISK-14558 has been closed. It appears res_timing_pthread may have been part of the culprit here.

If you continue to have issues or have other related problems, please open a new issue.