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 <cmath>
   6
   7 #include "media/cast/logging/stats_event_subscriber.h"
   8
   9 #include "base/format_macros.h"
  10 #include "base/logging.h"
  11 #include "base/strings/stringprintf.h"
  12 #include "base/values.h"
  13
  14 #define STAT_ENUM_TO_STRING(enum) \
  15   case enum:                      \
  16     return #enum
  17
  18 namespace media {
  19 namespace cast {
  20
  21 namespace {
  22
  23 using media::cast::CastLoggingEvent;
  24 using media::cast::EventMediaType;
  25
  26 const size_t kMaxPacketEventTimeMapSize = 1000;
  27
  28 bool IsReceiverEvent(CastLoggingEvent event) {
  29   return event == FRAME_DECODED
  30       || event == FRAME_PLAYOUT
  31       || event == FRAME_ACK_SENT
  32       || event == PACKET_RECEIVED;
  33 }
  34
  35 }  // namespace
  36
  37 StatsEventSubscriber::SimpleHistogram::SimpleHistogram(int64 min,
  38                                                        int64 max,
  39                                                        int64 width)
  40     : min_(min), max_(max), width_(width), buckets_((max - min) / width + 2) {
  41   CHECK_GT(buckets_.size(), 2u);
  42   CHECK_EQ(0, (max_ - min_) % width_);
  43 }
  44
  45 StatsEventSubscriber::SimpleHistogram::~SimpleHistogram() {
  46 }
  47
  48 void StatsEventSubscriber::SimpleHistogram::Add(int64 sample) {
  49   if (sample < min_) {
  50     ++buckets_.front();
  51   } else if (sample >= max_) {
  52     ++buckets_.back();
  53   } else {
  54     size_t index = 1 + (sample - min_) / width_;
  55     DCHECK_LT(index, buckets_.size());
  56     ++buckets_[index];
  57   }
  58 }
  59
  60 void StatsEventSubscriber::SimpleHistogram::Reset() {
  61   buckets_.assign(buckets_.size(), 0);
  62 }
  63
  64 scoped_ptr<base::ListValue>
  65 StatsEventSubscriber::SimpleHistogram::GetHistogram() const {
  66   scoped_ptr<base::ListValue> histo(new base::ListValue);
  67
  68   scoped_ptr<base::DictionaryValue> bucket(new base::DictionaryValue);
  69
  70   if (buckets_.front()) {
  71     bucket->SetInteger(base::StringPrintf("<%" PRId64, min_),
  72                        buckets_.front());
  73     histo->Append(bucket.release());
  74   }
  75
  76   for (size_t i = 1; i < buckets_.size() - 1; i++) {
  77     if (!buckets_[i])
  78       continue;
  79     bucket.reset(new base::DictionaryValue);
  80     int64 lower = min_ + (i - 1) * width_;
  81     int64 upper = lower + width_ - 1;
  82     bucket->SetInteger(
  83         base::StringPrintf("%" PRId64 "-%" PRId64, lower, upper),
  84         buckets_[i]);
  85     histo->Append(bucket.release());
  86   }
  87
  88   if (buckets_.back()) {
  89     bucket.reset(new base::DictionaryValue);
  90     bucket->SetInteger(base::StringPrintf(">=%" PRId64, max_),
  91                        buckets_.back());
  92     histo->Append(bucket.release());
  93   }
  94   return histo.Pass();
  95 }
  96
  97 StatsEventSubscriber::StatsEventSubscriber(
  98     EventMediaType event_media_type,
  99     base::TickClock* clock,
 100     ReceiverTimeOffsetEstimator* offset_estimator)
 101     : event_media_type_(event_media_type),
 102       clock_(clock),
 103       offset_estimator_(offset_estimator),
 104       capture_latency_datapoints_(0),
 105       encode_time_datapoints_(0),
 106       queueing_latency_datapoints_(0),
 107       network_latency_datapoints_(0),
 108       packet_latency_datapoints_(0),
 109       frame_latency_datapoints_(0),
 110       e2e_latency_datapoints_(0),
 111       num_frames_dropped_by_encoder_(0),
 112       num_frames_late_(0),
 113       start_time_(clock_->NowTicks()) {
 114   DCHECK(event_media_type == AUDIO_EVENT || event_media_type == VIDEO_EVENT);
 115
 116   InitHistograms();
 117 }
 118
 119 StatsEventSubscriber::~StatsEventSubscriber() {
 120   DCHECK(thread_checker_.CalledOnValidThread());
 121 }
 122
 123 void StatsEventSubscriber::OnReceiveFrameEvent(const FrameEvent& frame_event) {
 124   DCHECK(thread_checker_.CalledOnValidThread());
 125
 126   CastLoggingEvent type = frame_event.type;
 127   if (frame_event.media_type != event_media_type_)
 128     return;
 129
 130   FrameStatsMap::iterator it = frame_stats_.find(type);
 131   if (it == frame_stats_.end()) {
 132     FrameLogStats stats;
 133     stats.event_counter = 1;
 134     stats.sum_size = frame_event.size;
 135     stats.sum_delay = frame_event.delay_delta;
 136     frame_stats_.insert(std::make_pair(type, stats));
 137   } else {
 138     ++(it->second.event_counter);
 139     it->second.sum_size += frame_event.size;
 140     it->second.sum_delay += frame_event.delay_delta;
 141   }
 142
 143   bool is_receiver_event = IsReceiverEvent(type);
 144   UpdateFirstLastEventTime(frame_event.timestamp, is_receiver_event);
 145
 146   if (type == FRAME_CAPTURE_BEGIN) {
 147     RecordFrameCaptureTime(frame_event);
 148   } else if (type == FRAME_CAPTURE_END) {
 149     RecordCaptureLatency(frame_event);
 150   } else if (type == FRAME_ENCODED) {
 151     RecordEncodeLatency(frame_event);
 152   } else if (type == FRAME_ACK_SENT) {
 153     RecordFrameTxLatency(frame_event);
 154   } else if (type == FRAME_PLAYOUT) {
 155     RecordE2ELatency(frame_event);
 156     base::TimeDelta delay_delta = frame_event.delay_delta;
 157     histograms_[PLAYOUT_DELAY_MS_HISTO]->Add(delay_delta.InMillisecondsF());
 158
 159     // Positive delay_delta means the frame is late.
 160     if (delay_delta > base::TimeDelta())
 161       num_frames_late_++;
 162   }
 163
 164   if (is_receiver_event)
 165     UpdateLastResponseTime(frame_event.timestamp);
 166 }
 167
 168 void StatsEventSubscriber::OnReceivePacketEvent(
 169     const PacketEvent& packet_event) {
 170   DCHECK(thread_checker_.CalledOnValidThread());
 171
 172   CastLoggingEvent type = packet_event.type;
 173   if (packet_event.media_type != event_media_type_)
 174     return;
 175
 176   PacketStatsMap::iterator it = packet_stats_.find(type);
 177   if (it == packet_stats_.end()) {
 178     PacketLogStats stats;
 179     stats.event_counter = 1;
 180     stats.sum_size = packet_event.size;
 181     packet_stats_.insert(std::make_pair(type, stats));
 182   } else {
 183     ++(it->second.event_counter);
 184     it->second.sum_size += packet_event.size;
 185   }
 186
 187   bool is_receiver_event = IsReceiverEvent(type);
 188   UpdateFirstLastEventTime(packet_event.timestamp, is_receiver_event);
 189
 190   if (type == PACKET_SENT_TO_NETWORK ||
 191       type == PACKET_RECEIVED) {
 192     RecordPacketRelatedLatencies(packet_event);
 193   } else if (type == PACKET_RETRANSMITTED) {
 194     // We only measure network latency using packets that doesn't have to be
 195     // retransmitted as there is precisely one sent-receive timestamp pairs.
 196     ErasePacketSentTime(packet_event);
 197   }
 198
 199   if (is_receiver_event)
 200     UpdateLastResponseTime(packet_event.timestamp);
 201 }
 202
 203 void StatsEventSubscriber::UpdateFirstLastEventTime(base::TimeTicks timestamp,
 204                                                     bool is_receiver_event) {
 205   if (is_receiver_event) {
 206     base::TimeDelta receiver_offset;
 207     if (!GetReceiverOffset(&receiver_offset))
 208       return;
 209     timestamp -= receiver_offset;
 210   }
 211
 212   if (first_event_time_.is_null()) {
 213     first_event_time_ = timestamp;
 214   } else {
 215     first_event_time_ = std::min(first_event_time_, timestamp);
 216   }
 217   if (last_event_time_.is_null()) {
 218     last_event_time_ = timestamp;
 219   } else {
 220     last_event_time_ = std::max(last_event_time_, timestamp);
 221   }
 222 }
 223
 224 scoped_ptr<base::DictionaryValue> StatsEventSubscriber::GetStats() const {
 225   StatsMap stats_map;
 226   GetStatsInternal(&stats_map);
 227   scoped_ptr<base::DictionaryValue> ret(new base::DictionaryValue);
 228
 229   scoped_ptr<base::DictionaryValue> stats(new base::DictionaryValue);
 230   for (StatsMap::const_iterator it = stats_map.begin(); it != stats_map.end();
 231        ++it) {
 232     // Round to 3 digits after the decimal point.
 233     stats->SetDouble(CastStatToString(it->first),
 234                      round(it->second * 1000.0) / 1000.0);
 235   }
 236
 237   // Populate all histograms.
 238   for (HistogramMap::const_iterator it = histograms_.begin();
 239        it != histograms_.end();
 240        ++it) {
 241     stats->Set(CastStatToString(it->first),
 242                it->second->GetHistogram().release());
 243   }
 244
 245   ret->Set(event_media_type_ == AUDIO_EVENT ? "audio" : "video",
 246            stats.release());
 247
 248   return ret.Pass();
 249 }
 250
 251 void StatsEventSubscriber::Reset() {
 252   DCHECK(thread_checker_.CalledOnValidThread());
 253
 254   frame_stats_.clear();
 255   packet_stats_.clear();
 256   total_capture_latency_ = base::TimeDelta();
 257   capture_latency_datapoints_ = 0;
 258   total_encode_time_ = base::TimeDelta();
 259   encode_time_datapoints_ = 0;
 260   total_queueing_latency_ = base::TimeDelta();
 261   queueing_latency_datapoints_ = 0;
 262   total_network_latency_ = base::TimeDelta();
 263   network_latency_datapoints_ = 0;
 264   total_packet_latency_ = base::TimeDelta();
 265   packet_latency_datapoints_ = 0;
 266   total_frame_latency_ = base::TimeDelta();
 267   frame_latency_datapoints_ = 0;
 268   total_e2e_latency_ = base::TimeDelta();
 269   e2e_latency_datapoints_ = 0;
 270   num_frames_dropped_by_encoder_ = 0;
 271   num_frames_late_ = 0;
 272   recent_frame_infos_.clear();
 273   packet_sent_times_.clear();
 274   start_time_ = clock_->NowTicks();
 275   last_response_received_time_ = base::TimeTicks();
 276   for (HistogramMap::iterator it = histograms_.begin(); it != histograms_.end();
 277        ++it) {
 278     it->second->Reset();
 279   }
 280
 281   first_event_time_ = base::TimeTicks();
 282   last_event_time_ = base::TimeTicks();
 283 }
 284
 285 // static
 286 const char* StatsEventSubscriber::CastStatToString(CastStat stat) {
 287   switch (stat) {
 288     STAT_ENUM_TO_STRING(CAPTURE_FPS);
 289     STAT_ENUM_TO_STRING(ENCODE_FPS);
 290     STAT_ENUM_TO_STRING(DECODE_FPS);
 291     STAT_ENUM_TO_STRING(AVG_CAPTURE_LATENCY_MS);
 292     STAT_ENUM_TO_STRING(AVG_ENCODE_TIME_MS);
 293     STAT_ENUM_TO_STRING(AVG_QUEUEING_LATENCY_MS);
 294     STAT_ENUM_TO_STRING(AVG_NETWORK_LATENCY_MS);
 295     STAT_ENUM_TO_STRING(AVG_PACKET_LATENCY_MS);
 296     STAT_ENUM_TO_STRING(AVG_FRAME_LATENCY_MS);
 297     STAT_ENUM_TO_STRING(AVG_E2E_LATENCY_MS);
 298     STAT_ENUM_TO_STRING(ENCODE_KBPS);
 299     STAT_ENUM_TO_STRING(TRANSMISSION_KBPS);
 300     STAT_ENUM_TO_STRING(RETRANSMISSION_KBPS);
 301     STAT_ENUM_TO_STRING(MS_SINCE_LAST_RECEIVER_RESPONSE);
 302     STAT_ENUM_TO_STRING(NUM_FRAMES_CAPTURED);
 303     STAT_ENUM_TO_STRING(NUM_FRAMES_DROPPED_BY_ENCODER);
 304     STAT_ENUM_TO_STRING(NUM_FRAMES_LATE);
 305     STAT_ENUM_TO_STRING(NUM_PACKETS_SENT);
 306     STAT_ENUM_TO_STRING(NUM_PACKETS_RETRANSMITTED);
 307     STAT_ENUM_TO_STRING(NUM_PACKETS_RECEIVED);
 308     STAT_ENUM_TO_STRING(NUM_PACKETS_RTX_REJECTED);
 309     STAT_ENUM_TO_STRING(FIRST_EVENT_TIME_MS);
 310     STAT_ENUM_TO_STRING(LAST_EVENT_TIME_MS);
 311     STAT_ENUM_TO_STRING(CAPTURE_LATENCY_MS_HISTO);
 312     STAT_ENUM_TO_STRING(ENCODE_TIME_MS_HISTO);
 313     STAT_ENUM_TO_STRING(QUEUEING_LATENCY_MS_HISTO);
 314     STAT_ENUM_TO_STRING(NETWORK_LATENCY_MS_HISTO);
 315     STAT_ENUM_TO_STRING(PACKET_LATENCY_MS_HISTO);
 316     STAT_ENUM_TO_STRING(FRAME_LATENCY_MS_HISTO);
 317     STAT_ENUM_TO_STRING(E2E_LATENCY_MS_HISTO);
 318     STAT_ENUM_TO_STRING(PLAYOUT_DELAY_MS_HISTO);
 319   }
 320   NOTREACHED();
 321   return "";
 322 }
 323
 324 const int kDefaultMaxLatencyBucketMs = 800;
 325 const int kDefaultBucketWidthMs = 20;
 326
 327 // For small latency values.
 328 const int kSmallMaxLatencyBucketMs = 100;
 329 const int kSmallBucketWidthMs = 5;
 330
 331 // For large latency values.
 332 const int kLargeMaxLatencyBucketMs = 1200;
 333 const int kLargeBucketWidthMs = 50;
 334
 335 void StatsEventSubscriber::InitHistograms() {
 336   histograms_[E2E_LATENCY_MS_HISTO].reset(
 337       new SimpleHistogram(0, kLargeMaxLatencyBucketMs,
 338                           kLargeBucketWidthMs));
 339   histograms_[QUEUEING_LATENCY_MS_HISTO].reset(
 340       new SimpleHistogram(0, kDefaultMaxLatencyBucketMs,
 341                           kDefaultBucketWidthMs));
 342   histograms_[NETWORK_LATENCY_MS_HISTO].reset(
 343       new SimpleHistogram(0, kDefaultMaxLatencyBucketMs,
 344                           kDefaultBucketWidthMs));
 345   histograms_[PACKET_LATENCY_MS_HISTO].reset(
 346       new SimpleHistogram(0, kDefaultMaxLatencyBucketMs,
 347                           kDefaultBucketWidthMs));
 348   histograms_[FRAME_LATENCY_MS_HISTO].reset(
 349       new SimpleHistogram(0, kDefaultMaxLatencyBucketMs,
 350                           kDefaultBucketWidthMs));
 351   histograms_[PLAYOUT_DELAY_MS_HISTO].reset(
 352       new SimpleHistogram(0, kSmallMaxLatencyBucketMs,
 353                           kSmallBucketWidthMs));
 354   histograms_[CAPTURE_LATENCY_MS_HISTO].reset(
 355       new SimpleHistogram(0, kSmallMaxLatencyBucketMs,
 356                           kSmallBucketWidthMs));
 357   histograms_[ENCODE_TIME_MS_HISTO].reset(
 358       new SimpleHistogram(0, kSmallMaxLatencyBucketMs,
 359                           kSmallBucketWidthMs));
 360 }
 361
 362 void StatsEventSubscriber::GetStatsInternal(StatsMap* stats_map) const {
 363   DCHECK(thread_checker_.CalledOnValidThread());
 364
 365   stats_map->clear();
 366
 367   base::TimeTicks end_time = clock_->NowTicks();
 368
 369   PopulateFpsStat(
 370       end_time, FRAME_CAPTURE_BEGIN, CAPTURE_FPS, stats_map);
 371   PopulateFpsStat(
 372       end_time, FRAME_ENCODED, ENCODE_FPS, stats_map);
 373   PopulateFpsStat(
 374       end_time, FRAME_DECODED, DECODE_FPS, stats_map);
 375   PopulateFrameBitrateStat(end_time, stats_map);
 376   PopulatePacketBitrateStat(end_time,
 377                             PACKET_SENT_TO_NETWORK,
 378                             TRANSMISSION_KBPS,
 379                             stats_map);
 380   PopulatePacketBitrateStat(end_time,
 381                             PACKET_RETRANSMITTED,
 382                             RETRANSMISSION_KBPS,
 383                             stats_map);
 384   PopulateFrameCountStat(FRAME_CAPTURE_END, NUM_FRAMES_CAPTURED, stats_map);
 385   PopulatePacketCountStat(PACKET_SENT_TO_NETWORK, NUM_PACKETS_SENT, stats_map);
 386   PopulatePacketCountStat(
 387       PACKET_RETRANSMITTED, NUM_PACKETS_RETRANSMITTED, stats_map);
 388   PopulatePacketCountStat(PACKET_RECEIVED, NUM_PACKETS_RECEIVED, stats_map);
 389   PopulatePacketCountStat(
 390       PACKET_RTX_REJECTED, NUM_PACKETS_RTX_REJECTED, stats_map);
 391
 392   if (capture_latency_datapoints_ > 0) {
 393     double avg_capture_latency_ms =
 394         total_capture_latency_.InMillisecondsF() /
 395         capture_latency_datapoints_;
 396     stats_map->insert(
 397         std::make_pair(AVG_CAPTURE_LATENCY_MS, avg_capture_latency_ms));
 398   }
 399
 400   if (encode_time_datapoints_ > 0) {
 401     double avg_encode_time_ms =
 402         total_encode_time_.InMillisecondsF() /
 403         encode_time_datapoints_;
 404     stats_map->insert(
 405         std::make_pair(AVG_ENCODE_TIME_MS, avg_encode_time_ms));
 406   }
 407
 408   if (queueing_latency_datapoints_ > 0) {
 409     double avg_queueing_latency_ms =
 410         total_queueing_latency_.InMillisecondsF() /
 411         queueing_latency_datapoints_;
 412     stats_map->insert(
 413         std::make_pair(AVG_QUEUEING_LATENCY_MS, avg_queueing_latency_ms));
 414   }
 415
 416   if (network_latency_datapoints_ > 0) {
 417     double avg_network_latency_ms =
 418         total_network_latency_.InMillisecondsF() /
 419         network_latency_datapoints_;
 420     stats_map->insert(
 421         std::make_pair(AVG_NETWORK_LATENCY_MS, avg_network_latency_ms));
 422   }
 423
 424   if (packet_latency_datapoints_ > 0) {
 425     double avg_packet_latency_ms =
 426         total_packet_latency_.InMillisecondsF() /
 427         packet_latency_datapoints_;
 428     stats_map->insert(
 429         std::make_pair(AVG_PACKET_LATENCY_MS, avg_packet_latency_ms));
 430   }
 431
 432   if (frame_latency_datapoints_ > 0) {
 433     double avg_frame_latency_ms =
 434         total_frame_latency_.InMillisecondsF() / frame_latency_datapoints_;
 435     stats_map->insert(
 436         std::make_pair(AVG_FRAME_LATENCY_MS, avg_frame_latency_ms));
 437   }
 438
 439   if (e2e_latency_datapoints_ > 0) {
 440     double avg_e2e_latency_ms =
 441         total_e2e_latency_.InMillisecondsF() / e2e_latency_datapoints_;
 442     stats_map->insert(std::make_pair(AVG_E2E_LATENCY_MS, avg_e2e_latency_ms));
 443   }
 444
 445   if (!last_response_received_time_.is_null()) {
 446     stats_map->insert(
 447         std::make_pair(MS_SINCE_LAST_RECEIVER_RESPONSE,
 448         (end_time - last_response_received_time_).InMillisecondsF()));
 449   }
 450
 451   stats_map->insert(std::make_pair(NUM_FRAMES_DROPPED_BY_ENCODER,
 452                                    num_frames_dropped_by_encoder_));
 453   stats_map->insert(std::make_pair(NUM_FRAMES_LATE, num_frames_late_));
 454   if (!first_event_time_.is_null()) {
 455     stats_map->insert(std::make_pair(
 456         FIRST_EVENT_TIME_MS,
 457         (first_event_time_ - base::TimeTicks::UnixEpoch()).InMillisecondsF()));
 458   }
 459   if (!last_event_time_.is_null()) {
 460     stats_map->insert(std::make_pair(
 461         LAST_EVENT_TIME_MS,
 462         (last_event_time_ - base::TimeTicks::UnixEpoch()).InMillisecondsF()));
 463   }
 464 }
 465
 466 StatsEventSubscriber::SimpleHistogram*
 467 StatsEventSubscriber::GetHistogramForTesting(
 468     CastStat stats) const {
 469   DCHECK(histograms_.find(stats) != histograms_.end());
 470   return histograms_.find(stats)->second.get();
 471 }
 472
 473 bool StatsEventSubscriber::GetReceiverOffset(base::TimeDelta* offset) {
 474   base::TimeDelta receiver_offset_lower_bound;
 475   base::TimeDelta receiver_offset_upper_bound;
 476   if (!offset_estimator_->GetReceiverOffsetBounds(
 477           &receiver_offset_lower_bound, &receiver_offset_upper_bound)) {
 478     return false;
 479   }
 480
 481   *offset = (receiver_offset_lower_bound + receiver_offset_upper_bound) / 2;
 482   return true;
 483 }
 484
 485 void StatsEventSubscriber::MaybeInsertFrameInfo(RtpTimestamp rtp_timestamp,
 486                                                 const FrameInfo& frame_info) {
 487   // No need to insert if |rtp_timestamp| is the smaller than every key in the
 488   // map as it is just going to get erased anyway.
 489   if (recent_frame_infos_.size() == kMaxFrameInfoMapSize &&
 490       rtp_timestamp < recent_frame_infos_.begin()->first) {
 491     return;
 492   }
 493
 494   recent_frame_infos_.insert(std::make_pair(rtp_timestamp, frame_info));
 495
 496   if (recent_frame_infos_.size() >= kMaxFrameInfoMapSize) {
 497     FrameInfoMap::iterator erase_it = recent_frame_infos_.begin();
 498     if (erase_it->second.encode_end_time.is_null())
 499       num_frames_dropped_by_encoder_++;
 500     recent_frame_infos_.erase(erase_it);
 501   }
 502 }
 503
 504 void StatsEventSubscriber::RecordFrameCaptureTime(
 505     const FrameEvent& frame_event) {
 506   FrameInfo frame_info;
 507   frame_info.capture_time = frame_event.timestamp;
 508   MaybeInsertFrameInfo(frame_event.rtp_timestamp, frame_info);
 509 }
 510
 511 void StatsEventSubscriber::RecordCaptureLatency(const FrameEvent& frame_event) {
 512   FrameInfoMap::iterator it =
 513       recent_frame_infos_.find(frame_event.rtp_timestamp);
 514   if (it == recent_frame_infos_.end()) {
 515     return;
 516   }
 517
 518   if (!it->second.capture_time.is_null()) {
 519     base::TimeDelta latency = frame_event.timestamp - it->second.capture_time;
 520     total_capture_latency_ += latency;
 521     capture_latency_datapoints_++;
 522     histograms_[CAPTURE_LATENCY_MS_HISTO]->Add(latency.InMillisecondsF());
 523   }
 524
 525   it->second.capture_end_time = frame_event.timestamp;
 526 }
 527
 528 void StatsEventSubscriber::RecordEncodeLatency(const FrameEvent& frame_event) {
 529   FrameInfoMap::iterator it =
 530       recent_frame_infos_.find(frame_event.rtp_timestamp);
 531   if (it == recent_frame_infos_.end()) {
 532     FrameInfo frame_info;
 533     frame_info.encode_end_time = frame_event.timestamp;
 534     MaybeInsertFrameInfo(frame_event.rtp_timestamp, frame_info);
 535     return;
 536   }
 537
 538   if (!it->second.capture_end_time.is_null()) {
 539     base::TimeDelta latency =
 540         frame_event.timestamp - it->second.capture_end_time;
 541     total_encode_time_ += latency;
 542     encode_time_datapoints_++;
 543     histograms_[ENCODE_TIME_MS_HISTO]->Add(latency.InMillisecondsF());
 544   }
 545
 546   it->second.encode_end_time = frame_event.timestamp;
 547 }
 548
 549 void StatsEventSubscriber::RecordFrameTxLatency(const FrameEvent& frame_event) {
 550   FrameInfoMap::iterator it =
 551       recent_frame_infos_.find(frame_event.rtp_timestamp);
 552   if (it == recent_frame_infos_.end())
 553     return;
 554
 555   if (it->second.encode_end_time.is_null())
 556     return;
 557
 558   base::TimeDelta receiver_offset;
 559   if (!GetReceiverOffset(&receiver_offset))
 560     return;
 561
 562   base::TimeTicks sender_time = frame_event.timestamp - receiver_offset;
 563   base::TimeDelta latency = sender_time - it->second.encode_end_time;
 564   total_frame_latency_ += latency;
 565   frame_latency_datapoints_++;
 566   histograms_[FRAME_LATENCY_MS_HISTO]->Add(latency.InMillisecondsF());
 567 }
 568
 569 void StatsEventSubscriber::RecordE2ELatency(const FrameEvent& frame_event) {
 570   base::TimeDelta receiver_offset;
 571   if (!GetReceiverOffset(&receiver_offset))
 572     return;
 573
 574   FrameInfoMap::iterator it =
 575       recent_frame_infos_.find(frame_event.rtp_timestamp);
 576   if (it == recent_frame_infos_.end())
 577     return;
 578
 579   // Playout time is event time + playout delay.
 580   base::TimeTicks playout_time =
 581       frame_event.timestamp + frame_event.delay_delta - receiver_offset;
 582   base::TimeDelta latency = playout_time - it->second.capture_time;
 583   total_e2e_latency_ += latency;
 584   e2e_latency_datapoints_++;
 585   histograms_[E2E_LATENCY_MS_HISTO]->Add(latency.InMillisecondsF());
 586 }
 587
 588 void StatsEventSubscriber::UpdateLastResponseTime(
 589     base::TimeTicks receiver_time) {
 590   base::TimeDelta receiver_offset;
 591   if (!GetReceiverOffset(&receiver_offset))
 592     return;
 593   base::TimeTicks sender_time = receiver_time - receiver_offset;
 594   last_response_received_time_ = sender_time;
 595 }
 596
 597 void StatsEventSubscriber::ErasePacketSentTime(
 598     const PacketEvent& packet_event) {
 599   std::pair<RtpTimestamp, uint16> key(
 600       std::make_pair(packet_event.rtp_timestamp, packet_event.packet_id));
 601   packet_sent_times_.erase(key);
 602 }
 603
 604 void StatsEventSubscriber::RecordPacketRelatedLatencies(
 605     const PacketEvent& packet_event) {
 606   // Log queueing latency.
 607   if (packet_event.type == PACKET_SENT_TO_NETWORK) {
 608     FrameInfoMap::iterator it =
 609         recent_frame_infos_.find(packet_event.rtp_timestamp);
 610     if (it != recent_frame_infos_.end()) {
 611       base::TimeDelta latency =
 612           packet_event.timestamp - it->second.encode_end_time;
 613       total_queueing_latency_ += latency;
 614       queueing_latency_datapoints_++;
 615       histograms_[QUEUEING_LATENCY_MS_HISTO]->Add(
 616           latency.InMillisecondsF());
 617     }
 618   }
 619
 620   // Log network latency and total packet latency;
 621   base::TimeDelta receiver_offset;
 622   if (!GetReceiverOffset(&receiver_offset))
 623     return;
 624
 625   std::pair<RtpTimestamp, uint16> key(
 626       std::make_pair(packet_event.rtp_timestamp, packet_event.packet_id));
 627   PacketEventTimeMap::iterator it = packet_sent_times_.find(key);
 628   if (it == packet_sent_times_.end()) {
 629     std::pair<base::TimeTicks, CastLoggingEvent> value =
 630         std::make_pair(packet_event.timestamp, packet_event.type);
 631     packet_sent_times_.insert(std::make_pair(key, value));
 632     if (packet_sent_times_.size() > kMaxPacketEventTimeMapSize)
 633       packet_sent_times_.erase(packet_sent_times_.begin());
 634   } else {
 635     std::pair<base::TimeTicks, CastLoggingEvent> value = it->second;
 636     CastLoggingEvent recorded_type = value.second;
 637     bool match = false;
 638     base::TimeTicks packet_sent_time;
 639     base::TimeTicks packet_received_time;
 640     if (recorded_type == PACKET_SENT_TO_NETWORK &&
 641         packet_event.type == PACKET_RECEIVED) {
 642       packet_sent_time = value.first;
 643       packet_received_time = packet_event.timestamp;
 644       match = true;
 645     } else if (recorded_type == PACKET_RECEIVED &&
 646         packet_event.type == PACKET_SENT_TO_NETWORK) {
 647       packet_sent_time = packet_event.timestamp;
 648       packet_received_time = value.first;
 649       match = true;
 650     }
 651     if (match) {
 652       packet_sent_times_.erase(it);
 653
 654       // Subtract by offset.
 655       packet_received_time -= receiver_offset;
 656       base::TimeDelta latency_delta = packet_received_time - packet_sent_time;
 657
 658       total_network_latency_ += latency_delta;
 659       network_latency_datapoints_++;
 660       histograms_[NETWORK_LATENCY_MS_HISTO]->Add(
 661           latency_delta.InMillisecondsF());
 662
 663       // Log total network latency.
 664       FrameInfoMap::iterator frame_it =
 665           recent_frame_infos_.find(packet_event.rtp_timestamp);
 666       if (frame_it != recent_frame_infos_.end()) {
 667         base::TimeDelta latency =
 668             packet_received_time - frame_it->second.encode_end_time;
 669         total_packet_latency_ += latency;
 670         packet_latency_datapoints_++;
 671         histograms_[PACKET_LATENCY_MS_HISTO]->Add(
 672             latency.InMillisecondsF());
 673       }
 674     }
 675   }
 676 }
 677
 678 void StatsEventSubscriber::PopulateFpsStat(base::TimeTicks end_time,
 679                                            CastLoggingEvent event,
 680                                            CastStat stat,
 681                                            StatsMap* stats_map) const {
 682   FrameStatsMap::const_iterator it = frame_stats_.find(event);
 683   if (it != frame_stats_.end()) {
 684     double fps = 0.0;
 685     base::TimeDelta duration = (end_time - start_time_);
 686     int count = it->second.event_counter;
 687     if (duration > base::TimeDelta())
 688       fps = count / duration.InSecondsF();
 689     stats_map->insert(std::make_pair(stat, fps));
 690   }
 691 }
 692
 693 void StatsEventSubscriber::PopulateFrameCountStat(CastLoggingEvent event,
 694                                                   CastStat stat,
 695                                                   StatsMap* stats_map) const {
 696   FrameStatsMap::const_iterator it = frame_stats_.find(event);
 697   if (it != frame_stats_.end()) {
 698     stats_map->insert(std::make_pair(stat, it->second.event_counter));
 699   }
 700 }
 701
 702 void StatsEventSubscriber::PopulatePacketCountStat(CastLoggingEvent event,
 703                                                    CastStat stat,
 704                                                    StatsMap* stats_map) const {
 705   PacketStatsMap::const_iterator it = packet_stats_.find(event);
 706   if (it != packet_stats_.end()) {
 707     stats_map->insert(std::make_pair(stat, it->second.event_counter));
 708   }
 709 }
 710
 711 void StatsEventSubscriber::PopulateFrameBitrateStat(base::TimeTicks end_time,
 712                                                     StatsMap* stats_map) const {
 713   FrameStatsMap::const_iterator it = frame_stats_.find(FRAME_ENCODED);
 714   if (it != frame_stats_.end()) {
 715     double kbps = 0.0;
 716     base::TimeDelta duration = end_time - start_time_;
 717     if (duration > base::TimeDelta()) {
 718       kbps = it->second.sum_size / duration.InMillisecondsF() * 8;
 719     }
 720
 721     stats_map->insert(std::make_pair(ENCODE_KBPS, kbps));
 722   }
 723 }
 724
 725 void StatsEventSubscriber::PopulatePacketBitrateStat(
 726     base::TimeTicks end_time,
 727     CastLoggingEvent event,
 728     CastStat stat,
 729     StatsMap* stats_map) const {
 730   PacketStatsMap::const_iterator it = packet_stats_.find(event);
 731   if (it != packet_stats_.end()) {
 732     double kbps = 0;
 733     base::TimeDelta duration = end_time - start_time_;
 734     if (duration > base::TimeDelta()) {
 735       kbps = it->second.sum_size / duration.InMillisecondsF() * 8;
 736     }
 737
 738     stats_map->insert(std::make_pair(stat, kbps));
 739   }
 740 }
 741
 742 StatsEventSubscriber::FrameLogStats::FrameLogStats()
 743     : event_counter(0), sum_size(0) {}
 744 StatsEventSubscriber::FrameLogStats::~FrameLogStats() {}
 745
 746 StatsEventSubscriber::PacketLogStats::PacketLogStats()
 747     : event_counter(0), sum_size(0) {}
 748 StatsEventSubscriber::PacketLogStats::~PacketLogStats() {}
 749
 750 StatsEventSubscriber::FrameInfo::FrameInfo() : encoded(false) {
 751 }
 752 StatsEventSubscriber::FrameInfo::~FrameInfo() {
 753 }
 754
 755 }  // namespace cast
 756 }  // namespace media