Change VLOG levels in media/cast.

Convention:
VLOG(1) for information that's unlikely to flood logs.
VLOG(2) for per-frame information.
VLOG(3) for per-packet information (likely to flood logs).

Certain logs are 'promoted'. For example, per-frame information can
still use VLOG(1) if it does not occur that often or should be
considered important enough to use VLOG(1).

Review URL: https://codereview.chromium.org/191613002

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@256160 0039d316-1c4b-4281-b951-d872f2087c98

media/cast/audio_sender/audio_sender.cc

@@ -25,7 +25,7 @@ class LocalRtcpAudioSenderFeedback : public RtcpSenderFeedback {
     if (!cast_feedback.missing_frames_and_packets_.empty()) {
       audio_sender_->ResendPackets(cast_feedback.missing_frames_and_packets_);
     }
-    VLOG(1) << "Received audio ACK "
+    VLOG(2) << "Received audio ACK "
             << static_cast<int>(cast_feedback.ack_frame_id_);
   }
 

media/cast/framer/cast_message_builder.cc

@@ -58,7 +58,7 @@ void CastMessageBuilder::CompleteFrameReceived(uint32 frame_id,
     BuildPacketList();
   }
   // Send cast message.
-  VLOG(1) << "Send cast message Ack:" << static_cast<int>(frame_id);
+  VLOG(2) << "Send cast message Ack:" << static_cast<int>(frame_id);
   cast_feedback_->CastFeedback(cast_msg_);
 }
 

media/cast/framer/frame_id_map.cc

@@ -73,7 +73,7 @@ PacketType FrameIdMap::InsertPacket(const RtpCastHeader& rtp_header) {
     waiting_for_key_ = false;
   }
 
-  VLOG(1) << "InsertPacket frame:" << frame_id
+  VLOG(3) << "InsertPacket frame:" << frame_id
           << " packet:" << static_cast<int>(rtp_header.packet_id)
           << " max packet:" << static_cast<int>(rtp_header.max_packet_id);
 

media/cast/framer/framer.cc

@@ -61,7 +61,7 @@ bool Framer::InsertPacket(const uint8* payload_data,
   bool complete = (packet_type == kNewPacketCompletingFrame);
   if (complete) {
     // ACK as soon as possible.
-    VLOG(1) << "Complete frame " << static_cast<int>(rtp_header.frame_id);
+    VLOG(2) << "Complete frame " << static_cast<int>(rtp_header.frame_id);
     cast_msg_builder_->CompleteFrameReceived(rtp_header.frame_id,
                                              rtp_header.is_key_frame);
   }

media/cast/rtcp/receiver_rtcp_event_subscriber.cc

@@ -83,7 +83,7 @@ void ReceiverRtcpEventSubscriber::TruncateMapIfNeeded() {
   // If map size has exceeded |max_size_to_retain_|, remove entry with
   // the smallest RTP timestamp.
   if (rtcp_events_.size() > max_size_to_retain_) {
-    DVLOG(2) << "RTCP event map exceeded size limit; "
+    DVLOG(3) << "RTCP event map exceeded size limit; "
              << "removing oldest entry";
     // This is fine since we only insert elements one at a time.
     rtcp_events_.erase(rtcp_events_.begin());

media/cast/rtcp/rtcp_receiver.cc

@@ -175,7 +175,7 @@ void RtcpReceiver::HandleSenderReport(RtcpParser* rtcp_parser) {
   // Synchronization source identifier for the originator of this SR packet.
   uint32 remote_ssrc = rtcp_field.sender_report.sender_ssrc;
 
-  VLOG(1) << "Cast RTCP received SR from SSRC " << remote_ssrc;
+  VLOG(2) << "Cast RTCP received SR from SSRC " << remote_ssrc;
 
   if (remote_ssrc_ == remote_ssrc) {
     transport::RtcpSenderInfo remote_sender_info;
@@ -207,7 +207,7 @@ void RtcpReceiver::HandleReceiverReport(RtcpParser* rtcp_parser) {
 
   uint32 remote_ssrc = rtcp_field.receiver_report.sender_ssrc;
 
-  VLOG(1) << "Cast RTCP received RR from SSRC " << remote_ssrc;
+  VLOG(2) << "Cast RTCP received RR from SSRC " << remote_ssrc;
 
   rtcp_field_type = rtcp_parser->Iterate();
   while (rtcp_field_type == kRtcpReportBlockItemCode) {
@@ -234,7 +234,7 @@ void RtcpReceiver::HandleReportBlock(const RtcpField* rtcp_field,
     // This block is not for us ignore it.
     return;
   }
-  VLOG(1) << "Cast RTCP received RB from SSRC " << remote_ssrc;
+  VLOG(2) << "Cast RTCP received RB from SSRC " << remote_ssrc;
   base::TimeTicks now = cast_environment_->Clock()->NowTicks();
   cast_environment_->Logging()->InsertGenericEvent(
       now, kPacketLoss, rb.fraction_lost);
@@ -267,7 +267,7 @@ void RtcpReceiver::HandleSDES(RtcpParser* rtcp_parser) {
 
 void RtcpReceiver::HandleSDESChunk(RtcpParser* rtcp_parser) {
   const RtcpField& rtcp_field = rtcp_parser->Field();
-  VLOG(1) << "Cast RTCP received SDES with cname " << rtcp_field.c_name.name;
+  VLOG(2) << "Cast RTCP received SDES with cname " << rtcp_field.c_name.name;
 }
 
 void RtcpReceiver::HandleXr(RtcpParser* rtcp_parser) {
@@ -359,7 +359,7 @@ void RtcpReceiver::HandleBYE(RtcpParser* rtcp_parser) {
   const RtcpField& rtcp_field = rtcp_parser->Field();
   uint32 remote_ssrc = rtcp_field.bye.sender_ssrc;
   if (remote_ssrc_ == remote_ssrc) {
-    VLOG(1) << "Cast RTCP received BYE from SSRC " << remote_ssrc;
+    VLOG(2) << "Cast RTCP received BYE from SSRC " << remote_ssrc;
   }
   rtcp_parser->Iterate();
 }
@@ -368,7 +368,7 @@ void RtcpReceiver::HandlePLI(RtcpParser* rtcp_parser) {
   const RtcpField& rtcp_field = rtcp_parser->Field();
   if (ssrc_ == rtcp_field.pli.media_ssrc) {
     // Received a signal that we need to send a new key frame.
-    VLOG(1) << "Cast RTCP received PLI on our SSRC " << ssrc_;
+    VLOG(2) << "Cast RTCP received PLI on our SSRC " << ssrc_;
   }
   rtcp_parser->Iterate();
 }
@@ -399,7 +399,7 @@ void RtcpReceiver::HandleRpsi(RtcpParser* rtcp_parser) {
   }
   rpsi_picture_id += (rtcp_field.rpsi.native_bit_string[bytes - 1] & 0x7f);
 
-  VLOG(1) << "Cast RTCP received RPSI with picture_id " << rpsi_picture_id;
+  VLOG(2) << "Cast RTCP received RPSI with picture_id " << rpsi_picture_id;
 }
 
 void RtcpReceiver::HandlePayloadSpecificApp(RtcpParser* rtcp_parser) {
@@ -443,7 +443,7 @@ void RtcpReceiver::HandlePayloadSpecificRembItem(RtcpParser* rtcp_parser) {
   for (int i = 0; i < rtcp_field.remb_item.number_of_ssrcs; ++i) {
     if (rtcp_field.remb_item.ssrcs[i] == ssrc_) {
       // Found matching ssrc.
-      VLOG(1) << "Cast RTCP received REMB with received_bitrate "
+      VLOG(2) << "Cast RTCP received REMB with received_bitrate "
               << rtcp_field.remb_item.bitrate;
       return;
     }
@@ -632,7 +632,7 @@ void RtcpReceiver::HandleFIRItem(const RtcpField* rtcp_field) {
   if (ssrc_ != rtcp_field->fir_item.ssrc)
     return;
 
-  VLOG(1) << "Cast RTCP received FIR on our SSRC " << ssrc_;
+  VLOG(2) << "Cast RTCP received FIR on our SSRC " << ssrc_;
 }
 
 }  // namespace cast

media/cast/rtcp/rtcp_sender.cc

@@ -153,9 +153,9 @@ bool BuildRtcpReceiverLogMessage(
   DCHECK_GE(kMaxIpPacketSize, start_size + *rtcp_log_size)
       << "Not enough buffer space.";
 
-  VLOG(1) << "number of frames: " << *number_of_frames;
-  VLOG(1) << "total messages to send: " << *total_number_of_messages_to_send;
-  VLOG(1) << "rtcp log size: " << *rtcp_log_size;
+  VLOG(3) << "number of frames: " << *number_of_frames;
+  VLOG(3) << "total messages to send: " << *total_number_of_messages_to_send;
+  VLOG(3) << "rtcp log size: " << *rtcp_log_size;
   return *number_of_frames > 0;
 }
 }  // namespace

media/cast/test/receiver.cc

@@ -158,7 +158,7 @@ class ReceiverDisplay : public InProcessReceiver {
     // Print out the delta between frames.
     if (!last_render_time_.is_null()) {
       base::TimeDelta time_diff = render_time - last_render_time_;
-      VLOG(1) << "Size = " << video_frame->coded_size().ToString()
+      VLOG(2) << "Size = " << video_frame->coded_size().ToString()
               << "; RenderDelay[mS] =  " << time_diff.InMilliseconds();
     }
     last_render_time_ = render_time;
@@ -169,7 +169,7 @@ class ReceiverDisplay : public InProcessReceiver {
     // For audio just print the playout delta between audio frames.
     if (!last_playout_time_.is_null()) {
       base::TimeDelta time_diff = playout_time - last_playout_time_;
-      VLOG(1) << "SampleRate = " << audio_frame->frequency
+      VLOG(2) << "SampleRate = " << audio_frame->frequency
               << "; PlayoutDelay[mS] =  " << time_diff.InMilliseconds();
     }
     last_playout_time_ = playout_time;

media/cast/transport/rtp_sender/packet_storage/packet_storage.cc

@@ -166,7 +166,6 @@ bool PacketStorage::GetPacket(uint8 frame_id,
     return false;
   }
   it->second->GetCopy(packets);
-  VLOG(1) << "Resend " << static_cast<int>(frame_id) << ":" << packet_id;
   return true;
 }
 

media/cast/transport/rtp_sender/rtp_sender.cc

@@ -80,7 +80,7 @@ void RtpSender::ResendPackets(
     bool success = false;
 
     if (packets_set.empty()) {
-      VLOG(1) << "Missing all packets in frame " << static_cast<int>(frame_id);
+      VLOG(3) << "Missing all packets in frame " << static_cast<int>(frame_id);
 
       uint16 packet_id = 0;
       do {
@@ -89,7 +89,7 @@ void RtpSender::ResendPackets(
 
         // Resend packet to the network.
         if (success) {
-          VLOG(1) << "Resend " << static_cast<int>(frame_id) << ":"
+          VLOG(3) << "Resend " << static_cast<int>(frame_id) << ":"
                   << packet_id;
           // Set a unique incremental sequence number for every packet.
           Packet& packet = packets_to_resend.back();
@@ -108,7 +108,7 @@ void RtpSender::ResendPackets(
 
         // Resend packet to the network.
         if (success) {
-          VLOG(1) << "Resend " << static_cast<int>(frame_id) << ":"
+          VLOG(3) << "Resend " << static_cast<int>(frame_id) << ":"
                   << packet_id;
           Packet& packet = packets_to_resend.back();
           UpdateSequenceNumber(&packet);

media/cast/video_receiver/codecs/vp8/vp8_decoder.cc

@@ -62,7 +62,7 @@ bool Vp8Decoder::Decode(const transport::EncodedVideoFrame* encoded_frame,
                         const VideoFrameDecodedCallback& frame_decoded_cb) {
   DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::VIDEO_DECODER));
   const int frame_id_int = static_cast<int>(encoded_frame->frame_id);
-  VLOG(1) << "VP8 decode frame:" << frame_id_int
+  VLOG(2) << "VP8 decode frame:" << frame_id_int
           << " sized:" << encoded_frame->data.size();
 
   if (encoded_frame->data.empty())
@@ -77,7 +77,7 @@ bool Vp8Decoder::Decode(const transport::EncodedVideoFrame* encoded_frame,
           static_cast<unsigned int>(encoded_frame->data.size()),
           0,
           real_time_decoding)) {
-    VLOG(1) << "Failed to decode VP8 frame.";
+    VLOG(1) << "Failed to decode VP8 frame:" << frame_id_int;
     return false;
   }
 
@@ -117,7 +117,7 @@ bool Vp8Decoder::Decode(const transport::EncodedVideoFrame* encoded_frame,
             (img->d_h + 1) / 2,
             decoded_frame.get());
 
-  VLOG(1) << "Decoded frame " << frame_id_int;
+  VLOG(2) << "Decoded frame " << frame_id_int;
 
   // Update logging from the main thread.
   cast_environment_->PostTask(CastEnvironment::MAIN,

media/cast/video_receiver/video_receiver.cc

@@ -300,7 +300,7 @@ bool VideoReceiver::PullEncodedVideoFrame(
             << static_cast<int>((*encoded_frame)->frame_id)
             << " time_until_render:" << time_until_render.InMilliseconds();
   } else {
-    VLOG(1) << "Show frame " << static_cast<int>((*encoded_frame)->frame_id)
+    VLOG(2) << "Show frame " << static_cast<int>((*encoded_frame)->frame_id)
             << " time_until_render:" << time_until_render.InMilliseconds();
   }
   // We have a copy of the frame, release this one.
@@ -326,7 +326,7 @@ void VideoReceiver::PlayoutTimeout() {
     VLOG(1) << "Failed to retrieved a complete frame at this point in time";
     return;
   }
-  VLOG(1) << "PlayoutTimeout retrieved frame "
+  VLOG(2) << "PlayoutTimeout retrieved frame "
           << static_cast<int>(encoded_frame->frame_id);
 
   if (decryptor_.initialized() && !DecryptVideoFrame(&encoded_frame)) {

media/cast/video_sender/video_sender.cc

@@ -450,7 +450,7 @@ void VideoSender::ReceivedAck(uint32 acked_frame_id) {
   cast_environment_->Logging()->InsertFrameEvent(
       now, kVideoAckReceived, rtp_timestamp, acked_frame_id);
 
-  VLOG(1) << "ReceivedAck:" << static_cast<int>(acked_frame_id);
+  VLOG(2) << "ReceivedAck:" << static_cast<int>(acked_frame_id);
   last_acked_frame_id_ = acked_frame_id;
   active_session_ = true;
   UpdateFramesInFlight();
@@ -468,7 +468,7 @@ void VideoSender::UpdateFramesInFlight() {
     } else {
       frames_in_flight = static_cast<uint32>(last_sent_frame_id_) + 1;
     }
-    VLOG(1) << frames_in_flight
+    VLOG(2) << frames_in_flight
             << " Frames in flight; last sent: " << last_sent_frame_id_
             << " last acked:" << last_acked_frame_id_;
     if (frames_in_flight >= max_unacked_frames_) {