[asterisk-bugs] [Asterisk 0017384]: CPU usage very high when putting call on MOH
Asterisk Bug Tracker
noreply at bugs.digium.com
Tue Aug 17 16:03:16 CDT 2010
A NOTE has been added to this issue.
======================================================================
https://issues.asterisk.org/view.php?id=17384
======================================================================
Reported By: coolmig
Assigned To:
======================================================================
Project: Asterisk
Issue ID: 17384
Category: Resources/res_musiconhold
Reproducibility: always
Severity: major
Priority: normal
Status: feedback
Asterisk Version: 1.6.2.8-rc1
JIRA: SWP-1994
Regression: No
Reviewboard Link:
SVN Branch (only for SVN checkouts, not tarball releases): N/A
SVN Revision (number only!):
Request Review:
======================================================================
Date Submitted: 2010-05-24 11:26 CDT
Last Modified: 2010-08-17 16:03 CDT
======================================================================
Summary: CPU usage very high when putting call on MOH
Description:
Test scenario is very simple, two asterisk servers talking to each other
SIP.
SIP phone dials a extension on the first server which makes a call to the
other server that queues the call (and plays MOH). CPU usage is very
little, as always.
As long as I enable MOH on the SIP client, the CPU usage skyrockets... as
soon as I stop MOH on the SIP phone, everything goes back to normal.
This limits normal asterisk use with many channels involved.
======================================================================
----------------------------------------------------------------------
(0126040) coolmig (reporter) - 2010-08-17 16:03
https://issues.asterisk.org/view.php?id=17384#c126040
----------------------------------------------------------------------
OK I tested with the latest version (1.6.2.11) and this looks solved... I
think you can close this issue. I both tested with DAHDI and pthread timing
modules without difference. I set up the same scenario having positive
results, no CPU spikes and no weird MOH behavior.
As to the question "finally what was the issue?" I only can think about
what I saw on the first report (I will paste only interesting debug
lines):
[May 24 16:44:51] VERBOSE[13490] res_musiconhold.c: -- Started music
on hold, class 'default', on SIP/TRUNK_INTER_MAQUINAS-00000005
[May 24 16:44:51] DEBUG[13490] channel.c: Scheduling timer at (50
requested / 50 actual) timer ticks per second
Here is the weird part for me: the timing was requested but "generator got
voice" so timing is scheduled 0/0 with MOH on:
[May 24 16:44:51] DEBUG[13490] channel.c: Generator got voice, switching
to phase locked mode
[May 24 16:44:51] DEBUG[13490] channel.c: Scheduling timer at (0 requested
/ 0 actual) timer ticks per second
[May 24 16:44:52] DEBUG[13490] rtp.c: Got RTCP report of 64 bytes
That made MOH play at a very fast speed with the corresponding CPU spike:
[May 24 16:44:52] DEBUG[13490] res_musiconhold.c:
SIP/TRUNK_INTER_MAQUINAS-00000005 Opened file 2
'/var/lib/asterisk/moh/fpm-calm-river'
[May 24 16:44:53] DEBUG[13490] res_musiconhold.c:
SIP/TRUNK_INTER_MAQUINAS-00000005 Opened file 0
'/var/lib/asterisk/moh/fpm-sunshine'
[May 24 16:44:54] DEBUG[13490] res_musiconhold.c:
SIP/TRUNK_INTER_MAQUINAS-00000005 Opened file 1
'/var/lib/asterisk/moh/fpm-world-mix'
[May 24 16:44:56] DEBUG[13490] res_musiconhold.c:
SIP/TRUNK_INTER_MAQUINAS-00000005 Opened file 2
'/var/lib/asterisk/moh/fpm-calm-river'
[May 24 16:44:57] DEBUG[13490] res_musiconhold.c:
SIP/TRUNK_INTER_MAQUINAS-00000005 Opened file 0
'/var/lib/asterisk/moh/fpm-sunshine'
[May 24 16:44:57] DEBUG[13490] rtp.c: Got RTCP report of 64 bytes
[May 24 16:44:58] DEBUG[13490] res_musiconhold.c:
SIP/TRUNK_INTER_MAQUINAS-00000005 Opened file 1
'/var/lib/asterisk/moh/fpm-world-mix'
[May 24 16:44:59] DEBUG[13490] res_musiconhold.c:
SIP/TRUNK_INTER_MAQUINAS-00000005 Opened file 2
'/var/lib/asterisk/moh/fpm-calm-river'
[May 24 16:45:00] DEBUG[13490] res_musiconhold.c:
SIP/TRUNK_INTER_MAQUINAS-00000005 Opened file 0
'/var/lib/asterisk/moh/fpm-sunshine'
Now with 1.6.2.11, the same scenario plays well, with no "generator got
voice" and no 0/0 timer scheduling while MOH on:
[Aug 17 16:00:16] DEBUG[3556]: channel.c:2488 ast_settimeout: Scheduling
timer at (50 requested / 50 actual) timer ticks per second
[Aug 17 16:00:16] DEBUG[1813]: chan_sip.c:4091 __sip_ack: Stopping
retransmission on 'f29a31c8-b112-45a7-93de-e68074695d00' of Response 23987:
Match Found
-- Started music on hold, class 'default', on
SIP/TRUNK_INTER_MAQUINAS-00000003
[Aug 17 16:00:16] DEBUG[3556]: channel.c:2488 ast_settimeout: Scheduling
timer at (50 requested / 50 actual) timer ticks per second
virtual1_ast1*CLI> [Aug 17 16:00:16] DEBUG[3556]: res_musiconhold.c:307
ast_moh_files_next: SIP/TRUNK_INTER_MAQUINAS-00000003 Opened file 0
'/var/lib/asterisk/moh/fpm-sunshine'
[Aug 17 16:00:16] DEBUG[3556]: res_musiconhold.c:307 ast_moh_files_next:
SIP/TRUNK_INTER_MAQUINAS-00000003 Opened file 0
'/var/lib/asterisk/moh/fpm-sunshine
File plays well with almost 0% CPU consumption and no CPU spike. Timing
only goes to 0/0 when I hit the hold button again to disable MOH:
-- Stopped music on hold on SIP/TRUNK_INTER_MAQUINAS-00000003
virtual1_ast1*CLI> [Aug 17 16:02:19] DEBUG[3556]: channel.c:2488
ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks
per second
[Aug 17 16:02:19] DEBUG[3556]: channel.c:2488 ast_settimeout: Scheduling
timer at (0 requested / 0 actual) timer ticks per second
That was the cause IMHO.
Issue History
Date Modified Username Field Change
======================================================================
2010-08-17 16:03 coolmig Note Added: 0126040
======================================================================
More information about the asterisk-bugs
mailing list