<div dir="ltr">On Wed, Aug 28, 2013 at 3:00 PM, Gabriel Gunderson <span dir="ltr"><<a href="mailto:gabe@gundy.org" target="_blank">gabe@gundy.org</a>></span> wrote:<br><div class="gmail_extra"><div class="gmail_quote">
<blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex"><div class="im">On Mon, Aug 26, 2013 at 11:36 AM, Byron Clark <<a href="mailto:byron@theclarkfamily.name">byron@theclarkfamily.name</a>> wrote:<br>
> I'm using FreeSWITCH on EC2 to call into a conference bridge and record the<br>
> audio from the conference. It works well except for one thing: the recording<br>
> contains all the audio from the call, but the duration of the file is<br>
> shorter than the call. The duration is typically 3-5 seconds shorter than<br>
> the call for each 5 minutes of call. On a recent test, wall clock showed a<br>
> duration of 15:32.93 but the duration of the recording file was 15:19.96.<br>
> The ugly part is that this only happens on EC2 instances where there is some<br>
> CPU steal time (<5%) occurring.<br>
<br>
</div>Byron, do you see this in a regular bridge too? Or, is it only in a<br>
conf. room? I know it would be hard to get, but do you know how long<br>
the *actual* call was? Can you get back into the logs and see when<br>
those events happen and give a time based on syslog?<br></blockquote><div><br></div><div>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:</div>
<div>- Kernel CONFIG_HZ set to 1000 (Ubuntu 12.04 default on EC2 is 250)</div><div>- Using mod_timerfd</div><div><br></div><div><br></div><div>Here are the results of a recent test I ran where the recorded file was six seconds short after about four minutes.</div>
<div><br></div><div>Command</div><div>---------------</div><div><div>freeswitch@internal> originate {record_waste_resources=true}sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> &record(/tmp/record1.wav) default default</div>
<div>+OK e223c3e0-103d-11e3-aeea-0779ec213503</div><div><br></div><div>I used uuid_kill to terminate the call after 00:03:57.</div><div><br></div><div>Duration of the resulting file</div><div>----------------------------------------</div>
<div><div>Input #0, wav, from '/tmp/record1.wav':</div><div> Duration: 00:03:51.84, bitrate: 128 kb/s</div><div> Stream #0:0: Audio: pcm_s16le ([1][0][0][0] / 0x0001), 8000 Hz, 1 channels, s16, 128 kb/s</div></div>
<div><br></div><div>FreeSWITCH Console Output</div><div>-------------------------------------------</div><div>2013-08-28 23:59:32.417082 [DEBUG] switch_ivr_originate.c:2060 Parsing global variables</div><div>2013-08-28 23:59:32.417082 [DEBUG] switch_event.c:1617 Parsing variable [record_waste_resources]=[true]</div>
<div>2013-08-28 23:59:32.417082 [NOTICE] switch_channel.c:1030 New Channel sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> [e223c3e0-103d-11e3-aeea-0779ec213503]</div><div>2013-08-28 23:59:32.417082 [DEBUG] mod_sofia.c:5189 (sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>) State Change CS_NEW -> CS_INIT</div>
<div>2013-08-28 23:59:32.417082 [DEBUG] switch_core_session.c:1334 Send signal sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> [BREAK]</div><div>2013-08-28 23:59:32.417082 [DEBUG] switch_core_state_machine.c:415 (sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>) Running State Change CS_INIT</div>
<div>2013-08-28 23:59:32.417082 [DEBUG] switch_core_state_machine.c:454 (sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>) State INIT</div><div>2013-08-28 23:59:32.417082 [DEBUG] mod_sofia.c:87 sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> SOFIA INIT</div>
<div>2013-08-28 23:59:32.417082 [DEBUG] sofia_glue.c:2677 Local SDP:</div><div>v=0</div><div>o=FreeSWITCH 1377707312 1377707313 IN IP4 10.151.108.236</div><div>s=FreeSWITCH</div><div>c=IN IP4 10.151.108.236</div><div>t=0 0</div>
<div>m=audio 27060 RTP/AVP 0 8 101 13</div><div>a=rtpmap:101 telephone-event/8000</div><div>a=fmtp:101 0-16</div><div>a=ptime:20</div><div>a=sendrecv</div><div><br></div><div>2013-08-28 23:59:32.417082 [DEBUG] switch_core_session.c:999 Send signal sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> [BREAK]</div>
<div>2013-08-28 23:59:32.417082 [DEBUG] mod_sofia.c:127 (sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>) State Change CS_INIT -> CS_ROUTING</div><div>2013-08-28 23:59:32.417082 [DEBUG] switch_core_session.c:1334 Send signal sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> [BREAK]</div>
<div>2013-08-28 23:59:32.417082 [DEBUG] switch_core_state_machine.c:454 (sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>) State INIT going to sleep</div><div>2013-08-28 23:59:32.417082 [DEBUG] switch_core_state_machine.c:415 (sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>) Running State Change CS_ROUTING</div>
<div>2013-08-28 23:59:32.417082 [DEBUG] switch_core_state_machine.c:470 (sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>) State ROUTING</div><div>2013-08-28 23:59:32.417082 [DEBUG] mod_sofia.c:150 sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> SOFIA ROUTING</div>
<div>2013-08-28 23:59:32.417082 [DEBUG] switch_ivr_originate.c:67 (sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>) State Change CS_ROUTING -> CS_CONSUME_MEDIA</div><div>2013-08-28 23:59:32.417082 [DEBUG] switch_core_session.c:1334 Send signal sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> [BREAK]</div>
<div>2013-08-28 23:59:32.417082 [DEBUG] switch_core_state_machine.c:470 (sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>) State ROUTING going to sleep</div><div>2013-08-28 23:59:32.417082 [DEBUG] switch_core_state_machine.c:415 (sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>) Running State Change CS_CONSUME_MEDIA</div>
<div>2013-08-28 23:59:32.417082 [DEBUG] switch_core_state_machine.c:489 (sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>) State CONSUME_MEDIA</div><div>2013-08-28 23:59:32.417082 [DEBUG] switch_core_state_machine.c:489 (sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>) State CONSUME_MEDIA going to sleep</div>
<div>2013-08-28 23:59:32.417082 [DEBUG] sofia.c:5720 Channel sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> entering state [calling][0]</div><div>2013-08-28 23:59:32.917126 [DEBUG] switch_core_session.c:999 Send signal sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> [BREAK]</div>
<div>2013-08-28 23:59:32.917126 [DEBUG] switch_core_session.c:999 Send signal sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> [BREAK]</div><div>2013-08-28 23:59:32.917126 [DEBUG] sofia.c:5720 Channel sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> entering state [completing][200]</div>
<div>2013-08-28 23:59:32.917126 [DEBUG] sofia.c:5733 Remote SDP:</div><div>v=0</div><div>o=- 308297691 1827516553 IN IP4 217.9.36.145</div><div>s=-</div><div>c=IN IP4 217.9.36.145</div><div>t=0 0</div><div>m=audio 37892 RTP/AVP 0 8 101</div>
<div>a=rtpmap:0 PCMU/8000</div><div>a=rtpmap:8 PCMA/8000</div><div>a=rtpmap:101 telephone-event/8000</div><div>a=fmtp:101 0-15</div><div>a=direction:both</div><div><br></div><div>2013-08-28 23:59:32.917126 [DEBUG] switch_core_session.c:999 Send signal sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> [BREAK]</div>
<div>2013-08-28 23:59:32.917126 [DEBUG] switch_core_session.c:999 Send signal sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> [BREAK]</div><div>2013-08-28 23:59:32.917126 [DEBUG] sofia.c:5720 Channel sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> entering state [ready][200]</div>
<div>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]</div><div>2013-08-28 23:59:32.917126 [DEBUG] sofia_glue.c:3124 Set Codec sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> PCMU/8000 20 ms 160 samples 64000 bits</div>
<div>2013-08-28 23:59:32.917126 [DEBUG] switch_core_codec.c:111 sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> Original read codec set to PCMU:0</div><div>2013-08-28 23:59:32.917126 [DEBUG] sofia_glue.c:5303 Set 2833 dtmf send payload to 101</div>
<div>2013-08-28 23:59:32.917126 [DEBUG] sofia_glue.c:3383 AUDIO RTP [sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>] 10.151.108.236 port 27060 -> 217.9.36.145 port 37892 codec: 0 ms: 20</div>
<div>2013-08-28 23:59:32.917126 [DEBUG] switch_rtp.c:1985 Starting timer [soft] 160 bytes per 20ms</div><div>2013-08-28 23:59:32.917126 [DEBUG] sofia_glue.c:3647 Set 2833 dtmf send payload to 101</div><div>2013-08-28 23:59:32.917126 [DEBUG] sofia_glue.c:3653 Set 2833 dtmf receive payload to 101</div>
<div>2013-08-28 23:59:32.917126 [DEBUG] sofia_glue.c:3680 sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> Set rtp dtmf delay to 40</div><div>2013-08-28 23:59:32.917126 [NOTICE] sofia.c:6476 Channel [sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>] has been answered</div>
<div>2013-08-28 23:59:32.917126 [DEBUG] switch_channel.c:3576 (sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>) Callstate Change DOWN -> ACTIVE</div><div>2013-08-28 23:59:32.937082 [DEBUG] switch_ivr_originate.c:3494 Originate Resulted in Success: [sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>]</div>
<div>2013-08-28 23:59:32.937082 [INFO] switch_channel.c:2973 sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> Flipping CID from "" <0000000000> to "Outbound Call" <music></div>
<div>2013-08-28 23:59:32.937082 [DEBUG] mod_commands.c:4088 (sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>) State Change CS_CONSUME_MEDIA -> CS_EXECUTE</div><div>2013-08-28 23:59:32.937082 [DEBUG] switch_core_session.c:1334 Send signal sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> [BREAK]</div>
<div>2013-08-28 23:59:32.937082 [DEBUG] switch_core_state_machine.c:415 (sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>) Running State Change CS_EXECUTE</div><div>2013-08-28 23:59:32.937082 [DEBUG] switch_core_state_machine.c:477 (sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>) State EXECUTE</div>
<div>2013-08-28 23:59:32.937082 [DEBUG] mod_sofia.c:243 sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> SOFIA EXECUTE</div><div>2013-08-28 23:59:32.937082 [DEBUG] switch_core_state_machine.c:209 sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> Standard EXECUTE</div>
<div>EXECUTE sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> record(/tmp/record1.wav)</div><div>2013-08-28 23:59:32.937082 [DEBUG] switch_ivr_play_say.c:475 Raw Codec Activated, ready to waste resources!</div>
<div>2013-08-28 23:59:32.937082 [DEBUG] switch_ivr_play_say.c:599 Raw Codec Activated</div><div>2013-08-28 23:59:32.937082 [DEBUG] switch_core_codec.c:219 sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> Push codec L16:70</div>
<div>2013-08-28 23:59:33.077079 [DEBUG] switch_rtp.c:3706 Correct ip/port confirmed.</div></div><div><div>2013-08-29 00:03:29.537080 [NOTICE] switch_ivr.c:3675 Hangup sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> [CS_EXECUTE] [NORMAL_CLEARING]</div>
<div>2013-08-29 00:03:29.537080 [DEBUG] switch_channel.c:3130 Send signal sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> [KILL]</div><div>2013-08-29 00:03:29.537080 [DEBUG] switch_core_session.c:1334 Send signal sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> [BREAK]</div>
<div>2013-08-29 00:03:29.557080 [DEBUG] switch_core_codec.c:244 sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> Restore previous codec PCMU:0.</div><div>2013-08-29 00:03:29.557080 [DEBUG] switch_core_session.c:2740 sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)</div>
<div>2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:477 (sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>) State EXECUTE going to sleep</div><div>2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:415 (sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>) Running State Change CS_HANGUP</div>
<div>2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:678 (sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>) State HANGUP</div><div>2013-08-29 00:03:29.557080 [DEBUG] mod_sofia.c:504 Channel sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> hanging up, cause: NORMAL_CLEARING</div>
<div>2013-08-29 00:03:29.557080 [DEBUG] mod_sofia.c:556 Sending BYE to sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a></div><div>2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:48 sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> Standard HANGUP, cause: NORMAL_CLEARING</div>
<div>2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:678 (sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>) State HANGUP going to sleep</div><div>2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:689 (sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>) Callstate Change ACTIVE -> HANGUP</div>
<div>2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:446 (sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>) State Change CS_HANGUP -> CS_REPORTING</div><div>2013-08-29 00:03:29.557080 [DEBUG] switch_core_session.c:1334 Send signal sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> [BREAK]</div>
<div>2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:415 (sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>) Running State Change CS_REPORTING</div><div>2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:761 (sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>) State REPORTING</div>
<div>2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:92 sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> Standard REPORTING, cause: NORMAL_CLEARING</div><div>2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:761 (sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>) State REPORTING going to sleep</div>
<div>2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:440 (sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>) State Change CS_REPORTING -> CS_DESTROY</div><div>2013-08-29 00:03:29.557080 [DEBUG] switch_core_session.c:1334 Send signal sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> [BREAK]</div>
<div>2013-08-29 00:03:29.557080 [DEBUG] switch_core_session.c:1542 Session 6 (sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>) Locked, Waiting on external entities</div><div>2013-08-29 00:03:29.557080 [NOTICE] switch_core_session.c:1560 Session 6 (sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>) Ended</div>
<div>2013-08-29 00:03:29.557080 [NOTICE] switch_core_session.c:1564 Close Channel sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> [CS_DESTROY]</div><div>2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:565 (sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>) Callstate Change HANGUP -> DOWN</div>
<div>2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:568 (sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>) Running State Change CS_DESTROY</div><div>2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:578 (sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>) State DESTROY</div>
<div>2013-08-29 00:03:29.557080 [DEBUG] mod_sofia.c:397 sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> SOFIA DESTROY</div><div>2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:99 sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a> Standard DESTROY</div>
<div>2013-08-29 00:03:29.557080 [DEBUG] switch_core_state_machine.c:578 (sofia/external/<a href="mailto:sip%3Amusic@iptel.org">sip:music@iptel.org</a>) State DESTROY going to sleep</div></div></div></div></div>