Fixed time moving backwards in the AudioCodingModule.

Fixed time moving backwards in the AudioCodingModule.

There was a fast path in PreprocessToAddData that would just use the
input timestamps if the input format was equal to the required format of
the encoder. This works well as long as the codec never changes. If we
are first doing resampling (specifically upsampling) and then change to
a codec that does not require resampling, we'll need to stick to
whatever input timestamp we left off at, rather than silently accepting
whatever we're sent.

BUG=622435
Committed: https://crrev.com/63fb95a68d70cd7036db65c3378e91cb77faa44d
Cr-Commit-Position: refs/heads/master@{#13398}

[ossu, 2016-07-05 16:39:03]

ossu@webrtc.org changed reviewers:
+ ivoc@webrtc.org, tina.legrand@webrtc.org

[ossu, 2016-07-05 16:39:04]

PTAL at this. It fixes an error caught by clusterfuzz and is actually something
that might cause WebRTC to explode if a call ever moves from Opus to G722.

https://codereview.webrtc.org/2119393002/diff/1/webrtc/modules/audio_coding/a...
File webrtc/modules/audio_coding/acm2/audio_coding_module.cc (left):

https://codereview.webrtc.org/2119393002/diff/1/webrtc/modules/audio_coding/a...
webrtc/modules/audio_coding/acm2/audio_coding_module.cc:755: // TODO(turajs): Do
we need a warning here.
Probably.

[tlegrand-webrtc, 2016-07-06 08:25:44]

How is the input timestamp used? I'm asking, since the output timestamp should
be updated in 8 kHz mode for G.722, and I wonder if that is the case now.

https://codereview.webrtc.org/2119393002/diff/1/webrtc/modules/audio_coding/a...
File webrtc/modules/audio_coding/acm2/audio_coding_module.cc (right):

https://codereview.webrtc.org/2119393002/diff/1/webrtc/modules/audio_coding/a...
webrtc/modules/audio_coding/acm2/audio_coding_module.cc:761: << ", expected: "
<< expected_in_ts_;
Will we only end up here once in the case the codec changes?

[ossu, 2016-07-06 08:38:56]

The input timestamp (after being resampled to whatever input sample rate the
codec requires) is used to calculate the RTP output timestamp. I'm not sure if
it's also used for other things internally. I've added a comment where the
scaling takes place to turn it into RTP clockrate, when necessary.

https://codereview.webrtc.org/2119393002/diff/1/webrtc/modules/audio_coding/a...
File webrtc/modules/audio_coding/acm2/audio_coding_module.cc (right):

https://codereview.webrtc.org/2119393002/diff/1/webrtc/modules/audio_coding/a...
webrtc/modules/audio_coding/acm2/audio_coding_module.cc:482: first_frame_ ?
input_data.input_timestamp
Here is where the output timestamp gets adjusted if there's a mismatch between a
codec's sample rate and its RTP clockrate.

https://codereview.webrtc.org/2119393002/diff/1/webrtc/modules/audio_coding/a...
webrtc/modules/audio_coding/acm2/audio_coding_module.cc:761: << ", expected: "
<< expected_in_ts_;
On 2016/07/06 08:25:44, tlegrand-webrtc wrote:
> Will we only end up here once in the case the codec changes?

This shouldn't happen when the codec changes. In fact, I don't think we should
ever end up here. However, seeing as it's something we're not expecting, I think
we should log it. It could help track down other issues when we don't have
access to much other than logs.

Now, if this happens, we adjust for it and it should only log once, yes. Unless
something very strange is happening at the input (like maybe timestamps not
moving forward at all).

[tlegrand-webrtc, 2016-07-06 08:54:13]

On 2016/07/06 08:38:56, ossu wrote:
> The input timestamp (after being resampled to whatever input sample rate the
> codec requires) is used to calculate the RTP output timestamp. I'm not sure if
> it's also used for other things internally. I've added a comment where the
> scaling takes place to turn it into RTP clockrate, when necessary.

Can you double-check that the G.722 packets have timestamps update with 8000
samples/sec? Itäs probably correct, but better to be safe than sorry.
LGTM
> 
>
https://codereview.webrtc.org/2119393002/diff/1/webrtc/modules/audio_coding/a...
> File webrtc/modules/audio_coding/acm2/audio_coding_module.cc (right):
> 
>
https://codereview.webrtc.org/2119393002/diff/1/webrtc/modules/audio_coding/a...
> webrtc/modules/audio_coding/acm2/audio_coding_module.cc:482: first_frame_ ?
> input_data.input_timestamp
> Here is where the output timestamp gets adjusted if there's a mismatch between
a
> codec's sample rate and its RTP clockrate.
> 
>
https://codereview.webrtc.org/2119393002/diff/1/webrtc/modules/audio_coding/a...
> webrtc/modules/audio_coding/acm2/audio_coding_module.cc:761: << ", expected: "
> << expected_in_ts_;
> On 2016/07/06 08:25:44, tlegrand-webrtc wrote:
> > Will we only end up here once in the case the codec changes?
> 
> This shouldn't happen when the codec changes. In fact, I don't think we should
> ever end up here. However, seeing as it's something we're not expecting, I
think
> we should log it. It could help track down other issues when we don't have
> access to much other than logs.
> 
> Now, if this happens, we adjust for it and it should only log once, yes.
Unless
> something very strange is happening at the input (like maybe timestamps not
> moving forward at all).

[ossu, 2016-07-06 08:57:41]

On 2016/07/06 08:54:13, tlegrand-webrtc wrote:
> On 2016/07/06 08:38:56, ossu wrote:
> > The input timestamp (after being resampled to whatever input sample rate the
> > codec requires) is used to calculate the RTP output timestamp. I'm not sure
if
> > it's also used for other things internally. I've added a comment where the
> > scaling takes place to turn it into RTP clockrate, when necessary.
> 
> Can you double-check that the G.722 packets have timestamps update with 8000
> samples/sec? Itäs probably correct, but better to be safe than sorry.
> LGTM

Yeah, I mean, that part hasn't been changed, but sure. I'll double-check. :)

[ossu, 2016-07-06 09:51:33]

On 2016/07/06 08:57:41, ossu wrote:
> On 2016/07/06 08:54:13, tlegrand-webrtc wrote:
> > On 2016/07/06 08:38:56, ossu wrote:
> > > The input timestamp (after being resampled to whatever input sample rate
the
> > > codec requires) is used to calculate the RTP output timestamp. I'm not
sure
> if
> > > it's also used for other things internally. I've added a comment where the
> > > scaling takes place to turn it into RTP clockrate, when necessary.
> > 
> > Can you double-check that the G.722 packets have timestamps update with 8000
> > samples/sec? Itäs probably correct, but better to be safe than sorry.
> > LGTM
> 
> Yeah, I mean, that part hasn't been changed, but sure. I'll double-check. :)

I added in some temporary logging and rebuilt chrome to check this very
scenario. The output looks fine:
[1:11:0706/114532:WARNING:webrtcvoiceengine.cc(990)] webrtc:
(audio_coding_module.cc:501): Codec: 0, rtp_timestamp: 158040, Timestamp: 0
[1:11:0706/114532:WARNING:webrtcvoiceengine.cc(990)] webrtc:
(audio_coding_module.cc:501): Codec: 5, rtp_timestamp: 158120, Timestamp: 158040
[1:11:0706/114532:WARNING:webrtcvoiceengine.cc(990)] webrtc:
(audio_coding_module.cc:501): Codec: 0, rtp_timestamp: 158200, Timestamp: 0
[1:11:0706/114532:WARNING:webrtcvoiceengine.cc(990)] webrtc:
(audio_coding_module.cc:501): Codec: 5, rtp_timestamp: 158280, Timestamp: 158200
[1:11:0706/114532:WARNING:webrtcvoiceengine.cc(990)] webrtc:
(audio_coding_module.cc:501): Codec: 0, rtp_timestamp: 158360, Timestamp: 0
[1:11:0706/114533:WARNING:webrtcvoiceengine.cc(990)] webrtc:
(audio_coding_module.cc:501): Codec: 5, rtp_timestamp: 158440, Timestamp: 158360
[1:11:0706/114533:WARNING:webrtcvoiceengine.cc(990)] webrtc:
(audio_coding_module.cc:501): Codec: 0, rtp_timestamp: 158520, Timestamp: 0
[1:11:0706/114533:WARNING:webrtcvoiceengine.cc(990)] webrtc:
(audio_coding_module.cc:501): Codec: 5, rtp_timestamp: 158600, Timestamp: 158520

Codec 5 is G722. I guess it uses 20 ms packets, so every other 10 ms block of
audio is just swallowed and no audio is created (Codec: 0 ... Timestamp: 0).
rtp_timestamp is the value calculated around line 482. It advances by 80 clocks
per 10 ms - the output of G722 advances by 160 clocks per 20 ms.

[ossu, 2016-07-06 09:51:41]

The CQ bit was checked by ossu@webrtc.org

[commit-bot: I haz the power, 2016-07-06 09:51:47]

CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.webrtc.org/...

[commit-bot: I haz the power, 2016-07-06 10:00:36]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-07-06 10:00:37]

Try jobs failed on following builders:
  linux_ubsan on master.tryserver.webrtc (JOB_FAILED,
http://build.chromium.org/p/tryserver.webrtc/builders/linux_ubsan/builds/3317)

[ossu, 2016-07-06 10:04:57]

On 2016/07/06 10:00:37, commit-bot: I haz the power wrote:
> Try jobs failed on following builders:
>   linux_ubsan on master.tryserver.webrtc (JOB_FAILED,
> http://build.chromium.org/p/tryserver.webrtc/builders/linux_ubsan/builds/3317)

Hmm... so time _does_ move backwards sometimes. I'll look into if this is wrong,
or if there actually are valid usecases for that to happen.

[ossu, 2016-07-06 11:05:32]

PTAL. I've updated a test that was failing after this change. I expect it's
better to disallow the input timestamp to go backwards in general usage, since
that probably is an indication that something is wrong. If we really want to, I
could instead remove the new check for time going backwards, since it's actually
not directly related to this fix.

[tlegrand, 2016-07-06 11:19:23]

On 2016/07/06 11:05:32, ossu wrote:
> PTAL. I've updated a test that was failing after this change. I expect it's
> better to disallow the input timestamp to go backwards in general usage, since
> that probably is an indication that something is wrong. If we really want to,
I
> could instead remove the new check for time going backwards, since it's
actually
> not directly related to this fix.

I think updating the test makes sense. LGTM

[ossu, 2016-07-06 16:32:35]

The CQ bit was checked by ossu@webrtc.org

[ossu, 2016-07-06 16:32:35]

The patchset sent to the CQ was uploaded after l-g-t-m from
tina.legrand@webrtc.org
Link to the patchset: https://codereview.webrtc.org/2119393002/#ps20001 (title:
"Updated Dtx tests that moved the input timestamp backwards to not do that.")

[commit-bot: I haz the power, 2016-07-06 16:32:46]

CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.webrtc.org/...

[commit-bot: I haz the power, 2016-07-06 16:34:26]

Committed patchset #2 (id:20001)

[commit-bot: I haz the power, 2016-07-06 16:34:39]

Description was changed from

==========
Fixed time moving backwards in the AudioCodingModule.

There was a fast path in PreprocessToAddData that would just use the
input timestamps if the input format was equal to the required format of
the encoder. This works well as long as the codec never changes. If we
are first doing resampling (specifically upsampling) and then change to
a codec that does not require resampling, we'll need to stick to
whatever input timestamp we left off at, rather than silently accepting
whatever we're sent.

BUG=622435
==========

to

==========
Fixed time moving backwards in the AudioCodingModule.

There was a fast path in PreprocessToAddData that would just use the
input timestamps if the input format was equal to the required format of
the encoder. This works well as long as the codec never changes. If we
are first doing resampling (specifically upsampling) and then change to
a codec that does not require resampling, we'll need to stick to
whatever input timestamp we left off at, rather than silently accepting
whatever we're sent.

BUG=622435

Committed: https://crrev.com/63fb95a68d70cd7036db65c3378e91cb77faa44d
Cr-Commit-Position: refs/heads/master@{#13398}
==========

[commit-bot: I haz the power, 2016-07-06 16:34:40]

Patchset 2 (id:??) landed as
https://crrev.com/63fb95a68d70cd7036db65c3378e91cb77faa44d
Cr-Commit-Position: refs/heads/master@{#13398}