Cast logging: Additional stats for getStats() API.

Histograms in json format:
* capture time
* encode time
* packet latency
* frame latency
* playout delay

- Duration in ms
- first event unix time
- last event unix time

Also improved ReceiverTimeOffsetEstimatorImpl to re-estimate every 30 seconds to account for unknown amount of clock drift between sender and receiver.
BUG=403921

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

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

media/cast/logging/raw_event_subscriber_bundle.cc

@@ -54,7 +54,7 @@ RawEventSubscriberBundle::~RawEventSubscriberBundle() {
 void RawEventSubscriberBundle::AddEventSubscribers(bool is_audio) {
   if (!receiver_offset_estimator_.get()) {
     receiver_offset_estimator_.reset(
-        new ReceiverTimeOffsetEstimatorImpl);
+        new ReceiverTimeOffsetEstimatorImpl(cast_environment_->Clock()));
     cast_environment_->Logging()->AddRawEventSubscriber(
         receiver_offset_estimator_.get());
   }

media/cast/logging/receiver_time_offset_estimator_impl.cc

@@ -6,6 +6,7 @@
 #include <utility>
 
 #include "base/logging.h"
+#include "base/time/tick_clock.h"
 #include "media/cast/logging/receiver_time_offset_estimator_impl.h"
 
 namespace media {
@@ -15,8 +16,13 @@ namespace cast {
 // the entry gets removed from the map.
 const size_t kMaxEventTimesMapSize = 100;
 
-ReceiverTimeOffsetEstimatorImpl::ReceiverTimeOffsetEstimatorImpl()
-    : bounded_(false) {}
+ReceiverTimeOffsetEstimatorImpl::ReceiverTimeOffsetEstimatorImpl(
+    base::TickClock* clock)
+    : bounded_(false),
+      clock_(clock),
+      offset_bounds_valid_(false),
+      last_reset_time_(clock_->NowTicks()) {
+}
 
 ReceiverTimeOffsetEstimatorImpl::~ReceiverTimeOffsetEstimatorImpl() {
   DCHECK(thread_checker_.CalledOnValidThread());
@@ -93,8 +99,8 @@ bool ReceiverTimeOffsetEstimatorImpl::GetReceiverOffsetBounds(
   if (!bounded_)
     return false;
 
-  *lower_bound = offset_lower_bound_;
-  *upper_bound = offset_upper_bound_;
+  *lower_bound = prev_offset_lower_bound_;
+  *upper_bound = prev_offset_upper_bound_;
   return true;
 }
 
@@ -109,7 +115,7 @@ void ReceiverTimeOffsetEstimatorImpl::UpdateOffsetBounds(
   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 (bounded_) {
+  if (offset_bounds_valid_) {
     lower_bound = std::max(lower_bound, offset_lower_bound_);
     upper_bound = std::min(upper_bound, offset_upper_bound_);
   }
@@ -122,6 +128,22 @@ void ReceiverTimeOffsetEstimatorImpl::UpdateOffsetBounds(
 
   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;
+  }
+
   bounded_ = true;
 }
 

media/cast/logging/receiver_time_offset_estimator_impl.h

@@ -10,6 +10,10 @@
 #include "media/cast/logging/logging_defines.h"
 #include "media/cast/logging/receiver_time_offset_estimator.h"
 
+namespace base {
+class TickClock;
+}
+
 namespace media {
 namespace cast {
 
@@ -24,7 +28,7 @@ namespace cast {
 // The bound will become better as the latency between the events decreases.
 class ReceiverTimeOffsetEstimatorImpl : public ReceiverTimeOffsetEstimator {
  public:
-  ReceiverTimeOffsetEstimatorImpl();
+  ReceiverTimeOffsetEstimatorImpl(base::TickClock* clock);
 
   virtual ~ReceiverTimeOffsetEstimatorImpl();
 
@@ -51,8 +55,14 @@ class ReceiverTimeOffsetEstimatorImpl : public ReceiverTimeOffsetEstimator {
   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_;
 
   base::ThreadChecker thread_checker_;
   DISALLOW_COPY_AND_ASSIGN(ReceiverTimeOffsetEstimatorImpl);

media/cast/logging/receiver_time_offset_estimator_impl_unittest.cc

@@ -24,7 +24,8 @@ class ReceiverTimeOffsetEstimatorImplTest : public ::testing::Test {
             scoped_ptr<base::TickClock>(sender_clock_).Pass(),
             task_runner_,
             task_runner_,
-            task_runner_)) {
+            task_runner_)),
+        estimator_(cast_environment_->Clock()) {
     cast_environment_->Logging()->AddRawEventSubscriber(&estimator_);
   }
 

media/cast/logging/stats_event_subscriber.h

@@ -6,6 +6,7 @@
 #define MEDIA_CAST_LOGGING_STATS_EVENT_SUBSCRIBER_H_
 
 #include "base/gtest_prod_util.h"
+#include "base/memory/linked_ptr.h"
 #include "base/memory/scoped_ptr.h"
 #include "base/threading/thread_checker.h"
 #include "base/time/tick_clock.h"
@@ -15,6 +16,7 @@
 
 namespace base {
 class DictionaryValue;
+class ListValue;
 }
 
 namespace media {
@@ -76,6 +78,34 @@ class StatsEventSubscriber : public RawEventSubscriber {
     size_t sum_size;
   };
 
+  class SimpleHistogram {
+   public:
+    // This will create N+2 buckets where N = (max - min) / width:
+    // Underflow bucket: < min
+    // Bucket 0: [min, min + width - 1]
+    // Bucket 1: [min + width, min + 2 * width - 1]
+    // ...
+    // Bucket N-1: [max - width, max - 1]
+    // Overflow bucket: >= max
+    // |min| must be less than |max|.
+    // |width| must divide |max - min| evenly.
+    SimpleHistogram(int64 min, int64 max, int64 width);
+
+    ~SimpleHistogram();
+
+    void Add(int64 sample);
+
+    void Reset();
+
+    scoped_ptr<base::ListValue> GetHistogram() const;
+
+   private:
+    int64 min_;
+    int64 max_;
+    int64 width_;
+    std::vector<int> buckets_;
+  };
+
   enum CastStat {
     // Capture frame rate.
     CAPTURE_FPS,
@@ -116,17 +146,31 @@ class StatsEventSubscriber : public RawEventSubscriber {
     NUM_PACKETS_RETRANSMITTED,
     // Number of packets that had their retransmission cancelled.
     NUM_PACKETS_RTX_REJECTED,
+    // Unix time in milliseconds of first event since reset.
+    FIRST_EVENT_TIME_MS,
+    // Unix time in milliseconds of last event since reset.
+    LAST_EVENT_TIME_MS,
+
+    // Histograms
+    CAPTURE_LATENCY_MS_HISTO,
+    ENCODE_LATENCY_MS_HISTO,
+    PACKET_LATENCY_MS_HISTO,
+    FRAME_LATENCY_MS_HISTO,
+    PLAYOUT_DELAY_MS_HISTO
   };
 
   struct FrameInfo {
-    explicit FrameInfo(base::TimeTicks capture_time);
+    FrameInfo();
     ~FrameInfo();
 
     base::TimeTicks capture_time;
+    base::TimeTicks capture_end_time;
+    base::TimeTicks encode_time;
     bool encoded;
   };
 
   typedef std::map<CastStat, double> StatsMap;
+  typedef std::map<CastStat, linked_ptr<SimpleHistogram> > HistogramMap;
   typedef std::map<RtpTimestamp, FrameInfo> FrameInfoMap;
   typedef std::map<
       std::pair<RtpTimestamp, uint16>,
@@ -137,12 +181,20 @@ class StatsEventSubscriber : public RawEventSubscriber {
 
   static const char* CastStatToString(CastStat stat);
 
+  void InitHistograms();
+
   // Assigns |stats_map| with stats data. Used for testing.
   void GetStatsInternal(StatsMap* stats_map) const;
 
+  void UpdateFirstLastEventTime(base::TimeTicks timestamp,
+                                bool is_receiver_event);
   bool GetReceiverOffset(base::TimeDelta* offset);
+  void MaybeInsertFrameInfo(RtpTimestamp rtp_timestamp,
+                            const FrameInfo& frame_info);
   void RecordFrameCaptureTime(const FrameEvent& frame_event);
-  void MarkAsEncoded(RtpTimestamp rtp_timestamp);
+  void RecordCaptureLatency(const FrameEvent& frame_event);
+  void RecordEncodeLatency(const FrameEvent& frame_event);
+  void RecordFrameTxLatency(const FrameEvent& frame_event);
   void RecordE2ELatency(const FrameEvent& frame_event);
   void RecordPacketSentTime(const PacketEvent& packet_event);
   void ErasePacketSentTime(const PacketEvent& packet_event);
@@ -189,13 +241,17 @@ class StatsEventSubscriber : public RawEventSubscriber {
   int num_frames_late_;
 
   // Fixed size map to record when recent frames were captured and other info.
-  FrameInfoMap recent_captured_frames_;
+  FrameInfoMap recent_frame_infos_;
 
   // Fixed size map to record when recent packets were sent.
   PacketEventTimeMap packet_sent_times_;
 
   // Sender time assigned on creation and |Reset()|.
   base::TimeTicks start_time_;
+  base::TimeTicks first_event_time_;
+  base::TimeTicks last_event_time_;
+
+  HistogramMap histograms_;
 
   base::ThreadChecker thread_checker_;
   DISALLOW_COPY_AND_ASSIGN(StatsEventSubscriber);

media/cast/logging/stats_event_subscriber_unittest.cc

@@ -140,6 +140,9 @@ TEST_F(StatsEventSubscriberTest, Encode) {
   uint32 frame_id = 0;
   int num_frames = 10;
   base::TimeTicks start_time = sender_clock_->NowTicks();
+  AdvanceClocks(base::TimeDelta::FromMicroseconds(35678));
+  base::TimeTicks first_event_time = sender_clock_->NowTicks();
+  base::TimeTicks last_event_time;
   int total_size = 0;
   for (int i = 0; i < num_frames; i++) {
     int size = 1000 + base::RandInt(-100, 100);
@@ -152,6 +155,7 @@ TEST_F(StatsEventSubscriberTest, Encode) {
         size,
         true,
         5678);
+    last_event_time = sender_clock_->NowTicks();
 
     AdvanceClocks(base::TimeDelta::FromMicroseconds(35678));
     rtp_timestamp += 90;
@@ -177,6 +181,20 @@ TEST_F(StatsEventSubscriberTest, Encode) {
 
   EXPECT_DOUBLE_EQ(it->second,
               static_cast<double>(total_size) / duration.InMillisecondsF() * 8);
+
+  it = stats_map.find(StatsEventSubscriber::FIRST_EVENT_TIME_MS);
+  ASSERT_TRUE(it != stats_map.end());
+
+  EXPECT_DOUBLE_EQ(
+      it->second,
+      (first_event_time - base::TimeTicks::UnixEpoch()).InMillisecondsF());
+
+  it = stats_map.find(StatsEventSubscriber::LAST_EVENT_TIME_MS);
+  ASSERT_TRUE(it != stats_map.end());
+
+  EXPECT_DOUBLE_EQ(
+      it->second,
+      (last_event_time - base::TimeTicks::UnixEpoch()).InMillisecondsF());
 }
 
 TEST_F(StatsEventSubscriberTest, Decode) {

media/cast/test/sender.cc

@@ -355,7 +355,8 @@ int main(int argc, char** argv) {
 
   // Subscribers for stats.
   scoped_ptr<media::cast::ReceiverTimeOffsetEstimatorImpl> offset_estimator(
-      new media::cast::ReceiverTimeOffsetEstimatorImpl);
+      new media::cast::ReceiverTimeOffsetEstimatorImpl(
+          cast_environment->Clock()));
   cast_environment->Logging()->AddRawEventSubscriber(offset_estimator.get());
   scoped_ptr<media::cast::StatsEventSubscriber> video_stats_subscriber(
       new media::cast::StatsEventSubscriber(media::cast::VIDEO_EVENT,