[Home]

Summary:ASTERISK-10762: Distortion in Playback of .gsm files over non-GSM channel
Reporter:Peter Whisker (whiskerp)Labels:
Date Opened:2007-11-14 06:35:58.000-0600Date Closed:2010-07-22 13:19:09
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Codecs/codec_gsm
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) 1.2-gsm-gcc4.2.patch
( 1) 1.4-gsm-gcc4.2.patch
( 2) 11243-maybe-asm.diff
Description:On one of my Asterisk boxes, I am getting distortion on playback of .gsm sound files. Distortion is heard when transcoding is used to a non-GSM channel. Connecting over a GSM channel is fine.

The other Asterisk server running the same Asterisk SVN version is OK, so it may be related to dual-processor or OS version.

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

I have two Asterisk servers, both currently running tip of branches/1.4

svn checkout http://svn.digium.com/svn/asterisk/branches/1.4 asterisk-1.4
svn checkout http://svn.digium.com/svn/zaptel/branches/1.4 zaptel-1.4
svn checkout http://svn.digium.com/svn/libpri/branches/1.4 libpri-1.4

One is running Debian "Testing" on a twin-processor Pentium III. The other is running Ubuntu "Feisty Fawn" on a single-processor Pentium III. Both are fully updated to today.

uname -a:

Debian (2-processor):
Linux alambil 2.6.22-2-686 #1 SMP Fri Aug 31 00:24:01 UTC 2007 i686 GNU/Linux

Ubuntu (1-processor):
Linux network 2.6.20-16-server #2 SMP Sun Sep 23 19:57:25 UTC 2007 i686 GNU/Linux

Playback of .gsm files on the Debian-based server started to be distorted the last time I upgraded Asterisk. There are no errors reported. My SIP phone is a Sipura ATA with alaw preferred.

Debug is shown below. Should the channel write format change as frequently as it does or is this  normal?

[Nov 14 12:16:39] DEBUG[3865]: chan_sip.c:4468 sip_alloc: Allocating new SIP dialog for 29a21a37-e0b1061e@158.234.80.17 - INVITE (With RTP)
[Nov 14 12:16:39] DEBUG[3865]: chan_sip.c:15028 handle_request: **** Received INVITE (5) - Command in SIP INVITE
[Nov 14 12:16:39] DEBUG[3865]: chan_sip.c:2702 do_setnat: Setting NAT on RTP to Off
[Nov 14 12:16:39] DEBUG[3865]: chan_sip.c:2707 do_setnat: Setting NAT on VRTP to Off
[Nov 14 12:16:39] DEBUG[3865]: chan_sip.c:4521 find_call: = Found Their Call ID: 29a21a37-e0b1061e@158.234.80.17 Their Tag 394d336356dee2o0 Our tag: as009b4bc0
[Nov 14 12:16:39] DEBUG[3865]: chan_sip.c:15028 handle_request: **** Received ACK (6) - Command in SIP ACK
[Nov 14 12:16:39] DEBUG[3865]: chan_sip.c:2165 __sip_ack: Stopping retransmission on '29a21a37-e0b1061e@158.234.80.17' of Response 101: Match Not Found
[Nov 14 12:16:39] DEBUG[3865]: chan_sip.c:4521 find_call: = Found Their Call ID: 29a21a37-e0b1061e@158.234.80.17 Their Tag 394d336356dee2o0 Our tag: as009b4bc0
[Nov 14 12:16:39] DEBUG[3865]: chan_sip.c:15028 handle_request: **** Received INVITE (5) - Command in SIP INVITE
[Nov 14 12:16:39] DEBUG[3865]: chan_sip.c:2702 do_setnat: Setting NAT on RTP to Off
[Nov 14 12:16:39] DEBUG[3865]: chan_sip.c:2707 do_setnat: Setting NAT on VRTP to Off
[Nov 14 12:16:39] DEBUG[3865]: chan_sip.c:5319 process_sdp: T38 state changed to 0 on channel <none>
[Nov 14 12:16:39] DEBUG[3865]: chan_sip.c:5399 process_sdp: We're settling with these formats: 0x8 (alaw)
[Nov 14 12:16:39] DEBUG[3865]: chan_sip.c:13708 handle_request_invite: Checking SIP call limits for device 230
[Nov 14 12:16:39] DEBUG[3865]: chan_sip.c:3140 update_call_counter: Updating call counter for incoming call
[Nov 14 12:16:39] DEBUG[3865]: chan_sip.c:3957 sip_new: *** Our native formats are 0x8 (alaw)
[Nov 14 12:16:39] DEBUG[3865]: chan_sip.c:3958 sip_new: *** Joint capabilities are 0x8 (alaw)
[Nov 14 12:16:39] DEBUG[3865]: chan_sip.c:3959 sip_new: *** Our capabilities are 0x8 (alaw)
[Nov 14 12:16:39] DEBUG[3865]: chan_sip.c:3960 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw)
[Nov 14 12:16:39] DEBUG[3865]: chan_sip.c:3983 sip_new: This channel will not be able to handle video.
[Nov 14 12:16:39] DEBUG[3865]: chan_sip.c:8176 build_route: build_route: Contact hop: 230 <sip:230@158.234.80.17:5060>
[Nov 14 12:16:39] DEBUG[3865]: chan_sip.c:13787 handle_request_invite: SIP/230-081b06b8: New call is still down.... Trying...
[Nov 14 12:16:39] DEBUG[3865]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/230-081b06b8
[Nov 14 12:16:39] DEBUG[3996]: pbx.c:1814 pbx_extension_helper: Launching 'Answer'
   -- Executing [124@passworded:1] Answer("SIP/230-081b06b8", "") in new stack
[Nov 14 12:16:39] DEBUG[3863]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 230
[Nov 14 12:16:39] DEBUG[3996]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/230-081b06b8
[Nov 14 12:16:39] DEBUG[3863]: chan_sip.c:15655 sip_devicestate: Checking device state for peer 230
[Nov 14 12:16:39] DEBUG[3996]: chan_sip.c:3611 sip_answer: SIP answering channel: SIP/230-081b06b8
[Nov 14 12:16:39] DEBUG[3863]: devicestate.c:287 do_state_change: Changing state for SIP/230 - state 1 (Not in use)
[Nov 14 12:16:39] DEBUG[3996]: chan_sip.c:6592 transmit_response_with_sdp: Setting framing from config on incoming call
[Nov 14 12:16:39] DEBUG[3881]: app_queue.c:575 handle_statechange: Device 'SIP/230' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Nov 14 12:16:39] DEBUG[3996]: chan_sip.c:6356 add_sdp: ** Our capability: 0x8 (alaw) Video flag: True
[Nov 14 12:16:39] DEBUG[3996]: chan_sip.c:6357 add_sdp: ** Our prefcodec: 0x0 (nothing)
[Nov 14 12:16:39] DEBUG[3863]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 230
[Nov 14 12:16:39] DEBUG[3996]: chan_sip.c:6488 add_sdp: -- Done with adding codecs to SDP
[Nov 14 12:16:39] DEBUG[3863]: chan_sip.c:15655 sip_devicestate: Checking device state for peer 230
[Nov 14 12:16:39] DEBUG[3996]: channel.c:2553 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=21)
[Nov 14 12:16:39] DEBUG[3863]: devicestate.c:287 do_state_change: Changing state for SIP/230 - state 1 (Not in use)
[Nov 14 12:16:39] DEBUG[3996]: chan_sip.c:6533 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw)
[Nov 14 12:16:39] DEBUG[3881]: app_queue.c:575 handle_statechange: Device 'SIP/230' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Nov 14 12:16:39] DEBUG[3996]: pbx.c:1814 pbx_extension_helper: Launching 'SayUnixTime'
   -- Executing [124@passworded:2] SayUnixTime("SIP/230-081b06b8", "|GMT0BST|AdBY 'digits/at' IM") in new stack
[Nov 14 12:16:39] DEBUG[3996]: say.c:3010 ast_say_date_with_format_en: Parsing A (offset 0) in AdBY 'digits/at' IM
[Nov 14 12:16:39] DEBUG[3996]: channel.c:3041 set_format: Set channel SIP/230-081b06b8 to write format gsm
[Nov 14 12:16:39] DEBUG[3996]: rtp.c:2731 ast_rtp_write: Ooh, format changed from unknown to alaw
[Nov 14 12:16:39] DEBUG[3996]: rtp.c:2748 ast_rtp_write: Created smoother: format: 8 ms: 20 len: 160
[Nov 14 12:16:39] DEBUG[3996]: channel.c:2072 ast_settimeout: Scheduling timer at 160 sample intervals
   -- <SIP/230-081b06b8> Playing 'digits/day-3' (language 'en')
[Nov 14 12:16:39] DEBUG[3865]: chan_sip.c:4521 find_call: = Found Their Call ID: 29a21a37-e0b1061e@158.234.80.17 Their Tag 394d336356dee2o0 Our tag: as56a124e1
[Nov 14 12:16:39] DEBUG[3865]: chan_sip.c:15028 handle_request: **** Received ACK (6) - Command in SIP ACK
[Nov 14 12:16:39] DEBUG[3865]: chan_sip.c:2165 __sip_ack: Stopping retransmission on '29a21a37-e0b1061e@158.234.80.17' of Response 102: Match Not Found
[Nov 14 12:16:40] DEBUG[3996]: channel.c:2072 ast_settimeout: Scheduling timer at 0 sample intervals
[Nov 14 12:16:40] DEBUG[3996]: channel.c:2072 ast_settimeout: Scheduling timer at 0 sample intervals
[Nov 14 12:16:40] DEBUG[3996]: channel.c:3041 set_format: Set channel SIP/230-081b06b8 to write format alaw
[Nov 14 12:16:40] DEBUG[3996]: say.c:3010 ast_say_date_with_format_en: Parsing d (offset 1) in AdBY 'digits/at' IM
[Nov 14 12:16:40] DEBUG[3996]: channel.c:3041 set_format: Set channel SIP/230-081b06b8 to write format gsm
[Nov 14 12:16:40] DEBUG[3996]: channel.c:2072 ast_settimeout: Scheduling timer at 160 sample intervals
   -- <SIP/230-081b06b8> Playing 'digits/h-14' (language 'en')
[Nov 14 12:16:41] DEBUG[3996]: channel.c:2072 ast_settimeout: Scheduling timer at 0 sample intervals
[Nov 14 12:16:41] DEBUG[3996]: channel.c:2072 ast_settimeout: Scheduling timer at 0 sample intervals
[Nov 14 12:16:41] DEBUG[3996]: channel.c:3041 set_format: Set channel SIP/230-081b06b8 to write format alaw
[Nov 14 12:16:41] DEBUG[3996]: say.c:3010 ast_say_date_with_format_en: Parsing B (offset 2) in AdBY 'digits/at' IM
[Nov 14 12:16:41] DEBUG[3996]: channel.c:3041 set_format: Set channel SIP/230-081b06b8 to write format gsm
[Nov 14 12:16:41] DEBUG[3996]: channel.c:2072 ast_settimeout: Scheduling timer at 160 sample intervals

Comments:By: Tilghman Lesher (tilghman) 2007-11-14 10:39:47.000-0600

Are you sure this isn't a bandwidth problem?  alaw uses a significantly higher amount of bandwidth than gsm.  One thing to try is to run 'make menuselect' and install the alaw sounds, and try again.  If you're still getting distortion, then the problem is bandwidth, not transcoding.

By: Peter Whisker (whiskerp) 2007-11-14 13:07:25.000-0600

Absolutely certain its not bandwidth as I am on a LAN. I have used this server for some years, upgraded to 1.4 earlier in the year - all worked fine until a recent SVN upgrade. The call quality is 100% on normal calls and WAV sound files - it's just the GSM sound files that are distorted. I have not changed the files for years - they are the core Asterisk files. I know I could change them to WAV but that wouldn't solve the software problem! I have autoload on modules and no errors are showing in the logs.

By: Peter Whisker (whiskerp) 2007-11-22 07:06:23.000-0600

Making a little progress!

I rebuilt asterisk with DONT_OPTIMIZE selected in the Compiler Flags section of menuselect. All is now well with GSM, so it is something in the newer compilers optimising that is causing the trouble. I did update Debian this morning and a normal build still has a distorted GSM with the latest gcc 4.2.3 compiler.


gcc -v returns:

Using built-in specs.
Target: i486-linux-gnu
Configured with: ../src/configure -v --enable-languages=c,c++,fortran,objc,obj-c++,treelang --prefix=/usr --enable-shared --with-system-zlib --libexecdir=/usr/lib --without-included-gettext --enable-threads=posix --enable-nls --with-gxx-include-dir=/usr/include/c++/4.2 --program-suffix=-4.2 --enable-clocale=gnu --enable-libstdcxx-debug --enable-mpfr --enable-targets=all --enable-checking=release --build=i486-linux-gnu --host=i486-linux-gnu --target=i486-linux-gnu
Thread model: posix
gcc version 4.2.3 20071014 (prerelease) (Debian 4.2.2-3)


The Ubuntu box where I have no problems is running gcc 4.1.2. I'll try rebuilding with an older compiler.

Peter

By: Peter Whisker (whiskerp) 2007-11-22 07:18:27.000-0600

This appears to be the same problem as reported in Bug 0010226 so I'm happy if you close this. However the issue will probably keep recurring in gcc4.2 and one of the calls should probably remain open to track it.

By: Peter Whisker (whiskerp) 2007-11-22 07:22:08.000-0600

Confirmed that recompiling asterisk using gcc4.1 cures the problem completely.

By: pj (pj) 2007-11-22 08:32:04.000-0600

it's great news, whiskerp, that you found source of choppy sound issue, when transcoding gsm and new gcc! can workaround with DONT_OPTIMIZE turned on, have some negative efect to call processing, like low performance?

By: Badalian Vyacheslav (slavon) 2007-11-22 09:18:40.000-0600

Turn on DONT_OPTIMIZE help for me.

By: Peter Whisker (whiskerp) 2007-11-22 09:37:40.000-0600

DONT_OPTIMIZE is probably not an ideal solution as asterisk is probably bigger and will run slower.

The way I built with gcc-4.1 on Debian was to execute the build of asterisk witht the following commands:

export CC=gcc-4.1
export CXX=g++-4.1
./configure
make

The resulting Asterisk seems to work fine.

By: Tilghman Lesher (tilghman) 2007-11-22 13:27:27.000-0600

Actually, DONT_OPTIMIZE usually creates a smaller binary, which runs slightly slower.  I know this is a bit non-intuitive, but that's the way the gcc optimizer works.  It's not enough that you'd notice a slowdown, though.

By: Peter Whisker (whiskerp) 2007-11-23 04:18:26.000-0600

So, to summarise, there are two workarounds to this problem:
1) Build using gcc-4.2 with DONT_OPTIMIZE in "make menuselect"
2) Build normally using gcc-4.1

I don't have knowledge of the the inner workings of the codec translators to hazard a guess why they get broken by gcc-4.2 - do they make some assumption as to the way the compiler behaves which has changed or is it simply a bug/feature in gcc-4.2? Over to the Asterisk experts to solve, but at least there are workarounds.

By: Tilghman Lesher (tilghman) 2007-11-24 11:30:29.000-0600

Adding a link to the GCC bug I just filed:

http://gcc.gnu.org/bugzilla/show_bug.cgi?id=34216

By: pj (pj) 2007-11-26 11:05:07.000-0600

bugreport at gnu.org requires feedback, if someone have sufficient knowledge with gcc building options, please post your result there.

By: Tilghman Lesher (tilghman) 2007-12-01 09:42:15.000-0600

How exactly did you get gcc on Feisty to use gcc 4.2?  I'm attempting to replicate this behavior on Gutsy and I'm having no success.

By: Peter Whisker (whiskerp) 2007-12-01 16:11:38.000-0600

The gcc 4.2 version is running on Debian "testing" where it is the default.
Ubuntu Feisty has gcc 4.1.

apt.conf on the Debian box:
deb http://ftp.uk.debian.org/debian testing main contrib non-free
deb http://security.debian.org/ testing/updates main contrib non-free

By: Tzafrir Cohen (tzafrir) 2007-12-28 15:34:52.000-0600

What happens if you install libgsm-dev and use the system libgsm instead of the internal one?

I think this is done by:

 ./configure --with-gsm

By: Peter Whisker (whiskerp) 2007-12-29 01:33:01.000-0600

Unfortunately that makes no difference - it is choppy when * is compiled with gcc-4.2. It was one of the first things I tried.

By: Ken Myers (nny) 2007-12-29 21:47:12.000-0600

note it's :

export CC=gcc-4.1
export CXX=gcc-4.1
./configure
make

NOT

export CC=gcc-4.1
export CXX=g++-4.1
./configure
make

Sorry, I figured that was obvious, but the typo "g++" threw me off at first.



By: Martin Blatter (mblatter) 2007-12-31 02:24:45.000-0600

I can confirm the problem on a stock openSuSE 10.3 machine which gcc 4.2.1.

gcc -v returns:

Using built-in specs.
Target: i586-suse-linux
Configured with: ../configure --enable-threads=posix --prefix=/usr --with-local-prefix=/usr/local --infodir=/usr/share/info --mandir=/usr/share/man --libdir=/usr/lib --libexecdir=/usr/lib --enable-languages=c,c++,objc,fortran,obj-c++,java,ada --enable-checking=release --with-gxx-include-dir=/usr/include/c++/4.2.1 --enable-ssp --disable-libssp --disable-libgcj --with-slibdir=/lib --with-system-zlib --enable-shared --enable-__cxa_atexit --enable-libstdcxx-allocator=new --disable-libstdcxx-pch --program-suffix=-4.2 --enable-version-specific-runtime-libs --without-system-libunwind --with-cpu=generic --host=i586-suse-linux
Thread model: posix
gcc version 4.2.1 (SUSE Linux)

The cpu is a: Intel(R) Core(TM)2 Duo CPU     E6750  @ 2.66GHz

By: Frank Waller (explidous) 2008-01-15 08:17:57.000-0600

This also effects the 1.2 branch as well.

By: Frank Waller (explidous) 2008-01-15 09:26:40.000-0600

In 1.2.26 if you change "OPTIMIZE+=-O6" in the Makefile to "OPTIMIZE+=-O2" everything sounds fine. This way you at least get some optimizations. Without looking in 1.4 I am pretty sure you can do something similar.

I want to try and get it so that just the codec code is optimized at -O2 and see if that still fixes the issue. With the amount of load that we put on Asterisk every little bit of optimization is needed.

By: Frank Waller (explidous) 2008-01-15 12:31:12.000-0600

I uploaded two patches. One to 1.2 and one to 1.4. They make the codec/gsm/Makefile check the gcc version if it is in the 4.2 branch. If so it compiles the gsm code with -O2 instead of -O6. This fixed the issue with the 1.2 branch. I do not have a system that I can test 1.4 patch on. If someone could test the 1.4 patch I would greatly appreciate it.

By: Tilghman Lesher (tilghman) 2008-01-25 16:23:12.000-0600

The gcc maintainers ask the following questions:

Does -O3 -fno-strict-alising work?  Does -O3 -fwrapv work?

By: Tilghman Lesher (tilghman) 2008-02-13 01:19:51.000-0600

explidous:  have you had a chance to try these flags out yet?  If this is a gcc bug, the maintainers would really like an opportunity to figure out which of the optimizations is exactly the problem, so they can fix it.

By: Tilghman Lesher (tilghman) 2008-02-29 12:09:02.000-0600

explidous: ping

By: Frank Waller (explidous) 2008-03-18 15:34:04

Sorry did not have much time to look into the bug tracker recently. I will try those settings within the next few days and get back to you on that.

By: Jason Parker (jparker) 2008-03-18 15:47:15

Give this patch a try.  There was a somewhat similar issue reported, with a fix provided.  This patch does basically the same thing for gsm...  ASTERISK-11678

Disclaimer: I don't know assembly (at all), so I have absolutely no idea whether this works.

By: Jason Parker (jparker) 2008-03-27 12:13:33

Really?  Nobody wants to test this patch?

By: Digium Subversion (svnbot) 2008-03-28 16:41:12

Repository: asterisk
Revision: 111856

U   branches/1.4/codecs/gsm/inc/private.h

------------------------------------------------------------------------
r111856 | qwell | 2008-03-28 16:41:11 -0500 (Fri, 28 Mar 2008) | 12 lines

Allow gsm to compile correctly on x86 with gcc4 optimizations.

(closes issue ASTERISK-10762)
Reported by: whiskerp
Patches:
     11243-maybe-asm.diff uploaded by qwell (license 4)
Tested by: Seggy (IRC)

Note: While I did write this patch, I would not have found this if fossil
had not reported and fixed issue ASTERISK-11678.  A huge thanks to him for helping
to (indirectly) find the problem here.

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

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

By: Digium Subversion (svnbot) 2008-03-28 16:41:35

Repository: asterisk
Revision: 111857

_U  trunk/
U   trunk/codecs/gsm/inc/private.h

------------------------------------------------------------------------
r111857 | qwell | 2008-03-28 16:41:34 -0500 (Fri, 28 Mar 2008) | 20 lines

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

........
r111856 | qwell | 2008-03-28 16:45:35 -0500 (Fri, 28 Mar 2008) | 12 lines

Allow gsm to compile correctly on x86 with gcc4 optimizations.

(closes issue ASTERISK-10762)
Reported by: whiskerp
Patches:
     11243-maybe-asm.diff uploaded by qwell (license 4)
Tested by: Seggy (IRC)

Note: While I did write this patch, I would not have found this if fossil
had not reported and fixed issue ASTERISK-11678.  A huge thanks to him for helping
to (indirectly) find the problem here.

........

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

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

By: Digium Subversion (svnbot) 2008-03-28 16:41:55

Repository: asterisk
Revision: 111858

_U  branches/1.6.0/
U   branches/1.6.0/codecs/gsm/inc/private.h

------------------------------------------------------------------------
r111858 | qwell | 2008-03-28 16:41:55 -0500 (Fri, 28 Mar 2008) | 28 lines

Merged revisions 111857 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

................
r111857 | qwell | 2008-03-28 16:46:02 -0500 (Fri, 28 Mar 2008) | 20 lines

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

........
r111856 | qwell | 2008-03-28 16:45:35 -0500 (Fri, 28 Mar 2008) | 12 lines

Allow gsm to compile correctly on x86 with gcc4 optimizations.

(closes issue ASTERISK-10762)
Reported by: whiskerp
Patches:
     11243-maybe-asm.diff uploaded by qwell (license 4)
Tested by: Seggy (IRC)

Note: While I did write this patch, I would not have found this if fossil
had not reported and fixed issue ASTERISK-11678.  A huge thanks to him for helping
to (indirectly) find the problem here.

........

................

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

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