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
 264   TRACE_EVENT_ASYNC_BEGIN1("cast.stream",
 265       is_audio_ ? "Audio Transport" : "Video Transport",
 266       frame_id,
 267       "rtp_timestamp", encoded_frame->rtp_timestamp);
 268   transport_sender_->InsertFrame(ssrc_, *encoded_frame);
 269 }
 270
 271 void FrameSender::OnReceivedCastFeedback(const RtcpCastMessage& cast_feedback) {
 272   DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN));
 273
 274   const bool have_valid_rtt = current_round_trip_time_ > base::TimeDelta();
 275   if (have_valid_rtt) {
 276     congestion_control_->UpdateRtt(current_round_trip_time_);
 277
 278     // Having the RTT value implies the receiver sent back a receiver report
 279     // based on it having received a report from here.  Therefore, ensure this
 280     // sender stops aggressively sending reports.
 281     if (num_aggressive_rtcp_reports_sent_ < kNumAggressiveReportsSentAtStart) {
 282       VLOG(1) << SENDER_SSRC
 283               << "No longer a need to send reports aggressively (sent "
 284               << num_aggressive_rtcp_reports_sent_ << ").";
 285       num_aggressive_rtcp_reports_sent_ = kNumAggressiveReportsSentAtStart;
 286       ScheduleNextRtcpReport();
 287     }
 288   }
 289
 290   if (last_send_time_.is_null())
 291     return;  // Cannot get an ACK without having first sent a frame.
 292
 293   if (cast_feedback.missing_frames_and_packets.empty()) {
 294     OnAck(cast_feedback.ack_frame_id);
 295
 296     if (latest_acked_frame_id_ == cast_feedback.ack_frame_id) {
 297       VLOG(1) << SENDER_SSRC << "Received duplicate ACK for frame "
 298               << latest_acked_frame_id_;
 299       TRACE_EVENT_INSTANT2(
 300         "cast.stream", "Duplicate ACK", TRACE_EVENT_SCOPE_THREAD,
 301         "ack_frame_id", cast_feedback.ack_frame_id,
 302         "last_sent_frame_id", last_sent_frame_id_);
 303     }
 304     // We only count duplicate ACKs when we have sent newer frames.
 305     if (latest_acked_frame_id_ == cast_feedback.ack_frame_id &&
 306         latest_acked_frame_id_ != last_sent_frame_id_) {
 307       duplicate_ack_counter_++;
 308     } else {
 309       duplicate_ack_counter_ = 0;
 310     }
 311     // TODO(miu): The values "2" and "3" should be derived from configuration.
 312     if (duplicate_ack_counter_ >= 2 && duplicate_ack_counter_ % 3 == 2) {
 313       ResendForKickstart();
 314     }
 315   } else {
 316     // Only count duplicated ACKs if there is no NACK request in between.
 317     // This is to avoid aggresive resend.
 318     duplicate_ack_counter_ = 0;
 319   }
 320
 321   base::TimeTicks now = cast_environment_->Clock()->NowTicks();
 322   congestion_control_->AckFrame(cast_feedback.ack_frame_id, now);
 323
 324   cast_environment_->Logging()->InsertFrameEvent(
 325       now,
 326       FRAME_ACK_RECEIVED,
 327       is_audio_ ? AUDIO_EVENT : VIDEO_EVENT,
 328       GetRecordedRtpTimestamp(cast_feedback.ack_frame_id),
 329       cast_feedback.ack_frame_id);
 330
 331   const bool is_acked_out_of_order =
 332       static_cast<int32>(cast_feedback.ack_frame_id -
 333                              latest_acked_frame_id_) < 0;
 334   VLOG(2) << SENDER_SSRC
 335           << "Received ACK" << (is_acked_out_of_order ? " out-of-order" : "")
 336           << " for frame " << cast_feedback.ack_frame_id;
 337   if (is_acked_out_of_order) {
 338     TRACE_EVENT_INSTANT2(
 339         "cast.stream", "ACK out of order", TRACE_EVENT_SCOPE_THREAD,
 340         "ack_frame_id", cast_feedback.ack_frame_id,
 341         "latest_acked_frame_id", latest_acked_frame_id_);
 342   } else {
 343     // Cancel resends of acked frames.
 344     std::vector<uint32> cancel_sending_frames;
 345     while (latest_acked_frame_id_ != cast_feedback.ack_frame_id) {
 346       latest_acked_frame_id_++;
 347       cancel_sending_frames.push_back(latest_acked_frame_id_);
 348       // This is a good place to match the trace for frame ids
 349       // since this ensures we not only track frame ids that are
 350       // implicitly ACKed, but also handles duplicate ACKs
 351       TRACE_EVENT_ASYNC_END1("cast.stream",
 352           is_audio_ ? "Audio Transport" : "Video Transport",
 353           cast_feedback.ack_frame_id,
 354           "RTT_usecs", current_round_trip_time_.InMicroseconds());
 355     }
 356     transport_sender_->CancelSendingFrames(ssrc_, cancel_sending_frames);
 357     latest_acked_frame_id_ = cast_feedback.ack_frame_id;
 358   }
 359 }
 360
 361 bool FrameSender::ShouldDropNextFrame(base::TimeDelta frame_duration) const {
 362   // Check that accepting the next frame won't cause more frames to become
 363   // in-flight than the system's design limit.
 364   const int count_frames_in_flight =
 365       GetUnacknowledgedFrameCount() + GetNumberOfFramesInEncoder();
 366   if (count_frames_in_flight >= kMaxUnackedFrames) {
 367     VLOG(1) << SENDER_SSRC << "Dropping: Too many frames would be in-flight.";
 368     return true;
 369   }
 370
 371   // Check that accepting the next frame won't exceed the configured maximum
 372   // frame rate, allowing for short-term bursts.
 373   base::TimeDelta duration_in_flight = GetInFlightMediaDuration();
 374   const double max_frames_in_flight =
 375       max_frame_rate_ * duration_in_flight.InSecondsF();
 376   if (count_frames_in_flight >= max_frames_in_flight + kMaxFrameBurst) {
 377     VLOG(1) << SENDER_SSRC << "Dropping: Burst threshold would be exceeded.";
 378     return true;
 379   }
 380
 381   // Check that accepting the next frame won't exceed the allowed in-flight
 382   // media duration.
 383   const base::TimeDelta duration_would_be_in_flight =
 384       duration_in_flight + frame_duration;
 385   const base::TimeDelta allowed_in_flight = GetAllowedInFlightMediaDuration();
 386   if (VLOG_IS_ON(1)) {
 387     const int64 percent = allowed_in_flight > base::TimeDelta() ?
 388         100 * duration_would_be_in_flight / allowed_in_flight : kint64max;
 389     VLOG_IF(1, percent > 50)
 390         << SENDER_SSRC
 391         << duration_in_flight.InMicroseconds() << " usec in-flight + "
 392         << frame_duration.InMicroseconds() << " usec for next frame --> "
 393         << percent << "% of allowed in-flight.";
 394   }
 395   if (duration_would_be_in_flight > allowed_in_flight) {
 396     VLOG(1) << SENDER_SSRC << "Dropping: In-flight duration would be too high.";
 397     return true;
 398   }
 399
 400   // Next frame is accepted.
 401   return false;
 402 }
 403
 404 }  // namespace cast
 405 }  // namespace media