Bug 1049323 - Tidy up MSE logging. r=cajbir
authorMatthew Gregan <kinetik@flim.org>
Mon, 11 Aug 2014 13:21:17 +1200
changeset 198813 315d992d811e43f8a57b033723cb9aba79f05ff9
parent 198812 d532a13b92edd6a95ac87741c0c7db5df863f530
child 198814 579f8a1cbf34fb13c718474b6bd36aa8b5e85d12
push id27286
push usernigelbabu@gmail.com
push dateMon, 11 Aug 2014 06:26:45 +0000
treeherdermozilla-central@8c4a1b3a2a8b [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewerscajbir
bugs1049323
milestone34.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 1049323 - Tidy up MSE logging. r=cajbir
content/media/mediasource/MediaSource.cpp
content/media/mediasource/MediaSourceDecoder.cpp
content/media/mediasource/SourceBuffer.cpp
content/media/mediasource/SourceBufferList.cpp
--- a/content/media/mediasource/MediaSource.cpp
+++ b/content/media/mediasource/MediaSource.cpp
@@ -25,20 +25,39 @@
 #include "nsStringGlue.h"
 #include "nsThreadUtils.h"
 #include "prlog.h"
 
 struct JSContext;
 class JSObject;
 
 #ifdef PR_LOGGING
-PRLogModuleInfo* gMediaSourceLog;
-#define MSE_DEBUG(...) PR_LOG(gMediaSourceLog, PR_LOG_DEBUG, (__VA_ARGS__))
+PRLogModuleInfo* GetMediaSourceLog()
+{
+  static PRLogModuleInfo* sLogModule;
+  if (!sLogModule) {
+    sLogModule = PR_NewLogModule("MediaSource");
+  }
+  return sLogModule;
+}
+
+PRLogModuleInfo* GetMediaSourceAPILog()
+{
+  static PRLogModuleInfo* sLogModule;
+  if (!sLogModule) {
+    sLogModule = PR_NewLogModule("MediaSource");
+  }
+  return sLogModule;
+}
+
+#define MSE_DEBUG(...) PR_LOG(GetMediaSourceLog(), PR_LOG_DEBUG, (__VA_ARGS__))
+#define MSE_API(...) PR_LOG(GetMediaSourceAPILog(), PR_LOG_DEBUG, (__VA_ARGS__))
 #else
 #define MSE_DEBUG(...)
+#define MSE_API(...)
 #endif
 
 // Arbitrary limit.
 static const unsigned int MAX_SOURCE_BUFFERS = 16;
 
 namespace mozilla {
 
 static const char* const gMediaSourceTypes[6] = {
@@ -103,16 +122,17 @@ MediaSource::Constructor(const GlobalObj
   }
 
   nsRefPtr<MediaSource> mediaSource = new MediaSource(window);
   return mediaSource.forget();
 }
 
 MediaSource::~MediaSource()
 {
+  MSE_API("MediaSource(%p)::~MediaSource()", this);
 }
 
 SourceBufferList*
 MediaSource::SourceBuffers()
 {
   MOZ_ASSERT_IF(mReadyState == MediaSourceReadyState::Closed, mSourceBuffers->IsEmpty());
   return mSourceBuffers;
 }
@@ -137,33 +157,36 @@ MediaSource::Duration()
     return UnspecifiedNaN<double>();
   }
   return mDuration;
 }
 
 void
 MediaSource::SetDuration(double aDuration, ErrorResult& aRv)
 {
+  MSE_API("MediaSource(%p)::SetDuration(aDuration=%f)", this, aDuration);
   if (aDuration < 0 || IsNaN(aDuration)) {
     aRv.Throw(NS_ERROR_DOM_INVALID_ACCESS_ERR);
     return;
   }
   if (mReadyState != MediaSourceReadyState::Open ||
       mSourceBuffers->AnyUpdating()) {
     aRv.Throw(NS_ERROR_DOM_INVALID_STATE_ERR);
     return;
   }
   DurationChange(aDuration, aRv);
 }
 
 already_AddRefed<SourceBuffer>
 MediaSource::AddSourceBuffer(const nsAString& aType, ErrorResult& aRv)
 {
   nsresult rv = mozilla::IsTypeSupported(aType);
-  MSE_DEBUG("MediaSource::AddSourceBuffer(Type=%s) -> %x", NS_ConvertUTF16toUTF8(aType).get(), rv);
+  MSE_API("MediaSource(%p)::AddSourceBuffer(aType=%s)%s",
+          this, NS_ConvertUTF16toUTF8(aType).get(),
+          rv == NS_OK ? "" : " [not supported]");
   if (NS_FAILED(rv)) {
     aRv.Throw(rv);
     return nullptr;
   }
   if (mSourceBuffers->Length() >= MAX_SOURCE_BUFFERS) {
     aRv.Throw(NS_ERROR_DOM_QUOTA_EXCEEDED_ERR);
     return nullptr;
   }
@@ -180,26 +203,25 @@ MediaSource::AddSourceBuffer(const nsASt
   }
   nsRefPtr<SourceBuffer> sourceBuffer = SourceBuffer::Create(this, NS_ConvertUTF16toUTF8(mimeType));
   if (!sourceBuffer) {
     aRv.Throw(NS_ERROR_FAILURE); // XXX need a better error here
     return nullptr;
   }
   mSourceBuffers->Append(sourceBuffer);
   mActiveSourceBuffers->Append(sourceBuffer);
-  MSE_DEBUG("%p AddSourceBuffer(Type=%s) -> %p", this,
-            NS_ConvertUTF16toUTF8(mimeType).get(), sourceBuffer.get());
+  MSE_DEBUG("MediaSource(%p)::AddSourceBuffer() sourceBuffer=%p", this, sourceBuffer.get());
   return sourceBuffer.forget();
 }
 
 void
 MediaSource::RemoveSourceBuffer(SourceBuffer& aSourceBuffer, ErrorResult& aRv)
 {
   SourceBuffer* sourceBuffer = &aSourceBuffer;
-  MSE_DEBUG("%p RemoveSourceBuffer(Buffer=%p)", this, sourceBuffer);
+  MSE_API("MediaSource(%p)::RemoveSourceBuffer(aSourceBuffer=%p)", this, sourceBuffer);
   if (!mSourceBuffers->Contains(sourceBuffer)) {
     aRv.Throw(NS_ERROR_DOM_NOT_FOUND_ERR);
     return;
   }
   if (sourceBuffer->Updating()) {
     // TODO:
     // abort stream append loop (if running)
     // set updating to false
@@ -218,17 +240,18 @@ MediaSource::RemoveSourceBuffer(SourceBu
   }
   mSourceBuffers->Remove(sourceBuffer);
   // TODO: Free all resources associated with sourceBuffer
 }
 
 void
 MediaSource::EndOfStream(const Optional<MediaSourceEndOfStreamError>& aError, ErrorResult& aRv)
 {
-  MSE_DEBUG("%p EndOfStream(Error=%u)", this, aError.WasPassed() ? uint32_t(aError.Value()) : 0);
+  MSE_API("MediaSource(%p)::EndOfStream(aError=%d)",
+          this, aError.WasPassed() ? uint32_t(aError.Value()) : 0);
   if (mReadyState != MediaSourceReadyState::Open ||
       mSourceBuffers->AnyUpdating()) {
     aRv.Throw(NS_ERROR_DOM_INVALID_STATE_ERR);
     return;
   }
 
   SetReadyState(MediaSourceReadyState::Ended);
   mSourceBuffers->Ended();
@@ -256,44 +279,41 @@ MediaSource::EndOfStream(const Optional<
   default:
     aRv.Throw(NS_ERROR_DOM_INVALID_ACCESS_ERR);
   }
 }
 
 /* static */ bool
 MediaSource::IsTypeSupported(const GlobalObject&, const nsAString& aType)
 {
-#ifdef PR_LOGGING
-  if (!gMediaSourceLog) {
-    gMediaSourceLog = PR_NewLogModule("MediaSource");
-  }
-#endif
   nsresult rv = mozilla::IsTypeSupported(aType);
-  MSE_DEBUG("MediaSource::IsTypeSupported(Type=%s) -> %x", NS_ConvertUTF16toUTF8(aType).get(), rv);
+  MSE_API("MediaSource::IsTypeSupported(aType=%s)%s",
+          NS_ConvertUTF16toUTF8(aType).get(), rv == NS_OK ? "" : " [not supported]");
   return NS_SUCCEEDED(rv);
 }
 
 bool
 MediaSource::Attach(MediaSourceDecoder* aDecoder)
 {
-  MSE_DEBUG("%p Attaching decoder %p owner %p", this, aDecoder, aDecoder->GetOwner());
+  MSE_DEBUG("MediaSource(%p)::Attach(aDecoder=%p) owner=%p", this, aDecoder, aDecoder->GetOwner());
   MOZ_ASSERT(aDecoder);
   if (mReadyState != MediaSourceReadyState::Closed) {
     return false;
   }
   mDecoder = aDecoder;
   mDecoder->AttachMediaSource(this);
   SetReadyState(MediaSourceReadyState::Open);
   return true;
 }
 
 void
 MediaSource::Detach()
 {
-  MSE_DEBUG("%p Detaching decoder %p owner %p", this, mDecoder.get(), mDecoder->GetOwner());
+  MSE_DEBUG("MediaSource(%p)::Detach() mDecoder=%p owner=%p",
+            this, mDecoder.get(), mDecoder->GetOwner());
   MOZ_ASSERT(mDecoder);
   mDecoder->DetachMediaSource();
   mDecoder = nullptr;
   mDuration = UnspecifiedNaN<double>();
   mActiveSourceBuffers->Clear();
   mSourceBuffers->Clear();
   SetReadyState(MediaSourceReadyState::Closed);
 }
@@ -302,29 +322,25 @@ MediaSource::MediaSource(nsPIDOMWindow* 
   : DOMEventTargetHelper(aWindow)
   , mDuration(UnspecifiedNaN<double>())
   , mDecoder(nullptr)
   , mReadyState(MediaSourceReadyState::Closed)
   , mWaitForDataMonitor("MediaSource.WaitForData.Monitor")
 {
   mSourceBuffers = new SourceBufferList(this);
   mActiveSourceBuffers = new SourceBufferList(this);
-
-#ifdef PR_LOGGING
-  if (!gMediaSourceLog) {
-    gMediaSourceLog = PR_NewLogModule("MediaSource");
-  }
-#endif
+  MSE_API("MediaSource(%p)::MediaSource(aWindow=%p) mSourceBuffers=%p mActiveSourceBuffers=%p",
+          this, aWindow, mSourceBuffers.get(), mActiveSourceBuffers.get());
 }
 
 void
 MediaSource::SetReadyState(MediaSourceReadyState aState)
 {
   MOZ_ASSERT(aState != mReadyState);
-  MSE_DEBUG("%p SetReadyState old=%d new=%d", this, mReadyState, aState);
+  MSE_DEBUG("MediaSource(%p)::SetReadyState(aState=%d) mReadyState=%d", this, aState, mReadyState);
 
   MediaSourceReadyState oldState = mReadyState;
   mReadyState = aState;
 
   if (mReadyState == MediaSourceReadyState::Open &&
       (oldState == MediaSourceReadyState::Closed ||
        oldState == MediaSourceReadyState::Ended)) {
     QueueAsyncSimpleEvent("sourceopen");
@@ -345,80 +361,84 @@ MediaSource::SetReadyState(MediaSourceRe
   }
 
   NS_WARNING("Invalid MediaSource readyState transition");
 }
 
 void
 MediaSource::DispatchSimpleEvent(const char* aName)
 {
-  MSE_DEBUG("%p Dispatching event %s to MediaSource", this, aName);
+  MSE_API("MediaSource(%p) Dispatch event '%s'", this, aName);
   DispatchTrustedEvent(NS_ConvertUTF8toUTF16(aName));
 }
 
 void
 MediaSource::QueueAsyncSimpleEvent(const char* aName)
 {
-  MSE_DEBUG("%p Queuing event %s to MediaSource", this, aName);
+  MSE_DEBUG("MediaSource(%p) Queuing event '%s'", this, aName);
   nsCOMPtr<nsIRunnable> event = new AsyncEventRunner<MediaSource>(this, aName);
   NS_DispatchToMainThread(event);
 }
 
 void
 MediaSource::DurationChange(double aNewDuration, ErrorResult& aRv)
 {
+  MSE_DEBUG("MediaSource(%p)::DurationChange(aNewDuration=%f)", this, aNewDuration);
   if (mDuration == aNewDuration) {
     return;
   }
   double oldDuration = mDuration;
   mDuration = aNewDuration;
   if (aNewDuration < oldDuration) {
     mSourceBuffers->Remove(aNewDuration, oldDuration, aRv);
     if (aRv.Failed()) {
       return;
     }
   }
   // TODO: If partial audio frames/text cues exist, clamp duration based on mSourceBuffers.
   // TODO: Update media element's duration and run element's duration change algorithm.
 }
 
+void
+MediaSource::NotifyEvicted(double aStart, double aEnd)
+{
+  MSE_DEBUG("MediaSource(%p)::NotifyEvicted(aStart=%f, aEnd=%f)", this, aStart, aEnd);
+  // Cycle through all SourceBuffers and tell them to evict data in
+  // the given range.
+  mSourceBuffers->Evict(aStart, aEnd);
+}
+
+void
+MediaSource::WaitForData()
+{
+  MSE_DEBUG("MediaSource(%p)::WaitForData()", this);
+  MonitorAutoLock mon(mWaitForDataMonitor);
+  mon.Wait();
+}
+
+void
+MediaSource::NotifyGotData()
+{
+  MSE_DEBUG("MediaSource(%p)::NotifyGotData()", this);
+  MonitorAutoLock mon(mWaitForDataMonitor);
+  mon.NotifyAll();
+}
+
 nsPIDOMWindow*
 MediaSource::GetParentObject() const
 {
   return GetOwner();
 }
 
 JSObject*
 MediaSource::WrapObject(JSContext* aCx)
 {
   return MediaSourceBinding::Wrap(aCx, this);
 }
 
-void
-MediaSource::NotifyEvicted(double aStart, double aEnd)
-{
-  // Cycle through all SourceBuffers and tell them to evict data in
-  // the given range.
-  mSourceBuffers->Evict(aStart, aEnd);
-}
-
-void
-MediaSource::WaitForData()
-{
-  MonitorAutoLock lock(mWaitForDataMonitor);
-  lock.Wait();
-}
-
-void
-MediaSource::NotifyGotData()
-{
-  MonitorAutoLock lock(mWaitForDataMonitor);
-  lock.NotifyAll();
-}
-
 NS_IMPL_CYCLE_COLLECTION_INHERITED(MediaSource, DOMEventTargetHelper,
                                    mSourceBuffers, mActiveSourceBuffers)
 
 NS_IMPL_ADDREF_INHERITED(MediaSource, DOMEventTargetHelper)
 NS_IMPL_RELEASE_INHERITED(MediaSource, DOMEventTargetHelper)
 
 NS_INTERFACE_MAP_BEGIN_CYCLE_COLLECTION_INHERITED(MediaSource)
   NS_INTERFACE_MAP_ENTRY(mozilla::dom::MediaSource)
--- a/content/media/mediasource/MediaSourceDecoder.cpp
+++ b/content/media/mediasource/MediaSourceDecoder.cpp
@@ -25,20 +25,26 @@
 #include "VideoUtils.h"
 
 #ifdef MOZ_FMP4
 #include "MP4Decoder.h"
 #include "MP4Reader.h"
 #endif
 
 #ifdef PR_LOGGING
-extern PRLogModuleInfo* gMediaSourceLog;
-#define MSE_DEBUG(...) PR_LOG(gMediaSourceLog, PR_LOG_DEBUG, (__VA_ARGS__))
+extern PRLogModuleInfo* GetMediaSourceLog();
+extern PRLogModuleInfo* GetMediaSourceAPILog();
+
+#define MSE_DEBUG(...) PR_LOG(GetMediaSourceLog(), PR_LOG_DEBUG, (__VA_ARGS__))
+#define MSE_DEBUGV(...) PR_LOG(GetMediaSourceLog(), PR_LOG_DEBUG+1, (__VA_ARGS__))
+#define MSE_API(...) PR_LOG(GetMediaSourceAPILog(), PR_LOG_DEBUG, (__VA_ARGS__))
 #else
 #define MSE_DEBUG(...)
+#define MSE_DEBUGV(...)
+#define MSE_API(...)
 #endif
 
 namespace mozilla {
 
 namespace dom {
 
 class TimeRanges;
 
@@ -68,75 +74,75 @@ public:
   bool IsWaitingMediaResources() MOZ_OVERRIDE
   {
     return mDecoders.IsEmpty() && mPendingDecoders.IsEmpty();
   }
 
   void RequestAudioData() MOZ_OVERRIDE
   {
     if (!GetAudioReader()) {
-      MSE_DEBUG("%p MSR::RequestAudioData called with no audio reader", this);
+      MSE_DEBUG("MediaSourceReader(%p)::RequestAudioData called with no audio reader", this);
       MOZ_ASSERT(mPendingDecoders.IsEmpty());
       GetCallback()->OnDecodeError();
       return;
     }
     GetAudioReader()->RequestAudioData();
   }
 
   void OnAudioDecoded(AudioData* aSample)
   {
     GetCallback()->OnAudioDecoded(aSample);
   }
 
   void OnAudioEOS()
   {
-    MSE_DEBUG("%p OnAudioEOS %d (%p) EOS (readers=%u)",
+    MSE_DEBUG("MediaSourceReader(%p)::OnAudioEOS %d (%p) EOS (readers=%u)",
               this, mActiveAudioDecoder, mDecoders[mActiveAudioDecoder].get(), mDecoders.Length());
     GetCallback()->OnAudioEOS();
   }
 
   void RequestVideoData(bool aSkipToNextKeyframe, int64_t aTimeThreshold) MOZ_OVERRIDE
   {
     if (!GetVideoReader()) {
-      MSE_DEBUG("%p MSR::RequestVideoData called with no video reader", this);
+      MSE_DEBUG("MediaSourceReader(%p)::RequestVideoData called with no video reader", this);
       MOZ_ASSERT(mPendingDecoders.IsEmpty());
       GetCallback()->OnDecodeError();
       return;
     }
     mTimeThreshold = aTimeThreshold;
     SwitchVideoReaders(SWITCH_OPTIONAL);
     GetVideoReader()->RequestVideoData(aSkipToNextKeyframe, aTimeThreshold);
   }
 
   void OnVideoDecoded(VideoData* aSample)
   {
     if (mDropVideoBeforeThreshold) {
       if (aSample->mTime < mTimeThreshold) {
-        MSE_DEBUG("%p MSR::OnVideoDecoded VideoData mTime %lld below mTimeThreshold %lld",
+        MSE_DEBUG("MediaSourceReader(%p)::OnVideoDecoded mTime=%lld < mTimeThreshold=%lld",
                   this, aSample->mTime, mTimeThreshold);
         delete aSample;
         GetVideoReader()->RequestVideoData(false, mTimeThreshold);
         return;
       }
       mDropVideoBeforeThreshold = false;
     }
     GetCallback()->OnVideoDecoded(aSample);
   }
 
   void OnVideoEOS()
   {
     // End of stream. See if we can switch to another video decoder.
-    MSE_DEBUG("%p MSR::OnVideoEOS %d (%p) (readers=%u)",
+    MSE_DEBUG("MediaSourceReader(%p)::OnVideoEOS %d (%p) (readers=%u)",
               this, mActiveVideoDecoder, mDecoders[mActiveVideoDecoder].get(), mDecoders.Length());
     if (SwitchVideoReaders(SWITCH_FORCED)) {
       // Success! Resume decoding with next video decoder.
       RequestVideoData(false, mTimeThreshold);
     } else {
       // End of stream.
-      MSE_DEBUG("%p MSR::OnVideoEOS %d (%p) EOS (readers=%u)",
+      MSE_DEBUG("MediaSourceReader(%p)::OnVideoEOS %d (%p) EOS (readers=%u)",
                 this, mActiveVideoDecoder, mDecoders[mActiveVideoDecoder].get(), mDecoders.Length());
       GetCallback()->OnVideoEOS();
     }
   }
 
   void OnDecodeError() {
     GetCallback()->OnDecodeError();
   }
@@ -195,26 +201,33 @@ private:
   bool SwitchVideoReaders(SwitchType aType) {
     ReentrantMonitorAutoEnter mon(mDecoder->GetReentrantMonitor());
     MOZ_ASSERT(mActiveVideoDecoder != -1);
 
     InitializePendingDecoders();
 
     for (uint32_t i = mActiveVideoDecoder + 1; i < mDecoders.Length(); ++i) {
       SubBufferDecoder* decoder = mDecoders[i];
+      MSE_DEBUGV("MediaDecoderReader(%p)::SwitchVideoReaders(%d) decoder=%u (%p) discarded=%d"
+                 " hasVideo=%d timeThreshold=%lld startTime=%lld",
+                 this, aType, i, decoder, decoder->IsDiscarded(),
+                 decoder->GetReader()->GetMediaInfo().HasVideo(),
+                 mTimeThreshold, decoder->GetMediaStartTime());
+
       if (decoder->IsDiscarded() || !decoder->GetReader()->GetMediaInfo().HasVideo()) {
         continue;
       }
 
-      if (aType == SWITCH_FORCED || mTimeThreshold >= mDecoders[i]->GetMediaStartTime()) {
+      if (aType == SWITCH_FORCED || mTimeThreshold >= decoder->GetMediaStartTime()) {
         GetVideoReader()->SetIdle();
 
         mActiveVideoDecoder = i;
         mDropVideoBeforeThreshold = true;
-        MSE_DEBUG("%p MSR::SwitchVideoReaders(%d) switching to %d", this, aType, mActiveVideoDecoder);
+        MSE_DEBUG("MediaDecoderReader(%p)::SwitchVideoReaders(%d) switching to %d (%p)",
+                  this, aType, mActiveVideoDecoder, mDecoders[mActiveVideoDecoder].get());
         return true;
       }
     }
 
     return false;
   }
 
   MediaDecoderReader* GetAudioReader() {
@@ -328,16 +341,18 @@ MediaSourceDecoder::GetSeekable(dom::Tim
     // Return empty range.
   } else if (duration > 0 && mozilla::IsInfinite(duration)) {
     nsRefPtr<dom::TimeRanges> bufferedRanges = new dom::TimeRanges();
     GetBuffered(bufferedRanges);
     aSeekable->Add(bufferedRanges->GetStartTime(), bufferedRanges->GetEndTime());
   } else {
     aSeekable->Add(0, duration);
   }
+  MSE_DEBUG("MediaSourceDecoder(%p)::GetSeekable startTime=%f endTime=%f",
+            this, aSeekable->GetStartTime(), aSeekable->GetEndTime());
   return NS_OK;
 }
 
 /*static*/
 already_AddRefed<MediaResource>
 MediaSourceDecoder::CreateResource()
 {
   return nsRefPtr<MediaResource>(new MediaSourceResource()).forget();
@@ -392,48 +407,57 @@ private:
 
 void
 MediaSourceReader::InitializePendingDecoders()
 {
   ReentrantMonitorAutoEnter mon(mDecoder->GetReentrantMonitor());
   for (uint32_t i = 0; i < mPendingDecoders.Length(); ++i) {
     nsRefPtr<SubBufferDecoder> decoder = mPendingDecoders[i];
     MediaDecoderReader* reader = decoder->GetReader();
-    MSE_DEBUG("%p: Initializating subdecoder %p reader %p", this, decoder.get(), reader);
+    MSE_DEBUG("MediaSourceReader(%p): Initializing subdecoder %p reader %p",
+              this, decoder.get(), reader);
 
     MediaInfo mi;
     nsAutoPtr<MetadataTags> tags; // TODO: Handle metadata.
     nsresult rv;
     int64_t startTime = 0;
     {
       ReentrantMonitorAutoExit exitMon(mDecoder->GetReentrantMonitor());
       rv = reader->ReadMetadata(&mi, getter_Transfers(tags));
       if (NS_SUCCEEDED(rv)) {
         reader->FindStartTime(startTime);
       }
     }
     reader->SetIdle();
     if (NS_FAILED(rv)) {
       // XXX: Need to signal error back to owning SourceBuffer.
-      MSE_DEBUG("%p: Reader %p failed to initialize, rv=%x", this, reader, rv);
+      MSE_DEBUG("MediaSourceReader(%p): Reader %p failed to initialize, rv=%x", this, reader, rv);
       continue;
     }
     decoder->SetMediaStartTime(startTime);
 
     bool active = false;
     if (mi.HasVideo() || mi.HasAudio()) {
-      MSE_DEBUG("%p: Reader %p has video=%d audio=%d startTime=%lld",
+      MSE_DEBUG("MediaSourceReader(%p): Reader %p has video=%d audio=%d startTime=%lld",
                 this, reader, mi.HasVideo(), mi.HasAudio(), startTime);
+      if (mi.HasVideo()) {
+        MSE_DEBUG("MediaSourceReader(%p): Reader %p video resolution=%dx%d",
+                  this, reader, mi.mVideo.mDisplay.width, mi.mVideo.mDisplay.height);
+      }
+      if (mi.HasAudio()) {
+        MSE_DEBUG("MediaSourceReader(%p): Reader %p audio sampleRate=%d channels=%d",
+                  this, reader, mi.mAudio.mRate, mi.mAudio.mChannels);
+      }
       active = true;
     }
 
     if (active) {
       mDecoders.AppendElement(decoder);
     } else {
-      MSE_DEBUG("%p: Reader %p not activated", this, reader);
+      MSE_DEBUG("MediaSourceReader(%p): Reader %p not activated", this, reader);
     }
   }
   NS_DispatchToMainThread(new ReleaseDecodersTask(mPendingDecoders));
   MOZ_ASSERT(mPendingDecoders.IsEmpty());
   mDecoder->NotifyWaitingForResourcesStatusChanged();
 }
 
 MediaDecoderReader*
@@ -469,21 +493,22 @@ MediaSourceReader::CreateSubDecoder(cons
   // This reader will then forward them onto the state machine via this
   // reader's callback.
   RefPtr<MediaDataDecodedListener<MediaSourceReader>> callback =
     new MediaDataDecodedListener<MediaSourceReader>(this, aTaskQueue);
   reader->SetCallback(callback);
   reader->SetTaskQueue(aTaskQueue);
   reader->Init(nullptr);
   ReentrantMonitorAutoEnter mon(aParentDecoder->GetReentrantMonitor());
-  MSE_DEBUG("Registered subdecoder %p subreader %p", decoder.get(), reader.get());
+  MSE_DEBUG("MediaSourceReader(%p)::CreateSubDecoder subdecoder %p subreader %p",
+            this, decoder.get(), reader.get());
   decoder->SetReader(reader);
   mPendingDecoders.AppendElement(decoder);
   if (NS_FAILED(static_cast<MediaSourceDecoder*>(mDecoder)->EnqueueDecoderInitialization())) {
-    MSE_DEBUG("%p: Failed to enqueue decoder initialization task", this);
+    MSE_DEBUG("MediaSourceReader(%p): Failed to enqueue decoder initialization task", this);
     return nullptr;
   }
   mDecoder->NotifyWaitingForResourcesStatusChanged();
   return decoder.forget();
 }
 
 namespace {
 class ChangeToHaveMetadata : public nsRunnable {
@@ -505,27 +530,31 @@ private:
   nsRefPtr<AbstractMediaDecoder> mDecoder;
 };
 }
 
 nsresult
 MediaSourceReader::Seek(int64_t aTime, int64_t aStartTime, int64_t aEndTime,
                         int64_t aCurrentTime)
 {
+  MSE_DEBUG("MediaSourceReader(%p)::Seek(aTime=%lld, aStart=%lld, aEnd=%lld, aCurrent=%lld)",
+            this, aTime, aStartTime, aEndTime, aCurrentTime);
   double target = static_cast<double>(aTime) / USECS_PER_S;
   if (!mMediaSource->ActiveSourceBuffers()->AllContainsTime(target)) {
+    MSE_DEBUG("MediaSourceReader(%p)::Seek no active buffer contains target=%f", this, target);
     NS_DispatchToMainThread(new ChangeToHaveMetadata(mDecoder));
   }
 
   // Loop until we have the requested time range in the source buffers.
   // This is a workaround for our lack of async functionality in the
   // MediaDecoderStateMachine. Bug 979104 implements what we need and
   // we'll remove this for an async approach based on that in bug XXXXXXX.
   while (!mMediaSource->ActiveSourceBuffers()->AllContainsTime(target)
          && !IsShutdown()) {
+    MSE_DEBUG("MediaSourceReader(%p)::Seek waiting for target=%f", this, target);
     mMediaSource->WaitForData();
     SwitchVideoReaders(SWITCH_FORCED);
   }
 
   if (IsShutdown()) {
     return NS_OK;
   }
 
@@ -546,30 +575,33 @@ MediaSourceReader::Seek(int64_t aTime, i
 }
 
 nsresult
 MediaSourceReader::GetBuffered(dom::TimeRanges* aBuffered, int64_t aStartTime)
 {
   for (uint32_t i = 0; i < mDecoders.Length(); ++i) {
     nsRefPtr<dom::TimeRanges> r = new dom::TimeRanges();
     mDecoders[i]->GetBuffered(r);
+    MSE_DEBUGV("MediaSourceReader(%p)::GetBuffered i=%u start=%f end=%f%s",
+               this, i, r->GetStartTime(), r->GetEndTime(),
+               mDecoders[i]->IsDiscarded() ? " [discarded]" : "");
     aBuffered->Add(r->GetStartTime(), r->GetEndTime());
   }
   aBuffered->Normalize();
+  MSE_DEBUGV("MediaSourceReader(%p)::GetBuffered start=%f end=%f ranges=%u",
+             this, aBuffered->GetStartTime(), aBuffered->GetEndTime(), aBuffered->Length());
   return NS_OK;
 }
 
 nsresult
 MediaSourceReader::ReadMetadata(MediaInfo* aInfo, MetadataTags** aTags)
 {
-  MSE_DEBUG("%p: MSR::ReadMetadata pending=%u", this, mPendingDecoders.Length());
-
   InitializePendingDecoders();
 
-  MSE_DEBUG("%p: MSR::ReadMetadata decoders=%u", this, mDecoders.Length());
+  MSE_DEBUG("MediaSourceReader(%p)::ReadMetadata decoders=%u", this, mDecoders.Length());
 
   // XXX: Make subdecoder setup async, so that use cases like bug 989888 can
   // work.  This will require teaching the state machine about dynamic track
   // changes (and multiple tracks).
   // Shorter term, make this block until we've got at least one video track
   // and lie about having an audio track, then resample/remix as necessary
   // to match any audio track added later to fit the format we lied about
   // now.  For now we just configure what we've got and cross our fingers.
@@ -579,24 +611,26 @@ MediaSourceReader::ReadMetadata(MediaInf
 
     MediaInfo mi = reader->GetMediaInfo();
 
     if (mi.HasVideo() && !mInfo.HasVideo()) {
       MOZ_ASSERT(mActiveVideoDecoder == -1);
       mActiveVideoDecoder = i;
       mInfo.mVideo = mi.mVideo;
       maxDuration = std::max(maxDuration, mDecoders[i]->GetMediaDuration());
-      MSE_DEBUG("%p: MSR::ReadMetadata video decoder=%u maxDuration=%lld", this, i, maxDuration);
+      MSE_DEBUG("MediaSourceReader(%p)::ReadMetadata video decoder=%u maxDuration=%lld",
+                this, i, maxDuration);
     }
     if (mi.HasAudio() && !mInfo.HasAudio()) {
       MOZ_ASSERT(mActiveAudioDecoder == -1);
       mActiveAudioDecoder = i;
       mInfo.mAudio = mi.mAudio;
       maxDuration = std::max(maxDuration, mDecoders[i]->GetMediaDuration());
-      MSE_DEBUG("%p: MSR::ReadMetadata audio decoder=%u maxDuration=%lld", this, i, maxDuration);
+      MSE_DEBUG("MediaSourceReader(%p)::ReadMetadata audio decoder=%u maxDuration=%lld",
+                this, i, maxDuration);
     }
   }
 
   if (maxDuration != -1) {
     ReentrantMonitorAutoEnter mon(mDecoder->GetReentrantMonitor());
     mDecoder->SetMediaDuration(maxDuration);
     nsRefPtr<nsIRunnable> task (
       NS_NewRunnableMethodWithArg<double>(this, &MediaSourceReader::SetMediaSourceDuration, maxDuration));
--- a/content/media/mediasource/SourceBuffer.cpp
+++ b/content/media/mediasource/SourceBuffer.cpp
@@ -22,20 +22,24 @@
 #include "prlog.h"
 #include "SubBufferDecoder.h"
 #include "mozilla/Preferences.h"
 
 struct JSContext;
 class JSObject;
 
 #ifdef PR_LOGGING
-extern PRLogModuleInfo* gMediaSourceLog;
-#define MSE_DEBUG(...) PR_LOG(gMediaSourceLog, PR_LOG_DEBUG, (__VA_ARGS__))
+extern PRLogModuleInfo* GetMediaSourceLog();
+extern PRLogModuleInfo* GetMediaSourceAPILog();
+
+#define MSE_DEBUG(...) PR_LOG(GetMediaSourceLog(), PR_LOG_DEBUG, (__VA_ARGS__))
+#define MSE_API(...) PR_LOG(GetMediaSourceAPILog(), PR_LOG_DEBUG, (__VA_ARGS__))
 #else
 #define MSE_DEBUG(...)
+#define MSE_API(...)
 #endif
 
 namespace mozilla {
 
 class MediaResource;
 class ReentrantMonitor;
 
 namespace layers {
@@ -78,23 +82,23 @@ void
 SubBufferDecoder::SetMediaDuration(int64_t aDuration)
 {
   mMediaDuration = aDuration;
 }
 
 void
 SubBufferDecoder::UpdateEstimatedMediaDuration(int64_t aDuration)
 {
-  //mParentDecoder->UpdateEstimatedMediaDuration(aDuration);
+  MSE_DEBUG("SubBufferDecoder(%p)::UpdateEstimatedMediaDuration(aDuration=%lld)", this, aDuration);
 }
 
 void
 SubBufferDecoder::SetMediaSeekable(bool aMediaSeekable)
 {
-  //mParentDecoder->SetMediaSeekable(aMediaSeekable);
+  MSE_DEBUG("SubBufferDecoder(%p)::SetMediaSeekable(aMediaSeekable=%d)", this, aMediaSeekable);
 }
 
 layers::ImageContainer*
 SubBufferDecoder::GetImageContainer()
 {
   return mParentDecoder->GetImageContainer();
 }
 
@@ -121,26 +125,33 @@ SubBufferDecoder::ConvertToByteOffset(do
 }
 
 class ContainerParser {
 public:
   virtual ~ContainerParser() {}
 
   virtual bool IsInitSegmentPresent(const uint8_t* aData, uint32_t aLength)
   {
+    MSE_DEBUG("ContainerParser: aLength=%u [%x%x%x%x]",
+              aLength,
+              aLength > 0 ? aData[0] : 0,
+              aLength > 1 ? aData[1] : 0,
+              aLength > 2 ? aData[2] : 0,
+              aLength > 3 ? aData[3] : 0);
     return false;
   }
 
   static ContainerParser* CreateForMIMEType(const nsACString& aType);
 };
 
 class WebMContainerParser : public ContainerParser {
 public:
   bool IsInitSegmentPresent(const uint8_t* aData, uint32_t aLength)
   {
+    ContainerParser::IsInitSegmentPresent(aData, aLength);
     // XXX: This is overly primitive, needs to collect data as it's appended
     // to the SB and handle, rather than assuming everything is present in a
     // single aData segment.
     // 0x1a45dfa3 // EBML
     // ...
     // DocType == "webm"
     // ...
     // 0x18538067 // Segment (must be "unknown" size)
@@ -153,16 +164,17 @@ public:
     return false;
   }
 };
 
 class MP4ContainerParser : public ContainerParser {
 public:
   bool IsInitSegmentPresent(const uint8_t* aData, uint32_t aLength)
   {
+    ContainerParser::IsInitSegmentPresent(aData, aLength);
     // Each MP4 atom has a chunk size and chunk type. The root chunk in an MP4
     // file is the 'ftyp' atom followed by a file type. We just check for a
     // vaguely valid 'ftyp' atom.
 
     if (aLength < 8) {
       return false;
     }
 
@@ -197,32 +209,34 @@ ContainerParser::CreateForMIMEType(const
   return new ContainerParser();
 }
 
 namespace dom {
 
 void
 SourceBuffer::SetMode(SourceBufferAppendMode aMode, ErrorResult& aRv)
 {
+  MSE_API("SourceBuffer(%p)::SetMode(aMode=%d)", this, aMode);
   if (!IsAttached() || mUpdating) {
     aRv.Throw(NS_ERROR_DOM_INVALID_STATE_ERR);
     return;
   }
   MOZ_ASSERT(mMediaSource->ReadyState() != MediaSourceReadyState::Closed);
   if (mMediaSource->ReadyState() == MediaSourceReadyState::Ended) {
     mMediaSource->SetReadyState(MediaSourceReadyState::Open);
   }
   // TODO: Test append state.
   // TODO: If aMode is "sequence", set sequence start time.
   mAppendMode = aMode;
 }
 
 void
 SourceBuffer::SetTimestampOffset(double aTimestampOffset, ErrorResult& aRv)
 {
+  MSE_API("SourceBuffer(%p)::SetTimestampOffset(aTimestampOffset=%d)", this, aTimestampOffset);
   if (!IsAttached() || mUpdating) {
     aRv.Throw(NS_ERROR_DOM_INVALID_STATE_ERR);
     return;
   }
   MOZ_ASSERT(mMediaSource->ReadyState() != MediaSourceReadyState::Closed);
   if (mMediaSource->ReadyState() == MediaSourceReadyState::Ended) {
     mMediaSource->SetReadyState(MediaSourceReadyState::Open);
   }
@@ -238,92 +252,96 @@ SourceBuffer::GetBuffered(ErrorResult& a
     aRv.Throw(NS_ERROR_DOM_INVALID_STATE_ERR);
     return nullptr;
   }
   nsRefPtr<TimeRanges> ranges = new TimeRanges();
   if (mDecoder) {
     mDecoder->GetBuffered(ranges);
   }
   ranges->Normalize();
+  MSE_DEBUG("SourceBuffer(%p)::GetBuffered startTime=%f endTime=%f",
+            this, ranges->GetStartTime(), ranges->GetEndTime());
   return ranges.forget();
 }
 
 void
 SourceBuffer::SetAppendWindowStart(double aAppendWindowStart, ErrorResult& aRv)
 {
+  MSE_API("SourceBuffer(%p)::SetAppendWindowStart(aAppendWindowStart=%d)", this, aAppendWindowStart);
   if (!IsAttached() || mUpdating) {
     aRv.Throw(NS_ERROR_DOM_INVALID_STATE_ERR);
     return;
   }
   if (aAppendWindowStart < 0 || aAppendWindowStart >= mAppendWindowEnd) {
     aRv.Throw(NS_ERROR_DOM_INVALID_ACCESS_ERR);
     return;
   }
   mAppendWindowStart = aAppendWindowStart;
 }
 
 void
 SourceBuffer::SetAppendWindowEnd(double aAppendWindowEnd, ErrorResult& aRv)
 {
+  MSE_API("SourceBuffer(%p)::SetAppendWindowEnd(aAppendWindowEnd=%d)", this, aAppendWindowEnd);
   if (!IsAttached() || mUpdating) {
     aRv.Throw(NS_ERROR_DOM_INVALID_STATE_ERR);
     return;
   }
   if (IsNaN(aAppendWindowEnd) ||
       aAppendWindowEnd <= mAppendWindowStart) {
     aRv.Throw(NS_ERROR_DOM_INVALID_ACCESS_ERR);
     return;
   }
   mAppendWindowEnd = aAppendWindowEnd;
 }
 
 void
 SourceBuffer::AppendBuffer(const ArrayBuffer& aData, ErrorResult& aRv)
 {
+  MSE_API("SourceBuffer(%p)::AppendBuffer(ArrayBuffer)", this);
   aData.ComputeLengthAndData();
-
   AppendData(aData.Data(), aData.Length(), aRv);
 }
 
 void
 SourceBuffer::AppendBuffer(const ArrayBufferView& aData, ErrorResult& aRv)
 {
+  MSE_API("SourceBuffer(%p)::AppendBuffer(ArrayBufferView)", this);
   aData.ComputeLengthAndData();
-
   AppendData(aData.Data(), aData.Length(), aRv);
 }
 
 void
 SourceBuffer::Abort(ErrorResult& aRv)
 {
-  MSE_DEBUG("%p Abort()", this);
+  MSE_API("SourceBuffer(%p)::Abort()", this);
   if (!IsAttached()) {
     aRv.Throw(NS_ERROR_DOM_INVALID_STATE_ERR);
     return;
   }
   if (mMediaSource->ReadyState() != MediaSourceReadyState::Open) {
     aRv.Throw(NS_ERROR_DOM_INVALID_STATE_ERR);
     return;
   }
   if (mUpdating) {
     // TODO: Abort segment parser loop, buffer append, and stream append loop algorithms.
     AbortUpdating();
   }
   // TODO: Run reset parser algorithm.
   mAppendWindowStart = 0;
   mAppendWindowEnd = PositiveInfinity<double>();
 
-  MSE_DEBUG("%p Abort: Discarding decoder.", this);
+  MSE_DEBUG("SourceBuffer(%p)::Abort() Discarding decoder", this);
   DiscardDecoder();
 }
 
 void
 SourceBuffer::Remove(double aStart, double aEnd, ErrorResult& aRv)
 {
-  MSE_DEBUG("%p Remove(Start=%f End=%f)", this, aStart, aEnd);
+  MSE_API("SourceBuffer(%p)::Remove(aStart=%f, aEnd=%f)", this, aStart, aEnd);
   if (!IsAttached() || mUpdating ||
       mMediaSource->ReadyState() != MediaSourceReadyState::Open) {
     aRv.Throw(NS_ERROR_DOM_INVALID_STATE_ERR);
     return;
   }
   if (aStart < 0 || aStart > mMediaSource->Duration() ||
       aEnd <= aStart) {
     aRv.Throw(NS_ERROR_DOM_INVALID_ACCESS_ERR);
@@ -332,24 +350,26 @@ SourceBuffer::Remove(double aStart, doub
   StartUpdating();
   /// TODO: Run coded frame removal algorithm asynchronously (would call StopUpdating()).
   StopUpdating();
 }
 
 void
 SourceBuffer::Detach()
 {
+  MSE_DEBUG("SourceBuffer(%p)::Detach", this);
   Ended();
   DiscardDecoder();
   mMediaSource = nullptr;
 }
 
 void
 SourceBuffer::Ended()
 {
+  MSE_DEBUG("SourceBuffer(%p)::Ended", this);
   if (mDecoder) {
     mDecoder->GetResource()->Ended();
   }
 }
 
 SourceBuffer::SourceBuffer(MediaSource* aMediaSource, const nsACString& aType)
   : DOMEventTargetHelper(aMediaSource->GetParentObject())
   , mMediaSource(aMediaSource)
@@ -358,29 +378,30 @@ SourceBuffer::SourceBuffer(MediaSource* 
   , mAppendWindowEnd(PositiveInfinity<double>())
   , mTimestampOffset(0)
   , mAppendMode(SourceBufferAppendMode::Segments)
   , mUpdating(false)
   , mDecoderInitialized(false)
 {
   MOZ_ASSERT(aMediaSource);
   mParser = ContainerParser::CreateForMIMEType(aType);
-  MSE_DEBUG("%p SourceBuffer: Creating initial decoder.", this);
+  MSE_DEBUG("SourceBuffer(%p)::SourceBuffer: Creating initial decoder.", this);
   InitNewDecoder();
 }
 
 already_AddRefed<SourceBuffer>
 SourceBuffer::Create(MediaSource* aMediaSource, const nsACString& aType)
 {
   nsRefPtr<SourceBuffer> sourceBuffer = new SourceBuffer(aMediaSource, aType);
   return sourceBuffer.forget();
 }
 
 SourceBuffer::~SourceBuffer()
 {
+  MSE_DEBUG("SourceBuffer(%p)::~SourceBuffer", this);
   DiscardDecoder();
 }
 
 MediaSource*
 SourceBuffer::GetParentObject() const
 {
   return mMediaSource;
 }
@@ -389,45 +410,47 @@ JSObject*
 SourceBuffer::WrapObject(JSContext* aCx)
 {
   return SourceBufferBinding::Wrap(aCx, this);
 }
 
 void
 SourceBuffer::DispatchSimpleEvent(const char* aName)
 {
-  MSE_DEBUG("%p Dispatching event %s to SourceBuffer", this, aName);
+  MSE_API("SourceBuffer(%p) Dispatch event '%s'", this, aName);
   DispatchTrustedEvent(NS_ConvertUTF8toUTF16(aName));
 }
 
 void
 SourceBuffer::QueueAsyncSimpleEvent(const char* aName)
 {
-  MSE_DEBUG("%p Queuing event %s to SourceBuffer", this, aName);
+  MSE_DEBUG("SourceBuffer(%p) Queuing event '%s'", this, aName);
   nsCOMPtr<nsIRunnable> event = new AsyncEventRunner<SourceBuffer>(this, aName);
   NS_DispatchToMainThread(event, NS_DISPATCH_NORMAL);
 }
 
 bool
 SourceBuffer::InitNewDecoder()
 {
+  MSE_DEBUG("SourceBuffer(%p)::InitNewDecoder", this);
   MOZ_ASSERT(!mDecoder);
   MediaSourceDecoder* parentDecoder = mMediaSource->GetDecoder();
   nsRefPtr<SubBufferDecoder> decoder = parentDecoder->CreateSubDecoder(mType);
   if (!decoder) {
     return false;
   }
   mDecoder = decoder;
   mDecoderInitialized = false;
   return true;
 }
 
 void
 SourceBuffer::DiscardDecoder()
 {
+  MSE_DEBUG("SourceBuffer(%p)::DiscardDecoder mDecoder=%p", this, mDecoder.get());
   if (mDecoder) {
     mDecoder->SetDiscarded();
   }
   mDecoder = nullptr;
   mDecoderInitialized = false;
 }
 
 void
@@ -454,69 +477,72 @@ SourceBuffer::AbortUpdating()
   mUpdating = false;
   QueueAsyncSimpleEvent("abort");
   QueueAsyncSimpleEvent("updateend");
 }
 
 void
 SourceBuffer::AppendData(const uint8_t* aData, uint32_t aLength, ErrorResult& aRv)
 {
-  MSE_DEBUG("%p AppendBuffer(Data=%u bytes)", this, aLength);
+  MSE_DEBUG("SourceBuffer(%p)::AppendData(aLength=%u)", this, aLength);
   if (!IsAttached() || mUpdating) {
     aRv.Throw(NS_ERROR_DOM_INVALID_STATE_ERR);
     return;
   }
   if (mMediaSource->ReadyState() == MediaSourceReadyState::Ended) {
     mMediaSource->SetReadyState(MediaSourceReadyState::Open);
   }
   // TODO: Run coded frame eviction algorithm.
   // TODO: Test buffer full flag.
   StartUpdating();
   // TODO: Run buffer append algorithm asynchronously (would call StopUpdating()).
   if (mParser->IsInitSegmentPresent(aData, aLength)) {
-    MSE_DEBUG("%p AppendBuffer: New initialization segment.", this);
+    MSE_DEBUG("SourceBuffer(%p)::AppendData: New initialization segment.", this);
     if (mDecoderInitialized) {
       // Existing decoder has been used, time for a new one.
       DiscardDecoder();
     }
 
     // If we've got a decoder here, it's not initialized, so we can use it
     // rather than creating a new one.
     if (!mDecoder && !InitNewDecoder()) {
       aRv.Throw(NS_ERROR_FAILURE); // XXX: Review error handling.
       return;
     }
-    MSE_DEBUG("%p AppendBuffer: Decoder marked as initialized.", this);
+    MSE_DEBUG("SourceBuffer(%p)::AppendData: Decoder marked as initialized.", this);
     mDecoderInitialized = true;
   } else if (!mDecoderInitialized) {
-    MSE_DEBUG("%p AppendBuffer: Non-initialization segment appended during initialization.");
+    MSE_DEBUG("SourceBuffer(%p)::AppendData: Non-init segment appended during initialization.");
     Optional<MediaSourceEndOfStreamError> decodeError(MediaSourceEndOfStreamError::Decode);
     ErrorResult dummy;
     mMediaSource->EndOfStream(decodeError, dummy);
     aRv.Throw(NS_ERROR_FAILURE);
     return;
   }
   // XXX: For future reference: NDA call must run on the main thread.
   mDecoder->NotifyDataArrived(reinterpret_cast<const char*>(aData),
                               aLength,
                               mDecoder->GetResource()->GetLength());
   mDecoder->GetResource()->AppendData(aData, aLength);
 
   // Eviction uses a byte threshold. If the buffer is greater than the
   // number of bytes then data is evicted. The time range for this
   // eviction is reported back to the media source. It will then
-  // evict data before that range across all SourceBuffer's it knows
+  // evict data before that range across all SourceBuffers it knows
   // about.
   const int evict_threshold = 1000000;
   bool evicted = mDecoder->GetResource()->EvictData(evict_threshold);
   if (evicted) {
     double start = 0.0;
     double end = 0.0;
     GetBufferedStartEndTime(&start, &end);
 
+    MSE_DEBUG("SourceBuffer(%p)::AppendBuffer Evict; current start=%f end=%f",
+              this, start, end);
+
     // We notify that we've evicted from the time range 0 through to
     // the current start point.
     mMediaSource->NotifyEvicted(0.0, start);
   }
   StopUpdating();
 
   // Schedule the state machine thread to ensure playback starts
   // if required when data is appended.
@@ -536,26 +562,26 @@ SourceBuffer::GetBufferedStartEndTime(do
   }
   *aStart = ranges->Start(0, dummy);
   *aEnd = ranges->End(ranges->Length() - 1, dummy);
 }
 
 void
 SourceBuffer::Evict(double aStart, double aEnd)
 {
+  MSE_DEBUG("SourceBuffer(%p)::Evict(aStart=%f, aEnd=%f)", this, aStart, aEnd);
   if (!mDecoder) {
     return;
   }
   // Need to map time to byte offset then evict
   int64_t end = mDecoder->ConvertToByteOffset(aEnd);
   if (end > 0) {
     mDecoder->GetResource()->EvictBefore(end);
-  } else {
-    NS_WARNING("SourceBuffer::Evict failed");
   }
+  MSE_DEBUG("SourceBuffer(%p)::Evict offset=%lld", this, end);
 }
 
 bool
 SourceBuffer::ContainsTime(double aTime)
 {
   ErrorResult dummy;
   nsRefPtr<TimeRanges> ranges = GetBuffered(dummy);
   if (!ranges || ranges->Length() == 0) {
--- a/content/media/mediasource/SourceBufferList.cpp
+++ b/content/media/mediasource/SourceBufferList.cpp
@@ -16,20 +16,24 @@
 #include "nsStringGlue.h"
 #include "nsThreadUtils.h"
 #include "prlog.h"
 
 struct JSContext;
 class JSObject;
 
 #ifdef PR_LOGGING
-extern PRLogModuleInfo* gMediaSourceLog;
-#define MSE_DEBUG(...) PR_LOG(gMediaSourceLog, PR_LOG_DEBUG, (__VA_ARGS__))
+extern PRLogModuleInfo* GetMediaSourceLog();
+extern PRLogModuleInfo* GetMediaSourceAPILog();
+
+#define MSE_DEBUG(...) PR_LOG(GetMediaSourceLog(), PR_LOG_DEBUG, (__VA_ARGS__))
+#define MSE_API(...) PR_LOG(GetMediaSourceAPILog(), PR_LOG_DEBUG, (__VA_ARGS__))
 #else
 #define MSE_DEBUG(...)
+#define MSE_API(...)
 #endif
 
 namespace mozilla {
 
 namespace dom {
 
 SourceBufferList::~SourceBufferList()
 {
@@ -94,27 +98,29 @@ SourceBufferList::AnyUpdating()
     }
   }
   return false;
 }
 
 void
 SourceBufferList::Remove(double aStart, double aEnd, ErrorResult& aRv)
 {
+  MSE_DEBUG("SourceBufferList(%p)::Remove(aStart=%f, aEnd=%f", this, aStart, aEnd);
   for (uint32_t i = 0; i < mSourceBuffers.Length(); ++i) {
     mSourceBuffers[i]->Remove(aStart, aEnd, aRv);
     if (aRv.Failed()) {
       return;
     }
   }
 }
 
 void
 SourceBufferList::Evict(double aStart, double aEnd)
 {
+  MSE_DEBUG("SourceBufferList(%p)::Evict(aStart=%f, aEnd=%f)", this, aStart, aEnd);
   for (uint32_t i = 0; i < mSourceBuffers.Length(); ++i) {
     mSourceBuffers[i]->Evict(aStart, aEnd);
   }
 }
 
 bool
 SourceBufferList::AllContainsTime(double aTime)
 {
@@ -132,24 +138,24 @@ SourceBufferList::Ended()
   for (uint32_t i = 0; i < mSourceBuffers.Length(); ++i) {
     mSourceBuffers[i]->Ended();
   }
 }
 
 void
 SourceBufferList::DispatchSimpleEvent(const char* aName)
 {
-  MSE_DEBUG("%p Dispatching event %s to SourceBufferList", this, aName);
+  MSE_API("SourceBufferList(%p) Dispatch event '%s'", this, aName);
   DispatchTrustedEvent(NS_ConvertUTF8toUTF16(aName));
 }
 
 void
 SourceBufferList::QueueAsyncSimpleEvent(const char* aName)
 {
-  MSE_DEBUG("%p Queuing event %s to SourceBufferList", this, aName);
+  MSE_DEBUG("SourceBufferList(%p) Queuing event '%s'", this, aName);
   nsCOMPtr<nsIRunnable> event = new AsyncEventRunner<SourceBufferList>(this, aName);
   NS_DispatchToMainThread(event);
 }
 
 SourceBufferList::SourceBufferList(MediaSource* aMediaSource)
   : DOMEventTargetHelper(aMediaSource->GetParentObject())
   , mMediaSource(aMediaSource)
 {