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. Here's my setup: Operating System: Ubuntu 12.04 FreeSWITCH: 1.2.12 Command I'm using to start the call: originate {record_waste_resources=true}sofia/external/SIPADDR &record(/tmp/record1.wav) default default Any ideas on how to make the recording duration actually match up with the call duration? Or even what's really going wrong so I can work on fixing that? -- Byron Clark
On Mon, Aug 26, 2013 at 11:36 AM, Byron Clark <byron@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? Best, Gabe
On Wed, Aug 28, 2013 at 3:00 PM, Gabriel Gunderson <gabe@gundy.org> wrote:
On Mon, Aug 26, 2013 at 11:36 AM, Byron Clark <byron@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@internal> originate {record_waste_resources=true}sofia/external/ sip:music@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@iptel.org [e223c3e0-103d-11e3-aeea-0779ec213503] 2013-08-28 23:59:32.417082 [DEBUG] mod_sofia.c:5189 (sofia/external/ sip:music@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@iptel.org [BREAK] 2013-08-28 23:59:32.417082 [DEBUG] switch_core_state_machine.c:415 (sofia/external/sip:music@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@iptel.org) State INIT 2013-08-28 23:59:32.417082 [DEBUG] mod_sofia.c:87 sofia/external/ sip:music@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@iptel.org [BREAK] 2013-08-28 23:59:32.417082 [DEBUG] mod_sofia.c:127 (sofia/external/ sip:music@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@iptel.org [BREAK] 2013-08-28 23:59:32.417082 [DEBUG] switch_core_state_machine.c:454 (sofia/external/sip:music@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@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@iptel.org) State ROUTING 2013-08-28 23:59:32.417082 [DEBUG] mod_sofia.c:150 sofia/external/ sip:music@iptel.org SOFIA ROUTING 2013-08-28 23:59:32.417082 [DEBUG] switch_ivr_originate.c:67 (sofia/external/sip:music@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@iptel.org [BREAK] 2013-08-28 23:59:32.417082 [DEBUG] switch_core_state_machine.c:470 (sofia/external/sip:music@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@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@iptel.org) State CONSUME_MEDIA 2013-08-28 23:59:32.417082 [DEBUG] switch_core_state_machine.c:489 (sofia/external/sip:music@iptel.org) State CONSUME_MEDIA going to sleep 2013-08-28 23:59:32.417082 [DEBUG] sofia.c:5720 Channel sofia/external/ sip:music@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@iptel.org [BREAK] 2013-08-28 23:59:32.917126 [DEBUG] switch_core_session.c:999 Send signal sofia/external/sip:music@iptel.org [BREAK] 2013-08-28 23:59:32.917126 [DEBUG] sofia.c:5720 Channel sofia/external/ sip:music@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@iptel.org [BREAK] 2013-08-28 23:59:32.917126 [DEBUG] switch_core_session.c:999 Send signal sofia/external/sip:music@iptel.org [BREAK] 2013-08-28 23:59:32.917126 [DEBUG] sofia.c:5720 Channel sofia/external/ sip:music@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@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@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@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@iptel.org Set rtp dtmf delay to 40 2013-08-28 23:59:32.917126 [NOTICE] sofia.c:6476 Channel [sofia/external/ sip:music@iptel.org] has been answered 2013-08-28 23:59:32.917126 [DEBUG] switch_channel.c:3576 (sofia/external/ sip:music@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@iptel.org] 2013-08-28 23:59:32.937082 [INFO] switch_channel.c:2973 sofia/external/ sip:music@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@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@iptel.org [BREAK] 2013-08-28 23:59:32.937082 [DEBUG] switch_core_state_machine.c:415 (sofia/external/sip:music@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@iptel.org) State EXECUTE 2013-08-28 23:59:32.937082 [DEBUG] mod_sofia.c:243 sofia/external/ sip:music@iptel.org SOFIA EXECUTE 2013-08-28 23:59:32.937082 [DEBUG] switch_core_state_machine.c:209 sofia/external/sip:music@iptel.org Standard EXECUTE EXECUTE sofia/external/sip:music@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@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@iptel.org [CS_EXECUTE] [NORMAL_CLEARING] 2013-08-29 00:03:29.537080 [DEBUG] switch_channel.c:3130 Send signal sofia/external/sip:music@iptel.org [KILL] 2013-08-29 00:03:29.537080 [DEBUG] switch_core_session.c:1334 Send signal sofia/external/sip:music@iptel.org [BREAK] 2013-08-29 00:03:29.557080 [DEBUG] switch_core_codec.c:244 sofia/external/ sip:music@iptel.org Restore previous codec PCMU:0. 2013-08-29 00:03:29.557080 [DEBUG] switch_core_session.c:2740 sofia/external/sip:music@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@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@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@iptel.org) State HANGUP 2013-08-29 00:03:29.557080 [DEBUG] mod_sofia.c:504 Channel sofia/external/ sip:music@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@iptel.org 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:48 sofia/external/sip:music@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@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@iptel.org) Callstate Change ACTIVE -> HANGUP 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:446 (sofia/external/sip:music@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@iptel.org [BREAK] 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:415 (sofia/external/sip:music@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@iptel.org) State REPORTING 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:92 sofia/external/sip:music@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@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@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@iptel.org [BREAK] 2013-08-29 00:03:29.557080 [DEBUG] switch_core_session.c:1542 Session 6 (sofia/external/sip:music@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@iptel.org) Ended 2013-08-29 00:03:29.557080 [NOTICE] switch_core_session.c:1564 Close Channel sofia/external/sip:music@iptel.org [CS_DESTROY] 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:565 (sofia/external/sip:music@iptel.org) Callstate Change HANGUP -> DOWN 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:568 (sofia/external/sip:music@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@iptel.org) State DESTROY 2013-08-29 00:03:29.557080 [DEBUG] mod_sofia.c:397 sofia/external/ sip:music@iptel.org SOFIA DESTROY 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:99 sofia/external/sip:music@iptel.org Standard DESTROY 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:578 (sofia/external/sip:music@iptel.org) State DESTROY going to sleep
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@theclarkfamily.name>wrote:
On Wed, Aug 28, 2013 at 3:00 PM, Gabriel Gunderson <gabe@gundy.org> wrote:
On Mon, Aug 26, 2013 at 11:36 AM, Byron Clark <byron@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@internal> originate {record_waste_resources=true}sofia/external/sip:music@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@iptel.org [e223c3e0-103d-11e3-aeea-0779ec213503] 2013-08-28 23:59:32.417082 [DEBUG] mod_sofia.c:5189 (sofia/external/ sip:music@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@iptel.org [BREAK] 2013-08-28 23:59:32.417082 [DEBUG] switch_core_state_machine.c:415 (sofia/external/sip:music@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@iptel.org) State INIT 2013-08-28 23:59:32.417082 [DEBUG] mod_sofia.c:87 sofia/external/ sip:music@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@iptel.org [BREAK] 2013-08-28 23:59:32.417082 [DEBUG] mod_sofia.c:127 (sofia/external/ sip:music@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@iptel.org [BREAK] 2013-08-28 23:59:32.417082 [DEBUG] switch_core_state_machine.c:454 (sofia/external/sip:music@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@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@iptel.org) State ROUTING 2013-08-28 23:59:32.417082 [DEBUG] mod_sofia.c:150 sofia/external/ sip:music@iptel.org SOFIA ROUTING 2013-08-28 23:59:32.417082 [DEBUG] switch_ivr_originate.c:67 (sofia/external/sip:music@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@iptel.org [BREAK] 2013-08-28 23:59:32.417082 [DEBUG] switch_core_state_machine.c:470 (sofia/external/sip:music@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@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@iptel.org) State CONSUME_MEDIA 2013-08-28 23:59:32.417082 [DEBUG] switch_core_state_machine.c:489 (sofia/external/sip:music@iptel.org) State CONSUME_MEDIA going to sleep 2013-08-28 23:59:32.417082 [DEBUG] sofia.c:5720 Channel sofia/external/ sip:music@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@iptel.org [BREAK] 2013-08-28 23:59:32.917126 [DEBUG] switch_core_session.c:999 Send signal sofia/external/sip:music@iptel.org [BREAK] 2013-08-28 23:59:32.917126 [DEBUG] sofia.c:5720 Channel sofia/external/ sip:music@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@iptel.org [BREAK] 2013-08-28 23:59:32.917126 [DEBUG] switch_core_session.c:999 Send signal sofia/external/sip:music@iptel.org [BREAK] 2013-08-28 23:59:32.917126 [DEBUG] sofia.c:5720 Channel sofia/external/ sip:music@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@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@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@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@iptel.org Set rtp dtmf delay to 40 2013-08-28 23:59:32.917126 [NOTICE] sofia.c:6476 Channel [sofia/external/ sip:music@iptel.org] has been answered 2013-08-28 23:59:32.917126 [DEBUG] switch_channel.c:3576 (sofia/external/ sip:music@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@iptel.org] 2013-08-28 23:59:32.937082 [INFO] switch_channel.c:2973 sofia/external/ sip:music@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@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@iptel.org [BREAK] 2013-08-28 23:59:32.937082 [DEBUG] switch_core_state_machine.c:415 (sofia/external/sip:music@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@iptel.org) State EXECUTE 2013-08-28 23:59:32.937082 [DEBUG] mod_sofia.c:243 sofia/external/ sip:music@iptel.org SOFIA EXECUTE 2013-08-28 23:59:32.937082 [DEBUG] switch_core_state_machine.c:209 sofia/external/sip:music@iptel.org Standard EXECUTE EXECUTE sofia/external/sip:music@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@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@iptel.org [CS_EXECUTE] [NORMAL_CLEARING] 2013-08-29 00:03:29.537080 [DEBUG] switch_channel.c:3130 Send signal sofia/external/sip:music@iptel.org [KILL] 2013-08-29 00:03:29.537080 [DEBUG] switch_core_session.c:1334 Send signal sofia/external/sip:music@iptel.org [BREAK] 2013-08-29 00:03:29.557080 [DEBUG] switch_core_codec.c:244 sofia/external/ sip:music@iptel.org Restore previous codec PCMU:0. 2013-08-29 00:03:29.557080 [DEBUG] switch_core_session.c:2740 sofia/external/sip:music@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@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@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@iptel.org) State HANGUP 2013-08-29 00:03:29.557080 [DEBUG] mod_sofia.c:504 Channel sofia/external/ sip:music@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@iptel.org 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:48 sofia/external/sip:music@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@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@iptel.org) Callstate Change ACTIVE -> HANGUP 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:446 (sofia/external/sip:music@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@iptel.org [BREAK] 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:415 (sofia/external/sip:music@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@iptel.org) State REPORTING 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:92 sofia/external/sip:music@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@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@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@iptel.org [BREAK] 2013-08-29 00:03:29.557080 [DEBUG] switch_core_session.c:1542 Session 6 (sofia/external/sip:music@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@iptel.org) Ended 2013-08-29 00:03:29.557080 [NOTICE] switch_core_session.c:1564 Close Channel sofia/external/sip:music@iptel.org [CS_DESTROY] 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:565 (sofia/external/sip:music@iptel.org) Callstate Change HANGUP -> DOWN 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:568 (sofia/external/sip:music@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@iptel.org) State DESTROY 2013-08-29 00:03:29.557080 [DEBUG] mod_sofia.c:397 sofia/external/ sip:music@iptel.org SOFIA DESTROY 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:99 sofia/external/sip:music@iptel.org Standard DESTROY 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:578 (sofia/external/sip:music@iptel.org) State DESTROY going to sleep
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
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@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@theclarkfamily.name>wrote:
On Wed, Aug 28, 2013 at 3:00 PM, Gabriel Gunderson <gabe@gundy.org>wrote:
On Mon, Aug 26, 2013 at 11:36 AM, Byron Clark <byron@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@internal> originate {record_waste_resources=true}sofia/external/sip:music@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@iptel.org [e223c3e0-103d-11e3-aeea-0779ec213503] 2013-08-28 23:59:32.417082 [DEBUG] mod_sofia.c:5189 (sofia/external/ sip:music@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@iptel.org [BREAK] 2013-08-28 23:59:32.417082 [DEBUG] switch_core_state_machine.c:415 (sofia/external/sip:music@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@iptel.org) State INIT 2013-08-28 23:59:32.417082 [DEBUG] mod_sofia.c:87 sofia/external/ sip:music@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@iptel.org [BREAK] 2013-08-28 23:59:32.417082 [DEBUG] mod_sofia.c:127 (sofia/external/ sip:music@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@iptel.org [BREAK] 2013-08-28 23:59:32.417082 [DEBUG] switch_core_state_machine.c:454 (sofia/external/sip:music@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@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@iptel.org) State ROUTING 2013-08-28 23:59:32.417082 [DEBUG] mod_sofia.c:150 sofia/external/ sip:music@iptel.org SOFIA ROUTING 2013-08-28 23:59:32.417082 [DEBUG] switch_ivr_originate.c:67 (sofia/external/sip:music@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@iptel.org [BREAK] 2013-08-28 23:59:32.417082 [DEBUG] switch_core_state_machine.c:470 (sofia/external/sip:music@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@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@iptel.org) State CONSUME_MEDIA 2013-08-28 23:59:32.417082 [DEBUG] switch_core_state_machine.c:489 (sofia/external/sip:music@iptel.org) State CONSUME_MEDIA going to sleep 2013-08-28 23:59:32.417082 [DEBUG] sofia.c:5720 Channel sofia/external/ sip:music@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@iptel.org [BREAK] 2013-08-28 23:59:32.917126 [DEBUG] switch_core_session.c:999 Send signal sofia/external/sip:music@iptel.org [BREAK] 2013-08-28 23:59:32.917126 [DEBUG] sofia.c:5720 Channel sofia/external/ sip:music@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@iptel.org [BREAK] 2013-08-28 23:59:32.917126 [DEBUG] switch_core_session.c:999 Send signal sofia/external/sip:music@iptel.org [BREAK] 2013-08-28 23:59:32.917126 [DEBUG] sofia.c:5720 Channel sofia/external/ sip:music@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@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@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@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@iptel.org Set rtp dtmf delay to 40 2013-08-28 23:59:32.917126 [NOTICE] sofia.c:6476 Channel [sofia/external/ sip:music@iptel.org] has been answered 2013-08-28 23:59:32.917126 [DEBUG] switch_channel.c:3576 (sofia/external/ sip:music@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@iptel.org] 2013-08-28 23:59:32.937082 [INFO] switch_channel.c:2973 sofia/external/ sip:music@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@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@iptel.org [BREAK] 2013-08-28 23:59:32.937082 [DEBUG] switch_core_state_machine.c:415 (sofia/external/sip:music@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@iptel.org) State EXECUTE 2013-08-28 23:59:32.937082 [DEBUG] mod_sofia.c:243 sofia/external/ sip:music@iptel.org SOFIA EXECUTE 2013-08-28 23:59:32.937082 [DEBUG] switch_core_state_machine.c:209 sofia/external/sip:music@iptel.org Standard EXECUTE EXECUTE sofia/external/sip:music@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@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@iptel.org [CS_EXECUTE] [NORMAL_CLEARING] 2013-08-29 00:03:29.537080 [DEBUG] switch_channel.c:3130 Send signal sofia/external/sip:music@iptel.org [KILL] 2013-08-29 00:03:29.537080 [DEBUG] switch_core_session.c:1334 Send signal sofia/external/sip:music@iptel.org [BREAK] 2013-08-29 00:03:29.557080 [DEBUG] switch_core_codec.c:244 sofia/external/ sip:music@iptel.org Restore previous codec PCMU:0. 2013-08-29 00:03:29.557080 [DEBUG] switch_core_session.c:2740 sofia/external/sip:music@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@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@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@iptel.org) State HANGUP 2013-08-29 00:03:29.557080 [DEBUG] mod_sofia.c:504 Channel sofia/external/ sip:music@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@iptel.org 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:48 sofia/external/sip:music@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@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@iptel.org) Callstate Change ACTIVE -> HANGUP 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:446 (sofia/external/sip:music@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@iptel.org [BREAK] 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:415 (sofia/external/sip:music@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@iptel.org) State REPORTING 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:92 sofia/external/sip:music@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@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@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@iptel.org [BREAK] 2013-08-29 00:03:29.557080 [DEBUG] switch_core_session.c:1542 Session 6 (sofia/external/sip:music@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@iptel.org) Ended 2013-08-29 00:03:29.557080 [NOTICE] switch_core_session.c:1564 Close Channel sofia/external/sip:music@iptel.org [CS_DESTROY] 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:565 (sofia/external/sip:music@iptel.org) Callstate Change HANGUP -> DOWN 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:568 (sofia/external/sip:music@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@iptel.org) State DESTROY 2013-08-29 00:03:29.557080 [DEBUG] mod_sofia.c:397 sofia/external/ sip:music@iptel.org SOFIA DESTROY 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:99 sofia/external/sip:music@iptel.org Standard DESTROY 2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:578 (sofia/external/sip:music@iptel.org) State DESTROY going to sleep
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@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@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
Byron, We run a talk radio show based in EC2 with automated 55 minute shows, I have the same issue and never could figure out why recordings where short… You never lose full words, but a trained radio person can hear the missing bits along the way. Here are the last 20 shows, see below I had tried both wav and mp3, and messed with settings for energy, write buffers, continuous transmit etc… Never thought of trying it on bare metal server. I’m running c1.medium with ubuntu10.04 with 1.06FS. Overall works great, just need to fill the missing seconds in radio schedule when rebroadcasting. Here is the length of last 20 shows, so how do you monitor steal time? Length: 54:35 Length: 54:37 Length: 54:20 Length: 54:39 Length: 54:38 Length: 54:38 Length: 54:40 Length: 54:38 Length: 54:36 Length: 54:32 Length: 54:45 Length: 54:37 Length: 54:36 Length: 54:36 Length: 54:35 Length: 54:40 Length: 54:42 Length: 54:44 Length: 54:35 Length: 53:57 Regards, Stephen HostBBB – Online Learning Solutions http://www.hostbbb.com <http://www.hostbbb.com/> 207 Technology Group Inc. 1-888-229-9756 skype: Stephen_Dame From: freeswitch-users-bounces@lists.freeswitch.org [mailto:freeswitch-users-bounces@lists.freeswitch.org] On Behalf Of Byron Clark Sent: Monday, August 26, 2013 1:36 PM To: FreeSWITCH Users Subject: [Freeswitch-users] Recording Duration on EC2 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. Here's my setup: Operating System: Ubuntu 12.04 FreeSWITCH: 1.2.12 Command I'm using to start the call: originate {record_waste_resources=true}sofia/external/SIPADDR &record(/tmp/record1.wav) default default Any ideas on how to make the recording duration actually match up with the call duration? Or even what's really going wrong so I can work on fixing that? -- Byron Clark
Somehow this all reminds me about the importance of using the right software configuration (and hardware) for handling real-time audio. See for example: http://manual.ardour.org/setting-up-your-system/the-right-computer-system-fo... And since you're using ubuntu: https://help.ubuntu.com/community/UbuntuStudio/RealTimeKernel As the ubuntu page describes, the normal ubuntu stock kernel is different compared to the studio version. More real-time related information, links, articles and such: http://wiki.linuxaudio.org/wiki/real_time_info I hope this information may assist you into solving your issue. -- EL
Yes, you are right I always recommend our customer to use dedicated hardware for real time communications *Tahir Almas* Managing Partner ICT Innovations http://www.ictinnovations.com Leveraging open source in ICT On Thu, Aug 29, 2013 at 3:23 PM, EL <fs.user@fordior.net> wrote:
Somehow this all reminds me about the importance of using the right software configuration (and hardware) for handling real-time audio.
See for example:
http://manual.ardour.org/setting-up-your-system/the-right-computer-system-fo...
And since you're using ubuntu: https://help.ubuntu.com/community/UbuntuStudio/RealTimeKernel
As the ubuntu page describes, the normal ubuntu stock kernel is different compared to the studio version.
More real-time related information, links, articles and such: http://wiki.linuxaudio.org/wiki/real_time_info
I hope this information may assist you into solving your issue. -- EL
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
Tahir,
I always recommend our customer to use dedicated hardware for real time communications
It's not only using dedicated hardware, although it's better. I you use dedicated hardware with a standard linux kernel, you still can have trouble. I you look at the third provided URL, there are several references to other usefull links that provide additional information which is relevant if Real-Time processing is important to you. For example: https://rt.wiki.kernel.org/index.php/Frequently_Asked_Questions So I'm curious if the problems persist when the kernel/distro is replaced/customized with/to an RT version (even when it's still a virtual machine). I would love to get feedback on possible test results... -- EL
participants (6)
-
Byron Clark
-
EL
-
Gabriel Gunderson
-
Jayanth Acharya
-
Stephen Dame
-
Tahir Almas