[Freeswitch-users] Recording Duration on EC2

Tahir Almas tahir at ictinnovations.com
Thu Aug 29 12:13:07 MSD 2013


interesting findings so far !

it resemble to travelling in black-hole

I came across another research work that show time get slow  around heavy
objects like travelling near  egypt's pyramids

*Tahir Almas*

Managing Partner
ICT Innovations
http://www.ictinnovations.com
Leveraging open source in ICT



On Thu, Aug 29, 2013 at 9:44 AM, Jayanth Acharya <jayachar88 at gmail.com>wrote:

> Being a complete n00b with FS, I could be completely off the mark here,
> but recently when I was searching around for my extremely poor audio
> quality issues with mod_gsmopen, I found reference to timing issues, and
> then I saw this thread. Coming from an embedded background, I believe I can
> extend the logic that if you run too many instances with high-resolution
> software timers on same processor, the resolution of all instances gets
> impacted, since nobody would be getting "enough time" (or interrupts, fast
> enough)... this could be a clue to chase, if your problem is unique to a
> particular EC2 instance (however, I see follow-on posts indicating this to
> be a more generic issue).
>
> Here are 2 JIRA's that have interesting content:
>
> http://jira.freeswitch.org/browse/FS-4256
> http://jira.freeswitch.org/browse/FS-3290 (this one has a solution that worked for someone)
>
>
>
>
> On Thu, Aug 29, 2013 at 5:41 AM, Byron Clark <byron at theclarkfamily.name>wrote:
>
>> On Wed, Aug 28, 2013 at 3:00 PM, Gabriel Gunderson <gabe at gundy.org>wrote:
>>
>>> On Mon, Aug 26, 2013 at 11:36 AM, Byron Clark <byron at theclarkfamily.name>
>>> wrote:
>>> > I'm using FreeSWITCH on EC2 to call into a conference bridge and
>>> record the
>>> > audio from the conference. It works well except for one thing: the
>>> recording
>>> > contains all the audio from the call, but the duration of the file is
>>> > shorter than the call. The duration is typically 3-5 seconds shorter
>>> than
>>> > the call for each 5 minutes of call. On a recent test, wall clock
>>> showed a
>>> > duration of 15:32.93 but the duration of the recording file was
>>> 15:19.96.
>>> > The ugly part is that this only happens on EC2 instances where there
>>> is some
>>> > CPU steal time (<5%) occurring.
>>>
>>> Byron, do you see this in a regular bridge too? Or, is it only in a
>>> conf. room? I know it would be hard to get, but do you know how long
>>> the *actual* call was? Can you get back into the logs and see when
>>> those events happen and give a time based on syslog?
>>>
>>
>> Thanks, Gabe. I'm seeing this on any call I originate on the problematic
>> instances. Here are the things I've tried, to no avail, in order to improve
>> these results:
>> - Kernel CONFIG_HZ set to 1000 (Ubuntu 12.04 default on EC2 is 250)
>> - Using mod_timerfd
>>
>>
>> Here are the results of a recent test I ran where the recorded file was
>> six seconds short after about four minutes.
>>
>> Command
>> ---------------
>> freeswitch at internal> originate
>> {record_waste_resources=true}sofia/external/sip:music at iptel.org&record(/tmp/record1.wav) default default
>> +OK e223c3e0-103d-11e3-aeea-0779ec213503
>>
>> I used uuid_kill to terminate the call after 00:03:57.
>>
>> Duration of the resulting file
>> ----------------------------------------
>> Input #0, wav, from '/tmp/record1.wav':
>>   Duration: 00:03:51.84, bitrate: 128 kb/s
>>     Stream #0:0: Audio: pcm_s16le ([1][0][0][0] / 0x0001), 8000 Hz, 1
>> channels, s16, 128 kb/s
>>
>> FreeSWITCH Console Output
>> -------------------------------------------
>> 2013-08-28 23:59:32.417082 [DEBUG] switch_ivr_originate.c:2060 Parsing
>> global variables
>> 2013-08-28 23:59:32.417082 [DEBUG] switch_event.c:1617 Parsing variable
>> [record_waste_resources]=[true]
>> 2013-08-28 23:59:32.417082 [NOTICE] switch_channel.c:1030 New Channel
>> sofia/external/sip:music at iptel.org [e223c3e0-103d-11e3-aeea-0779ec213503]
>> 2013-08-28 23:59:32.417082 [DEBUG] mod_sofia.c:5189 (sofia/external/
>> sip:music at iptel.org) State Change CS_NEW -> CS_INIT
>> 2013-08-28 23:59:32.417082 [DEBUG] switch_core_session.c:1334 Send signal
>> sofia/external/sip:music at iptel.org [BREAK]
>> 2013-08-28 23:59:32.417082 [DEBUG] switch_core_state_machine.c:415
>> (sofia/external/sip:music at iptel.org) Running State Change CS_INIT
>> 2013-08-28 23:59:32.417082 [DEBUG] switch_core_state_machine.c:454
>> (sofia/external/sip:music at iptel.org) State INIT
>> 2013-08-28 23:59:32.417082 [DEBUG] mod_sofia.c:87 sofia/external/
>> sip:music at iptel.org SOFIA INIT
>> 2013-08-28 23:59:32.417082 [DEBUG] sofia_glue.c:2677 Local SDP:
>> v=0
>> o=FreeSWITCH 1377707312 1377707313 IN IP4 10.151.108.236
>> s=FreeSWITCH
>> c=IN IP4 10.151.108.236
>> t=0 0
>> m=audio 27060 RTP/AVP 0 8 101 13
>> a=rtpmap:101 telephone-event/8000
>> a=fmtp:101 0-16
>> a=ptime:20
>> a=sendrecv
>>
>> 2013-08-28 23:59:32.417082 [DEBUG] switch_core_session.c:999 Send signal
>> sofia/external/sip:music at iptel.org [BREAK]
>> 2013-08-28 23:59:32.417082 [DEBUG] mod_sofia.c:127 (sofia/external/
>> sip:music at iptel.org) State Change CS_INIT -> CS_ROUTING
>> 2013-08-28 23:59:32.417082 [DEBUG] switch_core_session.c:1334 Send signal
>> sofia/external/sip:music at iptel.org [BREAK]
>> 2013-08-28 23:59:32.417082 [DEBUG] switch_core_state_machine.c:454
>> (sofia/external/sip:music at iptel.org) State INIT going to sleep
>> 2013-08-28 23:59:32.417082 [DEBUG] switch_core_state_machine.c:415
>> (sofia/external/sip:music at iptel.org) Running State Change CS_ROUTING
>> 2013-08-28 23:59:32.417082 [DEBUG] switch_core_state_machine.c:470
>> (sofia/external/sip:music at iptel.org) State ROUTING
>> 2013-08-28 23:59:32.417082 [DEBUG] mod_sofia.c:150 sofia/external/
>> sip:music at iptel.org SOFIA ROUTING
>> 2013-08-28 23:59:32.417082 [DEBUG] switch_ivr_originate.c:67
>> (sofia/external/sip:music at iptel.org) State Change CS_ROUTING ->
>> CS_CONSUME_MEDIA
>> 2013-08-28 23:59:32.417082 [DEBUG] switch_core_session.c:1334 Send signal
>> sofia/external/sip:music at iptel.org [BREAK]
>> 2013-08-28 23:59:32.417082 [DEBUG] switch_core_state_machine.c:470
>> (sofia/external/sip:music at iptel.org) State ROUTING going to sleep
>> 2013-08-28 23:59:32.417082 [DEBUG] switch_core_state_machine.c:415
>> (sofia/external/sip:music at iptel.org) Running State Change
>> CS_CONSUME_MEDIA
>> 2013-08-28 23:59:32.417082 [DEBUG] switch_core_state_machine.c:489
>> (sofia/external/sip:music at iptel.org) State CONSUME_MEDIA
>> 2013-08-28 23:59:32.417082 [DEBUG] switch_core_state_machine.c:489
>> (sofia/external/sip:music at iptel.org) State CONSUME_MEDIA going to sleep
>> 2013-08-28 23:59:32.417082 [DEBUG] sofia.c:5720 Channel sofia/external/
>> sip:music at iptel.org entering state [calling][0]
>> 2013-08-28 23:59:32.917126 [DEBUG] switch_core_session.c:999 Send signal
>> sofia/external/sip:music at iptel.org [BREAK]
>> 2013-08-28 23:59:32.917126 [DEBUG] switch_core_session.c:999 Send signal
>> sofia/external/sip:music at iptel.org [BREAK]
>> 2013-08-28 23:59:32.917126 [DEBUG] sofia.c:5720 Channel sofia/external/
>> sip:music at iptel.org entering state [completing][200]
>> 2013-08-28 23:59:32.917126 [DEBUG] sofia.c:5733 Remote SDP:
>> v=0
>> o=- 308297691 1827516553 IN IP4 217.9.36.145
>> s=-
>> c=IN IP4 217.9.36.145
>> t=0 0
>> m=audio 37892 RTP/AVP 0 8 101
>> a=rtpmap:0 PCMU/8000
>> a=rtpmap:8 PCMA/8000
>> a=rtpmap:101 telephone-event/8000
>> a=fmtp:101 0-15
>> a=direction:both
>>
>> 2013-08-28 23:59:32.917126 [DEBUG] switch_core_session.c:999 Send signal
>> sofia/external/sip:music at iptel.org [BREAK]
>> 2013-08-28 23:59:32.917126 [DEBUG] switch_core_session.c:999 Send signal
>> sofia/external/sip:music at iptel.org [BREAK]
>> 2013-08-28 23:59:32.917126 [DEBUG] sofia.c:5720 Channel sofia/external/
>> sip:music at iptel.org entering state [ready][200]
>> 2013-08-28 23:59:32.917126 [DEBUG] sofia_glue.c:5181 Audio Codec Compare
>> [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000]
>> 2013-08-28 23:59:32.917126 [DEBUG] sofia_glue.c:3124 Set Codec
>> sofia/external/sip:music at iptel.org PCMU/8000 20 ms 160 samples 64000 bits
>> 2013-08-28 23:59:32.917126 [DEBUG] switch_core_codec.c:111 sofia/external/
>> sip:music at iptel.org Original read codec set to PCMU:0
>> 2013-08-28 23:59:32.917126 [DEBUG] sofia_glue.c:5303 Set 2833 dtmf send
>> payload to 101
>> 2013-08-28 23:59:32.917126 [DEBUG] sofia_glue.c:3383 AUDIO RTP
>> [sofia/external/sip:music at iptel.org] 10.151.108.236 port 27060 ->
>> 217.9.36.145 port 37892 codec: 0 ms: 20
>> 2013-08-28 23:59:32.917126 [DEBUG] switch_rtp.c:1985 Starting timer
>> [soft] 160 bytes per 20ms
>> 2013-08-28 23:59:32.917126 [DEBUG] sofia_glue.c:3647 Set 2833 dtmf send
>> payload to 101
>> 2013-08-28 23:59:32.917126 [DEBUG] sofia_glue.c:3653 Set 2833 dtmf
>> receive payload to 101
>> 2013-08-28 23:59:32.917126 [DEBUG] sofia_glue.c:3680 sofia/external/
>> sip:music at iptel.org Set rtp dtmf delay to 40
>> 2013-08-28 23:59:32.917126 [NOTICE] sofia.c:6476 Channel [sofia/external/
>> sip:music at iptel.org] has been answered
>> 2013-08-28 23:59:32.917126 [DEBUG] switch_channel.c:3576 (sofia/external/
>> sip:music at iptel.org) Callstate Change DOWN -> ACTIVE
>> 2013-08-28 23:59:32.937082 [DEBUG] switch_ivr_originate.c:3494 Originate
>> Resulted in Success: [sofia/external/sip:music at iptel.org]
>> 2013-08-28 23:59:32.937082 [INFO] switch_channel.c:2973 sofia/external/
>> sip:music at iptel.org Flipping CID from "" <0000000000> to "Outbound Call"
>> <music>
>> 2013-08-28 23:59:32.937082 [DEBUG] mod_commands.c:4088 (sofia/external/
>> sip:music at iptel.org) State Change CS_CONSUME_MEDIA -> CS_EXECUTE
>> 2013-08-28 23:59:32.937082 [DEBUG] switch_core_session.c:1334 Send signal
>> sofia/external/sip:music at iptel.org [BREAK]
>> 2013-08-28 23:59:32.937082 [DEBUG] switch_core_state_machine.c:415
>> (sofia/external/sip:music at iptel.org) Running State Change CS_EXECUTE
>> 2013-08-28 23:59:32.937082 [DEBUG] switch_core_state_machine.c:477
>> (sofia/external/sip:music at iptel.org) State EXECUTE
>> 2013-08-28 23:59:32.937082 [DEBUG] mod_sofia.c:243 sofia/external/
>> sip:music at iptel.org SOFIA EXECUTE
>> 2013-08-28 23:59:32.937082 [DEBUG] switch_core_state_machine.c:209
>> sofia/external/sip:music at iptel.org Standard EXECUTE
>> EXECUTE sofia/external/sip:music at iptel.org record(/tmp/record1.wav)
>> 2013-08-28 23:59:32.937082 [DEBUG] switch_ivr_play_say.c:475 Raw Codec
>> Activated, ready to waste resources!
>> 2013-08-28 23:59:32.937082 [DEBUG] switch_ivr_play_say.c:599 Raw Codec
>> Activated
>> 2013-08-28 23:59:32.937082 [DEBUG] switch_core_codec.c:219 sofia/external/
>> sip:music at iptel.org Push codec L16:70
>> 2013-08-28 23:59:33.077079 [DEBUG] switch_rtp.c:3706 Correct ip/port
>> confirmed.
>> 2013-08-29 00:03:29.537080 [NOTICE] switch_ivr.c:3675 Hangup
>> sofia/external/sip:music at iptel.org [CS_EXECUTE] [NORMAL_CLEARING]
>> 2013-08-29 00:03:29.537080 [DEBUG] switch_channel.c:3130 Send signal
>> sofia/external/sip:music at iptel.org [KILL]
>> 2013-08-29 00:03:29.537080 [DEBUG] switch_core_session.c:1334 Send signal
>> sofia/external/sip:music at iptel.org [BREAK]
>> 2013-08-29 00:03:29.557080 [DEBUG] switch_core_codec.c:244 sofia/external/
>> sip:music at iptel.org Restore previous codec PCMU:0.
>> 2013-08-29 00:03:29.557080 [DEBUG] switch_core_session.c:2740
>> sofia/external/sip:music at iptel.org skip receive message
>> [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
>> 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:477
>> (sofia/external/sip:music at iptel.org) State EXECUTE going to sleep
>> 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:415
>> (sofia/external/sip:music at iptel.org) Running State Change CS_HANGUP
>> 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:678
>> (sofia/external/sip:music at iptel.org) State HANGUP
>> 2013-08-29 00:03:29.557080 [DEBUG] mod_sofia.c:504 Channel sofia/external/
>> sip:music at iptel.org hanging up, cause: NORMAL_CLEARING
>> 2013-08-29 00:03:29.557080 [DEBUG] mod_sofia.c:556 Sending BYE to
>> sofia/external/sip:music at iptel.org
>> 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:48
>> sofia/external/sip:music at iptel.org Standard HANGUP, cause:
>> NORMAL_CLEARING
>> 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:678
>> (sofia/external/sip:music at iptel.org) State HANGUP going to sleep
>> 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:689
>> (sofia/external/sip:music at iptel.org) Callstate Change ACTIVE -> HANGUP
>> 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:446
>> (sofia/external/sip:music at iptel.org) State Change CS_HANGUP ->
>> CS_REPORTING
>> 2013-08-29 00:03:29.557080 [DEBUG] switch_core_session.c:1334 Send signal
>> sofia/external/sip:music at iptel.org [BREAK]
>> 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:415
>> (sofia/external/sip:music at iptel.org) Running State Change CS_REPORTING
>> 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:761
>> (sofia/external/sip:music at iptel.org) State REPORTING
>> 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:92
>> sofia/external/sip:music at iptel.org Standard REPORTING, cause:
>> NORMAL_CLEARING
>> 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:761
>> (sofia/external/sip:music at iptel.org) State REPORTING going to sleep
>> 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:440
>> (sofia/external/sip:music at iptel.org) State Change CS_REPORTING ->
>> CS_DESTROY
>> 2013-08-29 00:03:29.557080 [DEBUG] switch_core_session.c:1334 Send signal
>> sofia/external/sip:music at iptel.org [BREAK]
>> 2013-08-29 00:03:29.557080 [DEBUG] switch_core_session.c:1542 Session 6
>> (sofia/external/sip:music at iptel.org) Locked, Waiting on external entities
>> 2013-08-29 00:03:29.557080 [NOTICE] switch_core_session.c:1560 Session 6
>> (sofia/external/sip:music at iptel.org) Ended
>> 2013-08-29 00:03:29.557080 [NOTICE] switch_core_session.c:1564 Close
>> Channel sofia/external/sip:music at iptel.org [CS_DESTROY]
>> 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:565
>> (sofia/external/sip:music at iptel.org) Callstate Change HANGUP -> DOWN
>> 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:568
>> (sofia/external/sip:music at iptel.org) Running State Change CS_DESTROY
>> 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:578
>> (sofia/external/sip:music at iptel.org) State DESTROY
>> 2013-08-29 00:03:29.557080 [DEBUG] mod_sofia.c:397 sofia/external/
>> sip:music at iptel.org SOFIA DESTROY
>> 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:99
>> sofia/external/sip:music at iptel.org Standard DESTROY
>> 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:578
>> (sofia/external/sip:music at iptel.org) State DESTROY going to sleep
>>
>> _________________________________________________________________________
>> Professional FreeSWITCH Consulting Services:
>> consulting at freeswitch.org
>> http://www.freeswitchsolutions.com
>>
>> 
>> 
>>
>> Official FreeSWITCH Sites
>> http://www.freeswitch.org
>> http://wiki.freeswitch.org
>> http://www.cluecon.com
>>
>> FreeSWITCH-users mailing list
>> FreeSWITCH-users at lists.freeswitch.org
>> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
>> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
>> http://www.freeswitch.org
>>
>>
>
> _________________________________________________________________________
> Professional FreeSWITCH Consulting Services:
> consulting at freeswitch.org
> http://www.freeswitchsolutions.com
>
> 
> 
>
> Official FreeSWITCH Sites
> http://www.freeswitch.org
> http://wiki.freeswitch.org
> http://www.cluecon.com
>
> FreeSWITCH-users mailing list
> FreeSWITCH-users at lists.freeswitch.org
> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
> http://www.freeswitch.org
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20130829/689ce375/attachment-0001.html 


Join us at ClueCon 2013 Aug 6-8, 2013
More information about the FreeSWITCH-users mailing list