Cast: Logging estimates clock difference based on packets

Makes the clock offset estimator more accurate and reacts faster.
This comes from issue 519163002 (but without the tracing.)

Review URL: https://codereview.chromium.org/556693002

Cr-Commit-Position: refs/heads/master@{#294325}

4 files changed, 225 insertions, 143 deletions

diff --git a/media/cast/logging/raw_event_subscriber_bundle.cc b/media/cast/logging/raw_event_subscriber_bundle.cc
index 6382a7c..5dc5f79 100644
--- a/media/cast/logging/raw_event_subscriber_bundle.cc
+++ b/media/cast/logging/raw_event_subscriber_bundle.cc
@@ -53,8 +53,7 @@ RawEventSubscriberBundle::~RawEventSubscriberBundle() {
 
 void RawEventSubscriberBundle::AddEventSubscribers(bool is_audio) {
   if (!receiver_offset_estimator_.get()) {
-    receiver_offset_estimator_.reset(
-        new ReceiverTimeOffsetEstimatorImpl(cast_environment_->Clock()));
+    receiver_offset_estimator_.reset(new ReceiverTimeOffsetEstimatorImpl);
     cast_environment_->Logging()->AddRawEventSubscriber(
         receiver_offset_estimator_.get());
   }
diff --git a/media/cast/logging/receiver_time_offset_estimator_impl.cc b/media/cast/logging/receiver_time_offset_estimator_impl.cc
index 950b367..d511654 100644
--- a/media/cast/logging/receiver_time_offset_estimator_impl.cc
+++ b/media/cast/logging/receiver_time_offset_estimator_impl.cc
@@ -12,140 +12,134 @@
 namespace media {
 namespace cast {
 
-// This should be large enough so that we can collect all 3 events before
-// the entry gets removed from the map.
-const size_t kMaxEventTimesMapSize = 100;
-
-ReceiverTimeOffsetEstimatorImpl::ReceiverTimeOffsetEstimatorImpl(
-    base::TickClock* clock)
-    : bounded_(false),
-      clock_(clock),
-      offset_bounds_valid_(false),
-      last_reset_time_(clock_->NowTicks()) {
+ReceiverTimeOffsetEstimatorImpl::BoundCalculator::BoundCalculator()
+    : has_bound_(false) {}
+ReceiverTimeOffsetEstimatorImpl::BoundCalculator::~BoundCalculator() {}
+
+void ReceiverTimeOffsetEstimatorImpl::BoundCalculator::SetSent(
+    uint32 rtp,
+    uint32 packet_id,
+    bool audio,
+    base::TimeTicks t) {
+  uint64 key = (static_cast<uint64>(rtp) << 32) | (packet_id << 1) |
+      static_cast<uint64>(audio);
+  events_[key].first = t;
+  CheckUpdate(key);
+}
+
+void ReceiverTimeOffsetEstimatorImpl::BoundCalculator::SetReceived(
+    uint32 rtp,
+    uint16 packet_id,
+    bool audio,
+    base::TimeTicks t) {
+  uint64 key = (static_cast<uint64>(rtp) << 32) | (packet_id << 1) |
+      static_cast<uint64>(audio);
+  events_[key].second = t;
+  CheckUpdate(key);
+}
+
+void ReceiverTimeOffsetEstimatorImpl::BoundCalculator::UpdateBound(
+    base::TimeTicks sent, base::TimeTicks received) {
+    base::TimeDelta delta = received - sent;
+    if (has_bound_) {
+      if (delta < bound_) {
+        bound_ = delta;
+      } else {
+        bound_ += (delta - bound_) / kClockDriftSpeed;
+      }
+    } else {
+      bound_ = delta;
+    }
+    has_bound_ = true;
+  }
+
+void ReceiverTimeOffsetEstimatorImpl::BoundCalculator::CheckUpdate(
+    uint64 key) {
+  const TimeTickPair& ticks = events_[key];
+  if (!ticks.first.is_null() && !ticks.second.is_null()) {
+    UpdateBound(ticks.first, ticks.second);
+    events_.erase(key);
+    return;
+  }
+
+  if (events_.size() > kMaxEventTimesMapSize) {
+    EventMap::iterator i = ModMapOldest(&events_);
+    if (i != events_.end()) {
+      events_.erase(i);
+    }
+  }
+}
+
+ReceiverTimeOffsetEstimatorImpl::ReceiverTimeOffsetEstimatorImpl() {
 }
 
 ReceiverTimeOffsetEstimatorImpl::~ReceiverTimeOffsetEstimatorImpl() {
   DCHECK(thread_checker_.CalledOnValidThread());
 }
 
+
 void ReceiverTimeOffsetEstimatorImpl::OnReceiveFrameEvent(
     const FrameEvent& frame_event) {
   DCHECK(thread_checker_.CalledOnValidThread());
-
-  if (frame_event.media_type != VIDEO_EVENT)
-    return;
-
-  CastLoggingEvent event = frame_event.type;
-  if (event != FRAME_ENCODED && event != FRAME_ACK_SENT &&
-      event != FRAME_ACK_RECEIVED)
-    return;
-
-  EventTimesMap::iterator it = event_times_map_.find(frame_event.rtp_timestamp);
-  if (it == event_times_map_.end()) {
-    EventTimes event_times;
-    it = event_times_map_.insert(std::make_pair(frame_event.rtp_timestamp,
-                                                event_times)).first;
-  }
-  switch (event) {
-    case FRAME_ENCODED:
-      // Encode is supposed to happen only once. If we see duplicate event,
-      // throw away the entry.
-      if (it->second.event_a_time.is_null()) {
-        it->second.event_a_time = frame_event.timestamp;
-      } else {
-        event_times_map_.erase(it);
-        return;
-      }
-      break;
+  switch (frame_event.type) {
     case FRAME_ACK_SENT:
-      if (it->second.event_b_time.is_null()) {
-        it->second.event_b_time = frame_event.timestamp;
-      } else if (it->second.event_b_time != frame_event.timestamp) {
-        // Duplicate ack sent events are normal due to RTCP redundancy,
-        // but they must have the same event timestamp.
-        event_times_map_.erase(it);
-        return;
-      }
+      lower_bound_.SetSent(frame_event.rtp_timestamp,
+                           0,
+                           frame_event.media_type == AUDIO_EVENT,
+                           frame_event.timestamp);
       break;
     case FRAME_ACK_RECEIVED:
-      // If there are duplicate ack received events, pick the one with the
-      // smallest event timestamp so we can get a better bound.
-      if (it->second.event_c_time.is_null()) {
-        it->second.event_c_time = frame_event.timestamp;
-      } else {
-        it->second.event_c_time =
-            std::min(frame_event.timestamp, it->second.event_c_time);
-      }
+      lower_bound_.SetReceived(frame_event.rtp_timestamp,
+                               0,
+                               frame_event.media_type == AUDIO_EVENT,
+                               frame_event.timestamp);
       break;
     default:
-      NOTREACHED();
-  }
-
-  if (!it->second.event_a_time.is_null() &&
-      !it->second.event_b_time.is_null() &&
-      !it->second.event_c_time.is_null()) {
-    UpdateOffsetBounds(it->second);
-    event_times_map_.erase(it);
+      // Ignored
+      break;
   }
-
-  // Keep the map size at most |kMaxEventTimesMapSize|.
-  if (event_times_map_.size() > kMaxEventTimesMapSize)
-    event_times_map_.erase(event_times_map_.begin());
 }
 
 bool ReceiverTimeOffsetEstimatorImpl::GetReceiverOffsetBounds(
     base::TimeDelta* lower_bound,
     base::TimeDelta* upper_bound) {
-  if (!bounded_)
+  if (!lower_bound_.has_bound() || !upper_bound_.has_bound())
     return false;
 
-  *lower_bound = prev_offset_lower_bound_;
-  *upper_bound = prev_offset_upper_bound_;
+  *lower_bound = -lower_bound_.bound();
+  *upper_bound = upper_bound_.bound();
+
+  // Sanitize the output, we don't want the upper bound to be
+  // lower than the lower bound, make them the same.
+  if (upper_bound < lower_bound) {
+    lower_bound += (lower_bound - upper_bound) / 2;
+    upper_bound = lower_bound;
+  }
   return true;
 }
 
 void ReceiverTimeOffsetEstimatorImpl::OnReceivePacketEvent(
     const PacketEvent& packet_event) {
-  // Not interested in packet events.
   DCHECK(thread_checker_.CalledOnValidThread());
-}
-
-void ReceiverTimeOffsetEstimatorImpl::UpdateOffsetBounds(
-    const EventTimes& event) {
-  base::TimeDelta lower_bound = event.event_b_time - event.event_c_time;
-  base::TimeDelta upper_bound = event.event_b_time - event.event_a_time;
-
-  if (offset_bounds_valid_) {
-    lower_bound = std::max(lower_bound, offset_lower_bound_);
-    upper_bound = std::min(upper_bound, offset_upper_bound_);
-  }
-
-  if (lower_bound > upper_bound) {
-    VLOG(2) << "Got bogus offset bound values [" << lower_bound.InMilliseconds()
-            << ", " << upper_bound.InMilliseconds() << "].";
-    return;
-  }
-
-  offset_lower_bound_ = lower_bound;
-  offset_upper_bound_ = upper_bound;
-  offset_bounds_valid_ = true;
-  if (!bounded_ ||
-      offset_upper_bound_ - offset_lower_bound_ <
-          base::TimeDelta::FromMilliseconds(20)) {
-    prev_offset_lower_bound_ = offset_lower_bound_;
-    prev_offset_upper_bound_ = offset_upper_bound_;
-  }
-
-  base::TimeTicks now = clock_->NowTicks();
-  if (now - last_reset_time_ > base::TimeDelta::FromSeconds(20)) {
-    last_reset_time_ = now;
-    offset_lower_bound_ = base::TimeDelta();
-    offset_upper_bound_ = base::TimeDelta();
-    offset_bounds_valid_ = false;
+  switch (packet_event.type) {
+    case PACKET_SENT_TO_NETWORK:
+      upper_bound_.SetSent(packet_event.rtp_timestamp,
+                           packet_event.packet_id,
+                           packet_event.media_type == AUDIO_EVENT,
+                           packet_event.timestamp);
+      break;
+    case PACKET_RECEIVED:
+      upper_bound_.SetReceived(packet_event.rtp_timestamp,
+                               packet_event.packet_id,
+                               packet_event.media_type == AUDIO_EVENT,
+                               packet_event.timestamp);
+      break;
+    default:
+      // Ignored
+      break;
   }
-
-  bounded_ = true;
 }
 
+
 }  // namespace cast
 }  // namespace media
diff --git a/media/cast/logging/receiver_time_offset_estimator_impl.h b/media/cast/logging/receiver_time_offset_estimator_impl.h
index f0abd29..768ccbd 100644
--- a/media/cast/logging/receiver_time_offset_estimator_impl.h
+++ b/media/cast/logging/receiver_time_offset_estimator_impl.h
@@ -5,30 +5,36 @@
 #ifndef MEDIA_CAST_LOGGING_RECEIVER_TIME_OFFSET_ESTIMATOR_IMPL_H_
 #define MEDIA_CAST_LOGGING_RECEIVER_TIME_OFFSET_ESTIMATOR_IMPL_H_
 
+#include <map>
+
 #include "base/time/time.h"
 #include "base/threading/thread_checker.h"
+#include "media/cast/common/mod_util.h"
 #include "media/cast/logging/logging_defines.h"
 #include "media/cast/logging/receiver_time_offset_estimator.h"
 
-namespace base {
-class TickClock;
-}
-
 namespace media {
 namespace cast {
 
-// This implementation listens to three types of video events:
-// 1. FRAME_ENCODED (sender side)
-// 2. FRAME_ACK_SENT (receiver side)
-// 3. FRAME_ACK_RECEIVED (sender side)
+
+// This should be large enough so that we can collect all 3 events before
+// the entry gets removed from the map.
+const size_t kMaxEventTimesMapSize = 500;
+
+// The lower, this is, the faster we adjust to clock drift.
+// (But with more jitter.)
+const size_t kClockDriftSpeed = 500;
+
+
+// This implementation listens to two pair of events
+// 1. FRAME_ACK_SENT / FRAME_ACK_RECEIVED  (receiver->sender)
+// 2. PACKET_SENT_TO_NETWORK / PACKET_RECEIVED (sender->receiver)
 // There is a causal relationship between these events in that these events
 // must happen in order. This class obtains the lower and upper bounds for
-// the offset by taking the difference of timestamps (2) - (1) and (2) - (3),
-// respectively.
-// The bound will become better as the latency between the events decreases.
+// the offset by taking the difference of timestamps.
 class ReceiverTimeOffsetEstimatorImpl : public ReceiverTimeOffsetEstimator {
  public:
-  ReceiverTimeOffsetEstimatorImpl(base::TickClock* clock);
+  ReceiverTimeOffsetEstimatorImpl();
 
   virtual ~ReceiverTimeOffsetEstimatorImpl();
 
@@ -41,28 +47,47 @@ class ReceiverTimeOffsetEstimatorImpl : public ReceiverTimeOffsetEstimator {
                                        base::TimeDelta* upper_bound) OVERRIDE;
 
  private:
-  struct EventTimes {
-    base::TimeTicks event_a_time;
-    base::TimeTicks event_b_time;
-    base::TimeTicks event_c_time;
+  // This helper uses the difference between sent and recived event
+  // to calculate an upper bound on the difference between the clocks
+  // on the sender and receiver. Note that this difference can take
+  // very large positive or negative values, but the smaller value is
+  // always the better estimate, since a receive event cannot possibly
+  // happen before a send event.  Note that we use this to calculate
+  // both upper and lower bounds by reversing the sender/receiver
+  // relationship.
+  class BoundCalculator {
+   public:
+    typedef std::pair<base::TimeTicks, base::TimeTicks> TimeTickPair;
+    typedef std::map<uint64, TimeTickPair> EventMap;
+
+    BoundCalculator();
+    ~BoundCalculator();
+    bool has_bound() const { return has_bound_; }
+    base::TimeDelta bound() const { return bound_; }
+
+    void SetSent(uint32 rtp,
+                 uint32 packet_id,
+                 bool audio,
+                 base::TimeTicks t);
+
+    void SetReceived(uint32 rtp,
+                     uint16 packet_id,
+                     bool audio,
+                     base::TimeTicks t);
+
+   private:
+    void UpdateBound(base::TimeTicks a, base::TimeTicks b);
+    void CheckUpdate(uint64 key);
+
+   private:
+    EventMap events_;
+    bool has_bound_;
+    base::TimeDelta bound_;
   };
 
-  typedef std::map<RtpTimestamp, EventTimes> EventTimesMap;
-
-  void UpdateOffsetBounds(const EventTimes& event);
-
   // Fixed size storage to store event times for recent frames.
-  EventTimesMap event_times_map_;
-
-  bool bounded_;
-  base::TickClock* clock_;  // Not owned by this class.
-
-  bool offset_bounds_valid_;
-  base::TimeDelta offset_lower_bound_;
-  base::TimeDelta offset_upper_bound_;
-  base::TimeDelta prev_offset_lower_bound_;
-  base::TimeDelta prev_offset_upper_bound_;
-  base::TimeTicks last_reset_time_;
+  BoundCalculator upper_bound_;
+  BoundCalculator lower_bound_;
 
   base::ThreadChecker thread_checker_;
   DISALLOW_COPY_AND_ASSIGN(ReceiverTimeOffsetEstimatorImpl);
diff --git a/media/cast/logging/receiver_time_offset_estimator_impl_unittest.cc b/media/cast/logging/receiver_time_offset_estimator_impl_unittest.cc
index 16f0e51..c1059ae 100644
--- a/media/cast/logging/receiver_time_offset_estimator_impl_unittest.cc
+++ b/media/cast/logging/receiver_time_offset_estimator_impl_unittest.cc
@@ -24,8 +24,7 @@ class ReceiverTimeOffsetEstimatorImplTest : public ::testing::Test {
             scoped_ptr<base::TickClock>(sender_clock_).Pass(),
             task_runner_,
             task_runner_,
-            task_runner_)),
-        estimator_(cast_environment_->Clock()) {
+            task_runner_)) {
     cast_environment_->Logging()->AddRawEventSubscriber(&estimator_);
   }
 
@@ -73,6 +72,13 @@ TEST_F(ReceiverTimeOffsetEstimatorImplTest, EstimateOffset) {
       true,
       5678);
 
+  cast_environment_->Logging()->InsertPacketEvent(
+      sender_clock_->NowTicks(),
+      PACKET_SENT_TO_NETWORK, VIDEO_EVENT,
+      rtp_timestamp,
+      frame_id,
+      56, 78, 1500);
+
   EXPECT_FALSE(estimator_.GetReceiverOffsetBounds(&lower_bound, &upper_bound));
 
   AdvanceClocks(base::TimeDelta::FromMilliseconds(10));
@@ -80,6 +86,13 @@ TEST_F(ReceiverTimeOffsetEstimatorImplTest, EstimateOffset) {
       receiver_clock_.NowTicks(), FRAME_ACK_SENT, VIDEO_EVENT,
       rtp_timestamp, frame_id);
 
+  cast_environment_->Logging()->InsertPacketEvent(
+      receiver_clock_.NowTicks(),
+      PACKET_RECEIVED, VIDEO_EVENT,
+      rtp_timestamp,
+      frame_id,
+      56, 78, 1500);
+
   EXPECT_FALSE(estimator_.GetReceiverOffsetBounds(&lower_bound, &upper_bound));
 
   AdvanceClocks(base::TimeDelta::FromMilliseconds(30));
@@ -122,6 +135,13 @@ TEST_F(ReceiverTimeOffsetEstimatorImplTest, EventCArrivesBeforeEventB) {
       true,
       5678);
 
+  cast_environment_->Logging()->InsertPacketEvent(
+      sender_clock_->NowTicks(),
+      PACKET_SENT_TO_NETWORK, VIDEO_EVENT,
+      rtp_timestamp,
+      frame_id,
+      56, 78, 1500);
+
   EXPECT_FALSE(estimator_.GetReceiverOffsetBounds(&lower_bound, &upper_bound));
 
   AdvanceClocks(base::TimeDelta::FromMilliseconds(10));
@@ -134,6 +154,13 @@ TEST_F(ReceiverTimeOffsetEstimatorImplTest, EventCArrivesBeforeEventB) {
 
   EXPECT_FALSE(estimator_.GetReceiverOffsetBounds(&lower_bound, &upper_bound));
 
+  cast_environment_->Logging()->InsertPacketEvent(
+      event_b_time,
+      PACKET_RECEIVED, VIDEO_EVENT,
+      rtp_timestamp,
+      frame_id,
+      56, 78, 1500);
+
   cast_environment_->Logging()->InsertFrameEvent(
       event_b_time, FRAME_ACK_SENT, VIDEO_EVENT, rtp_timestamp, frame_id);
 
@@ -176,6 +203,13 @@ TEST_F(ReceiverTimeOffsetEstimatorImplTest, MultipleIterations) {
       true,
       5678);
 
+  cast_environment_->Logging()->InsertPacketEvent(
+      sender_clock_->NowTicks(),
+      PACKET_SENT_TO_NETWORK, VIDEO_EVENT,
+      rtp_timestamp_a,
+      frame_id_a,
+      56, 78, 1500);
+
   AdvanceClocks(base::TimeDelta::FromMilliseconds(10));
   cast_environment_->Logging()->InsertEncodedFrameEvent(
       sender_clock_->NowTicks(),
@@ -185,11 +219,27 @@ TEST_F(ReceiverTimeOffsetEstimatorImplTest, MultipleIterations) {
       1234,
       true,
       5678);
+
+  cast_environment_->Logging()->InsertPacketEvent(
+      sender_clock_->NowTicks(),
+      PACKET_SENT_TO_NETWORK, VIDEO_EVENT,
+      rtp_timestamp_b,
+      frame_id_b,
+      56, 78, 1500);
+
   cast_environment_->Logging()->InsertFrameEvent(
       receiver_clock_.NowTicks(), FRAME_ACK_SENT, VIDEO_EVENT,
       rtp_timestamp_a, frame_id_a);
 
   AdvanceClocks(base::TimeDelta::FromMilliseconds(20));
+
+  cast_environment_->Logging()->InsertPacketEvent(
+      receiver_clock_.NowTicks(),
+      PACKET_RECEIVED, VIDEO_EVENT,
+      rtp_timestamp_b,
+      frame_id_b,
+      56, 78, 1500);
+
   cast_environment_->Logging()->InsertFrameEvent(
       receiver_clock_.NowTicks(), FRAME_ACK_SENT, VIDEO_EVENT,
       rtp_timestamp_b, frame_id_b);
@@ -218,7 +268,21 @@ TEST_F(ReceiverTimeOffsetEstimatorImplTest, MultipleIterations) {
       true,
       5678);
 
+  cast_environment_->Logging()->InsertPacketEvent(
+      sender_clock_->NowTicks(),
+      PACKET_SENT_TO_NETWORK, VIDEO_EVENT,
+      rtp_timestamp_c,
+      frame_id_c,
+      56, 78, 1500);
+
   AdvanceClocks(base::TimeDelta::FromMilliseconds(3));
+  cast_environment_->Logging()->InsertPacketEvent(
+      receiver_clock_.NowTicks(),
+      PACKET_RECEIVED, VIDEO_EVENT,
+      rtp_timestamp_c,
+      frame_id_c,
+      56, 78, 1500);
+
   cast_environment_->Logging()->InsertFrameEvent(
       receiver_clock_.NowTicks(), FRAME_ACK_SENT, VIDEO_EVENT,
       rtp_timestamp_c, frame_id_c);
@@ -233,10 +297,10 @@ TEST_F(ReceiverTimeOffsetEstimatorImplTest, MultipleIterations) {
   EXPECT_TRUE(estimator_.GetReceiverOffsetBounds(&lower_bound, &upper_bound));
   int64 lower_bound_ms = lower_bound.InMilliseconds();
   int64 upper_bound_ms = upper_bound.InMilliseconds();
-  EXPECT_EQ(95, lower_bound_ms);
-  EXPECT_EQ(103, upper_bound_ms);
-  EXPECT_GE(true_offset_ms, lower_bound_ms);
-  EXPECT_LE(true_offset_ms, upper_bound_ms);
+  EXPECT_GT(lower_bound_ms, 90);
+  EXPECT_LE(lower_bound_ms, true_offset_ms);
+  EXPECT_LT(upper_bound_ms, 150);
+  EXPECT_GT(upper_bound_ms, true_offset_ms);
 }
 
 }  // namespace cast