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 = 1000000;  // 1000 seconds.
@@ skipping 56 matching lines @@
   }
 
   virtual void OnReceivedSendReportRequest() OVERRIDE {
     rtcp_->OnReceivedSendReportRequest();
   }
 
  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,
            bool sending_media,
            uint32 local_ssrc,
            const std::string& c_name)
     : rtcp_interval_(rtcp_interval),
       rtcp_mode_(rtcp_mode),
       sending_media_(sending_media),
       local_ssrc_(local_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_sent_(0),
       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::~Rtcp() {}
 
 // static
 bool Rtcp::IsRtcpPacket(const uint8* packet, size_t length) {
   DCHECK_GE(length, kMinLengthOfRtcp) << "Invalid RTCP packet";
@@ skipping 32 matching lines @@
   if (!rtcp_parser.IsValid()) {
     // Silently ignore packet.
     DLOG(ERROR) << "Received invalid RTCP packet";
     return;
   }
   rtcp_receiver_->IncomingRtcpPacket(&rtcp_parser);
 }
 
 void Rtcp::SendRtcpCast(const RtcpCastMessage& cast_message) {
   uint32 packet_type_flags = 0;
-  base::TimeTicks now = clock_->NowTicks();
+  base::TimeTicks now = cast_environment_->Clock()->NowTicks();
 
   if (rtcp_mode_ == kRtcpCompound || now >= next_time_to_send_rtcp_) {
     if (sending_media_) {
       packet_type_flags = RtcpSender::kRtcpSr;
     } else {
       packet_type_flags = RtcpSender::kRtcpRr;
     }
   }
   packet_type_flags |= RtcpSender::kRtcpCast;
 
+  cast_environment_->Logging()->InsertGenericEvent(kAckSent,
+                                                   cast_message.ack_frame_id_);
+
   SendRtcp(now, packet_type_flags, 0, &cast_message);
 }
 
 void Rtcp::SendRtcpPli(uint32 pli_remote_ssrc) {
   uint32 packet_type_flags = 0;
-  base::TimeTicks now = clock_->NowTicks();
+  base::TimeTicks now = cast_environment_->Clock()->NowTicks();
 
   if (rtcp_mode_ == kRtcpCompound || now >= next_time_to_send_rtcp_) {
     if (sending_media_) {
       packet_type_flags = RtcpSender::kRtcpSr;
     } else {
       packet_type_flags = RtcpSender::kRtcpRr;
     }
   }
   packet_type_flags |= RtcpSender::kRtcpPli;
   SendRtcp(now, packet_type_flags, pli_remote_ssrc, NULL);
 }
 
 void Rtcp::SendRtcpReport(uint32 media_ssrc) {
   uint32 packet_type_flags;
-  base::TimeTicks now = clock_->NowTicks();
+  base::TimeTicks now = cast_environment_->Clock()->NowTicks();
   if (sending_media_) {
     packet_type_flags = RtcpSender::kRtcpSr;
   } else {
     packet_type_flags = RtcpSender::kRtcpRr;
   }
   SendRtcp(now, packet_type_flags, media_ssrc, NULL);
 }
 
 void Rtcp::SendRtcp(const base::TimeTicks& now,
                     uint32 packet_type_flags,
@@ skipping 39 matching lines @@
   } else {
     RtcpReportBlock report_block;
     report_block.remote_ssrc = 0;  // Not needed to set send side.
     report_block.media_ssrc = media_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 16 matching lines @@
                            media_ssrc,
                            NULL,
                            &rrtr,
                            cast_message);
   }
 }
 
 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 22 matching lines @@
       base::TimeDelta::FromMilliseconds(rtp_time_diff_ms);
   return true;
 }
 
 void Rtcp::OnReceivedDelaySinceLastReport(uint32 receivers_ssrc,
                                           uint32 last_report,
                                           uint32 delay_since_last_report) {
   if (last_report_sent_ != last_report)  return;  // Feedback on another report.
   if (time_last_report_sent_.is_null())  return;
 
-  base::TimeDelta sender_delay = clock_->NowTicks() - time_last_report_sent_;
+  base::TimeDelta sender_delay = cast_environment_->Clock()->NowTicks()
+      - time_last_report_sent_;
   UpdateRtt(sender_delay, ConvertFromNtpDiff(delay_since_last_report));
 }
 
 void Rtcp::UpdateRtt(const base::TimeDelta& sender_delay,
                      const base::TimeDelta& receiver_delay) {
   base::TimeDelta rtt = sender_delay - receiver_delay;
   rtt = std::max(rtt, base::TimeDelta::FromMilliseconds(1));
   rtt_ = rtt;
   min_rtt_ = std::min(min_rtt_, rtt);
   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