media/cast/sender/frame_sender.cc

   1 // Copyright 2014 The Chromium Authors. All rights reserved.
   2 // Use of this source code is governed by a BSD-style license that can be
   3 // found in the LICENSE file.
   4
   5 #include "media/cast/sender/frame_sender.h"
   6
   7 #include "base/trace_event/trace_event.h"
   8 #include "media/cast/sender/sender_encoded_frame.h"
   9
  10 namespace media {
  11 namespace cast {
  12 namespace {
  13
  14 const int kMinSchedulingDelayMs = 1;
  15 const int kNumAggressiveReportsSentAtStart = 100;
  16
  17 // The additional number of frames that can be in-flight when input exceeds the
  18 // maximum frame rate.
  19 const int kMaxFrameBurst = 5;
  20
  21 }  // namespace
  22
  23 // Convenience macro used in logging statements throughout this file.
  24 #define SENDER_SSRC (is_audio_ ? "AUDIO[" : "VIDEO[") << ssrc_ << "] "
  25
  26 FrameSender::FrameSender(scoped_refptr<CastEnvironment> cast_environment,
  27                          bool is_audio,
  28                          CastTransportSender* const transport_sender,
  29                          int rtp_timebase,
  30                          uint32 ssrc,
  31                          double max_frame_rate,
  32                          base::TimeDelta min_playout_delay,
  33                          base::TimeDelta max_playout_delay,
  34                          CongestionControl* congestion_control)
  35     : cast_environment_(cast_environment),
  36       transport_sender_(transport_sender),
  37       ssrc_(ssrc),
  38       min_playout_delay_(min_playout_delay == base::TimeDelta() ?
  39                          max_playout_delay : min_playout_delay),
  40       max_playout_delay_(max_playout_delay),
  41       send_target_playout_delay_(false),
  42       max_frame_rate_(max_frame_rate),
  43       num_aggressive_rtcp_reports_sent_(0),
  44       last_sent_frame_id_(0),
  45       latest_acked_frame_id_(0),
  46       duplicate_ack_counter_(0),
  47       congestion_control_(congestion_control),
  48       rtp_timebase_(rtp_timebase),
  49       is_audio_(is_audio),
  50       weak_factory_(this) {
  51   DCHECK(transport_sender_);
  52   DCHECK_GT(rtp_timebase_, 0);
  53   DCHECK(congestion_control_);
  54   SetTargetPlayoutDelay(min_playout_delay_);
  55   send_target_playout_delay_ = false;
  56   memset(frame_rtp_timestamps_, 0, sizeof(frame_rtp_timestamps_));
  57 }
  58
  59 FrameSender::~FrameSender() {
  60 }
  61
  62 void FrameSender::ScheduleNextRtcpReport() {
  63   DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN));
  64
  65   cast_environment_->PostDelayedTask(
  66       CastEnvironment::MAIN, FROM_HERE,
  67       base::Bind(&FrameSender::SendRtcpReport, weak_factory_.GetWeakPtr(),
  68                  true),
  69       base::TimeDelta::FromMilliseconds(kDefaultRtcpIntervalMs));
  70 }
  71
  72 void FrameSender::SendRtcpReport(bool schedule_future_reports) {
  73   DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN));
  74
  75   // Sanity-check: We should have sent at least the first frame by this point.
  76   DCHECK(!last_send_time_.is_null());
  77
  78   // Create lip-sync info for the sender report.  The last sent frame's
  79   // reference time and RTP timestamp are used to estimate an RTP timestamp in
  80   // terms of "now."  Note that |now| is never likely to be precise to an exact
  81   // frame boundary; and so the computation here will result in a
  82   // |now_as_rtp_timestamp| value that is rarely equal to any one emitted by the
  83   // encoder.
  84   const base::TimeTicks now = cast_environment_->Clock()->NowTicks();
  85   const base::TimeDelta time_delta =
  86       now - GetRecordedReferenceTime(last_sent_frame_id_);
  87   const int64 rtp_delta = TimeDeltaToRtpDelta(time_delta, rtp_timebase_);
  88   const uint32 now_as_rtp_timestamp =
  89       GetRecordedRtpTimestamp(last_sent_frame_id_) +
  90           static_cast<uint32>(rtp_delta);
  91   transport_sender_->SendSenderReport(ssrc_, now, now_as_rtp_timestamp);
  92
  93   if (schedule_future_reports)
  94     ScheduleNextRtcpReport();
  95 }
  96
  97 void FrameSender::OnMeasuredRoundTripTime(base::TimeDelta rtt) {
  98   DCHECK(rtt > base::TimeDelta());
  99   current_round_trip_time_ = rtt;
 100 }
 101
 102 void FrameSender::SetTargetPlayoutDelay(
 103     base::TimeDelta new_target_playout_delay) {
 104   if (send_target_playout_delay_ &&
 105       target_playout_delay_ == new_target_playout_delay) {
 106     return;
 107   }
 108   new_target_playout_delay = std::max(new_target_playout_delay,
 109                                       min_playout_delay_);
 110   new_target_playout_delay = std::min(new_target_playout_delay,
 111                                       max_playout_delay_);
 112   VLOG(2) << SENDER_SSRC << "Target playout delay changing from "
 113           << target_playout_delay_.InMilliseconds() << " ms to "
 114           << new_target_playout_delay.InMilliseconds() << " ms.";
 115   target_playout_delay_ = new_target_playout_delay;
 116   send_target_playout_delay_ = true;
 117   congestion_control_->UpdateTargetPlayoutDelay(target_playout_delay_);
 118 }
 119
 120 void FrameSender::ResendCheck() {
 121   DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN));
 122   DCHECK(!last_send_time_.is_null());
 123   const base::TimeDelta time_since_last_send =
 124       cast_environment_->Clock()->NowTicks() - last_send_time_;
 125   if (time_since_last_send > target_playout_delay_) {
 126     if (latest_acked_frame_id_ == last_sent_frame_id_) {
 127       // Last frame acked, no point in doing anything
 128     } else {
 129       VLOG(1) << SENDER_SSRC << "ACK timeout; last acked frame: "
 130               << latest_acked_frame_id_;
 131       ResendForKickstart();
 132     }
 133   }
 134   ScheduleNextResendCheck();
 135 }
 136
 137 void FrameSender::ScheduleNextResendCheck() {
 138   DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN));
 139   DCHECK(!last_send_time_.is_null());
 140   base::TimeDelta time_to_next =
 141       last_send_time_ - cast_environment_->Clock()->NowTicks() +
 142       target_playout_delay_;
 143   time_to_next = std::max(
 144       time_to_next, base::TimeDelta::FromMilliseconds(kMinSchedulingDelayMs));
 145   cast_environment_->PostDelayedTask(
 146       CastEnvironment::MAIN,
 147       FROM_HERE,
 148       base::Bind(&FrameSender::ResendCheck, weak_factory_.GetWeakPtr()),
 149       time_to_next);
 150 }
 151
 152 void FrameSender::ResendForKickstart() {
 153   DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN));
 154   DCHECK(!last_send_time_.is_null());
 155   VLOG(1) << SENDER_SSRC << "Resending last packet of frame "
 156           << last_sent_frame_id_ << " to kick-start.";
 157   last_send_time_ = cast_environment_->Clock()->NowTicks();
 158   transport_sender_->ResendFrameForKickstart(ssrc_, last_sent_frame_id_);
 159 }
 160
 161 void FrameSender::RecordLatestFrameTimestamps(uint32 frame_id,
 162                                               base::TimeTicks reference_time,
 163                                               RtpTimestamp rtp_timestamp) {
 164   DCHECK(!reference_time.is_null());
 165   frame_reference_times_[frame_id % arraysize(frame_reference_times_)] =
 166       reference_time;
 167   frame_rtp_timestamps_[frame_id % arraysize(frame_rtp_timestamps_)] =
 168       rtp_timestamp;
 169 }
 170
 171 base::TimeTicks FrameSender::GetRecordedReferenceTime(uint32 frame_id) const {
 172   return frame_reference_times_[frame_id % arraysize(frame_reference_times_)];
 173 }
 174
 175 RtpTimestamp FrameSender::GetRecordedRtpTimestamp(uint32 frame_id) const {
 176   return frame_rtp_timestamps_[frame_id % arraysize(frame_rtp_timestamps_)];
 177 }
 178
 179 int FrameSender::GetUnacknowledgedFrameCount() const {
 180   const int count =
 181       static_cast<int32>(last_sent_frame_id_ - latest_acked_frame_id_);
 182   DCHECK_GE(count, 0);
 183   return count;
 184 }
 185
 186 base::TimeDelta FrameSender::GetAllowedInFlightMediaDuration() const {
 187   // The total amount allowed in-flight media should equal the amount that fits
 188   // within the entire playout delay window, plus the amount of time it takes to
 189   // receive an ACK from the receiver.
 190   // TODO(miu): Research is needed, but there is likely a better formula.
 191   return target_playout_delay_ + (current_round_trip_time_ / 2);
 192 }
 193
 194 void FrameSender::SendEncodedFrame(
 195     int requested_bitrate_before_encode,
 196     scoped_ptr<SenderEncodedFrame> encoded_frame) {
 197   DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN));
 198
 199   VLOG(2) << SENDER_SSRC << "About to send another frame: last_sent="
 200           << last_sent_frame_id_ << ", latest_acked=" << latest_acked_frame_id_;
 201
 202   const uint32 frame_id = encoded_frame->frame_id;
 203
 204   const bool is_first_frame_to_be_sent = last_send_time_.is_null();
 205   last_send_time_ = cast_environment_->Clock()->NowTicks();
 206   last_sent_frame_id_ = frame_id;
 207   // If this is the first frame about to be sent, fake the value of
 208   // |latest_acked_frame_id_| to indicate the receiver starts out all caught up.
 209   // Also, schedule the periodic frame re-send checks.
 210   if (is_first_frame_to_be_sent) {
 211     latest_acked_frame_id_ = frame_id - 1;
 212     ScheduleNextResendCheck();
 213   }
 214
 215   VLOG_IF(1, !is_audio_ && encoded_frame->dependency == EncodedFrame::KEY)
 216       << SENDER_SSRC << "Sending encoded key frame, id=" << frame_id;
 217
 218   cast_environment_->Logging()->InsertEncodedFrameEvent(
 219       last_send_time_, FRAME_ENCODED,
 220       is_audio_ ? AUDIO_EVENT : VIDEO_EVENT,
 221       encoded_frame->rtp_timestamp,
 222       frame_id, static_cast<int>(encoded_frame->data.size()),
 223       encoded_frame->dependency == EncodedFrame::KEY,
 224       requested_bitrate_before_encode,
 225       encoded_frame->deadline_utilization,
 226       encoded_frame->lossy_utilization);
 227
 228   RecordLatestFrameTimestamps(frame_id,
 229                               encoded_frame->reference_time,
 230                               encoded_frame->rtp_timestamp);
 231
 232   if (!is_audio_) {
 233     // Used by chrome/browser/extension/api/cast_streaming/performance_test.cc
 234     TRACE_EVENT_INSTANT1(
 235         "cast_perf_test", "VideoFrameEncoded",
 236         TRACE_EVENT_SCOPE_THREAD,
 237         "rtp_timestamp", encoded_frame->rtp_timestamp);
 238   }
 239
 240   // At the start of the session, it's important to send reports before each
 241   // frame so that the receiver can properly compute playout times.  The reason
 242   // more than one report is sent is because transmission is not guaranteed,
 243   // only best effort, so send enough that one should almost certainly get
 244   // through.
 245   if (num_aggressive_rtcp_reports_sent_ < kNumAggressiveReportsSentAtStart) {
 246     // SendRtcpReport() will schedule future reports to be made if this is the
 247     // last "aggressive report."
 248     ++num_aggressive_rtcp_reports_sent_;
 249     const bool is_last_aggressive_report =
 250         (num_aggressive_rtcp_reports_sent_ == kNumAggressiveReportsSentAtStart);
 251     VLOG_IF(1, is_last_aggressive_report)
 252         << SENDER_SSRC << "Sending last aggressive report.";
 253     SendRtcpReport(is_last_aggressive_report);
 254   }
 255
 256   congestion_control_->SendFrameToTransport(
 257       frame_id, encoded_frame->data.size() * 8, last_send_time_);
 258
 259   if (send_target_playout_delay_) {
 260     encoded_frame->new_playout_delay_ms =
 261         target_playout_delay_.InMilliseconds();
 262   }
 263   transport_sender_->InsertFrame(ssrc_, *encoded_frame);
 264 }
 265
 266 void FrameSender::OnReceivedCastFeedback(const RtcpCastMessage& cast_feedback) {
 267   DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN));
 268
 269   const bool have_valid_rtt = current_round_trip_time_ > base::TimeDelta();
 270   if (have_valid_rtt) {
 271     congestion_control_->UpdateRtt(current_round_trip_time_);
 272
 273     // Having the RTT value implies the receiver sent back a receiver report
 274     // based on it having received a report from here.  Therefore, ensure this
 275     // sender stops aggressively sending reports.
 276     if (num_aggressive_rtcp_reports_sent_ < kNumAggressiveReportsSentAtStart) {
 277       VLOG(1) << SENDER_SSRC
 278               << "No longer a need to send reports aggressively (sent "
 279               << num_aggressive_rtcp_reports_sent_ << ").";
 280       num_aggressive_rtcp_reports_sent_ = kNumAggressiveReportsSentAtStart;
 281       ScheduleNextRtcpReport();
 282     }
 283   }
 284
 285   if (last_send_time_.is_null())
 286     return;  // Cannot get an ACK without having first sent a frame.
 287
 288   if (cast_feedback.missing_frames_and_packets.empty()) {
 289     OnAck(cast_feedback.ack_frame_id);
 290
 291     // We only count duplicate ACKs when we have sent newer frames.
 292     if (latest_acked_frame_id_ == cast_feedback.ack_frame_id &&
 293         latest_acked_frame_id_ != last_sent_frame_id_) {
 294       duplicate_ack_counter_++;
 295     } else {
 296       duplicate_ack_counter_ = 0;
 297     }
 298     // TODO(miu): The values "2" and "3" should be derived from configuration.
 299     if (duplicate_ack_counter_ >= 2 && duplicate_ack_counter_ % 3 == 2) {
 300       VLOG(1) << SENDER_SSRC << "Received duplicate ACK for frame "
 301               << latest_acked_frame_id_;
 302       ResendForKickstart();
 303     }
 304   } else {
 305     // Only count duplicated ACKs if there is no NACK request in between.
 306     // This is to avoid aggresive resend.
 307     duplicate_ack_counter_ = 0;
 308   }
 309
 310   base::TimeTicks now = cast_environment_->Clock()->NowTicks();
 311   congestion_control_->AckFrame(cast_feedback.ack_frame_id, now);
 312
 313   cast_environment_->Logging()->InsertFrameEvent(
 314       now,
 315       FRAME_ACK_RECEIVED,
 316       is_audio_ ? AUDIO_EVENT : VIDEO_EVENT,
 317       GetRecordedRtpTimestamp(cast_feedback.ack_frame_id),
 318       cast_feedback.ack_frame_id);
 319
 320   const bool is_acked_out_of_order =
 321       static_cast<int32>(cast_feedback.ack_frame_id -
 322                              latest_acked_frame_id_) < 0;
 323   VLOG(2) << SENDER_SSRC
 324           << "Received ACK" << (is_acked_out_of_order ? " out-of-order" : "")
 325           << " for frame " << cast_feedback.ack_frame_id;
 326   if (!is_acked_out_of_order) {
 327     // Cancel resends of acked frames.
 328     std::vector<uint32> cancel_sending_frames;
 329     while (latest_acked_frame_id_ != cast_feedback.ack_frame_id) {
 330       latest_acked_frame_id_++;
 331       cancel_sending_frames.push_back(latest_acked_frame_id_);
 332     }
 333     transport_sender_->CancelSendingFrames(ssrc_, cancel_sending_frames);
 334     latest_acked_frame_id_ = cast_feedback.ack_frame_id;
 335   }
 336 }
 337
 338 bool FrameSender::ShouldDropNextFrame(base::TimeDelta frame_duration) const {
 339   // Check that accepting the next frame won't cause more frames to become
 340   // in-flight than the system's design limit.
 341   const int count_frames_in_flight =
 342       GetUnacknowledgedFrameCount() + GetNumberOfFramesInEncoder();
 343   if (count_frames_in_flight >= kMaxUnackedFrames) {
 344     VLOG(1) << SENDER_SSRC << "Dropping: Too many frames would be in-flight.";
 345     return true;
 346   }
 347
 348   // Check that accepting the next frame won't exceed the configured maximum
 349   // frame rate, allowing for short-term bursts.
 350   base::TimeDelta duration_in_flight = GetInFlightMediaDuration();
 351   const double max_frames_in_flight =
 352       max_frame_rate_ * duration_in_flight.InSecondsF();
 353   if (count_frames_in_flight >= max_frames_in_flight + kMaxFrameBurst) {
 354     VLOG(1) << SENDER_SSRC << "Dropping: Burst threshold would be exceeded.";
 355     return true;
 356   }
 357
 358   // Check that accepting the next frame won't exceed the allowed in-flight
 359   // media duration.
 360   const base::TimeDelta duration_would_be_in_flight =
 361       duration_in_flight + frame_duration;
 362   const base::TimeDelta allowed_in_flight = GetAllowedInFlightMediaDuration();
 363   if (VLOG_IS_ON(1)) {
 364     const int64 percent = allowed_in_flight > base::TimeDelta() ?
 365         100 * duration_would_be_in_flight / allowed_in_flight : kint64max;
 366     VLOG_IF(1, percent > 50)
 367         << SENDER_SSRC
 368         << duration_in_flight.InMicroseconds() << " usec in-flight + "
 369         << frame_duration.InMicroseconds() << " usec for next frame --> "
 370         << percent << "% of allowed in-flight.";
 371   }
 372   if (duration_would_be_in_flight > allowed_in_flight) {
 373     VLOG(1) << SENDER_SSRC << "Dropping: In-flight duration would be too high.";
 374     return true;
 375   }
 376
 377   // Next frame is accepted.
 378   return false;
 379 }
 380
 381 }  // namespace cast
 382 }  // namespace media