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