[Cast] Repair receiver playout time calculations and frame skip logic.

[Cast] Repair receiver playout time calculations and frame skip logic.

Fixed playout time calculations by relying on the sender reports in order
to compute reliable capture timestamps in terms of the local clock.  Added
a ClockDriftSmoother to smooth out jitter/skew in the "NTP to local clock
TimeTicks" conversions.  Used the same to provide a gradual timeline shift
in the case where a receiver had to "hack up" playout times before the
first sender report was processed.

As proof-of-concept, also added playout_time "smoothness" testing to the
End2EndTest's.  Both first and second order effects are tested.

Miscellaneous clean-ups and fixes in timing code throughout media/cast.

BUG=356942
Committed: https://src.chromium.org/viewvc/chrome?view=rev&revision=272893

[miu, 2014-05-13 23:19:02]

hubbe/hclam: PTAL.

https://codereview.chromium.org/280993002/diff/1/media/cast/audio_receiver/au...
File media/cast/audio_receiver/audio_receiver.cc (left):

https://codereview.chromium.org/280993002/diff/1/media/cast/audio_receiver/au...
media/cast/audio_receiver/audio_receiver.cc:192: if
(!is_waiting_for_consecutive_frame_) {
Explanation for "unnecessary factoring" here: I had factored this out because,
in an earlier iteration of the code, I was using it more than once.  However,
rather than undo it, I think it makes things more readable so I've decided to
leave it in.

[hubbe, 2014-05-14 23:12:23]

First pass

https://codereview.chromium.org/280993002/diff/1/media/cast/audio_receiver/au...
File media/cast/audio_receiver/audio_receiver.cc (right):

https://codereview.chromium.org/280993002/diff/1/media/cast/audio_receiver/au...
media/cast/audio_receiver/audio_receiver.cc:167: if
(!is_consecutively_next_frame &&
Hmm, I think the framer should not return non-decodable frames.

https://codereview.chromium.org/280993002/diff/1/media/cast/audio_receiver/au...
File media/cast/audio_receiver/audio_receiver.h (right):

https://codereview.chromium.org/280993002/diff/1/media/cast/audio_receiver/au...
media/cast/audio_receiver/audio_receiver.h:151: bool reports_are_scheduled_;
Maybe add comments for these variables?

https://codereview.chromium.org/280993002/diff/1/media/cast/cast_defines.h
File media/cast/cast_defines.h (right):

https://codereview.chromium.org/280993002/diff/1/media/cast/cast_defines.h#ne...
media/cast/cast_defines.h:145: CHECK(seconds_component <=
std::numeric_limits<uint32>::max());
When will this wrap?
What happens when if wraps?

https://codereview.chromium.org/280993002/diff/1/media/cast/rtcp/rtcp.cc
File media/cast/rtcp/rtcp.cc (left):

https://codereview.chromium.org/280993002/diff/1/media/cast/rtcp/rtcp.cc#oldc...
media/cast/rtcp/rtcp.cc:413: int Rtcp::CheckForWrapAround(uint32 new_timestamp,
uint32 old_timestamp) const {
Where did this logic go?

https://codereview.chromium.org/280993002/diff/1/media/cast/rtcp/rtcp.cc
File media/cast/rtcp/rtcp.cc (right):

https://codereview.chromium.org/280993002/diff/1/media/cast/rtcp/rtcp.cc#newc...
media/cast/rtcp/rtcp.cc:313: return base::TimeTicks();
I think this should be last_rtp_received_ticks + (rtp_timestamp -
last_rtp_received) / rtp_rate_per_second - kSenderLatencyGuess or something like
that.

https://codereview.chromium.org/280993002/diff/1/media/cast/rtcp/rtcp.h
File media/cast/rtcp/rtcp.h (right):

https://codereview.chromium.org/280993002/diff/1/media/cast/rtcp/rtcp.h#newco...
media/cast/rtcp/rtcp.h:111: base::TimeTicks ToApproximateLocalTime(uint32
remote_ntp_seconds,
Can this be made private?

https://codereview.chromium.org/280993002/diff/1/media/cast/rtcp/rtcp.h#newco...
media/cast/rtcp/rtcp.h:171: uint32 GetTruncatedLastNtpReportTime() const;
Where is the inverse of this function?

https://codereview.chromium.org/280993002/diff/1/media/cast/rtcp/rtcp.h#newco...
media/cast/rtcp/rtcp.h:197: uint64 last_report_ntp_time_;
Don't we need some sort of min() calculation for these?

https://codereview.chromium.org/280993002/diff/1/media/cast/rtcp/rtcp.h#newco...
media/cast/rtcp/rtcp.h:204: // this data regularly and in a timely manner (i.e.,
about once per second).
i.e. -> e.g.

https://codereview.chromium.org/280993002/diff/1/media/cast/video_receiver/vi...
File media/cast/video_receiver/video_receiver.cc (right):

https://codereview.chromium.org/280993002/diff/1/media/cast/video_receiver/vi...
media/cast/video_receiver/video_receiver.cc:252: capture_time =
cast_environment_->Clock()->NowTicks() -
Doesn't ToApproximateCaptureTime() also guess?
Better to guess in one place than in two, right?

[Alpha Left Google, 2014-05-15 21:49:54]

hubbe is already reviewing this, i'll defer to him.

[miu, 2014-05-16 22:45:48]

hubbe: PTAL.

https://codereview.chromium.org/280993002/diff/1/media/cast/audio_receiver/au...
File media/cast/audio_receiver/audio_receiver.cc (right):

https://codereview.chromium.org/280993002/diff/1/media/cast/audio_receiver/au...
media/cast/audio_receiver/audio_receiver.cc:167: if
(!is_consecutively_next_frame &&
On 2014/05/14 23:12:23, hubbe wrote:
> Hmm, I think the framer should not return non-decodable frames.

Done.

https://codereview.chromium.org/280993002/diff/1/media/cast/audio_receiver/au...
File media/cast/audio_receiver/audio_receiver.h (right):

https://codereview.chromium.org/280993002/diff/1/media/cast/audio_receiver/au...
media/cast/audio_receiver/audio_receiver.h:151: bool reports_are_scheduled_;
On 2014/05/14 23:12:23, hubbe wrote:
> Maybe add comments for these variables?

Done.

https://codereview.chromium.org/280993002/diff/1/media/cast/cast_defines.h
File media/cast/cast_defines.h (right):

https://codereview.chromium.org/280993002/diff/1/media/cast/cast_defines.h#ne...
media/cast/cast_defines.h:145: CHECK(seconds_component <=
std::numeric_limits<uint32>::max());
On 2014/05/14 23:12:23, hubbe wrote:
> When will this wrap?
> What happens when if wraps?

Done.  Documented.

https://codereview.chromium.org/280993002/diff/1/media/cast/rtcp/rtcp.cc
File media/cast/rtcp/rtcp.cc (left):

https://codereview.chromium.org/280993002/diff/1/media/cast/rtcp/rtcp.cc#oldc...
media/cast/rtcp/rtcp.cc:413: int Rtcp::CheckForWrapAround(uint32 new_timestamp,
uint32 old_timestamp) const {
On 2014/05/14 23:12:23, hubbe wrote:
> Where did this logic go?

It was meaningless.  Subtraction when zero, one, or both uint32's have
overflowed still works (in ToApproximateCaptureTime()).  The assumption there is
that the sender reports are providing RTP timestamps within 1 minute of those
found in the current packets/frames.

https://codereview.chromium.org/280993002/diff/1/media/cast/rtcp/rtcp.cc
File media/cast/rtcp/rtcp.cc (right):

https://codereview.chromium.org/280993002/diff/1/media/cast/rtcp/rtcp.cc#newc...
media/cast/rtcp/rtcp.cc:313: return base::TimeTicks();
On 2014/05/14 23:12:23, hubbe wrote:
> I think this should be last_rtp_received_ticks + (rtp_timestamp -
> last_rtp_received) / rtp_rate_per_second - kSenderLatencyGuess or something
like
> that.

As discussed, this isn't base::TimeTicks::Now(); it is "null."  The guessing
logic happens in XXXXXReceiver::GetPlayoutTime() in response to a "null" return
from here.

https://codereview.chromium.org/280993002/diff/1/media/cast/rtcp/rtcp.h
File media/cast/rtcp/rtcp.h (right):

https://codereview.chromium.org/280993002/diff/1/media/cast/rtcp/rtcp.h#newco...
media/cast/rtcp/rtcp.h:111: base::TimeTicks ToApproximateLocalTime(uint32
remote_ntp_seconds,
On 2014/05/14 23:12:23, hubbe wrote:
> Can this be made private?

Done.

https://codereview.chromium.org/280993002/diff/1/media/cast/rtcp/rtcp.h#newco...
media/cast/rtcp/rtcp.h:171: uint32 GetTruncatedLastNtpReportTime() const;
On 2014/05/14 23:12:23, hubbe wrote:
> Where is the inverse of this function?

Not implemented.  It appears to be parsed and delivered to
RtcpReceiver::HandleReportBlock(), but is not consumed for anything.

https://codereview.chromium.org/280993002/diff/1/media/cast/rtcp/rtcp.h#newco...
media/cast/rtcp/rtcp.h:197: uint64 last_report_ntp_time_;
On 2014/05/14 23:12:23, hubbe wrote:
> Don't we need some sort of min() calculation for these?

Nope.  These are just snapshots from the latest sender report.

Since we ignore RTT in the calculation (see TODO comment in
ToApproximateLocalTime()), there's nothing to min() here.  Unless there was
something else we discussed that I'm forgetting?

https://codereview.chromium.org/280993002/diff/1/media/cast/rtcp/rtcp.h#newco...
media/cast/rtcp/rtcp.h:204: // this data regularly and in a timely manner (i.e.,
about once per second).
On 2014/05/14 23:12:23, hubbe wrote:
> i.e. -> e.g.

Done.

https://codereview.chromium.org/280993002/diff/1/media/cast/video_receiver/vi...
File media/cast/video_receiver/video_receiver.cc (right):

https://codereview.chromium.org/280993002/diff/1/media/cast/video_receiver/vi...
media/cast/video_receiver/video_receiver.cc:252: capture_time =
cast_environment_->Clock()->NowTicks() -
On 2014/05/14 23:12:23, hubbe wrote:
> Doesn't ToApproximateCaptureTime() also guess?
> Better to guess in one place than in two, right?

No.  Only XXXXXReceiver::GetPlayoutTime() has the evil guessing logic.

[hubbe, 2014-05-19 17:52:20]

https://codereview.chromium.org/280993002/diff/1/media/cast/rtcp/rtcp.h
File media/cast/rtcp/rtcp.h (right):

https://codereview.chromium.org/280993002/diff/1/media/cast/rtcp/rtcp.h#newco...
media/cast/rtcp/rtcp.h:197: uint64 last_report_ntp_time_;
On 2014/05/16 22:45:47, miu wrote:
> On 2014/05/14 23:12:23, hubbe wrote:
> > Don't we need some sort of min() calculation for these?
> 
> Nope.  These are just snapshots from the latest sender report.
> 
> Since we ignore RTT in the calculation (see TODO comment in
> ToApproximateLocalTime()), there's nothing to min() here.  Unless there was
> something else we discussed that I'm forgetting?

Hmm, maybe I'm missing something. Isn't this used as a local time base for
converting remote clocks to local clocks? If you just use the last report,
wouldn't the offset change every time you get a new report? Potentially by a
lot?

It seems to me that when we get a new sender report, we should use it's ntp time
to calculate when it was sent in local time. *based on previous sender reports*
If the send time comes out to be in the future, we should set
time_last_report_received_ to Now(), otherwise we set it to 0.995 *
calculated_time + 0.005 * now to account for gradual drift.

https://codereview.chromium.org/280993002/diff/20001/media/cast/audio_receive...
File media/cast/audio_receiver/audio_receiver.cc (right):

https://codereview.chromium.org/280993002/diff/20001/media/cast/audio_receive...
media/cast/audio_receiver/audio_receiver.cc:213: void
AudioReceiver::RetryEmitAfterWaiting(base::TimeDelta wait_time) {
This doesn't seem complicated enough to break out into it's own function unless
it's called in multiple places. (Which I can't find)

https://codereview.chromium.org/280993002/diff/20001/media/cast/audio_receive...
media/cast/audio_receiver/audio_receiver.cc:254: capture_time =
cast_environment_->Clock()->NowTicks() -
This is not a very good guess.
I think the guess should at least be good enough to return *roughly* the same
result if you call getplayouttime again later, and it should probably take
rtp_timestamp into account.

The capture_time as written here might be ok if we recorded it when we got the
first package of the frame.

https://codereview.chromium.org/280993002/diff/20001/media/cast/cast_defines.h
File media/cast/cast_defines.h (right):

https://codereview.chromium.org/280993002/diff/20001/media/cast/cast_defines....
media/cast/cast_defines.h:148: // off the entire system.
Maybe put a DCHECK(ntp_time_us is less than the year 2035) to auto-break this
one year before the deadline? :)

Hopefully this code is dead and buried by then, but if it not, we could at least
give the poor schmuck who is working on it then a year to fix it...

https://codereview.chromium.org/280993002/diff/20001/media/cast/rtcp/rtcp.h
File media/cast/rtcp/rtcp.h (right):

https://codereview.chromium.org/280993002/diff/20001/media/cast/rtcp/rtcp.h#n...
media/cast/rtcp/rtcp.h:114: base::TimeTicks ToApproximateCaptureTime(uint32
rtp_timestamp,
I'm not sure "Capture Time" is the terminology we want to use in the cast
library, since technically the frame might not have been "captured" at all.

Perhaps "SenderPlayoutTimeInLocalTime" ?

[miu, 2014-05-23 03:09:00]

hubbe: Ready for another look.  Notice the new "proof of concept" additions to
the End2EndTest's.  :)

https://codereview.chromium.org/280993002/diff/1/media/cast/rtcp/rtcp.h
File media/cast/rtcp/rtcp.h (right):

https://codereview.chromium.org/280993002/diff/1/media/cast/rtcp/rtcp.h#newco...
media/cast/rtcp/rtcp.h:197: uint64 last_report_ntp_time_;
On 2014/05/19 17:52:20, hubbe wrote:
> On 2014/05/16 22:45:47, miu wrote:
> > On 2014/05/14 23:12:23, hubbe wrote:
> > > Don't we need some sort of min() calculation for these?
> > 
> > Nope.  These are just snapshots from the latest sender report.
> > 
> > Since we ignore RTT in the calculation (see TODO comment in
> > ToApproximateLocalTime()), there's nothing to min() here.  Unless there was
> > something else we discussed that I'm forgetting?
> 
> Hmm, maybe I'm missing something. Isn't this used as a local time base for
> converting remote clocks to local clocks? If you just use the last report,
> wouldn't the offset change every time you get a new report? Potentially by a
> lot?
> 
> It seems to me that when we get a new sender report, we should use it's ntp
time
> to calculate when it was sent in local time. *based on previous sender
reports*
> If the send time comes out to be in the future, we should set
> time_last_report_received_ to Now(), otherwise we set it to 0.995 *
> calculated_time + 0.005 * now to account for gradual drift.
> 
> 

Done.  Created a ClockDriftSmoother, and incorporated your suggested logic into
the clock offset tracking.

https://codereview.chromium.org/280993002/diff/20001/media/cast/audio_receive...
File media/cast/audio_receiver/audio_receiver.cc (right):

https://codereview.chromium.org/280993002/diff/20001/media/cast/audio_receive...
media/cast/audio_receiver/audio_receiver.cc:213: void
AudioReceiver::RetryEmitAfterWaiting(base::TimeDelta wait_time) {
On 2014/05/19 17:52:20, hubbe wrote:
> This doesn't seem complicated enough to break out into it's own function
unless
> it's called in multiple places. (Which I can't find)

Done.

https://codereview.chromium.org/280993002/diff/20001/media/cast/audio_receive...
media/cast/audio_receiver/audio_receiver.cc:254: capture_time =
cast_environment_->Clock()->NowTicks() -
On 2014/05/19 17:52:20, hubbe wrote:
> This is not a very good guess.
> I think the guess should at least be good enough to return *roughly* the same
> result if you call getplayouttime again later, and it should probably take
> rtp_timestamp into account.
> 
> The capture_time as written here might be ok if we recorded it when we got the
> first package of the frame.

Done.  See the code I added in OnReceivedPayloadData(), where the lip-sync is
refreshed (or hacked) whenever the first packet of each frame is encountered. 
If the hack is used, the ClockDriftSmoother will ensure a clean, smooth
transition between the "hack timeline" and the one provided by the sender.

https://codereview.chromium.org/280993002/diff/20001/media/cast/cast_defines.h
File media/cast/cast_defines.h (right):

https://codereview.chromium.org/280993002/diff/20001/media/cast/cast_defines....
media/cast/cast_defines.h:148: // off the entire system.
On 2014/05/19 17:52:20, hubbe wrote:
> Maybe put a DCHECK(ntp_time_us is less than the year 2035) to auto-break this
> one year before the deadline? :)
> 
> Hopefully this code is dead and buried by then, but if it not, we could at
least
> give the poor schmuck who is working on it then a year to fix it...

Done.

https://codereview.chromium.org/280993002/diff/20001/media/cast/rtcp/rtcp.h
File media/cast/rtcp/rtcp.h (right):

https://codereview.chromium.org/280993002/diff/20001/media/cast/rtcp/rtcp.h#n...
media/cast/rtcp/rtcp.h:114: base::TimeTicks ToApproximateCaptureTime(uint32
rtp_timestamp,
On 2014/05/19 17:52:20, hubbe wrote:
> I'm not sure "Capture Time" is the terminology we want to use in the cast
> library, since technically the frame might not have been "captured" at all.
> 
> Perhaps "SenderPlayoutTimeInLocalTime" ?

Done.  After fixing the logic, I moved the code around a little.  The concept of
"capture time" is no longer found anywhere in rtcp.*.

[hubbe, 2014-05-23 19:46:25]

https://codereview.chromium.org/280993002/diff/60001/media/cast/base/clock_dr...
File media/cast/base/clock_drift_smoother.h (right):

https://codereview.chromium.org/280993002/diff/60001/media/cast/base/clock_dr...
media/cast/base/clock_drift_smoother.h:13: // Tracks the jitter and drift
between clocks, providing a smoothed offset.
This doesn't seem to be the algorithm that I suggested.
It's missing the part where if the latest estimate suggests that the last packet
was transmitted in the future, we just use Reset().

Also, we may want to adjust the smoothness over time. In particular, smoothness
is just not important before we've released the first frame. Instead we just
want to get the best* estimate. After we start playing video, smoothness is much
more important.

* Important: the "best" estimate is not just dependent on the last packet!

[miu, 2014-05-23 23:06:54]

hubbe: I made a separate, explicit End2EndTest for the playout smoothness (and
took the smoothness checks out of ReceiverClockFast, ReceiverClockSlow, and
EvilNetwork).  LGTY?

As discussed, we'll plan on revisiting this smoothing logic later after: 1) some
refactoring/merging of code; 2) the sharing of sender-->receiver clock offset
estimates between receivers is put in-place; and 3) pending spec
changes/discussions take place.

[hubbe, 2014-05-23 23:19:03]

LGE (My father used to say "Looks Good Enough", when building things...)  I
suspect that this system will need me to say LGTM though. :)

[miu, 2014-05-23 23:21:53]

The CQ bit was checked by miu@chromium.org

[commit-bot: I haz the power, 2014-05-23 23:23:33]

CQ is trying da patch. Follow status at
 https://chromium-status.appspot.com/cq/miu@chromium.org/280993002/80001

[commit-bot: I haz the power, 2014-05-24 02:44:19]

FYI, CQ is re-trying this CL (attempt #1).
Please consider checking whether the failures are real,
and report flakes to chrome-troopers@google.com.
The failing builders are:
  android_dbg_triggered_tests on tryserver.chromium
(http://build.chromium.org/p/tryserver.chromium/builders/android_dbg_triggered...)
  win_chromium_rel on tryserver.chromium
(http://build.chromium.org/p/tryserver.chromium/builders/win_chromium_rel/buil...)

[miu, 2014-05-24 09:24:56]

The CQ bit was unchecked by miu@chromium.org

[miu, 2014-05-24 18:04:41]

The CQ bit was checked by miu@chromium.org

[commit-bot: I haz the power, 2014-05-24 23:19:50]

CQ is trying da patch. Follow status at
 https://chromium-status.appspot.com/cq/miu@chromium.org/280993002/100001

[commit-bot: I haz the power, 2014-05-25 01:28:24]

FYI, CQ is re-trying this CL (attempt #1).
Please consider checking whether the failures are real,
and report flakes to chrome-troopers@google.com.
The failing builders are:
  android_aosp on tryserver.chromium
(http://build.chromium.org/p/tryserver.chromium/builders/android_aosp/builds/7...)

[commit-bot: I haz the power, 2014-05-25 01:31:50]

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

[commit-bot: I haz the power, 2014-05-25 01:31:51]

Try jobs failed on following builders:
  android_aosp on tryserver.chromium
(http://build.chromium.org/p/tryserver.chromium/builders/android_aosp/builds/7...)

[miu, 2014-05-25 01:39:58]

The CQ bit was checked by miu@chromium.org

[commit-bot: I haz the power, 2014-05-25 01:40:23]

CQ is trying da patch. Follow status at
 https://chromium-status.appspot.com/cq/miu@chromium.org/280993002/100001

[commit-bot: I haz the power, 2014-05-25 01:48:44]

FYI, CQ is re-trying this CL (attempt #1).
Please consider checking whether the failures are real,
and report flakes to chrome-troopers@google.com.
The failing builders are:
  android_aosp on tryserver.chromium
(http://build.chromium.org/p/tryserver.chromium/builders/android_aosp/builds/7...)

[commit-bot: I haz the power, 2014-05-25 02:18:56]

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

[commit-bot: I haz the power, 2014-05-25 02:18:57]

Try jobs failed on following builders:
  android_aosp on tryserver.chromium
(http://build.chromium.org/p/tryserver.chromium/builders/android_aosp/builds/7...)

[miu, 2014-05-25 02:28:10]

The CQ bit was checked by miu@chromium.org

[commit-bot: I haz the power, 2014-05-25 02:28:14]

CQ is trying da patch. Follow status at
 https://chromium-status.appspot.com/cq/miu@chromium.org/280993002/100001

[commit-bot: I haz the power, 2014-05-25 02:31:37]

FYI, CQ is re-trying this CL (attempt #1).
Please consider checking whether the failures are real,
and report flakes to chrome-troopers@google.com.
The failing builders are:
  android_aosp on tryserver.chromium
(http://build.chromium.org/p/tryserver.chromium/builders/android_aosp/builds/7...)

[commit-bot: I haz the power, 2014-05-25 02:56:30]

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

[commit-bot: I haz the power, 2014-05-25 02:56:31]

Try jobs failed on following builders:
  android_aosp on tryserver.chromium
(http://build.chromium.org/p/tryserver.chromium/builders/android_aosp/builds/7...)

[miu, 2014-05-26 17:21:46]

The CQ bit was checked by miu@chromium.org

[commit-bot: I haz the power, 2014-05-26 17:22:11]

CQ is trying da patch. Follow status at
 https://chromium-status.appspot.com/cq/miu@chromium.org/280993002/100001

[commit-bot: I haz the power, 2014-05-26 17:27:58]

FYI, CQ is re-trying this CL (attempt #1).
Please consider checking whether the failures are real,
and report flakes to chrome-troopers@google.com.
The failing builders are:
  android_aosp on tryserver.chromium
(http://build.chromium.org/p/tryserver.chromium/builders/android_aosp/builds/7...)

[commit-bot: I haz the power, 2014-05-26 17:33:54]

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

[commit-bot: I haz the power, 2014-05-26 17:33:55]

Try jobs failed on following builders:
  android_aosp on tryserver.chromium
(http://build.chromium.org/p/tryserver.chromium/builders/android_aosp/builds/7...)

[miu, 2014-05-26 18:05:24]

The CQ bit was checked by miu@chromium.org

[commit-bot: I haz the power, 2014-05-26 18:06:16]

CQ is trying da patch. Follow status at
 https://chromium-status.appspot.com/cq/miu@chromium.org/280993002/100001

[commit-bot: I haz the power, 2014-05-27 00:03:33]

Change committed as 272893