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}

7 files changed, 346 insertions, 38 deletions

diff --git a/media/cast/logging/raw_event_subscriber_bundle.cc b/media/cast/logging/raw_event_subscriber_bundle.cc
index 1946b6c..6382a7c 100644
--- a/media/cast/logging/raw_event_subscriber_bundle.cc
+++ b/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());
   }
diff --git a/media/cast/logging/receiver_time_offset_estimator_impl.cc b/media/cast/logging/receiver_time_offset_estimator_impl.cc
index 44d5eb0..950b367 100644
--- a/media/cast/logging/receiver_time_offset_estimator_impl.cc
+++ b/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;
 }
 
diff --git a/media/cast/logging/receiver_time_offset_estimator_impl.h b/media/cast/logging/receiver_time_offset_estimator_impl.h
index 1d0f6c8..f0abd29 100644
--- a/media/cast/logging/receiver_time_offset_estimator_impl.h
+++ b/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);
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 1cdbecf..16f0e51 100644
--- a/media/cast/logging/receiver_time_offset_estimator_impl_unittest.cc
+++ b/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_);
   }
 
diff --git a/media/cast/logging/stats_event_subscriber.cc b/media/cast/logging/stats_event_subscriber.cc
index 03c669c..b9cf265 100644
--- a/media/cast/logging/stats_event_subscriber.cc
+++ b/media/cast/logging/stats_event_subscriber.cc
@@ -4,7 +4,9 @@
 
 #include "media/cast/logging/stats_event_subscriber.h"
 
+#include "base/format_macros.h"
 #include "base/logging.h"
+#include "base/strings/stringprintf.h"
 #include "base/values.h"
 
 #define STAT_ENUM_TO_STRING(enum) \
@@ -30,6 +32,63 @@ bool IsReceiverEvent(CastLoggingEvent event) {
 
 }  // namespace
 
+StatsEventSubscriber::SimpleHistogram::SimpleHistogram(int64 min,
+                                                       int64 max,
+                                                       int64 width)
+    : min_(min), max_(max), width_(width), buckets_((max - min) / width + 2) {
+  CHECK_GT(buckets_.size(), 2u);
+  CHECK_EQ(0, (max_ - min_) % width_);
+}
+
+StatsEventSubscriber::SimpleHistogram::~SimpleHistogram() {
+}
+
+void StatsEventSubscriber::SimpleHistogram::Add(int64 sample) {
+  if (sample < min_) {
+    ++buckets_.front();
+  } else if (sample >= max_) {
+    ++buckets_.back();
+  } else {
+    size_t index = 1 + (sample - min_) / width_;
+    DCHECK_LT(index, buckets_.size());
+    ++buckets_[index];
+  }
+}
+
+void StatsEventSubscriber::SimpleHistogram::Reset() {
+  buckets_.assign(buckets_.size(), 0);
+}
+
+scoped_ptr<base::ListValue>
+StatsEventSubscriber::SimpleHistogram::GetHistogram() const {
+  scoped_ptr<base::ListValue> histo(new base::ListValue);
+
+  scoped_ptr<base::DictionaryValue> bucket(new base::DictionaryValue);
+
+  bucket->SetString("bucket", base::StringPrintf("< %" PRId64, min_));
+  bucket->SetInteger("count", buckets_.front());
+  histo->Append(bucket.release());
+
+  for (size_t i = 1; i < buckets_.size() - 1; i++) {
+    bucket.reset(new base::DictionaryValue);
+
+    int64 lower = min_ + (i - 1) * width_;
+    int64 upper = lower + width_ - 1;
+    bucket->SetString(
+        "bucket", base::StringPrintf("%" PRId64 " - %" PRId64, lower, upper));
+    bucket->SetInteger("count", buckets_[i]);
+    histo->Append(bucket.release());
+  }
+
+  bucket.reset(new base::DictionaryValue);
+
+  bucket->SetString("bucket", base::StringPrintf(">= %" PRId64, max_));
+  bucket->SetInteger("count", buckets_.back());
+  histo->Append(bucket.release());
+
+  return histo.Pass();
+}
+
 StatsEventSubscriber::StatsEventSubscriber(
     EventMediaType event_media_type,
     base::TickClock* clock,
@@ -40,11 +99,11 @@ StatsEventSubscriber::StatsEventSubscriber(
       network_latency_datapoints_(0),
       e2e_latency_datapoints_(0),
       num_frames_dropped_by_encoder_(0),
-      num_frames_late_(0) {
+      num_frames_late_(0),
+      start_time_(clock_->NowTicks()) {
   DCHECK(event_media_type == AUDIO_EVENT || event_media_type == VIDEO_EVENT);
-  base::TimeTicks now = clock_->NowTicks();
-  start_time_ = now;
-  last_response_received_time_ = base::TimeTicks();
+
+  InitHistograms();
 }
 
 StatsEventSubscriber::~StatsEventSubscriber() {
@@ -71,17 +130,26 @@ void StatsEventSubscriber::OnReceiveFrameEvent(const FrameEvent& frame_event) {
     it->second.sum_delay += frame_event.delay_delta;
   }
 
+  bool is_receiver_event = IsReceiverEvent(type);
+  UpdateFirstLastEventTime(frame_event.timestamp, is_receiver_event);
+
   if (type == FRAME_CAPTURE_BEGIN) {
     RecordFrameCaptureTime(frame_event);
+  } else if (type == FRAME_CAPTURE_END) {
+    RecordCaptureLatency(frame_event);
   } else if (type == FRAME_ENCODED) {
-    MarkAsEncoded(frame_event.rtp_timestamp);
+    RecordEncodeLatency(frame_event);
+  } else if (type == FRAME_ACK_SENT) {
+    RecordFrameTxLatency(frame_event);
   } else if (type == FRAME_PLAYOUT) {
     RecordE2ELatency(frame_event);
-    if (frame_event.delay_delta <= base::TimeDelta())
+    base::TimeDelta delay_delta = frame_event.delay_delta;
+    histograms_[PLAYOUT_DELAY_MS_HISTO]->Add(delay_delta.InMillisecondsF());
+    if (delay_delta <= base::TimeDelta())
       num_frames_late_++;
   }
 
-  if (IsReceiverEvent(type))
+  if (is_receiver_event)
     UpdateLastResponseTime(frame_event.timestamp);
 }
 
@@ -104,6 +172,9 @@ void StatsEventSubscriber::OnReceivePacketEvent(
     it->second.sum_size += packet_event.size;
   }
 
+  bool is_receiver_event = IsReceiverEvent(type);
+  UpdateFirstLastEventTime(packet_event.timestamp, is_receiver_event);
+
   if (type == PACKET_SENT_TO_NETWORK ||
       type == PACKET_RECEIVED) {
     RecordNetworkLatency(packet_event);
@@ -113,10 +184,31 @@ void StatsEventSubscriber::OnReceivePacketEvent(
     ErasePacketSentTime(packet_event);
   }
 
-  if (IsReceiverEvent(type))
+  if (is_receiver_event)
     UpdateLastResponseTime(packet_event.timestamp);
 }
 
+void StatsEventSubscriber::UpdateFirstLastEventTime(base::TimeTicks timestamp,
+                                                    bool is_receiver_event) {
+  if (is_receiver_event) {
+    base::TimeDelta receiver_offset;
+    if (!GetReceiverOffset(&receiver_offset))
+      return;
+    timestamp -= receiver_offset;
+  }
+
+  if (first_event_time_.is_null()) {
+    first_event_time_ = timestamp;
+  } else {
+    first_event_time_ = std::min(first_event_time_, timestamp);
+  }
+  if (last_event_time_.is_null()) {
+    last_event_time_ = timestamp;
+  } else {
+    last_event_time_ = std::max(last_event_time_, timestamp);
+  }
+}
+
 scoped_ptr<base::DictionaryValue> StatsEventSubscriber::GetStats() const {
   StatsMap stats_map;
   GetStatsInternal(&stats_map);
@@ -127,6 +219,12 @@ scoped_ptr<base::DictionaryValue> StatsEventSubscriber::GetStats() const {
        ++it) {
     stats->SetDouble(CastStatToString(it->first), it->second);
   }
+  for (HistogramMap::const_iterator it = histograms_.begin();
+       it != histograms_.end();
+       ++it) {
+    stats->Set(CastStatToString(it->first),
+               it->second->GetHistogram().release());
+  }
 
   ret->Set(event_media_type_ == AUDIO_EVENT ? "audio" : "video",
            stats.release());
@@ -145,10 +243,17 @@ void StatsEventSubscriber::Reset() {
   e2e_latency_datapoints_ = 0;
   num_frames_dropped_by_encoder_ = 0;
   num_frames_late_ = 0;
-  recent_captured_frames_.clear();
+  recent_frame_infos_.clear();
   packet_sent_times_.clear();
   start_time_ = clock_->NowTicks();
   last_response_received_time_ = base::TimeTicks();
+  for (HistogramMap::iterator it = histograms_.begin(); it != histograms_.end();
+       ++it) {
+    it->second->Reset();
+  }
+
+  first_event_time_ = base::TimeTicks();
+  last_event_time_ = base::TimeTicks();
 }
 
 // static
@@ -172,11 +277,34 @@ const char* StatsEventSubscriber::CastStatToString(CastStat stat) {
     STAT_ENUM_TO_STRING(NUM_PACKETS_SENT);
     STAT_ENUM_TO_STRING(NUM_PACKETS_RETRANSMITTED);
     STAT_ENUM_TO_STRING(NUM_PACKETS_RTX_REJECTED);
+    STAT_ENUM_TO_STRING(FIRST_EVENT_TIME_MS);
+    STAT_ENUM_TO_STRING(LAST_EVENT_TIME_MS);
+    STAT_ENUM_TO_STRING(CAPTURE_LATENCY_MS_HISTO);
+    STAT_ENUM_TO_STRING(ENCODE_LATENCY_MS_HISTO);
+    STAT_ENUM_TO_STRING(PACKET_LATENCY_MS_HISTO);
+    STAT_ENUM_TO_STRING(FRAME_LATENCY_MS_HISTO);
+    STAT_ENUM_TO_STRING(PLAYOUT_DELAY_MS_HISTO);
   }
   NOTREACHED();
   return "";
 }
 
+const int kMaxLatencyBucketMs = 800;
+const int kBucketWidthMs = 20;
+
+void StatsEventSubscriber::InitHistograms() {
+  histograms_[CAPTURE_LATENCY_MS_HISTO].reset(
+      new SimpleHistogram(0, kMaxLatencyBucketMs, kBucketWidthMs));
+  histograms_[ENCODE_LATENCY_MS_HISTO].reset(
+      new SimpleHistogram(0, kMaxLatencyBucketMs, kBucketWidthMs));
+  histograms_[PACKET_LATENCY_MS_HISTO].reset(
+      new SimpleHistogram(0, kMaxLatencyBucketMs, kBucketWidthMs));
+  histograms_[FRAME_LATENCY_MS_HISTO].reset(
+      new SimpleHistogram(0, kMaxLatencyBucketMs, kBucketWidthMs));
+  histograms_[PLAYOUT_DELAY_MS_HISTO].reset(
+      new SimpleHistogram(0, kMaxLatencyBucketMs, kBucketWidthMs));
+}
+
 void StatsEventSubscriber::GetStatsInternal(StatsMap* stats_map) const {
   DCHECK(thread_checker_.CalledOnValidThread());
 
@@ -231,6 +359,16 @@ void StatsEventSubscriber::GetStatsInternal(StatsMap* stats_map) const {
   stats_map->insert(std::make_pair(NUM_FRAMES_DROPPED_BY_ENCODER,
                                    num_frames_dropped_by_encoder_));
   stats_map->insert(std::make_pair(NUM_FRAMES_LATE, num_frames_late_));
+  if (!first_event_time_.is_null()) {
+    stats_map->insert(std::make_pair(
+        FIRST_EVENT_TIME_MS,
+        (first_event_time_ - base::TimeTicks::UnixEpoch()).InMillisecondsF()));
+  }
+  if (!last_event_time_.is_null()) {
+    stats_map->insert(std::make_pair(
+        LAST_EVENT_TIME_MS,
+        (last_event_time_ - base::TimeTicks::UnixEpoch()).InMillisecondsF()));
+  }
 }
 
 bool StatsEventSubscriber::GetReceiverOffset(base::TimeDelta* offset) {
@@ -245,22 +383,83 @@ bool StatsEventSubscriber::GetReceiverOffset(base::TimeDelta* offset) {
   return true;
 }
 
+void StatsEventSubscriber::MaybeInsertFrameInfo(RtpTimestamp rtp_timestamp,
+                                                const FrameInfo& frame_info) {
+  // No need to insert if |rtp_timestamp| is the smaller than every key in the
+  // map as it is just going to get erased anyway.
+  if (recent_frame_infos_.size() == kMaxFrameInfoMapSize &&
+      rtp_timestamp < recent_frame_infos_.begin()->first) {
+    return;
+  }
+
+  recent_frame_infos_.insert(std::make_pair(rtp_timestamp, frame_info));
+
+  if (recent_frame_infos_.size() >= kMaxFrameInfoMapSize) {
+    FrameInfoMap::iterator erase_it = recent_frame_infos_.begin();
+    if (erase_it->second.encode_time.is_null())
+      num_frames_dropped_by_encoder_++;
+    recent_frame_infos_.erase(erase_it);
+  }
+}
+
 void StatsEventSubscriber::RecordFrameCaptureTime(
     const FrameEvent& frame_event) {
-  recent_captured_frames_.insert(std::make_pair(
-      frame_event.rtp_timestamp, FrameInfo(frame_event.timestamp)));
-  if (recent_captured_frames_.size() > kMaxFrameInfoMapSize) {
-    FrameInfoMap::iterator erase_it = recent_captured_frames_.begin();
-    if (!erase_it->second.encoded)
-      num_frames_dropped_by_encoder_++;
-    recent_captured_frames_.erase(erase_it);
+  FrameInfo frame_info;
+  frame_info.capture_time = frame_event.timestamp;
+  MaybeInsertFrameInfo(frame_event.rtp_timestamp, frame_info);
+}
+
+void StatsEventSubscriber::RecordCaptureLatency(const FrameEvent& frame_event) {
+  FrameInfoMap::iterator it =
+      recent_frame_infos_.find(frame_event.rtp_timestamp);
+  if (it == recent_frame_infos_.end())
+    return;
+
+  if (!it->second.capture_time.is_null()) {
+    double capture_latency_ms =
+        (it->second.capture_time - frame_event.timestamp).InMillisecondsF();
+    histograms_[CAPTURE_LATENCY_MS_HISTO]->Add(capture_latency_ms);
   }
+
+  it->second.capture_end_time = frame_event.timestamp;
 }
 
-void StatsEventSubscriber::MarkAsEncoded(RtpTimestamp rtp_timestamp) {
-  FrameInfoMap::iterator it = recent_captured_frames_.find(rtp_timestamp);
-  if (it != recent_captured_frames_.end())
-    it->second.encoded = true;
+void StatsEventSubscriber::RecordEncodeLatency(const FrameEvent& frame_event) {
+  FrameInfoMap::iterator it =
+      recent_frame_infos_.find(frame_event.rtp_timestamp);
+  if (it == recent_frame_infos_.end()) {
+    FrameInfo frame_info;
+    frame_info.encode_time = frame_event.timestamp;
+    MaybeInsertFrameInfo(frame_event.rtp_timestamp, frame_info);
+    return;
+  }
+
+  if (!it->second.capture_end_time.is_null()) {
+    double encode_latency_ms =
+        (frame_event.timestamp - it->second.capture_end_time).InMillisecondsF();
+    histograms_[ENCODE_LATENCY_MS_HISTO]->Add(encode_latency_ms);
+  }
+
+  it->second.encode_time = frame_event.timestamp;
+}
+
+void StatsEventSubscriber::RecordFrameTxLatency(const FrameEvent& frame_event) {
+  FrameInfoMap::iterator it =
+      recent_frame_infos_.find(frame_event.rtp_timestamp);
+  if (it == recent_frame_infos_.end())
+    return;
+
+  if (it->second.encode_time.is_null())
+    return;
+
+  base::TimeDelta receiver_offset;
+  if (!GetReceiverOffset(&receiver_offset))
+    return;
+
+  base::TimeTicks sender_time = frame_event.timestamp - receiver_offset;
+  double frame_tx_latency_ms =
+      (sender_time - it->second.encode_time).InMillisecondsF();
+  histograms_[FRAME_LATENCY_MS_HISTO]->Add(frame_tx_latency_ms);
 }
 
 void StatsEventSubscriber::RecordE2ELatency(const FrameEvent& frame_event) {
@@ -269,8 +468,8 @@ void StatsEventSubscriber::RecordE2ELatency(const FrameEvent& frame_event) {
     return;
 
   FrameInfoMap::iterator it =
-      recent_captured_frames_.find(frame_event.rtp_timestamp);
-  if (it == recent_captured_frames_.end())
+      recent_frame_infos_.find(frame_event.rtp_timestamp);
+  if (it == recent_frame_infos_.end())
     return;
 
   // Playout time is event time + playout delay.
@@ -306,8 +505,6 @@ void StatsEventSubscriber::RecordNetworkLatency(
       std::make_pair(packet_event.rtp_timestamp, packet_event.packet_id));
   PacketEventTimeMap::iterator it = packet_sent_times_.find(key);
   if (it == packet_sent_times_.end()) {
-    std::pair<RtpTimestamp, uint16> key(
-        std::make_pair(packet_event.rtp_timestamp, packet_event.packet_id));
     std::pair<base::TimeTicks, CastLoggingEvent> value =
         std::make_pair(packet_event.timestamp, packet_event.type);
     packet_sent_times_.insert(std::make_pair(key, value));
@@ -333,9 +530,14 @@ void StatsEventSubscriber::RecordNetworkLatency(
     if (match) {
       // Subtract by offset.
       packet_received_time -= receiver_offset;
+      base::TimeDelta latency_delta = packet_received_time - packet_sent_time;
 
-      total_network_latency_ += packet_received_time - packet_sent_time;
+      total_network_latency_ += latency_delta;
       network_latency_datapoints_++;
+
+      histograms_[PACKET_LATENCY_MS_HISTO]->Add(
+          latency_delta.InMillisecondsF());
+
       packet_sent_times_.erase(it);
     }
   }
@@ -447,8 +649,7 @@ StatsEventSubscriber::PacketLogStats::PacketLogStats()
     : event_counter(0), sum_size(0) {}
 StatsEventSubscriber::PacketLogStats::~PacketLogStats() {}
 
-StatsEventSubscriber::FrameInfo::FrameInfo(base::TimeTicks capture_time)
-    : capture_time(capture_time), encoded(false) {
+StatsEventSubscriber::FrameInfo::FrameInfo() : encoded(false) {
 }
 StatsEventSubscriber::FrameInfo::~FrameInfo() {
 }
diff --git a/media/cast/logging/stats_event_subscriber.h b/media/cast/logging/stats_event_subscriber.h
index 06ceaca9..7662e60 100644
--- a/media/cast/logging/stats_event_subscriber.h
+++ b/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);
diff --git a/media/cast/logging/stats_event_subscriber_unittest.cc b/media/cast/logging/stats_event_subscriber_unittest.cc
index fe03bc6..95616b1 100644
--- a/media/cast/logging/stats_event_subscriber_unittest.cc
+++ b/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) {