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