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

media/cast/video_receiver/video_receiver.cc

 // Copyright 2013 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "media/cast/video_receiver/video_receiver.h"
 
 #include <algorithm>
 
 #include "base/bind.h"
 #include "base/debug/trace_event.h"
 #include "base/logging.h"
 #include "base/message_loop/message_loop.h"
 #include "media/base/video_frame.h"
 #include "media/cast/logging/logging_defines.h"
 #include "media/cast/transport/cast_transport_defines.h"
 #include "media/cast/video_receiver/video_decoder.h"
 
 namespace {
 const int kMinSchedulingDelayMs = 1;
-const int kMinTimeBetweenOffsetUpdatesMs = 1000;
-const int kTimeOffsetMaxCounter = 10;
 }  // namespace
 
 namespace media {
 namespace cast {
 
 VideoReceiver::VideoReceiver(scoped_refptr<CastEnvironment> cast_environment,
                              const VideoReceiverConfig& video_config,
                              transport::PacedPacketSender* const packet_sender)
     : RtpReceiver(cast_environment->Clock(), NULL, &video_config),
       cast_environment_(cast_environment),
       event_subscriber_(kReceiverRtcpEventHistorySize, VIDEO_EVENT),
       codec_(video_config.codec),
-      target_delay_delta_(
+      target_playout_delay_(
           base::TimeDelta::FromMilliseconds(video_config.rtp_max_delay_ms)),
       expected_frame_duration_(
           base::TimeDelta::FromSeconds(1) / video_config.max_frame_rate),
+      reports_are_scheduled_(false),
       framer_(cast_environment->Clock(),
               this,
               video_config.incoming_ssrc,
               video_config.decoder_faster_than_max_frame_rate,
               video_config.rtp_max_delay_ms * video_config.max_frame_rate /
                   1000),
       rtcp_(cast_environment_,
             NULL,
             NULL,
             packet_sender,
             GetStatistics(),
             video_config.rtcp_mode,
             base::TimeDelta::FromMilliseconds(video_config.rtcp_interval),
             video_config.feedback_ssrc,
             video_config.incoming_ssrc,
             video_config.rtcp_c_name,
             false),
-      time_offset_counter_(0),
-      time_incoming_packet_updated_(false),
-      incoming_rtp_timestamp_(0),
-      is_waiting_for_consecutive_frame_(false),
+      is_waiting_to_emit_frames_(false),
       weak_factory_(this) {
   DCHECK_GT(video_config.rtp_max_delay_ms, 0);
   DCHECK_GT(video_config.max_frame_rate, 0);
   if (!video_config.use_external_decoder) {
     video_decoder_.reset(new VideoDecoder(cast_environment, video_config));
   }
   decryptor_.Initialize(video_config.aes_key, video_config.aes_iv_mask);
-  rtcp_.SetTargetDelay(target_delay_delta_);
+  rtcp_.SetTargetDelay(target_playout_delay_);
   cast_environment_->Logging()->AddRawEventSubscriber(&event_subscriber_);
   memset(frame_id_to_rtp_timestamp_, 0, sizeof(frame_id_to_rtp_timestamp_));
 }
 
 VideoReceiver::~VideoReceiver() {
   DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN));
   cast_environment_->Logging()->RemoveRawEventSubscriber(&event_subscriber_);
 }
 
-void VideoReceiver::InitializeTimers() {
-  DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN));
-  ScheduleNextRtcpReport();
-  ScheduleNextCastMessage();
-}
-
 void VideoReceiver::GetRawVideoFrame(
     const VideoFrameDecodedCallback& callback) {
   DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN));
   DCHECK(!callback.is_null());
   DCHECK(video_decoder_.get());
   GetEncodedVideoFrame(base::Bind(
       &VideoReceiver::DecodeEncodedVideoFrame,
       // Note: Use of Unretained is safe since this Closure is guaranteed to be
       // invoked before destruction of |this|.
       base::Unretained(this),
@@ skipping 62 matching lines @@
     // payload yet!  Or, at least, peek using a StringPiece instead of a copy.
     scoped_ptr<transport::EncodedVideoFrame> encoded_frame(
         new transport::EncodedVideoFrame());
     bool is_consecutively_next_frame = false;
     if (!framer_.GetEncodedVideoFrame(encoded_frame.get(),
                                       &is_consecutively_next_frame)) {
       VLOG(1) << "Wait for more video packets to produce a completed frame.";
       return;  // OnReceivedPayloadData() will invoke this method in the future.
     }
 
+    const base::TimeTicks playout_time =
+        GetPlayoutTime(encoded_frame->rtp_timestamp);
+
     // If |framer_| has a frame ready that is out of sequence, examine the
     // playout time to determine whether it's acceptable to continue, thereby
     // skipping one or more frames.  Skip if the missing frame wouldn't complete
     // playing before the start of playback of the available frame.
-    const base::TimeTicks now = cast_environment_->Clock()->NowTicks();
-    const base::TimeTicks playout_time =
-        GetPlayoutTime(now, encoded_frame->rtp_timestamp);
     if (!is_consecutively_next_frame) {
+      const base::TimeTicks now = cast_environment_->Clock()->NowTicks();
       // TODO(miu): Also account for expected decode time here?
       const base::TimeTicks earliest_possible_end_time_of_missing_frame =
           now + expected_frame_duration_;
       if (earliest_possible_end_time_of_missing_frame < playout_time) {
         VLOG(1) << "Wait for next consecutive frame instead of skipping.";
-        if (!is_waiting_for_consecutive_frame_) {
-          is_waiting_for_consecutive_frame_ = true;
-          cast_environment_->PostDelayedTask(
-              CastEnvironment::MAIN,
-              FROM_HERE,
-              base::Bind(&VideoReceiver::EmitAvailableEncodedFramesAfterWaiting,
-                         weak_factory_.GetWeakPtr()),
-              playout_time - now);
-        }
+        RetryEmitAfterWaiting(playout_time - now);
         return;
       }
     }
 
     // Decrypt the payload data in the frame, if crypto is being used.
     if (decryptor_.initialized()) {
       std::string decrypted_video_data;
       if (!decryptor_.Decrypt(encoded_frame->frame_id,
                               encoded_frame->data,
                               &decrypted_video_data)) {
@@ skipping 17 matching lines @@
         "render_time", playout_time.ToInternalValue());
     cast_environment_->PostTask(CastEnvironment::MAIN,
                                 FROM_HERE,
                                 base::Bind(frame_request_queue_.front(),
                                            base::Passed(&encoded_frame),
                                            playout_time));
     frame_request_queue_.pop_front();
   }
 }
 
+void VideoReceiver::RetryEmitAfterWaiting(base::TimeDelta wait_time) {
+  DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN));
+  if (is_waiting_to_emit_frames_)
+    return;
+  is_waiting_to_emit_frames_ = true;
+  cast_environment_->PostDelayedTask(
+      CastEnvironment::MAIN,
+      FROM_HERE,
+      base::Bind(&VideoReceiver::EmitAvailableEncodedFramesAfterWaiting,
+                 weak_factory_.GetWeakPtr()),
+      wait_time);
+}
+
 void VideoReceiver::EmitAvailableEncodedFramesAfterWaiting() {
   DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN));
-  DCHECK(is_waiting_for_consecutive_frame_);
-  is_waiting_for_consecutive_frame_ = false;
+  DCHECK(is_waiting_to_emit_frames_);
+  is_waiting_to_emit_frames_ = false;
   EmitAvailableEncodedFrames();
 }
 
-base::TimeTicks VideoReceiver::GetPlayoutTime(base::TimeTicks now,
-                                              uint32 rtp_timestamp) {
-  // TODO(miu): This and AudioReceiver::GetPlayoutTime() need to be reconciled!
+base::TimeTicks VideoReceiver::GetPlayoutTime(uint32 rtp_timestamp) const {
+  base::TimeTicks capture_time = rtcp_.ToApproximateCaptureTime(
+      rtp_timestamp, kVideoFrequency);
 
-  DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN));
-  // Senders time in ms when this frame was captured.
-  // Note: the senders clock and our local clock might not be synced.
-  base::TimeTicks rtp_timestamp_in_ticks;
-
-  // Compute the time offset_in_ticks based on the incoming_rtp_timestamp_.
-  if (time_offset_counter_ == 0) {
-    // Check for received RTCP to sync the stream play it out asap.
-    if (rtcp_.RtpTimestampInSenderTime(kVideoFrequency,
-                                       incoming_rtp_timestamp_,
-                                       &rtp_timestamp_in_ticks)) {
-       ++time_offset_counter_;
-    }
-  } else if (time_incoming_packet_updated_) {
-    if (rtcp_.RtpTimestampInSenderTime(kVideoFrequency,
-                                       incoming_rtp_timestamp_,
-                                       &rtp_timestamp_in_ticks)) {
-      // Time to update the time_offset.
-      base::TimeDelta time_offset =
-          time_incoming_packet_ - rtp_timestamp_in_ticks;
-      // Taking the minimum of the first kTimeOffsetMaxCounter values. We are
-      // assuming that we are looking for the minimum offset, which will occur
-      // when network conditions are the best. This should occur at least once
-      // within the first kTimeOffsetMaxCounter samples. Any drift should be
-      // very slow, and negligible for this use case.
-      if (time_offset_counter_ == 1)
-        time_offset_ = time_offset;
-      else if (time_offset_counter_ < kTimeOffsetMaxCounter) {
-        time_offset_ = std::min(time_offset_, time_offset);
-      }
-      if (time_offset_counter_ < kTimeOffsetMaxCounter)
-        ++time_offset_counter_;
-    }
-  }
-  // Reset |time_incoming_packet_updated_| to enable a future measurement.
-  time_incoming_packet_updated_ = false;
-  // Compute the actual rtp_timestamp_in_ticks based on the current timestamp.
-  if (!rtcp_.RtpTimestampInSenderTime(
-           kVideoFrequency, rtp_timestamp, &rtp_timestamp_in_ticks)) {
-    // This can fail if we have not received any RTCP packets in a long time.
-    // BUG: These calculations are a placeholder, and to be revisited in a
-    // soon-upcoming change.  http://crbug.com/356942
-    const int frequency_khz = kVideoFrequency / 1000;
-    const base::TimeDelta delta_based_on_rtp_timestamps =
-        base::TimeDelta::FromMilliseconds(
-            static_cast<int32>(rtp_timestamp - incoming_rtp_timestamp_) /
-                frequency_khz);
-    return time_incoming_packet_ + delta_based_on_rtp_timestamps;
+  // HACK: The sender should have provided Sender Reports which allow this
+  // receiver to map RTP timestamps back to the time the frame was captured on
+  // the sender.  It should have done this before sending the first frame, but
+  // the spec does not currently require this.  Therefore, if the data is
+  // missing, this receiver is forced to take a guess.
+  //
+  // The guess is based on a number of assumptions which in many environments
+  // will be completely wrong:
+  //   1. The difference between the sender clock and receiver clock (relative
+  //      to NTP epoch) is very close to zero.
+  //   2. The amount of time the sender took to encode/process the frame before
+  //      transport is approximately 1/2 the amount of time between frames.
+  //   3. Perfect network conditions (i.e., negligible latency, no packet loss,
+  //      frames are arriving in-order, etc.).
+  if (capture_time.is_null()) {
+    VLOG(1) << ("Guessing playout time because sender has not yet sent lip "
+                "sync info.  Expect jank in the near future!");
+    capture_time = cast_environment_->Clock()->NowTicks() -
+        (expected_frame_duration_ / 2);
   }
 
-  base::TimeTicks render_time =
-      rtp_timestamp_in_ticks + time_offset_ + target_delay_delta_;
-  // TODO(miu): This is broken since this "getter" method may be called on
-  // frames received out-of-order, which means the playout times for earlier
-  // frames will be computed incorrectly.
-#if 0
-  if (last_render_time_ > render_time)
-    render_time = last_render_time_;
-  last_render_time_ = render_time;
-#endif
-
-  return render_time;
+  return capture_time + target_playout_delay_;
 }
 
 void VideoReceiver::IncomingPacket(scoped_ptr<Packet> packet) {
   DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN));
   if (Rtcp::IsRtcpPacket(&packet->front(), packet->size())) {
     rtcp_.IncomingRtcpPacket(&packet->front(), packet->size());
   } else {
     ReceivedPacket(&packet->front(), packet->size());
   }
+  if (!reports_are_scheduled_) {
+    ScheduleNextRtcpReport();
+    ScheduleNextCastMessage();
+    reports_are_scheduled_ = true;
+  }
 }
 
 void VideoReceiver::OnReceivedPayloadData(const uint8* payload_data,
                                           size_t payload_size,
                                           const RtpCastHeader& rtp_header) {
   DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN));
 
-  base::TimeTicks now = cast_environment_->Clock()->NowTicks();
-  if (time_incoming_packet_.is_null() ||
-      now - time_incoming_packet_ >
-          base::TimeDelta::FromMilliseconds(kMinTimeBetweenOffsetUpdatesMs)) {
-    if (time_incoming_packet_.is_null())
-      InitializeTimers();
-    incoming_rtp_timestamp_ = rtp_header.rtp_timestamp;
-    // The following incoming packet info is used for syncing sender and
-    // receiver clock. Use only the first packet of every frame to obtain a
-    // minimal value.
-    if (rtp_header.packet_id == 0) {
-      time_incoming_packet_ = now;
-      time_incoming_packet_updated_ = true;
-    }
-  }
+  const base::TimeTicks now = cast_environment_->Clock()->NowTicks();
 
   frame_id_to_rtp_timestamp_[rtp_header.frame_id & 0xff] =
       rtp_header.rtp_timestamp;
   cast_environment_->Logging()->InsertPacketEvent(
       now,
       PACKET_RECEIVED,
       VIDEO_EVENT,
       rtp_header.rtp_timestamp,
       rtp_header.frame_id,
       rtp_header.packet_id,
@@ skipping 73 matching lines @@
 }
 
 void VideoReceiver::SendNextRtcpReport() {
   DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN));
   rtcp_.SendRtcpFromRtpReceiver(NULL, NULL);
   ScheduleNextRtcpReport();
 }
 
 }  // namespace cast
 }  // namespace media