Bug 1346005: add audio samples-inserted logging using AudioLatency:4 r=padenot
☠☠ backed out by 3a2b595587f8 ☠ ☠
authorRandell Jesup <rjesup@jesup.org>
Fri, 10 Mar 2017 15:22:42 -0500
changeset 397733 2b23902cadd88baa085f7e1f8c8ccb193e23b305
parent 397732 2140db6f8e483685dccc150d64963aa351758d39
child 397734 3c437072e721cba38ef7d1faed22a78bd7880f19
push id1490
push usermtabara@mozilla.com
push dateMon, 31 Jul 2017 14:08:16 +0000
treeherdermozilla-release@70e32e6bf15e [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewerspadenot
bugs1346005
milestone55.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1346005: add audio samples-inserted logging using AudioLatency:4 r=padenot MozReview-Commit-ID: JZukIfjapuy
dom/media/webrtc/MediaEngineWebRTC.h
dom/media/webrtc/MediaEngineWebRTCAudio.cpp
media/webrtc/signaling/src/mediapipeline/MediaPipeline.cpp
--- a/dom/media/webrtc/MediaEngineWebRTC.h
+++ b/dom/media/webrtc/MediaEngineWebRTC.h
@@ -568,16 +568,18 @@ private:
   int mChannel;
   MOZ_INIT_OUTSIDE_CTOR TrackID mTrackID;
   bool mStarted;
 
   nsString mDeviceName;
   nsCString mDeviceUUID;
 
   int32_t mSampleFrequency;
+  uint64_t mTotalFrames;
+  uint64_t mLastLogFrames;
   int32_t mPlayoutDelay;
 
   NullTransport *mNullTransport;
 
   nsTArray<int16_t> mInputBuffer;
   // mSkipProcessing is true if none of the processing passes are enabled,
   // because of prefs or constraints. This allows simply copying the audio into
   // the MSG, skipping resampling and the whole webrtc.org code.
--- a/dom/media/webrtc/MediaEngineWebRTCAudio.cpp
+++ b/dom/media/webrtc/MediaEngineWebRTCAudio.cpp
@@ -35,16 +35,21 @@ namespace mozilla {
 #ifdef LOG
 #undef LOG
 #endif
 
 extern LogModule* GetMediaManagerLog();
 #define LOG(msg) MOZ_LOG(GetMediaManagerLog(), mozilla::LogLevel::Debug, msg)
 #define LOG_FRAMES(msg) MOZ_LOG(GetMediaManagerLog(), mozilla::LogLevel::Verbose, msg)
 
+LogModule* AudioLogModule() {
+  static mozilla::LazyLogModule log("AudioLatency");
+  return static_cast<LogModule*>(log);
+}
+
 /**
  * Webrtc microphone source source.
  */
 NS_IMPL_ISUPPORTS0(MediaEngineWebRTCMicrophoneSource)
 NS_IMPL_ISUPPORTS0(MediaEngineWebRTCAudioCaptureSource)
 
 // XXX temp until MSG supports registration
 StaticRefPtr<AudioOutputObserver> gFarendObserver;
@@ -193,16 +198,18 @@ MediaEngineWebRTCMicrophoneSource::Media
   , mVoiceEngine(aVoiceEnginePtr)
   , mAudioInput(aAudioInput)
   , mMonitor("WebRTCMic.Monitor")
   , mCapIndex(aIndex)
   , mChannel(-1)
   , mTrackID(TRACK_NONE)
   , mStarted(false)
   , mSampleFrequency(MediaEngine::DEFAULT_SAMPLE_RATE)
+  , mTotalFrames(0)
+  , mLastLogFrames(0)
   , mPlayoutDelay(0)
   , mNullTransport(nullptr)
   , mSkipProcessing(false)
 {
   MOZ_ASSERT(aVoiceEnginePtr);
   MOZ_ASSERT(aAudioInput);
   mDeviceName.Assign(NS_ConvertUTF8toUTF16(name));
   mDeviceUUID.Assign(uuid);
@@ -573,16 +580,26 @@ void
 MediaEngineWebRTCMicrophoneSource::InsertInGraph(const T* aBuffer,
                                                  size_t aFrames,
                                                  uint32_t aChannels)
 {
   if (mState != kStarted) {
     return;
   }
 
+  if (MOZ_LOG_TEST(AudioLogModule(), LogLevel::Debug)) {
+    mTotalFrames += aFrames;
+    if (mTotalFrames > mLastLogFrames + mSampleFrequency) { // ~ 1 second
+      MOZ_LOG(AudioLogModule(), LogLevel::Debug,
+              ("%p: Inserting %" PRIuSIZE " samples into graph, total frames = %" PRIu64,
+               (void*)this, aFrames, mTotalFrames));
+      mLastLogFrames = mTotalFrames;
+    }
+  }
+
   size_t len = mSources.Length();
   for (size_t i = 0; i < len; i++) {
     if (!mSources[i]) {
       continue;
     }
     RefPtr<SharedBuffer> buffer =
       SharedBuffer::Create(aFrames * aChannels * sizeof(T));
     PodCopy(static_cast<T*>(buffer->Data()),
--- a/media/webrtc/signaling/src/mediapipeline/MediaPipeline.cpp
+++ b/media/webrtc/signaling/src/mediapipeline/MediaPipeline.cpp
@@ -67,16 +67,17 @@ using namespace mozilla;
 using namespace mozilla::dom;
 using namespace mozilla::gfx;
 using namespace mozilla::layers;
 
 // Logging context
 MOZ_MTLOG_MODULE("mediapipeline")
 
 namespace mozilla {
+extern mozilla::LogModule* AudioLogModule();
 
 class VideoConverterListener
 {
 public:
   NS_INLINE_DECL_THREADSAFE_REFCOUNTING(VideoConverterListener)
 
   virtual void OnVideoFrameConverted(unsigned char* aVideoFrame,
                                      unsigned int aVideoFrameLength,
@@ -1834,16 +1835,17 @@ static void AddListener(MediaStream* sou
 
 class GenericReceiveListener : public MediaStreamListener
 {
  public:
   GenericReceiveListener(SourceMediaStream *source, TrackID track_id)
     : source_(source),
       track_id_(track_id),
       played_ticks_(0),
+      last_log_(0),
       principal_handle_(PRINCIPAL_HANDLE_NONE) {}
 
   virtual ~GenericReceiveListener() {}
 
   void AddSelf()
   {
     AddListener(source_, this);
   }
@@ -1883,16 +1885,17 @@ class GenericReceiveListener : public Me
   {
     principal_handle_ = principal_handle;
   }
 
  protected:
   SourceMediaStream *source_;
   const TrackID track_id_;
   TrackTicks played_ticks_;
+  TrackTicks last_log_; // played_ticks_ when we last logged
   PrincipalHandle principal_handle_;
 };
 
 MediaPipelineReceive::MediaPipelineReceive(
     const std::string& pc,
     nsCOMPtr<nsIEventTarget> main_thread,
     nsCOMPtr<nsIEventTarget> sts_thread,
     SourceMediaStream *stream,
@@ -2009,16 +2012,24 @@ public:
       outputChannels.AppendElements(channels);
 
       segment.AppendFrames(samples.forget(), outputChannels, frames,
                            principal_handle_);
 
       // Handle track not actually added yet or removed/finished
       if (source_->AppendToTrack(track_id_, &segment)) {
         played_ticks_ += frames;
+        if (MOZ_LOG_TEST(AudioLogModule(), LogLevel::Debug)) {
+          if (played_ticks_ > last_log_ + WEBRTC_DEFAULT_SAMPLE_RATE) { // ~ 1 second
+            MOZ_LOG(AudioLogModule(), LogLevel::Debug,
+                    ("%p: Inserting %" PRIuSIZE " samples into track %d, total = %" PRIu64,
+                     (void*) this, frames, track_id_, played_ticks_));
+            last_log_ = played_ticks_;
+          }
+        }
       } else {
         MOZ_MTLOG(ML_ERROR, "AppendToTrack failed");
         // we can't un-read the data, but that's ok since we don't want to
         // buffer - but don't i-loop!
         return;
       }
     }
   }