Incorporating logging into Cast

media/cast/rtcp/rtcp.cc

 // Copyright 2013 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "media/cast/rtcp/rtcp.h"
 
-#include "base/debug/trace_event.h"
 #include "base/rand_util.h"
 #include "media/cast/cast_config.h"
 #include "media/cast/cast_defines.h"
+#include "media/cast/cast_environment.h"
 #include "media/cast/rtcp/rtcp_defines.h"
 #include "media/cast/rtcp/rtcp_receiver.h"
 #include "media/cast/rtcp/rtcp_sender.h"
 #include "media/cast/rtcp/rtcp_utility.h"
 #include "net/base/big_endian.h"
 
 namespace media {
 namespace cast {
 
 static const int kMaxRttMs = 10000;  // 10 seconds.
@@ skipping 72 matching lines @@
     const RtcpSenderLogMessage& sender_log)  OVERRIDE {
     // TODO(pwestin): Implement.
     // Add received log messages into our log system.
     NOTIMPLEMENTED();
   }
 
  private:
   Rtcp* rtcp_;
 };
 
-Rtcp::Rtcp(base::TickClock* clock,
+Rtcp::Rtcp(scoped_refptr<CastEnvironment> cast_environment,
            RtcpSenderFeedback* sender_feedback,
            PacedPacketSender* paced_packet_sender,
            RtpSenderStatistics* rtp_sender_statistics,
            RtpReceiverStatistics* rtp_receiver_statistics,
            RtcpMode rtcp_mode,
            const base::TimeDelta& rtcp_interval,
            uint32 local_ssrc,
            uint32 remote_ssrc,
            const std::string& c_name)
     : rtcp_interval_(rtcp_interval),
       rtcp_mode_(rtcp_mode),
       local_ssrc_(local_ssrc),
       remote_ssrc_(remote_ssrc),
       rtp_sender_statistics_(rtp_sender_statistics),
       rtp_receiver_statistics_(rtp_receiver_statistics),
       receiver_feedback_(new LocalRtcpReceiverFeedback(this)),
       rtt_feedback_(new LocalRtcpRttFeedback(this)),
-      rtcp_sender_(new RtcpSender(paced_packet_sender, local_ssrc, c_name)),
+      rtcp_sender_(new RtcpSender(cast_environment, paced_packet_sender,
+                                  local_ssrc, c_name)),
       last_report_received_(0),
       last_received_rtp_timestamp_(0),
       last_received_ntp_seconds_(0),
       last_received_ntp_fraction_(0),
       min_rtt_(base::TimeDelta::FromMilliseconds(kMaxRttMs)),
       number_of_rtt_in_avg_(0),
-      clock_(clock) {
-  rtcp_receiver_.reset(new RtcpReceiver(sender_feedback,
+      cast_environment_(cast_environment) {
+  rtcp_receiver_.reset(new RtcpReceiver(cast_environment,
+                                        sender_feedback,
                                         receiver_feedback_.get(),
                                         rtt_feedback_.get(),
                                         local_ssrc));
   rtcp_receiver_->SetRemoteSSRC(remote_ssrc);
 }
 
 Rtcp::~Rtcp() {}
 
 // static
 bool Rtcp::IsRtcpPacket(const uint8* packet, size_t length) {
@@ skipping 31 matching lines @@
     DLOG(ERROR) << "Received invalid RTCP packet";
     return;
   }
   rtcp_receiver_->IncomingRtcpPacket(&rtcp_parser);
 }
 
 void Rtcp::SendRtcpFromRtpReceiver(const RtcpCastMessage* cast_message,
                                    const RtcpReceiverLogMessage* receiver_log) {
   uint32 packet_type_flags = 0;
 
-  base::TimeTicks now = clock_->NowTicks();
+  base::TimeTicks now = cast_environment_->Clock()->NowTicks();
   RtcpReportBlock report_block;
   RtcpReceiverReferenceTimeReport rrtr;
 
   if (cast_message) {
     packet_type_flags |= RtcpSender::kRtcpCast;
   }
   if (receiver_log) {
     packet_type_flags |= RtcpSender::kRtcpReceiverLog;
   }
   if (rtcp_mode_ == kRtcpCompound || now >= next_time_to_send_rtcp_) {
     packet_type_flags |= RtcpSender::kRtcpRr;
 
     report_block.remote_ssrc = 0;  // Not needed to set send side.
     report_block.media_ssrc = remote_ssrc_;  // SSRC of the RTP packet sender.
     if (rtp_receiver_statistics_) {
       rtp_receiver_statistics_->GetStatistics(
           &report_block.fraction_lost,
           &report_block.cumulative_lost,
           &report_block.extended_high_sequence_number,
           &report_block.jitter);
+      cast_environment_->Logging()->InsertGenericEvent(kJitterMs,
+          report_block.jitter);
+      cast_environment_->Logging()->InsertGenericEvent(kPacketLoss,
+          report_block.fraction_lost);
+
     }
 
     report_block.last_sr = last_report_received_;
     if (!time_last_report_received_.is_null()) {
       uint32 delay_seconds = 0;
       uint32 delay_fraction = 0;
       base::TimeDelta delta = now - time_last_report_received_;
       ConvertTimeToFractions(delta.InMicroseconds(),
                              &delay_seconds,
                              &delay_fraction);
@@ skipping 11 matching lines @@
   rtcp_sender_->SendRtcpFromRtpReceiver(packet_type_flags,
                                         &report_block,
                                         &rrtr,
                                         cast_message,
                                         receiver_log);
 }
 
 void Rtcp::SendRtcpFromRtpSender(
     const RtcpSenderLogMessage* sender_log_message) {
   uint32 packet_type_flags = RtcpSender::kRtcpSr;
-  base::TimeTicks now = clock_->NowTicks();
+  base::TimeTicks now = cast_environment_->Clock()->NowTicks();
 
   RtcpSenderInfo sender_info;
   RtcpDlrrReportBlock dlrr;
 
   if (sender_log_message) packet_type_flags |= RtcpSender::kRtcpSenderLog;
 
   if (rtp_sender_statistics_) {
     rtp_sender_statistics_->GetStatistics(now, &sender_info);
   } else {
     memset(&sender_info, 0, sizeof(sender_info));
@@ skipping 16 matching lines @@
   rtcp_sender_->SendRtcpFromRtpSender(packet_type_flags,
                                       &sender_info,
                                       &dlrr,
                                       sender_log_message);
   UpdateNextTimeToSendRtcp();
 }
 
 void Rtcp::OnReceivedNtp(uint32 ntp_seconds, uint32 ntp_fraction) {
   last_report_received_ = (ntp_seconds << 16) + (ntp_fraction >> 16);
 
-  base::TimeTicks now = clock_->NowTicks();
+  base::TimeTicks now = cast_environment_->Clock()->NowTicks();
   time_last_report_received_ = now;
 }
 
 void Rtcp::OnReceivedLipSyncInfo(uint32 rtp_timestamp,
                                  uint32 ntp_seconds,
                                  uint32 ntp_fraction) {
   last_received_rtp_timestamp_ = rtp_timestamp;
   last_received_ntp_seconds_ = ntp_seconds;
   last_received_ntp_fraction_ = ntp_fraction;
 }
 
 void Rtcp::OnReceivedSendReportRequest() {
-  base::TimeTicks now = clock_->NowTicks();
+  base::TimeTicks now = cast_environment_->Clock()->NowTicks();
 
   // Trigger a new RTCP report at next timer.
   next_time_to_send_rtcp_ = now;
 }
 
 bool Rtcp::RtpTimestampInSenderTime(int frequency, uint32 rtp_timestamp,
       base::TimeTicks* rtp_timestamp_in_ticks) const {
   if (last_received_ntp_seconds_ == 0)  return false;
 
   int wrap = CheckForWrapAround(rtp_timestamp, last_received_rtp_timestamp_);
@@ skipping 23 matching lines @@
   return true;
 }
 
 void Rtcp::OnReceivedDelaySinceLastReport(uint32 receivers_ssrc,
                                           uint32 last_report,
                                           uint32 delay_since_last_report) {
   RtcpSendTimeMap::iterator it = last_reports_sent_map_.find(last_report);
   if (it == last_reports_sent_map_.end()) {
     return;  // Feedback on another report.
   }
-  base::TimeDelta sender_delay = clock_->NowTicks() - it->second;
+
+  base::TimeDelta sender_delay = cast_environment_->Clock()->NowTicks()
+      - it->second;
   UpdateRtt(sender_delay, ConvertFromNtpDiff(delay_since_last_report));
 }
 
 void Rtcp::SaveLastSentNtpTime(const base::TimeTicks& now,
                                uint32 last_ntp_seconds,
                                uint32 last_ntp_fraction) {
   // Make sure |now| is always greater than the last element in
   // |last_reports_sent_queue_|.
   if (!last_reports_sent_queue_.empty()) {
     DCHECK(now >= last_reports_sent_queue_.back().second);
@@ skipping 26 matching lines @@
   max_rtt_ = std::max(max_rtt_, rtt);
 
   if (number_of_rtt_in_avg_ != 0) {
     float ac = static_cast<float>(number_of_rtt_in_avg_);
     avg_rtt_ms_= ((ac / (ac + 1.0)) * avg_rtt_ms_) +
         ((1.0 / (ac + 1.0)) * rtt.InMilliseconds());
   } else {
     avg_rtt_ms_ = rtt.InMilliseconds();
   }
   number_of_rtt_in_avg_++;
-  TRACE_COUNTER_ID1("cast_rtcp", "RTT", local_ssrc_, rtt.InMilliseconds());
 }
 
 bool Rtcp::Rtt(base::TimeDelta* rtt,
                base::TimeDelta* avg_rtt,
                base::TimeDelta* min_rtt,
                base::TimeDelta* max_rtt) const {
   DCHECK(rtt) << "Invalid argument";
   DCHECK(avg_rtt) << "Invalid argument";
   DCHECK(min_rtt) << "Invalid argument";
   DCHECK(max_rtt) << "Invalid argument";
 
-  if (number_of_rtt_in_avg_ == 0)  return false;
+  if (number_of_rtt_in_avg_ == 0) return false;
+  cast_environment_->Logging()->InsertGenericEvent(kRttMs,
+                                                   rtt->InMilliseconds());
 
   *rtt = rtt_;
   *avg_rtt = base::TimeDelta::FromMilliseconds(avg_rtt_ms_);
   *min_rtt = min_rtt_;
   *max_rtt = max_rtt_;
   return true;
 }
 
 int Rtcp::CheckForWrapAround(uint32 new_timestamp,
                              uint32 old_timestamp) const {
@@ skipping 10 matching lines @@
     return -1;
   }
   return 0;
 }
 
 void Rtcp::UpdateNextTimeToSendRtcp() {
   int random = base::RandInt(0, 999);
   base::TimeDelta time_to_next = (rtcp_interval_ / 2) +
       (rtcp_interval_ * random / 1000);
 
-  base::TimeTicks now = clock_->NowTicks();
+  base::TimeTicks now = cast_environment_->Clock()->NowTicks();
   next_time_to_send_rtcp_ = now + time_to_next;
 }
 
 }  // namespace cast
 }  // namespace media