Summary:ASTERISK-07766: activating applicatoion feature cause 100% system load
Reporter:Martin Vit (festr)Labels:
Date Opened:2006-09-18 13:46:49Date Closed:2006-09-27 11:59:34
Versions:Frequency of
Description:asterisk: 1.2-r43072M

call SIP A -> SIP B. B press # and loop stop until hangup.

testfeature => ASTERISK-5,callee,Playback,vm-intro


Sep 18 20:07:50 DEBUG[11592]: rtp.c:193 send_dtmf: Sending dtmf: 42 (*), at x.x.x.x
Sep 18 20:07:50 DEBUG[11592]: channel.c:3405 ast_generic_bridge: Got DTMF on channel (SIP/festrntb-08162b78)
Sep 18 20:07:50 DEBUG[11592]: channel.c:3661 ast_channel_bridge: Bridge stops bridging channels IAX2/festr-3 and SIP/festrntb-08162b78
Sep 18 20:07:50 DEBUG[11592]: res_features.c:999 ast_feature_interpret: Feature interpret: chan=IAX2/festr-3, peer=SIP/festrntb-08162b78, sense=2, features=2
Sep 18 20:07:50 DEBUG[11592]: res_features.c:1479 ast_bridge_call: Set time limit to 500
Sep 18 20:07:51 DEBUG[11592]: rtp.c:1267 ast_rtp_raw_write: Difference is 952, ms is 139
Sep 18 20:07:51 DEBUG[11592]: channel.c:3361 ast_generic_bridge: Nobody there, continuing...

from this point loop start at:

(attached gdb on running thread)

0xb7e6a871 in gettimeofday () from /lib/tls/libc.so.6
(gdb) bt
#0  0xb7e6a871 in gettimeofday () from /lib/tls/libc.so.6
#1  0x08068c05 in ast_channel_bridge (c0=0x814e558, c1=0x817e8a0, config=0xb604cf60, fo=0xb604c418, rc=0xb604c41c) at time.h:99
#2  0xb7b49f86 in ast_bridge_call (chan=0x814e558, peer=0x817e8a0, config=0xb604cf60) at res_features.c:1330
#3  0xb61f6fe4 in dial_exec_full (chan=0x814e558, data=0x50, peerflags=0xb604d608) at app_dial.c:1607
#4  0xb61f994d in dial_exec (chan=0x0, data=0x1) at app_dial.c:1649
ASTERISK-1  0x08091f9d in pbx_extension_helper (c=0x814e558, con=0xb60580b0, context=0x814e6a8 "macro-dial_ext", exten=0x814e79c "ss", priority=11, label=0x0,
   callerid=0xb60517d0 "SIP/festr|60|jtT", action=136603224) at pbx.c:553
ASTERISK-2  0x0809254c in ast_spawn_extension (c=0x0, context=0x1 <Address 0x1 out of bounds>, exten=0x1 <Address 0x1 out of bounds>, priority=1,
   callerid=0x1 <Address 0x1 out of bounds>) at pbx.c:2230
ASTERISK-3  0xb63b58dc in macro_exec (chan=0x814e558, data=0x814e558) at app_macro.c:215
ASTERISK-4  0x08091f9d in pbx_extension_helper (c=0x814e558, con=0x0, context=0x814e6a8 "macro-dial_ext", exten=0x814e79c "ss", priority=1, label=0x0,
   callerid=0xb60580b0 "dial_ext|60|jtT|Vit|exten|91|116|SIP/festr|0", action=0) at pbx.c:553
ASTERISK-5  0x08093266 in __ast_pbx_run (c=0x814e558) at pbx.c:2230
ASTERISK-6 0x08094dcc in pbx_thread (data=0x0) at pbx.c:2517
ASTERISK-7 0xb7fd0ccd in start_thread () from /lib/tls/libpthread.so.0
ASTERISK-8 0xb7eb9b0e in clone () from /lib/tls/libc.so.6

strace on this thread shows fast gettimeofday calls:

gettimeofday({1158585691, 93397}, NULL) = 0
gettimeofday({1158585691, 93528}, NULL) = 0
gettimeofday({1158585691, 93675}, NULL) = 0
gettimeofday({1158585691, 93789}, NULL) = 0
gettimeofday({1158585691, 93848}, NULL) = 0
gettimeofday({1158585691, 93919}, NULL) = 0
Comments:By: Martin Vit (festr) 2006-09-18 13:51:47

one more thing, the loop is at this line

channel.c:3504 -  for (/* ever */;;) {...

By: Serge Vecher (serge-v) 2006-09-18 14:35:33

what modifications have you done to the source?

By: Martin Vit (festr) 2006-09-18 14:39:49

no modifications,  only some breakpoints in channel.c with DEBUG printing to figer out where the loop was

By: Serge Vecher (serge-v) 2006-09-19 09:07:23

what's the output of 'ps ax' when this happens?

By: Martin Vit (festr) 2006-09-19 09:44:49

output is the same as before this happens

ps ax:

-- cut --
11362 ?        S<     0:00 /bin/sh /usr/sbin/safe_asterisk
11368 ?        S<l    5:42 /usr/sbin/asterisk -vvvg -c
11379 ?        S<     0:10 mpg123 -q -s --mono -r 8000 -b 2048 -f 8192 fpm-calm-river.mp3 le_wax_the_end.mp3 the_funky_lowlives.mp3 Flywheel.mp3 cloudy_this_morning.mp3 bana
11410 ?        S<     0:00 mpg123 -q -s --mono -r 8000 -b 2048 -f 8192 fpm-calm-river.mp3 le_wax_the_end.mp3 the_funky_lowlives.mp3 Flywheel.mp3 cloudy_this_morning.mp3 bana
21359 pts/4    S+     0:00 rasterisk r
--- cut ---

i've to cut some processes from output because of some public ip adresses

By: Serge Vecher (serge-v) 2006-09-19 10:02:02

I bet it's is the mpg123 that causes the 100% cpu utilization, the question is why  is it related to ## dtmf ...

By: Martin Vit (festr) 2006-09-19 11:14:03

i've stopped mpg123 (uncomment it in /etc/asterisk/musiconhold.conf and for sure ps ax if there is no mpg123) but the problem is the same. It is releted to any dtmf (tested * or number etc). If i do not set DYNAMIC_FEATURE for the channel, the problem does not occur.

By: Russell Bryant (russell) 2006-09-27 11:59:34

This has been fixed in the 1.2 branch, 1.4 branch, and the trunk in revisions 43778, 43779, and 43780. If you exeperience any further problems, please file a new report and please make sure that I see it. Thanks!