Incorporating logging into Cast:

1. Adding logging to CastEnvironment.
2. Actually triggering logging within the cast library.
3. Adding thread checks.
4. Removing trace calls outside of the logging class.

Open issues: 
1.Use of rtp_timestamp and frame id is not consistent.
In addition, the AudioBus does not include these values.
2. There is a pending cl to switch frame_id to int. This cl does not include that.
3. There are a few more places to add logging.

As this cl is already big enough, all of the above will come in a follow-up cl.

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

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

chrome/renderer/media/cast_session_delegate.cc

@@ -9,6 +9,7 @@
 #include "content/public/renderer/render_thread.h"
 #include "media/cast/cast_environment.h"
 #include "media/cast/cast_sender.h"
+#include "media/cast/logging/logging_defines.h"
 
 using media::cast::AudioSenderConfig;
 using media::cast::CastEnvironment;
@@ -56,13 +57,15 @@ void CastSessionDelegate::StartSending() {
   // CastSender uses the renderer's IO thread as the main thread. This reduces
   // thread hopping for incoming video frames and outgoing network packets.
   // There's no need to decode so no thread assigned for decoding.
+  // Get default logging: All disabled.
   cast_environment_ = new CastEnvironment(
       &clock_,
       base::MessageLoopProxy::current(),
       audio_encode_thread_.message_loop_proxy(),
       NULL,
       video_encode_thread_.message_loop_proxy(),
-      NULL);
+      NULL,
+      media::cast::GetDefaultCastLoggingConfig());
 
   // TODO(hclam): A couple things need to be done here:
   // 1. Connect media::cast::PacketSender to net::Socket interface.

media/base/audio_bus.h

@@ -47,7 +47,6 @@ class MEDIA_EXPORT AudioBus {
   static scoped_ptr<AudioBus> WrapMemory(int channels, int frames, void* data);
   static scoped_ptr<AudioBus> WrapMemory(const AudioParameters& params,
                                          void* data);
-  // Returns the required memory size to use the WrapMemory() method.
   static int CalculateMemorySize(const AudioParameters& params);
 
   // Calculates the required size for an AudioBus given the number of channels

media/cast/audio_receiver/audio_receiver.cc

@@ -119,7 +119,7 @@ AudioReceiver::AudioReceiver(scoped_refptr<CastEnvironment> cast_environment,
       new LocalRtpReceiverStatistics(rtp_receiver_.get()));
   base::TimeDelta rtcp_interval_delta =
       base::TimeDelta::FromMilliseconds(audio_config.rtcp_interval);
-  rtcp_.reset(new Rtcp(cast_environment->Clock(),
+  rtcp_.reset(new Rtcp(cast_environment,
                        NULL,
                        packet_sender,
                        NULL,
@@ -142,6 +142,10 @@ void AudioReceiver::InitializeTimers() {
 void AudioReceiver::IncomingParsedRtpPacket(const uint8* payload_data,
                                             size_t payload_size,
                                             const RtpCastHeader& rtp_header) {
+  cast_environment_->Logging()->InsertPacketEvent(kPacketReceived,
+      rtp_header.webrtc.header.timestamp, rtp_header.frame_id,
+      rtp_header.packet_id, rtp_header.max_packet_id, payload_size);
+
   // TODO(pwestin): update this as video to refresh over time.
   DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN));
   if (time_first_incoming_packet_.is_null()) {
@@ -216,6 +220,10 @@ void AudioReceiver::DecodeAudioFrameThread(
   base::TimeTicks now = cast_environment_->Clock()->NowTicks();
   base::TimeTicks playout_time;
   playout_time = GetPlayoutTime(now, rtp_timestamp);
+  base::TimeDelta diff = playout_time - now;
+
+  cast_environment_->Logging()->InsertFrameEvent(kAudioPlayoutDelay,
+      rtp_timestamp, diff.InMilliseconds());
 
   // Frame is ready - Send back to the main thread.
   cast_environment_->PostTask(CastEnvironment::MAIN, FROM_HERE,

media/cast/audio_receiver/audio_receiver_unittest.cc

@@ -77,7 +77,8 @@ class AudioReceiverTest : public ::testing::Test {
         base::TimeDelta::FromMilliseconds(kStartMillisecond));
     task_runner_ = new test::FakeTaskRunner(&testing_clock_);
     cast_environment_ = new CastEnvironment(&testing_clock_, task_runner_,
-        task_runner_, task_runner_, task_runner_, task_runner_);
+        task_runner_, task_runner_, task_runner_, task_runner_,
+        GetDefaultCastLoggingConfig());
     test_audio_encoder_callback_ = new TestAudioEncoderCallback();
   }
 

media/cast/audio_sender/audio_encoder_unittest.cc

@@ -97,7 +97,8 @@ class AudioEncoderTest : public ::testing::TestWithParam<TestScenario> {
   virtual void SetUp() {
     task_runner_ = new test::FakeTaskRunner(&testing_clock_);
     cast_environment_ = new CastEnvironment(&testing_clock_, task_runner_,
-        task_runner_, task_runner_, task_runner_, task_runner_);
+        task_runner_, task_runner_, task_runner_, task_runner_,
+        GetDefaultCastLoggingConfig());
   }
 
   virtual ~AudioEncoderTest() {}

media/cast/audio_sender/audio_sender.cc

@@ -10,6 +10,7 @@
 #include "crypto/encryptor.h"
 #include "crypto/symmetric_key.h"
 #include "media/cast/audio_sender/audio_encoder.h"
+#include "media/cast/cast_environment.h"
 #include "media/cast/rtcp/rtcp.h"
 #include "media/cast/rtp_sender/rtp_sender.h"
 
@@ -56,12 +57,12 @@ AudioSender::AudioSender(scoped_refptr<CastEnvironment> cast_environment,
                          const AudioSenderConfig& audio_config,
                          PacedPacketSender* const paced_packet_sender)
       : cast_environment_(cast_environment),
-        rtp_sender_(cast_environment->Clock(), &audio_config, NULL,
+        rtp_sender_(cast_environment, &audio_config, NULL,
                     paced_packet_sender),
         rtcp_feedback_(new LocalRtcpAudioSenderFeedback(this)),
         rtp_audio_sender_statistics_(
             new LocalRtpSenderStatistics(&rtp_sender_)),
-        rtcp_(cast_environment->Clock(),
+        rtcp_(cast_environment,
               rtcp_feedback_.get(),
               paced_packet_sender,
               rtp_audio_sender_statistics_.get(),

media/cast/audio_sender/audio_sender_unittest.cc

@@ -34,7 +34,8 @@ class AudioSenderTest : public ::testing::Test {
   virtual void SetUp() {
     task_runner_ = new test::FakeTaskRunner(&testing_clock_);
     cast_environment_ = new CastEnvironment(&testing_clock_, task_runner_,
-        task_runner_, task_runner_, task_runner_, task_runner_);
+        task_runner_, task_runner_, task_runner_, task_runner_,
+        GetDefaultCastLoggingConfig());
     audio_config_.codec = kOpus;
     audio_config_.use_external_encoder = false;
     audio_config_.frequency = kDefaultAudioSamplingRate;

media/cast/cast.gyp

@@ -14,11 +14,23 @@
       'include_dirs': [
         '<(DEPTH)/',
       ],
+      'dependencies': [
+        '<(DEPTH)/base/base.gyp:base',
+      #  '<(DEPTH)/base/base.gyp:test_support_base',
+      ],
       'sources': [
         'cast_config.cc',
         'cast_config.h',
         'cast_environment.cc',
         'cast_environment.h',
+        'logging/logging_defines.cc',
+        'logging/logging_defines.h',
+        'logging/logging_impl.cc',
+        'logging/logging_impl.h',
+        'logging/logging_raw.cc',
+        'logging/logging_raw.h',
+        'logging/logging_stats.cc',
+        'logging/logging_stats.h',
       ], # source
     },
   ],  # targets,
@@ -32,7 +44,6 @@
             'cast_config',
             'cast_receiver.gyp:cast_receiver',
             'cast_sender.gyp:cast_sender',
-            'logging/logging.gyp:cast_logging',
             'test/utility/utility.gyp:cast_test_utility',
             '<(DEPTH)/base/base.gyp:run_all_unittests',
             '<(DEPTH)/crypto/crypto.gyp:crypto',

media/cast/cast_defines.h

@@ -186,6 +186,13 @@ inline std::string GetAesNonce(uint32 frame_id, const std::string& iv_mask) {
   return aes_nonce;
 }
 
+inline uint32 GetVideoRtpTimestamp(const base::TimeTicks& time_ticks) {
+  base::TimeTicks zero_time;
+  base::TimeDelta recorded_delta = time_ticks - zero_time;
+  // Timestamp is in 90 KHz for video.
+  return static_cast<uint32>(recorded_delta.InMilliseconds() * 90);
+}
+
 }  // namespace cast
 }  // namespace media
 

media/cast/cast_environment.cc

@@ -17,13 +17,15 @@ CastEnvironment::CastEnvironment(
     scoped_refptr<TaskRunner> audio_encode_thread_proxy,
     scoped_refptr<TaskRunner> audio_decode_thread_proxy,
     scoped_refptr<TaskRunner> video_encode_thread_proxy,
-    scoped_refptr<TaskRunner> video_decode_thread_proxy)
+    scoped_refptr<TaskRunner> video_decode_thread_proxy,
+    const CastLoggingConfig& config)
     : clock_(clock),
       main_thread_proxy_(main_thread_proxy),
       audio_encode_thread_proxy_(audio_encode_thread_proxy),
       audio_decode_thread_proxy_(audio_decode_thread_proxy),
       video_encode_thread_proxy_(video_encode_thread_proxy),
-      video_decode_thread_proxy_(video_decode_thread_proxy) {
+      video_decode_thread_proxy_(video_decode_thread_proxy),
+      logging_(new LoggingImpl(clock, main_thread_proxy, config)) {
   DCHECK(main_thread_proxy) << "Main thread required";
 }
 
@@ -62,7 +64,7 @@ scoped_refptr<TaskRunner> CastEnvironment::GetMessageTaskRunnerForThread(
     case CastEnvironment::VIDEO_DECODER:
       return video_decode_thread_proxy_;
     default:
-      NOTREACHED() << "Invalid Thread ID.";
+      NOTREACHED() << "Invalid Thread identifier";
       return NULL;
   }
 }
@@ -80,14 +82,20 @@ bool CastEnvironment::CurrentlyOn(ThreadId identifier) {
     case CastEnvironment::VIDEO_DECODER:
       return video_decode_thread_proxy_->RunsTasksOnCurrentThread();
     default:
-      NOTREACHED() << "Wrong thread identifier";
+      NOTREACHED() << "Invalid thread identifier";
       return false;
   }
 }
 
-base::TickClock* CastEnvironment::Clock() {
+base::TickClock* CastEnvironment::Clock() const {
   return clock_;
 }
 
+LoggingImpl* CastEnvironment::Logging() {
+  DCHECK(CurrentlyOn(CastEnvironment::MAIN)) <<
+      "Must be called from main thread";
+  return logging_.get();
+}
+
 }  // namespace cast
 }  // namespace media

media/cast/cast_environment.h

@@ -10,6 +10,8 @@
 #include "base/task_runner.h"
 #include "base/time/tick_clock.h"
 #include "base/time/time.h"
+#include "media/cast/logging/logging_defines.h"
+#include "media/cast/logging/logging_impl.h"
 
 namespace media {
 namespace cast {
@@ -38,7 +40,8 @@ class CastEnvironment : public base::RefCountedThreadSafe<CastEnvironment> {
                   scoped_refptr<base::TaskRunner> audio_encode_thread_proxy,
                   scoped_refptr<base::TaskRunner> audio_decode_thread_proxy,
                   scoped_refptr<base::TaskRunner> video_encode_thread_proxy,
-                  scoped_refptr<base::TaskRunner> video_decode_thread_proxy);
+                  scoped_refptr<base::TaskRunner> video_decode_thread_proxy,
+                  const CastLoggingConfig& config);
 
   // These are the same methods in message_loop.h, but are guaranteed to either
   // get posted to the MessageLoop if it's still alive, or be deleted otherwise.
@@ -56,7 +59,10 @@ class CastEnvironment : public base::RefCountedThreadSafe<CastEnvironment> {
 
   bool CurrentlyOn(ThreadId identifier);
 
- base::TickClock* Clock();
+  base::TickClock* Clock() const;
+
+  // Logging is not thread safe. Should always be called from the main thread.
+  LoggingImpl* Logging();
 
  protected:
   virtual ~CastEnvironment();
@@ -74,6 +80,8 @@ class CastEnvironment : public base::RefCountedThreadSafe<CastEnvironment> {
   scoped_refptr<base::TaskRunner> video_encode_thread_proxy_;
   scoped_refptr<base::TaskRunner> video_decode_thread_proxy_;
 
+  scoped_ptr<LoggingImpl> logging_;
+
   DISALLOW_COPY_AND_ASSIGN(CastEnvironment);
 };
 

media/cast/cast_sender_impl.cc

@@ -34,6 +34,9 @@ class LocalFrameInput : public FrameInput {
   virtual void InsertRawVideoFrame(const I420VideoFrame* video_frame,
                                    const base::TimeTicks& capture_time,
                                    const base::Closure callback) OVERRIDE {
+  cast_environment_->Logging()->InsertFrameEvent(kVideoFrameReceived,
+      GetVideoRtpTimestamp(capture_time), kFrameIdUnknown);
+
     cast_environment_->PostTask(CastEnvironment::MAIN, FROM_HERE,
         base::Bind(&VideoSender::InsertRawVideoFrame, video_sender_,
             video_frame, capture_time, callback));
@@ -50,6 +53,8 @@ class LocalFrameInput : public FrameInput {
   virtual void InsertAudio(const AudioBus* audio_bus,
                            const base::TimeTicks& recorded_time,
                            const base::Closure& done_callback) OVERRIDE {
+    cast_environment_->Logging()->InsertFrameEvent(kAudioFrameReceived,
+        GetVideoRtpTimestamp(recorded_time), kFrameIdUnknown);
     cast_environment_->PostTask(CastEnvironment::MAIN, FROM_HERE,
         base::Bind(&AudioSender::InsertAudio, audio_sender_,
             audio_bus, recorded_time, done_callback));

media/cast/logging/logging_defines.cc

@@ -9,20 +9,36 @@
 namespace media {
 namespace cast {
 
+CastLoggingConfig::CastLoggingConfig()
+    : enable_data_collection(false),
+      enable_uma_stats(false),
+      enable_tracing(false) {}
+
+CastLoggingConfig::~CastLoggingConfig() {}
+
+CastLoggingConfig GetDefaultCastLoggingConfig() {
+  CastLoggingConfig config;
+  return config;
+}
+
 std::string CastLoggingToString(CastLoggingEvent event) {
   switch (event) {
-    case(kRtt):
-      return "Rtt";
+    case(kRttMs):
+      return "RttMs";
     case(kPacketLoss):
       return "PacketLoss";
-    case(kJitter):
-      return "Jitter";
+    case(kJitterMs):
+      return "JitterMs";
     case(kAckReceived):
       return "AckReceived";
+    case(kRembBitrate):
+      return "RembBitrate";
     case(kAckSent):
       return "AckSent";
     case(kLastEvent):
       return "LastEvent";
+    case(kAudioFrameReceived):
+      return "AudioFrameReceived";
     case(kAudioFrameCaptured):
       return "AudioFrameCaptured";
     case(kAudioFrameEncoded):
@@ -33,6 +49,8 @@ std::string CastLoggingToString(CastLoggingEvent event) {
       return "AudioFrameDecoded";
     case(kVideoFrameCaptured):
       return "VideoFrameCaptured";
+    case(kVideoFrameReceived):
+      return "VideoFrameReceived";
     case(kVideoFrameSentToEncoder):
       return "VideoFrameSentToEncoder";
     case(kVideoFrameEncoded):