Update To 11.40.268.0
[platform/framework/web/crosswalk.git] / src / media / cast / logging / stats_event_subscriber.cc
index b22812e..c42affa 100644 (file)
@@ -101,7 +101,12 @@ StatsEventSubscriber::StatsEventSubscriber(
     : event_media_type_(event_media_type),
       clock_(clock),
       offset_estimator_(offset_estimator),
+      capture_latency_datapoints_(0),
+      encode_time_datapoints_(0),
+      queueing_latency_datapoints_(0),
       network_latency_datapoints_(0),
+      packet_latency_datapoints_(0),
+      frame_latency_datapoints_(0),
       e2e_latency_datapoints_(0),
       num_frames_dropped_by_encoder_(0),
       num_frames_late_(0),
@@ -150,7 +155,9 @@ void StatsEventSubscriber::OnReceiveFrameEvent(const FrameEvent& frame_event) {
     RecordE2ELatency(frame_event);
     base::TimeDelta delay_delta = frame_event.delay_delta;
     histograms_[PLAYOUT_DELAY_MS_HISTO]->Add(delay_delta.InMillisecondsF());
-    if (delay_delta <= base::TimeDelta())
+
+    // Positive delay_delta means the frame is late.
+    if (delay_delta > base::TimeDelta())
       num_frames_late_++;
   }
 
@@ -182,7 +189,7 @@ void StatsEventSubscriber::OnReceivePacketEvent(
 
   if (type == PACKET_SENT_TO_NETWORK ||
       type == PACKET_RECEIVED) {
-    RecordNetworkLatency(packet_event);
+    RecordPacketRelatedLatencies(packet_event);
   } else if (type == PACKET_RETRANSMITTED) {
     // We only measure network latency using packets that doesn't have to be
     // retransmitted as there is precisely one sent-receive timestamp pairs.
@@ -226,6 +233,8 @@ scoped_ptr<base::DictionaryValue> StatsEventSubscriber::GetStats() const {
     stats->SetDouble(CastStatToString(it->first),
                      round(it->second * 1000.0) / 1000.0);
   }
+
+  // Populate all histograms.
   for (HistogramMap::const_iterator it = histograms_.begin();
        it != histograms_.end();
        ++it) {
@@ -244,8 +253,18 @@ void StatsEventSubscriber::Reset() {
 
   frame_stats_.clear();
   packet_stats_.clear();
+  total_capture_latency_ = base::TimeDelta();
+  capture_latency_datapoints_ = 0;
+  total_encode_time_ = base::TimeDelta();
+  encode_time_datapoints_ = 0;
+  total_queueing_latency_ = base::TimeDelta();
+  queueing_latency_datapoints_ = 0;
   total_network_latency_ = base::TimeDelta();
   network_latency_datapoints_ = 0;
+  total_packet_latency_ = base::TimeDelta();
+  packet_latency_datapoints_ = 0;
+  total_frame_latency_ = base::TimeDelta();
+  frame_latency_datapoints_ = 0;
   total_e2e_latency_ = base::TimeDelta();
   e2e_latency_datapoints_ = 0;
   num_frames_dropped_by_encoder_ = 0;
@@ -269,47 +288,75 @@ const char* StatsEventSubscriber::CastStatToString(CastStat stat) {
     STAT_ENUM_TO_STRING(CAPTURE_FPS);
     STAT_ENUM_TO_STRING(ENCODE_FPS);
     STAT_ENUM_TO_STRING(DECODE_FPS);
+    STAT_ENUM_TO_STRING(AVG_CAPTURE_LATENCY_MS);
     STAT_ENUM_TO_STRING(AVG_ENCODE_TIME_MS);
-    STAT_ENUM_TO_STRING(AVG_PLAYOUT_DELAY_MS);
+    STAT_ENUM_TO_STRING(AVG_QUEUEING_LATENCY_MS);
     STAT_ENUM_TO_STRING(AVG_NETWORK_LATENCY_MS);
+    STAT_ENUM_TO_STRING(AVG_PACKET_LATENCY_MS);
+    STAT_ENUM_TO_STRING(AVG_FRAME_LATENCY_MS);
     STAT_ENUM_TO_STRING(AVG_E2E_LATENCY_MS);
     STAT_ENUM_TO_STRING(ENCODE_KBPS);
     STAT_ENUM_TO_STRING(TRANSMISSION_KBPS);
     STAT_ENUM_TO_STRING(RETRANSMISSION_KBPS);
-    STAT_ENUM_TO_STRING(PACKET_LOSS_FRACTION);
     STAT_ENUM_TO_STRING(MS_SINCE_LAST_RECEIVER_RESPONSE);
     STAT_ENUM_TO_STRING(NUM_FRAMES_CAPTURED);
     STAT_ENUM_TO_STRING(NUM_FRAMES_DROPPED_BY_ENCODER);
     STAT_ENUM_TO_STRING(NUM_FRAMES_LATE);
     STAT_ENUM_TO_STRING(NUM_PACKETS_SENT);
     STAT_ENUM_TO_STRING(NUM_PACKETS_RETRANSMITTED);
+    STAT_ENUM_TO_STRING(NUM_PACKETS_RECEIVED);
     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(ENCODE_TIME_MS_HISTO);
+    STAT_ENUM_TO_STRING(QUEUEING_LATENCY_MS_HISTO);
+    STAT_ENUM_TO_STRING(NETWORK_LATENCY_MS_HISTO);
     STAT_ENUM_TO_STRING(PACKET_LATENCY_MS_HISTO);
     STAT_ENUM_TO_STRING(FRAME_LATENCY_MS_HISTO);
+    STAT_ENUM_TO_STRING(E2E_LATENCY_MS_HISTO);
     STAT_ENUM_TO_STRING(PLAYOUT_DELAY_MS_HISTO);
   }
   NOTREACHED();
   return "";
 }
 
-const int kMaxLatencyBucketMs = 800;
-const int kBucketWidthMs = 20;
+const int kDefaultMaxLatencyBucketMs = 800;
+const int kDefaultBucketWidthMs = 20;
+
+// For small latency values.
+const int kSmallMaxLatencyBucketMs = 100;
+const int kSmallBucketWidthMs = 5;
+
+// For large latency values.
+const int kLargeMaxLatencyBucketMs = 1200;
+const int kLargeBucketWidthMs = 50;
 
 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_[E2E_LATENCY_MS_HISTO].reset(
+      new SimpleHistogram(0, kLargeMaxLatencyBucketMs,
+                          kLargeBucketWidthMs));
+  histograms_[QUEUEING_LATENCY_MS_HISTO].reset(
+      new SimpleHistogram(0, kDefaultMaxLatencyBucketMs,
+                          kDefaultBucketWidthMs));
+  histograms_[NETWORK_LATENCY_MS_HISTO].reset(
+      new SimpleHistogram(0, kDefaultMaxLatencyBucketMs,
+                          kDefaultBucketWidthMs));
   histograms_[PACKET_LATENCY_MS_HISTO].reset(
-      new SimpleHistogram(0, kMaxLatencyBucketMs, kBucketWidthMs));
+      new SimpleHistogram(0, kDefaultMaxLatencyBucketMs,
+                          kDefaultBucketWidthMs));
   histograms_[FRAME_LATENCY_MS_HISTO].reset(
-      new SimpleHistogram(0, kMaxLatencyBucketMs, kBucketWidthMs));
+      new SimpleHistogram(0, kDefaultMaxLatencyBucketMs,
+                          kDefaultBucketWidthMs));
   histograms_[PLAYOUT_DELAY_MS_HISTO].reset(
-      new SimpleHistogram(0, kMaxLatencyBucketMs, kBucketWidthMs));
+      new SimpleHistogram(0, kSmallMaxLatencyBucketMs,
+                          kSmallBucketWidthMs));
+  histograms_[CAPTURE_LATENCY_MS_HISTO].reset(
+      new SimpleHistogram(0, kSmallMaxLatencyBucketMs,
+                          kSmallBucketWidthMs));
+  histograms_[ENCODE_TIME_MS_HISTO].reset(
+      new SimpleHistogram(0, kSmallMaxLatencyBucketMs,
+                          kSmallBucketWidthMs));
 }
 
 void StatsEventSubscriber::GetStatsInternal(StatsMap* stats_map) const {
@@ -325,7 +372,6 @@ void StatsEventSubscriber::GetStatsInternal(StatsMap* stats_map) const {
       end_time, FRAME_ENCODED, ENCODE_FPS, stats_map);
   PopulateFpsStat(
       end_time, FRAME_DECODED, DECODE_FPS, stats_map);
-  PopulatePlayoutDelayStat(stats_map);
   PopulateFrameBitrateStat(end_time, stats_map);
   PopulatePacketBitrateStat(end_time,
                             PACKET_SENT_TO_NETWORK,
@@ -335,14 +381,38 @@ void StatsEventSubscriber::GetStatsInternal(StatsMap* stats_map) const {
                             PACKET_RETRANSMITTED,
                             RETRANSMISSION_KBPS,
                             stats_map);
-  PopulatePacketLossPercentageStat(stats_map);
   PopulateFrameCountStat(FRAME_CAPTURE_END, NUM_FRAMES_CAPTURED, stats_map);
   PopulatePacketCountStat(PACKET_SENT_TO_NETWORK, NUM_PACKETS_SENT, stats_map);
   PopulatePacketCountStat(
       PACKET_RETRANSMITTED, NUM_PACKETS_RETRANSMITTED, stats_map);
+  PopulatePacketCountStat(PACKET_RECEIVED, NUM_PACKETS_RECEIVED, stats_map);
   PopulatePacketCountStat(
       PACKET_RTX_REJECTED, NUM_PACKETS_RTX_REJECTED, stats_map);
 
+  if (capture_latency_datapoints_ > 0) {
+    double avg_capture_latency_ms =
+        total_capture_latency_.InMillisecondsF() /
+        capture_latency_datapoints_;
+    stats_map->insert(
+        std::make_pair(AVG_CAPTURE_LATENCY_MS, avg_capture_latency_ms));
+  }
+
+  if (encode_time_datapoints_ > 0) {
+    double avg_encode_time_ms =
+        total_encode_time_.InMillisecondsF() /
+        encode_time_datapoints_;
+    stats_map->insert(
+        std::make_pair(AVG_ENCODE_TIME_MS, avg_encode_time_ms));
+  }
+
+  if (queueing_latency_datapoints_ > 0) {
+    double avg_queueing_latency_ms =
+        total_queueing_latency_.InMillisecondsF() /
+        queueing_latency_datapoints_;
+    stats_map->insert(
+        std::make_pair(AVG_QUEUEING_LATENCY_MS, avg_queueing_latency_ms));
+  }
+
   if (network_latency_datapoints_ > 0) {
     double avg_network_latency_ms =
         total_network_latency_.InMillisecondsF() /
@@ -351,6 +421,21 @@ void StatsEventSubscriber::GetStatsInternal(StatsMap* stats_map) const {
         std::make_pair(AVG_NETWORK_LATENCY_MS, avg_network_latency_ms));
   }
 
+  if (packet_latency_datapoints_ > 0) {
+    double avg_packet_latency_ms =
+        total_packet_latency_.InMillisecondsF() /
+        packet_latency_datapoints_;
+    stats_map->insert(
+        std::make_pair(AVG_PACKET_LATENCY_MS, avg_packet_latency_ms));
+  }
+
+  if (frame_latency_datapoints_ > 0) {
+    double avg_frame_latency_ms =
+        total_frame_latency_.InMillisecondsF() / frame_latency_datapoints_;
+    stats_map->insert(
+        std::make_pair(AVG_FRAME_LATENCY_MS, avg_frame_latency_ms));
+  }
+
   if (e2e_latency_datapoints_ > 0) {
     double avg_e2e_latency_ms =
         total_e2e_latency_.InMillisecondsF() / e2e_latency_datapoints_;
@@ -378,6 +463,13 @@ void StatsEventSubscriber::GetStatsInternal(StatsMap* stats_map) const {
   }
 }
 
+StatsEventSubscriber::SimpleHistogram*
+StatsEventSubscriber::GetHistogramForTesting(
+    CastStat stats) const {
+  DCHECK(histograms_.find(stats) != histograms_.end());
+  return histograms_.find(stats)->second.get();
+}
+
 bool StatsEventSubscriber::GetReceiverOffset(base::TimeDelta* offset) {
   base::TimeDelta receiver_offset_lower_bound;
   base::TimeDelta receiver_offset_upper_bound;
@@ -403,7 +495,7 @@ void StatsEventSubscriber::MaybeInsertFrameInfo(RtpTimestamp rtp_timestamp,
 
   if (recent_frame_infos_.size() >= kMaxFrameInfoMapSize) {
     FrameInfoMap::iterator erase_it = recent_frame_infos_.begin();
-    if (erase_it->second.encode_time.is_null())
+    if (erase_it->second.encode_end_time.is_null())
       num_frames_dropped_by_encoder_++;
     recent_frame_infos_.erase(erase_it);
   }
@@ -419,13 +511,15 @@ void StatsEventSubscriber::RecordFrameCaptureTime(
 void StatsEventSubscriber::RecordCaptureLatency(const FrameEvent& frame_event) {
   FrameInfoMap::iterator it =
       recent_frame_infos_.find(frame_event.rtp_timestamp);
-  if (it == recent_frame_infos_.end())
+  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);
+    base::TimeDelta latency = frame_event.timestamp - it->second.capture_time;
+    total_capture_latency_ += latency;
+    capture_latency_datapoints_++;
+    histograms_[CAPTURE_LATENCY_MS_HISTO]->Add(latency.InMillisecondsF());
   }
 
   it->second.capture_end_time = frame_event.timestamp;
@@ -436,18 +530,20 @@ void StatsEventSubscriber::RecordEncodeLatency(const FrameEvent& frame_event) {
       recent_frame_infos_.find(frame_event.rtp_timestamp);
   if (it == recent_frame_infos_.end()) {
     FrameInfo frame_info;
-    frame_info.encode_time = frame_event.timestamp;
+    frame_info.encode_end_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);
+    base::TimeDelta latency =
+        frame_event.timestamp - it->second.capture_end_time;
+    total_encode_time_ += latency;
+    encode_time_datapoints_++;
+    histograms_[ENCODE_TIME_MS_HISTO]->Add(latency.InMillisecondsF());
   }
 
-  it->second.encode_time = frame_event.timestamp;
+  it->second.encode_end_time = frame_event.timestamp;
 }
 
 void StatsEventSubscriber::RecordFrameTxLatency(const FrameEvent& frame_event) {
@@ -456,7 +552,7 @@ void StatsEventSubscriber::RecordFrameTxLatency(const FrameEvent& frame_event) {
   if (it == recent_frame_infos_.end())
     return;
 
-  if (it->second.encode_time.is_null())
+  if (it->second.encode_end_time.is_null())
     return;
 
   base::TimeDelta receiver_offset;
@@ -464,9 +560,10 @@ void StatsEventSubscriber::RecordFrameTxLatency(const FrameEvent& frame_event) {
     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);
+  base::TimeDelta latency = sender_time - it->second.encode_end_time;
+  total_frame_latency_ += latency;
+  frame_latency_datapoints_++;
+  histograms_[FRAME_LATENCY_MS_HISTO]->Add(latency.InMillisecondsF());
 }
 
 void StatsEventSubscriber::RecordE2ELatency(const FrameEvent& frame_event) {
@@ -482,8 +579,10 @@ void StatsEventSubscriber::RecordE2ELatency(const FrameEvent& frame_event) {
   // Playout time is event time + playout delay.
   base::TimeTicks playout_time =
       frame_event.timestamp + frame_event.delay_delta - receiver_offset;
-  total_e2e_latency_ += playout_time - it->second.capture_time;
+  base::TimeDelta latency = playout_time - it->second.capture_time;
+  total_e2e_latency_ += latency;
   e2e_latency_datapoints_++;
+  histograms_[E2E_LATENCY_MS_HISTO]->Add(latency.InMillisecondsF());
 }
 
 void StatsEventSubscriber::UpdateLastResponseTime(
@@ -502,8 +601,23 @@ void StatsEventSubscriber::ErasePacketSentTime(
   packet_sent_times_.erase(key);
 }
 
-void StatsEventSubscriber::RecordNetworkLatency(
+void StatsEventSubscriber::RecordPacketRelatedLatencies(
     const PacketEvent& packet_event) {
+  // Log queueing latency.
+  if (packet_event.type == PACKET_SENT_TO_NETWORK) {
+    FrameInfoMap::iterator it =
+        recent_frame_infos_.find(packet_event.rtp_timestamp);
+    if (it != recent_frame_infos_.end()) {
+      base::TimeDelta latency =
+          packet_event.timestamp - it->second.encode_end_time;
+      total_queueing_latency_ += latency;
+      queueing_latency_datapoints_++;
+      histograms_[QUEUEING_LATENCY_MS_HISTO]->Add(
+          latency.InMillisecondsF());
+    }
+  }
+
+  // Log network latency and total packet latency;
   base::TimeDelta receiver_offset;
   if (!GetReceiverOffset(&receiver_offset))
     return;
@@ -535,17 +649,28 @@ void StatsEventSubscriber::RecordNetworkLatency(
       match = true;
     }
     if (match) {
+      packet_sent_times_.erase(it);
+
       // Subtract by offset.
       packet_received_time -= receiver_offset;
       base::TimeDelta latency_delta = packet_received_time - packet_sent_time;
 
       total_network_latency_ += latency_delta;
       network_latency_datapoints_++;
-
-      histograms_[PACKET_LATENCY_MS_HISTO]->Add(
+      histograms_[NETWORK_LATENCY_MS_HISTO]->Add(
           latency_delta.InMillisecondsF());
 
-      packet_sent_times_.erase(it);
+      // Log total network latency.
+      FrameInfoMap::iterator frame_it =
+          recent_frame_infos_.find(packet_event.rtp_timestamp);
+      if (frame_it != recent_frame_infos_.end()) {
+        base::TimeDelta latency =
+            packet_received_time - frame_it->second.encode_end_time;
+        total_packet_latency_ += latency;
+        packet_latency_datapoints_++;
+        histograms_[PACKET_LATENCY_MS_HISTO]->Add(
+            latency.InMillisecondsF());
+      }
     }
   }
 }
@@ -583,18 +708,6 @@ void StatsEventSubscriber::PopulatePacketCountStat(CastLoggingEvent event,
   }
 }
 
-void StatsEventSubscriber::PopulatePlayoutDelayStat(StatsMap* stats_map) const {
-  FrameStatsMap::const_iterator it = frame_stats_.find(FRAME_PLAYOUT);
-  if (it != frame_stats_.end()) {
-    double avg_delay_ms = 0.0;
-    base::TimeDelta sum_delay = it->second.sum_delay;
-    int count = it->second.event_counter;
-    if (count != 0)
-      avg_delay_ms = sum_delay.InMillisecondsF() / count;
-    stats_map->insert(std::make_pair(AVG_PLAYOUT_DELAY_MS, avg_delay_ms));
-  }
-}
-
 void StatsEventSubscriber::PopulateFrameBitrateStat(base::TimeTicks end_time,
                                                     StatsMap* stats_map) const {
   FrameStatsMap::const_iterator it = frame_stats_.find(FRAME_ENCODED);
@@ -626,28 +739,6 @@ void StatsEventSubscriber::PopulatePacketBitrateStat(
   }
 }
 
-void StatsEventSubscriber::PopulatePacketLossPercentageStat(
-    StatsMap* stats_map) const {
-  // We assume that retransmission means that the packet's previous
-  // (re)transmission was lost.
-  // This means the percentage of packet loss is
-  // (# of retransmit events) / (# of transmit + retransmit events).
-  PacketStatsMap::const_iterator sent_it =
-      packet_stats_.find(PACKET_SENT_TO_NETWORK);
-  if (sent_it == packet_stats_.end())
-    return;
-  PacketStatsMap::const_iterator retransmitted_it =
-      packet_stats_.find(PACKET_RETRANSMITTED);
-  int sent_count = sent_it->second.event_counter;
-  int retransmitted_count = 0;
-  if (retransmitted_it != packet_stats_.end())
-    retransmitted_count = retransmitted_it->second.event_counter;
-  double packet_loss_fraction = static_cast<double>(retransmitted_count) /
-                                (sent_count + retransmitted_count);
-  stats_map->insert(
-      std::make_pair(PACKET_LOSS_FRACTION, packet_loss_fraction));
-}
-
 StatsEventSubscriber::FrameLogStats::FrameLogStats()
     : event_counter(0), sum_size(0) {}
 StatsEventSubscriber::FrameLogStats::~FrameLogStats() {}