[Home]

Summary:ASTERISK-16804: [regression] DTMF on agent channel causes high CPU
Reporter:Richard Odekerken (rgj)Labels:
Date Opened:2010-10-13 06:34:28Date Closed:2011-02-10 12:57:47.000-0600
Priority:BlockerRegression?Yes
Status:Closed/CompleteComponents:General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:We've recently updated Asterisk to the latest 1.4 version.
Since then, pressing a DTMF key on an agent channel causes CPU load on a specific thread to rise with about 10%. Every time a DMTF key is pressed the CPU load goes up - and it never goes back down again until the agent logs out.

This results in our entire server going to 0% idle within 20 key presses.

Is there a way to disable DMTF while this bug is being solved so we can at least make it through?

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

We've been able to reproduce and pinpoint this behaviour and it seems to have been introduced in version 1.4.33. Versions up to 1.4.32 does not behave like this, versions 1.4.33 and up do. Bug is still present in 1.4.37-rc1.

The agent phone is registered on another asterisk running 1.2.26 (don't ask - no we cannot upgrade this box), using SIP.

I'm pretty sure this is related to r264996-265089. If we kill the thread it's always running like a mad man in asterisk_safe_sleep_conditional, running through the while() loop.
The value of ms is always 1000 when this happens.

We can fully reproduce this in our development server so if we need to test any patches or fixes please let me know.
Comments:By: Richard Odekerken (rgj) 2010-10-13 07:32:07

Just found out that the logging keeps saying that DMTF is being received, this continues after agent has stopped pressing keys on the phone. The perceived duration keeps on rising as well, after half an hour it says  "begin emulation of '7' with duration 4595 "

This is what the logging shows after agent login and a SINGLE press on the '7' key on the phone.

[Oct 13 14:31:08] VERBOSE[616] logger.c:     -- Started music on hold, class 'silence', on SIP/g2-00000001
[Oct 13 14:31:08] VERBOSE[616] logger.c:   == Agent '2004' logged in (format ulaw/ulaw)
[Oct 13 14:31:15] DTMF[616] channel.c: DTMF begin '7' received on SIP/g2-00000001
[Oct 13 14:31:15] DTMF[616] channel.c: DTMF begin passthrough '7' on SIP/g2-00000001
[Oct 13 14:31:15] DTMF[616] channel.c: DTMF end '7' received on SIP/g2-00000001, duration 60 ms
[Oct 13 14:31:15] DTMF[616] channel.c: DTMF end accepted with begin '7' on SIP/g2-00000001
[Oct 13 14:31:15] DTMF[616] channel.c: DTMF end '7' has duration 60 but want minimum 80, emulating on SIP/g2-00000001
[Oct 13 14:31:15] DTMF[616] channel.c: DTMF end emulation of '7' queued on SIP/g2-00000001
[Oct 13 14:31:15] DTMF[616] channel.c: DTMF end '7' received on SIP/g2-00000001, duration 101 ms
[Oct 13 14:31:15] DTMF[616] channel.c: DTMF begin emulation of '7' with duration 101 queued on SIP/g2-00000001
[Oct 13 14:31:15] DTMF[616] channel.c: DTMF end emulation of '7' queued on SIP/g2-00000001
[Oct 13 14:31:16] DTMF[616] channel.c: DTMF end '7' received on SIP/g2-00000001, duration 108 ms
[Oct 13 14:31:16] DTMF[616] channel.c: DTMF begin emulation of '7' with duration 108 queued on SIP/g2-00000001
[Oct 13 14:31:16] DTMF[616] channel.c: DTMF end emulation of '7' queued on SIP/g2-00000001
[Oct 13 14:31:17] DTMF[616] channel.c: DTMF end '7' received on SIP/g2-00000001, duration 126 ms
[Oct 13 14:31:17] DTMF[616] channel.c: DTMF begin emulation of '7' with duration 126 queued on SIP/g2-00000001
[Oct 13 14:31:17] DTMF[616] channel.c: DTMF end emulation of '7' queued on SIP/g2-00000001
[Oct 13 14:31:18] DTMF[616] channel.c: DTMF end '7' received on SIP/g2-00000001, duration 145 ms
[Oct 13 14:31:18] DTMF[616] channel.c: DTMF begin emulation of '7' with duration 145 queued on SIP/g2-00000001
[Oct 13 14:31:18] DTMF[616] channel.c: DTMF end emulation of '7' queued on SIP/g2-00000001
[Oct 13 14:31:19] DTMF[616] channel.c: DTMF end '7' received on SIP/g2-00000001, duration 145 ms
[Oct 13 14:31:19] DTMF[616] channel.c: DTMF begin emulation of '7' with duration 145 queued on SIP/g2-00000001
[Oct 13 14:31:20] DTMF[616] channel.c: DTMF end emulation of '7' queued on SIP/g2-00000001
[Oct 13 14:31:20] DTMF[616] channel.c: DTMF end '7' received on SIP/g2-00000001, duration 151 ms
[Oct 13 14:31:20] DTMF[616] channel.c: DTMF begin emulation of '7' with duration 151 queued on SIP/g2-00000001
[Oct 13 14:31:21] DTMF[616] channel.c: DTMF end emulation of '7' queued on SIP/g2-00000001
[Oct 13 14:31:21] DTMF[616] channel.c: DTMF end '7' received on SIP/g2-00000001, duration 169 ms
[Oct 13 14:31:21] DTMF[616] channel.c: DTMF begin emulation of '7' with duration 169 queued on SIP/g2-00000001
[Oct 13 14:31:22] DTMF[616] channel.c: DTMF end emulation of '7' queued on SIP/g2-00000001
[Oct 13 14:31:22] DTMF[616] channel.c: DTMF end '7' received on SIP/g2-00000001, duration 187 ms
[Oct 13 14:31:22] DTMF[616] channel.c: DTMF begin emulation of '7' with duration 187 queued on SIP/g2-00000001
[Oct 13 14:31:23] DTMF[616] channel.c: DTMF end emulation of '7' queued on SIP/g2-00000001
[Oct 13 14:31:24] DTMF[616] channel.c: DTMF end '7' received on SIP/g2-00000001, duration 203 ms
[Oct 13 14:31:24] DTMF[616] channel.c: DTMF begin emulation of '7' with duration 203 queued on SIP/g2-00000001

and on and on forever.


By: Richard Odekerken (rgj) 2010-10-21 04:31:27

Awaiting a patch, is there a workaround, for instance disabling DTMF ? This is a day to day issue now, getting towards critical.
By: Leif Madsen (lmadsen) 2010-11-04 13:34:42

Upgrading this as a blocker for the next version. Hopefully a developer will have a chance to look at this shortly.
By: Richard Odekerken (rgj) 2010-12-15 08:00:43.000-0600

Still not fixed in 1.4.38 ... is anyone actually working on this?
Is there anything we can do to help out?
By: Digium Subversion (svnbot) 2011-01-12 12:10:44.000-0600

Repository: asterisk
Revision: 301502

U   branches/1.4/main/channel.c

------------------------------------------------------------------------
r301502 | jpeeler | 2011-01-12 12:10:43 -0600 (Wed, 12 Jan 2011) | 12 lines

Fix CPU spike when pressing DTMF after agent login.

The problem here is that DTMF was being continuously deferred and requeued
since ast_safe_sleep is called in a loop. There are serveral other places in the
code that sleeps and then loops in a similar fashion. Because of this fact I
opted to not defer DTMF any more, which will not affect the original fix:

https://reviewboard.asterisk.org/r/674

(closes issue ASTERISK-16804)
Reported by: rgj

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=301502
By: Digium Subversion (svnbot) 2011-01-12 12:11:50.000-0600

Repository: asterisk
Revision: 301503

_U  branches/1.6.2/
U   branches/1.6.2/main/channel.c

------------------------------------------------------------------------
r301503 | jpeeler | 2011-01-12 12:11:50 -0600 (Wed, 12 Jan 2011) | 19 lines

Merged revisions 301502 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.4

........
 r301502 | jpeeler | 2011-01-12 12:10:42 -0600 (Wed, 12 Jan 2011) | 12 lines
 
 Fix CPU spike when pressing DTMF after agent login.
 
 The problem here is that DTMF was being continuously deferred and requeued
 since ast_safe_sleep is called in a loop. There are serveral other places in the
 code that sleeps and then loops in a similar fashion. Because of this fact I
 opted to not defer DTMF any more, which will not affect the original fix:
 
 https://reviewboard.asterisk.org/r/674
 
 (closes issue ASTERISK-16804)
 Reported by: rgj
........

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=301503
By: Digium Subversion (svnbot) 2011-01-12 12:12:09.000-0600

Repository: asterisk
Revision: 301504

_U  branches/1.8/
U   branches/1.8/main/channel.c

------------------------------------------------------------------------
r301504 | jpeeler | 2011-01-12 12:12:09 -0600 (Wed, 12 Jan 2011) | 26 lines

Merged revisions 301503 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.6.2

................
 r301503 | jpeeler | 2011-01-12 12:11:49 -0600 (Wed, 12 Jan 2011) | 19 lines
 
 Merged revisions 301502 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.4
 
 ........
   r301502 | jpeeler | 2011-01-12 12:10:42 -0600 (Wed, 12 Jan 2011) | 12 lines
   
   Fix CPU spike when pressing DTMF after agent login.
   
   The problem here is that DTMF was being continuously deferred and requeued
   since ast_safe_sleep is called in a loop. There are serveral other places in the
   code that sleeps and then loops in a similar fashion. Because of this fact I
   opted to not defer DTMF any more, which will not affect the original fix:
   
   https://reviewboard.asterisk.org/r/674
   
   (closes issue ASTERISK-16804)
   Reported by: rgj
 ........
................

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=301504
By: Digium Subversion (svnbot) 2011-01-12 12:12:33.000-0600

Repository: asterisk
Revision: 301505

_U  trunk/
U   trunk/main/channel.c

------------------------------------------------------------------------
r301505 | jpeeler | 2011-01-12 12:12:32 -0600 (Wed, 12 Jan 2011) | 33 lines

Merged revisions 301504 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.8

................
 r301504 | jpeeler | 2011-01-12 12:12:08 -0600 (Wed, 12 Jan 2011) | 26 lines
 
 Merged revisions 301503 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.6.2
 
 ................
   r301503 | jpeeler | 2011-01-12 12:11:49 -0600 (Wed, 12 Jan 2011) | 19 lines
   
   Merged revisions 301502 via svnmerge from
   https://origsvn.digium.com/svn/asterisk/branches/1.4
   
   ........
     r301502 | jpeeler | 2011-01-12 12:10:42 -0600 (Wed, 12 Jan 2011) | 12 lines
     
     Fix CPU spike when pressing DTMF after agent login.
     
     The problem here is that DTMF was being continuously deferred and requeued
     since ast_safe_sleep is called in a loop. There are serveral other places in the
     code that sleeps and then loops in a similar fashion. Because of this fact I
     opted to not defer DTMF any more, which will not affect the original fix:
     
     https://reviewboard.asterisk.org/r/674
     
     (closes issue ASTERISK-16804)
     Reported by: rgj
   ........
 ................
................

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=301505