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