Bug 1600063 - Add some logging for DecodedStream. r=padenot

Depends on D55981

Differential Revision: https://phabricator.services.mozilla.com/D56375

--HG--
extra : moz-landing-system : lando

dom/media/mediasink/DecodedStream.cpp

@@ -25,6 +25,12 @@ namespace mozilla {
 using media::NullableTimeUnit;
 using media::TimeUnit;
 
+extern LazyLogModule gMediaDecoderLog;
+
+#define LOG_DS(type, fmt, ...)    \
+  MOZ_LOG(gMediaDecoderLog, type, \
+          ("DecodedStream=%p " fmt, this, ##__VA_ARGS__))
+
 /*
  * A container class to make it easier to pass the playback info all the
  * way to DecodedStreamGraphListener from DecodedStream.
@@ -408,6 +414,9 @@ nsresult DecodedStream::Start(const TimeUnit& aStartTime,
   MOZ_ASSERT(mStartTime.isNothing(), "playback already started.");
   MOZ_DIAGNOSTIC_ASSERT(!mOutputTracks.IsEmpty());
 
+  LOG_DS(LogLevel::Debug, "Start() mStartTime=%" PRId64,
+         aStartTime.ToMicroseconds());
+
   mStartTime.emplace(aStartTime);
   mLastOutputTime = TimeUnit::Zero();
   mInfo = aInfo;
@@ -492,6 +501,8 @@ void DecodedStream::Stop() {
   AssertOwnerThread();
   MOZ_ASSERT(mStartTime.isSome(), "playback not started.");
 
+  LOG_DS(LogLevel::Debug, "Stop()");
+
   DisconnectListener();
   ResetVideo(mPrincipalHandle);
   ResetAudio();
@@ -542,6 +553,7 @@ void DecodedStream::SetPlaying(bool aPlaying) {
     return;
   }
 
+  LOG_DS(LogLevel::Debug, "playing (%d) -> (%d)", mPlaying.Ref(), aPlaying);
   mPlaying = aPlaying;
 }
 
@@ -632,6 +644,9 @@ void DecodedStream::SendAudio(double aVolume,
   // is ref-counted.
   mAudioQueue.GetElementsAfter(mData->mNextAudioTime, &audio);
   for (uint32_t i = 0; i < audio.Length(); ++i) {
+    LOG_DS(LogLevel::Verbose, "Queueing audio [%" PRId64 ",%" PRId64 "]",
+           audio[i]->mTime.ToMicroseconds(),
+           audio[i]->GetEndTime().ToMicroseconds());
     SendStreamAudio(mData.get(), mStartTime.ref(), audio[i], &output, rate,
                     aPrincipalHandle);
   }
@@ -881,6 +896,7 @@ void DecodedStream::SendData() {
     return;
   }
 
+  LOG_DS(LogLevel::Verbose, "SendData()");
   SendAudio(mVolume, mPrincipalHandle);
   SendVideo(mPrincipalHandle);
 }
@@ -920,9 +936,14 @@ void DecodedStream::NotifyOutput(int64_t aTime) {
   mLastOutputTime = time;
   auto currentTime = GetPosition();
 
+  LOG_DS(LogLevel::Verbose, "time is now %" PRId64,
+         currentTime.ToMicroseconds());
+
   // Remove audio samples that have been played by MTG from the queue.
   RefPtr<AudioData> a = mAudioQueue.PeekFront();
   for (; a && a->GetEndTime() < currentTime;) {
+    LOG_DS(LogLevel::Debug, "Dropping audio [%" PRId64 ",%" PRId64 "]",
+           a->mTime.ToMicroseconds(), a->GetEndTime().ToMicroseconds());
     RefPtr<AudioData> releaseMe = mAudioQueue.PopFront();
     a = mAudioQueue.PeekFront();
   }
@@ -980,4 +1001,6 @@ void DecodedStream::GetDebugInfo(dom::MediaSinkDebugInfo& aInfo) {
   }
 }
 
+#undef LOG_DS
+
 }  // namespace mozilla