media/cast/logging/stats_event_subscriber.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/logging/stats_event_subscriber.h"
   6
   7 #include "base/logging.h"
   8 #include "base/values.h"
   9
  10 #define STAT_ENUM_TO_STRING(enum) \
  11   case enum:                      \
  12     return #enum
  13
  14 namespace media {
  15 namespace cast {
  16
  17 namespace {
  18
  19 using media::cast::CastLoggingEvent;
  20 using media::cast::EventMediaType;
  21
  22 const size_t kMaxFrameEventTimeMapSize = 100;
  23 const size_t kMaxPacketEventTimeMapSize = 1000;
  24
  25 bool IsReceiverEvent(CastLoggingEvent event) {
  26   return event == FRAME_DECODED
  27       || event == FRAME_PLAYOUT
  28       || event == FRAME_ACK_SENT
  29       || event == PACKET_RECEIVED;
  30 }
  31
  32 }  // namespace
  33
  34 StatsEventSubscriber::StatsEventSubscriber(
  35     EventMediaType event_media_type,
  36     base::TickClock* clock,
  37     ReceiverTimeOffsetEstimator* offset_estimator)
  38     : event_media_type_(event_media_type),
  39       clock_(clock),
  40       offset_estimator_(offset_estimator),
  41       network_latency_datapoints_(0),
  42       e2e_latency_datapoints_(0) {
  43   DCHECK(event_media_type == AUDIO_EVENT || event_media_type == VIDEO_EVENT);
  44   base::TimeTicks now = clock_->NowTicks();
  45   start_time_ = now;
  46   last_response_received_time_ = base::TimeTicks();
  47 }
  48
  49 StatsEventSubscriber::~StatsEventSubscriber() {
  50   DCHECK(thread_checker_.CalledOnValidThread());
  51 }
  52
  53 void StatsEventSubscriber::OnReceiveFrameEvent(const FrameEvent& frame_event) {
  54   DCHECK(thread_checker_.CalledOnValidThread());
  55
  56   CastLoggingEvent type = frame_event.type;
  57   if (frame_event.media_type != event_media_type_)
  58     return;
  59
  60   FrameStatsMap::iterator it = frame_stats_.find(type);
  61   if (it == frame_stats_.end()) {
  62     FrameLogStats stats;
  63     stats.event_counter = 1;
  64     stats.sum_size = frame_event.size;
  65     stats.sum_delay = frame_event.delay_delta;
  66     frame_stats_.insert(std::make_pair(type, stats));
  67   } else {
  68     ++(it->second.event_counter);
  69     it->second.sum_size += frame_event.size;
  70     it->second.sum_delay += frame_event.delay_delta;
  71   }
  72
  73   if (type == FRAME_CAPTURE_BEGIN) {
  74     RecordFrameCapturedTime(frame_event);
  75   } else if (type == FRAME_PLAYOUT) {
  76     RecordE2ELatency(frame_event);
  77   }
  78
  79   if (IsReceiverEvent(type))
  80     UpdateLastResponseTime(frame_event.timestamp);
  81 }
  82
  83 void StatsEventSubscriber::OnReceivePacketEvent(
  84     const PacketEvent& packet_event) {
  85   DCHECK(thread_checker_.CalledOnValidThread());
  86
  87   CastLoggingEvent type = packet_event.type;
  88   if (packet_event.media_type != event_media_type_)
  89     return;
  90
  91   PacketStatsMap::iterator it = packet_stats_.find(type);
  92   if (it == packet_stats_.end()) {
  93     PacketLogStats stats;
  94     stats.event_counter = 1;
  95     stats.sum_size = packet_event.size;
  96     packet_stats_.insert(std::make_pair(type, stats));
  97   } else {
  98     ++(it->second.event_counter);
  99     it->second.sum_size += packet_event.size;
 100   }
 101
 102   if (type == PACKET_SENT_TO_NETWORK ||
 103       type == PACKET_RECEIVED) {
 104     RecordNetworkLatency(packet_event);
 105   } else if (type == PACKET_RETRANSMITTED) {
 106     // We only measure network latency using packets that doesn't have to be
 107     // retransmitted as there is precisely one sent-receive timestamp pairs.
 108     ErasePacketSentTime(packet_event);
 109   }
 110
 111   if (IsReceiverEvent(type))
 112     UpdateLastResponseTime(packet_event.timestamp);
 113 }
 114
 115 scoped_ptr<base::DictionaryValue> StatsEventSubscriber::GetStats() const {
 116   StatsMap stats_map;
 117   GetStatsInternal(&stats_map);
 118   scoped_ptr<base::DictionaryValue> ret(new base::DictionaryValue);
 119
 120   scoped_ptr<base::DictionaryValue> stats(new base::DictionaryValue);
 121   for (StatsMap::const_iterator it = stats_map.begin(); it != stats_map.end();
 122        ++it) {
 123     stats->SetDouble(CastStatToString(it->first), it->second);
 124   }
 125
 126   ret->Set(event_media_type_ == AUDIO_EVENT ? "audio" : "video",
 127            stats.release());
 128
 129   return ret.Pass();
 130 }
 131
 132 void StatsEventSubscriber::Reset() {
 133   DCHECK(thread_checker_.CalledOnValidThread());
 134
 135   frame_stats_.clear();
 136   packet_stats_.clear();
 137   total_network_latency_ = base::TimeDelta();
 138   network_latency_datapoints_ = 0;
 139   total_e2e_latency_ = base::TimeDelta();
 140   e2e_latency_datapoints_ = 0;
 141   frame_captured_times_.clear();
 142   packet_sent_times_.clear();
 143   start_time_ = clock_->NowTicks();
 144   last_response_received_time_ = base::TimeTicks();
 145 }
 146
 147 // static
 148 const char* StatsEventSubscriber::CastStatToString(CastStat stat) {
 149   switch (stat) {
 150     STAT_ENUM_TO_STRING(CAPTURE_FPS);
 151     STAT_ENUM_TO_STRING(ENCODE_FPS);
 152     STAT_ENUM_TO_STRING(DECODE_FPS);
 153     STAT_ENUM_TO_STRING(AVG_ENCODE_TIME_MS);
 154     STAT_ENUM_TO_STRING(AVG_PLAYOUT_DELAY_MS);
 155     STAT_ENUM_TO_STRING(AVG_NETWORK_LATENCY_MS);
 156     STAT_ENUM_TO_STRING(AVG_E2E_LATENCY_MS);
 157     STAT_ENUM_TO_STRING(ENCODE_KBPS);
 158     STAT_ENUM_TO_STRING(TRANSMISSION_KBPS);
 159     STAT_ENUM_TO_STRING(RETRANSMISSION_KBPS);
 160     STAT_ENUM_TO_STRING(PACKET_LOSS_FRACTION);
 161     STAT_ENUM_TO_STRING(MS_SINCE_LAST_RECEIVER_RESPONSE);
 162   }
 163   NOTREACHED();
 164   return "";
 165 }
 166
 167 void StatsEventSubscriber::GetStatsInternal(StatsMap* stats_map) const {
 168   DCHECK(thread_checker_.CalledOnValidThread());
 169
 170   stats_map->clear();
 171
 172   base::TimeTicks end_time = clock_->NowTicks();
 173
 174   PopulateFpsStat(
 175       end_time, FRAME_CAPTURE_BEGIN, CAPTURE_FPS, stats_map);
 176   PopulateFpsStat(
 177       end_time, FRAME_ENCODED, ENCODE_FPS, stats_map);
 178   PopulateFpsStat(
 179       end_time, FRAME_DECODED, DECODE_FPS, stats_map);
 180   PopulatePlayoutDelayStat(stats_map);
 181   PopulateFrameBitrateStat(end_time, stats_map);
 182   PopulatePacketBitrateStat(end_time,
 183                             PACKET_SENT_TO_NETWORK,
 184                             TRANSMISSION_KBPS,
 185                             stats_map);
 186   PopulatePacketBitrateStat(end_time,
 187                             PACKET_RETRANSMITTED,
 188                             RETRANSMISSION_KBPS,
 189                             stats_map);
 190   PopulatePacketLossPercentageStat(stats_map);
 191
 192   if (network_latency_datapoints_ > 0) {
 193     double avg_network_latency_ms =
 194         total_network_latency_.InMillisecondsF() /
 195         network_latency_datapoints_;
 196     stats_map->insert(
 197         std::make_pair(AVG_NETWORK_LATENCY_MS, avg_network_latency_ms));
 198   }
 199
 200   if (e2e_latency_datapoints_ > 0) {
 201     double avg_e2e_latency_ms =
 202         total_e2e_latency_.InMillisecondsF() / e2e_latency_datapoints_;
 203     stats_map->insert(std::make_pair(AVG_E2E_LATENCY_MS, avg_e2e_latency_ms));
 204   }
 205
 206   if (!last_response_received_time_.is_null()) {
 207     stats_map->insert(
 208         std::make_pair(MS_SINCE_LAST_RECEIVER_RESPONSE,
 209         (end_time - last_response_received_time_).InMillisecondsF()));
 210   }
 211 }
 212
 213 bool StatsEventSubscriber::GetReceiverOffset(base::TimeDelta* offset) {
 214   base::TimeDelta receiver_offset_lower_bound;
 215   base::TimeDelta receiver_offset_upper_bound;
 216   if (!offset_estimator_->GetReceiverOffsetBounds(
 217           &receiver_offset_lower_bound, &receiver_offset_upper_bound)) {
 218     return false;
 219   }
 220
 221   *offset = (receiver_offset_lower_bound + receiver_offset_upper_bound) / 2;
 222   return true;
 223 }
 224
 225 void StatsEventSubscriber::RecordFrameCapturedTime(
 226     const FrameEvent& frame_event) {
 227   frame_captured_times_.insert(
 228       std::make_pair(frame_event.rtp_timestamp, frame_event.timestamp));
 229   if (frame_captured_times_.size() > kMaxFrameEventTimeMapSize)
 230     frame_captured_times_.erase(frame_captured_times_.begin());
 231 }
 232
 233 void StatsEventSubscriber::RecordE2ELatency(const FrameEvent& frame_event) {
 234   base::TimeDelta receiver_offset;
 235   if (!GetReceiverOffset(&receiver_offset))
 236     return;
 237
 238   FrameEventTimeMap::iterator it =
 239       frame_captured_times_.find(frame_event.rtp_timestamp);
 240   if (it == frame_captured_times_.end())
 241     return;
 242
 243   // Playout time is event time + playout delay.
 244   base::TimeTicks playout_time =
 245       frame_event.timestamp + frame_event.delay_delta - receiver_offset;
 246   total_e2e_latency_ += playout_time - it->second;
 247   e2e_latency_datapoints_++;
 248 }
 249
 250 void StatsEventSubscriber::UpdateLastResponseTime(
 251     base::TimeTicks receiver_time) {
 252   base::TimeDelta receiver_offset;
 253   if (!GetReceiverOffset(&receiver_offset))
 254     return;
 255   base::TimeTicks sender_time = receiver_time - receiver_offset;
 256   last_response_received_time_ = sender_time;
 257 }
 258
 259 void StatsEventSubscriber::ErasePacketSentTime(
 260     const PacketEvent& packet_event) {
 261   std::pair<RtpTimestamp, uint16> key(
 262       std::make_pair(packet_event.rtp_timestamp, packet_event.packet_id));
 263   packet_sent_times_.erase(key);
 264 }
 265
 266 void StatsEventSubscriber::RecordNetworkLatency(
 267     const PacketEvent& packet_event) {
 268   base::TimeDelta receiver_offset;
 269   if (!GetReceiverOffset(&receiver_offset))
 270     return;
 271
 272   std::pair<RtpTimestamp, uint16> key(
 273       std::make_pair(packet_event.rtp_timestamp, packet_event.packet_id));
 274   PacketEventTimeMap::iterator it = packet_sent_times_.find(key);
 275   if (it == packet_sent_times_.end()) {
 276     std::pair<RtpTimestamp, uint16> key(
 277         std::make_pair(packet_event.rtp_timestamp, packet_event.packet_id));
 278     std::pair<base::TimeTicks, CastLoggingEvent> value =
 279         std::make_pair(packet_event.timestamp, packet_event.type);
 280     packet_sent_times_.insert(std::make_pair(key, value));
 281     if (packet_sent_times_.size() > kMaxPacketEventTimeMapSize)
 282       packet_sent_times_.erase(packet_sent_times_.begin());
 283   } else {
 284     std::pair<base::TimeTicks, CastLoggingEvent> value = it->second;
 285     CastLoggingEvent recorded_type = value.second;
 286     bool match = false;
 287     base::TimeTicks packet_sent_time;
 288     base::TimeTicks packet_received_time;
 289     if (recorded_type == PACKET_SENT_TO_NETWORK &&
 290         packet_event.type == PACKET_RECEIVED) {
 291       packet_sent_time = value.first;
 292       packet_received_time = packet_event.timestamp;
 293       match = true;
 294     } else if (recorded_type == PACKET_RECEIVED &&
 295         packet_event.type == PACKET_SENT_TO_NETWORK) {
 296       packet_sent_time = packet_event.timestamp;
 297       packet_received_time = value.first;
 298       match = true;
 299     }
 300     if (match) {
 301       // Subtract by offset.
 302       packet_received_time -= receiver_offset;
 303
 304       total_network_latency_ += packet_received_time - packet_sent_time;
 305       network_latency_datapoints_++;
 306       packet_sent_times_.erase(it);
 307     }
 308   }
 309 }
 310
 311 void StatsEventSubscriber::PopulateFpsStat(base::TimeTicks end_time,
 312                                            CastLoggingEvent event,
 313                                            CastStat stat,
 314                                            StatsMap* stats_map) const {
 315   FrameStatsMap::const_iterator it = frame_stats_.find(event);
 316   if (it != frame_stats_.end()) {
 317     double fps = 0.0;
 318     base::TimeDelta duration = (end_time - start_time_);
 319     int count = it->second.event_counter;
 320     if (duration > base::TimeDelta())
 321       fps = count / duration.InSecondsF();
 322     stats_map->insert(std::make_pair(stat, fps));
 323   }
 324 }
 325
 326 void StatsEventSubscriber::PopulatePlayoutDelayStat(StatsMap* stats_map) const {
 327   FrameStatsMap::const_iterator it = frame_stats_.find(FRAME_PLAYOUT);
 328   if (it != frame_stats_.end()) {
 329     double avg_delay_ms = 0.0;
 330     base::TimeDelta sum_delay = it->second.sum_delay;
 331     int count = it->second.event_counter;
 332     if (count != 0)
 333       avg_delay_ms = sum_delay.InMillisecondsF() / count;
 334     stats_map->insert(std::make_pair(AVG_PLAYOUT_DELAY_MS, avg_delay_ms));
 335   }
 336 }
 337
 338 void StatsEventSubscriber::PopulateFrameBitrateStat(base::TimeTicks end_time,
 339                                                     StatsMap* stats_map) const {
 340   FrameStatsMap::const_iterator it = frame_stats_.find(FRAME_ENCODED);
 341   if (it != frame_stats_.end()) {
 342     double kbps = 0.0;
 343     base::TimeDelta duration = end_time - start_time_;
 344     if (duration > base::TimeDelta()) {
 345       kbps = it->second.sum_size / duration.InMillisecondsF() * 8;
 346     }
 347
 348     stats_map->insert(std::make_pair(ENCODE_KBPS, kbps));
 349   }
 350 }
 351
 352 void StatsEventSubscriber::PopulatePacketBitrateStat(
 353     base::TimeTicks end_time,
 354     CastLoggingEvent event,
 355     CastStat stat,
 356     StatsMap* stats_map) const {
 357   PacketStatsMap::const_iterator it = packet_stats_.find(event);
 358   if (it != packet_stats_.end()) {
 359     double kbps = 0;
 360     base::TimeDelta duration = end_time - start_time_;
 361     if (duration > base::TimeDelta()) {
 362       kbps = it->second.sum_size / duration.InMillisecondsF() * 8;
 363     }
 364
 365     stats_map->insert(std::make_pair(stat, kbps));
 366   }
 367 }
 368
 369 void StatsEventSubscriber::PopulatePacketLossPercentageStat(
 370     StatsMap* stats_map) const {
 371   // We assume that retransmission means that the packet's previous
 372   // (re)transmission was lost.
 373   // This means the percentage of packet loss is
 374   // (# of retransmit events) / (# of transmit + retransmit events).
 375   PacketStatsMap::const_iterator sent_it =
 376       packet_stats_.find(PACKET_SENT_TO_NETWORK);
 377   if (sent_it == packet_stats_.end())
 378     return;
 379   PacketStatsMap::const_iterator retransmitted_it =
 380       packet_stats_.find(PACKET_RETRANSMITTED);
 381   int sent_count = sent_it->second.event_counter;
 382   int retransmitted_count = 0;
 383   if (retransmitted_it != packet_stats_.end())
 384     retransmitted_count = retransmitted_it->second.event_counter;
 385   double packet_loss_fraction = static_cast<double>(retransmitted_count) /
 386                                 (sent_count + retransmitted_count);
 387   stats_map->insert(
 388       std::make_pair(PACKET_LOSS_FRACTION, packet_loss_fraction));
 389 }
 390
 391 StatsEventSubscriber::FrameLogStats::FrameLogStats()
 392     : event_counter(0), sum_size(0) {}
 393 StatsEventSubscriber::FrameLogStats::~FrameLogStats() {}
 394
 395 StatsEventSubscriber::PacketLogStats::PacketLogStats()
 396     : event_counter(0), sum_size(0) {}
 397 StatsEventSubscriber::PacketLogStats::~PacketLogStats() {}
 398
 399 }  // namespace cast
 400 }  // namespace media