Bug 998168 - add decoder pointer to the log message of MediaDecoderStateMachine/MediaDecoder for debugging. r=cpearce
authorJW Wang <jwwang@mozilla.com>
Wed, 23 Apr 2014 05:29:04 -0400
changeset 179694 d97882e9c503b30a66c3e842156d3a152a8adfb1
parent 179693 368a6f1f7eea8b7a99a2f89b32649aec499291ac
child 179695 243bf2777fa46e67016265f46ee2e23e889805a6
push id42590
push userrjesup@wgate.com
push dateWed, 23 Apr 2014 09:30:22 +0000
treeherdermozilla-inbound@243bf2777fa4 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewerscpearce
bugs998168
milestone31.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 998168 - add decoder pointer to the log message of MediaDecoderStateMachine/MediaDecoder for debugging. r=cpearce
content/media/MediaDecoder.cpp
content/media/MediaDecoderStateMachine.cpp
--- a/content/media/MediaDecoder.cpp
+++ b/content/media/MediaDecoder.cpp
@@ -43,21 +43,25 @@ static const uint32_t STALL_MS = 3000;
 // Number of estimated seconds worth of data we need to have buffered
 // ahead of the current playback position before we allow the media decoder
 // to report that it can play through the entire media without the decode
 // catching up with the download. Having this margin make the
 // MediaDecoder::CanPlayThrough() calculation more stable in the case of
 // fluctuating bitrates.
 static const int64_t CAN_PLAY_THROUGH_MARGIN = 1;
 
+// avoid redefined macro in unified build
+#undef DECODER_LOG
+
 #ifdef PR_LOGGING
 PRLogModuleInfo* gMediaDecoderLog;
-#define DECODER_LOG(type, msg) PR_LOG(gMediaDecoderLog, type, msg)
+#define DECODER_LOG(type, msg, ...) \
+  PR_LOG(gMediaDecoderLog, type, ("Decoder=%p " msg, this, ##__VA_ARGS__))
 #else
-#define DECODER_LOG(type, msg)
+#define DECODER_LOG(type, msg, ...)
 #endif
 
 class MediaMemoryTracker : public nsIMemoryReporter
 {
   NS_DECL_THREADSAFE_ISUPPORTS
   NS_DECL_NSIMEMORYREPORTER
 
   MOZ_DEFINE_MALLOC_SIZE_OF(MallocSizeOf);
@@ -309,18 +313,17 @@ void MediaDecoder::UpdateStreamBlockingF
     }
   }
 }
 
 void MediaDecoder::RecreateDecodedStream(int64_t aStartTimeUSecs)
 {
   MOZ_ASSERT(NS_IsMainThread());
   GetReentrantMonitor().AssertCurrentThreadIn();
-  DECODER_LOG(PR_LOG_DEBUG, ("MediaDecoder::RecreateDecodedStream this=%p aStartTimeUSecs=%lld!",
-                             this, (long long)aStartTimeUSecs));
+  DECODER_LOG(PR_LOG_DEBUG, "RecreateDecodedStream aStartTimeUSecs=%lld!", aStartTimeUSecs);
 
   DestroyDecodedStream();
 
   mDecodedStream = new DecodedStreamData(this, aStartTimeUSecs,
     MediaStreamGraph::GetInstance()->CreateSourceStream(nullptr));
 
   // Note that the delay between removing ports in DestroyDecodedStream
   // and adding new ones won't cause a glitch since all graph operations
@@ -342,18 +345,17 @@ void MediaDecoder::RecreateDecodedStream
     mDecodedStream->mStream->ChangeExplicitBlockerCount(1);
   }
 }
 
 void MediaDecoder::AddOutputStream(ProcessedMediaStream* aStream,
                                    bool aFinishWhenEnded)
 {
   MOZ_ASSERT(NS_IsMainThread());
-  DECODER_LOG(PR_LOG_DEBUG, ("MediaDecoder::AddOutputStream this=%p aStream=%p!",
-                             this, aStream));
+  DECODER_LOG(PR_LOG_DEBUG, "AddOutputStream aStream=%p!", aStream);
 
   {
     ReentrantMonitorAutoEnter mon(GetReentrantMonitor());
     if (!mDecodedStream) {
       RecreateDecodedStream(mDecoderStateMachine ?
           int64_t(mDecoderStateMachine->GetCurrentTime()*USECS_PER_S) : 0);
     }
     OutputStreamData* os = mOutputStreams.AppendElement();
@@ -504,49 +506,49 @@ nsresult MediaDecoder::OpenResource(nsIS
   {
     // Hold the lock while we do this to set proper lock ordering
     // expectations for dynamic deadlock detectors: decoder lock(s)
     // should be grabbed before the cache lock
     ReentrantMonitorAutoEnter mon(GetReentrantMonitor());
 
     nsresult rv = mResource->Open(aStreamListener);
     if (NS_FAILED(rv)) {
-      DECODER_LOG(PR_LOG_DEBUG, ("%p Failed to open stream!", this));
+      DECODER_LOG(PR_LOG_WARNING, "Failed to open stream!");
       return rv;
     }
   }
   return NS_OK;
 }
 
 nsresult MediaDecoder::Load(nsIStreamListener** aStreamListener,
                             MediaDecoder* aCloneDonor)
 {
   MOZ_ASSERT(NS_IsMainThread());
 
   nsresult rv = OpenResource(aStreamListener);
   NS_ENSURE_SUCCESS(rv, rv);
 
   mDecoderStateMachine = CreateStateMachine();
   if (!mDecoderStateMachine) {
-    DECODER_LOG(PR_LOG_DEBUG, ("%p Failed to create state machine!", this));
+    DECODER_LOG(PR_LOG_WARNING, "Failed to create state machine!");
     return NS_ERROR_FAILURE;
   }
 
   return InitializeStateMachine(aCloneDonor);
 }
 
 nsresult MediaDecoder::InitializeStateMachine(MediaDecoder* aCloneDonor)
 {
   MOZ_ASSERT(NS_IsMainThread());
   NS_ASSERTION(mDecoderStateMachine, "Cannot initialize null state machine!");
 
   MediaDecoder* cloneDonor = static_cast<MediaDecoder*>(aCloneDonor);
   if (NS_FAILED(mDecoderStateMachine->Init(cloneDonor ?
                                            cloneDonor->mDecoderStateMachine : nullptr))) {
-    DECODER_LOG(PR_LOG_DEBUG, ("%p Failed to init state machine!", this));
+    DECODER_LOG(PR_LOG_WARNING, "Failed to init state machine!");
     return NS_ERROR_FAILURE;
   }
   {
     ReentrantMonitorAutoEnter mon(GetReentrantMonitor());
     mDecoderStateMachine->SetTransportSeekable(mTransportSeekable);
     mDecoderStateMachine->SetMediaSeekable(mMediaSeekable);
     mDecoderStateMachine->SetDuration(mDuration);
     mDecoderStateMachine->SetVolume(mInitialVolume);
@@ -1228,17 +1230,17 @@ void MediaDecoder::DurationChanged()
   int64_t oldDuration = mDuration;
   mDuration = mDecoderStateMachine ? mDecoderStateMachine->GetDuration() : -1;
   // Duration has changed so we should recompute playback rate
   UpdatePlaybackRate();
 
   SetInfinite(mDuration == -1);
 
   if (mOwner && oldDuration != mDuration && !IsInfinite()) {
-    DECODER_LOG(PR_LOG_DEBUG, ("%p duration changed to %lld", this, mDuration));
+    DECODER_LOG(PR_LOG_DEBUG, "Duration changed to %lld", mDuration);
     mOwner->DispatchEvent(NS_LITERAL_STRING("durationchange"));
   }
 }
 
 void MediaDecoder::SetDuration(double aDuration)
 {
   MOZ_ASSERT(NS_IsMainThread());
   if (mozilla::IsInfinite(aDuration)) {
@@ -1794,8 +1796,10 @@ MediaMemoryTracker::InitMemoryReporter()
 
 MediaMemoryTracker::~MediaMemoryTracker()
 {
   UnregisterWeakMemoryReporter(this);
 }
 
 } // namespace mozilla
 
+// avoid redefined macro in unified build
+#undef DECODER_LOG
--- a/content/media/MediaDecoderStateMachine.cpp
+++ b/content/media/MediaDecoderStateMachine.cpp
@@ -38,21 +38,33 @@
 #include <algorithm>
 
 namespace mozilla {
 
 using namespace mozilla::layers;
 using namespace mozilla::dom;
 using namespace mozilla::gfx;
 
+// avoid redefined macro in unified build
+#undef DECODER_LOG
+#undef VERBOSE_LOG
+
 #ifdef PR_LOGGING
 extern PRLogModuleInfo* gMediaDecoderLog;
-#define DECODER_LOG(type, msg) PR_LOG(gMediaDecoderLog, type, msg)
+#define DECODER_LOG(type, msg, ...) \
+  PR_LOG(gMediaDecoderLog, type, ("Decoder=%p " msg, mDecoder.get(), ##__VA_ARGS__))
+#define VERBOSE_LOG(msg, ...)                          \
+    PR_BEGIN_MACRO                                     \
+      if (!PR_GetEnv("MOZ_QUIET")) {                   \
+        DECODER_LOG(PR_LOG_DEBUG, msg, ##__VA_ARGS__); \
+      }                                                \
+    PR_END_MACRO
 #else
-#define DECODER_LOG(type, msg)
+#define DECODER_LOG(type, msg, ...)
+#define VERBOSE_LOG(msg, ...)
 #endif
 
 // GetCurrentTime is defined in winbase.h as zero argument macro forwarding to
 // GetTickCount() and conflicts with MediaDecoderStateMachine::GetCurrentTime
 // implementation.  With unified builds, putting this in headers is not enough.
 #ifdef GetCurrentTime
 #undef GetCurrentTime
 #endif
@@ -294,18 +306,18 @@ void MediaDecoderStateMachine::SendStrea
   // the exact same silences
   CheckedInt64 audioWrittenOffset = UsecsToFrames(mInfo.mAudio.mRate,
       aStream->mInitialTime + mStartTime) + aStream->mAudioFramesWritten;
   CheckedInt64 frameOffset = UsecsToFrames(mInfo.mAudio.mRate, aAudio->mTime);
   if (!audioWrittenOffset.isValid() || !frameOffset.isValid())
     return;
   if (audioWrittenOffset.value() < frameOffset.value()) {
     // Write silence to catch up
-    DECODER_LOG(PR_LOG_DEBUG, ("%p Decoder writing %d frames of silence to MediaStream",
-                               mDecoder.get(), int32_t(frameOffset.value() - audioWrittenOffset.value())));
+    VERBOSE_LOG("writing %d frames of silence to MediaStream",
+                int32_t(frameOffset.value() - audioWrittenOffset.value()));
     AudioSegment silence;
     silence.InsertNullDataAtStart(frameOffset.value() - audioWrittenOffset.value());
     aStream->mAudioFramesWritten += silence.GetDuration();
     aOutput->AppendFrom(&silence);
   }
 
   int64_t offset;
   if (aStream->mAudioFramesWritten == 0) {
@@ -324,18 +336,18 @@ void MediaDecoderStateMachine::SendStrea
   aAudio->EnsureAudioBuffer();
   nsRefPtr<SharedBuffer> buffer = aAudio->mAudioBuffer;
   AudioDataValue* bufferData = static_cast<AudioDataValue*>(buffer->Data());
   nsAutoTArray<const AudioDataValue*,2> channels;
   for (uint32_t i = 0; i < aAudio->mChannels; ++i) {
     channels.AppendElement(bufferData + i*aAudio->mFrames + offset);
   }
   aOutput->AppendFrames(buffer.forget(), channels, aAudio->mFrames);
-  DECODER_LOG(PR_LOG_DEBUG, ("%p Decoder writing %d frames of data to MediaStream for AudioData at %lld",
-                             mDecoder.get(), aAudio->mFrames - int32_t(offset), aAudio->mTime));
+  VERBOSE_LOG("writing %d frames of data to MediaStream for AudioData at %lld",
+              aAudio->mFrames - int32_t(offset), aAudio->mTime);
   aStream->mAudioFramesWritten += aAudio->mFrames - int32_t(offset);
 }
 
 static void WriteVideoToMediaStream(layers::Image* aImage,
                                     int64_t aDuration,
                                     const IntSize& aIntrinsicSize,
                                     VideoSegment* aOutput)
 {
@@ -416,39 +428,37 @@ void MediaDecoderStateMachine::SendStrea
       nsAutoTArray<VideoData*,10> video;
       // It's OK to hold references to the VideoData only the decoder thread
       // pops from the queue.
       mReader->VideoQueue().GetElementsAfter(stream->mNextVideoTime, &video);
       VideoSegment output;
       for (uint32_t i = 0; i < video.Length(); ++i) {
         VideoData* v = video[i];
         if (stream->mNextVideoTime < v->mTime) {
-          DECODER_LOG(PR_LOG_DEBUG, ("%p Decoder writing last video to MediaStream %p for %lldus",
-                                     mDecoder.get(), mediaStream,
-                                     v->mTime - stream->mNextVideoTime));
+          VERBOSE_LOG("writing last video to MediaStream %p for %lldus",
+                      mediaStream, v->mTime - stream->mNextVideoTime);
           // Write last video frame to catch up. mLastVideoImage can be null here
           // which is fine, it just means there's no video.
           WriteVideoToMediaStream(stream->mLastVideoImage,
             v->mTime - stream->mNextVideoTime, stream->mLastVideoImageDisplaySize,
               &output);
           stream->mNextVideoTime = v->mTime;
         }
         if (stream->mNextVideoTime < v->GetEndTime()) {
-          DECODER_LOG(PR_LOG_DEBUG, ("%p Decoder writing video frame %lldus to MediaStream %p for %lldus",
-                                     mDecoder.get(), v->mTime, mediaStream,
-                                     v->GetEndTime() - stream->mNextVideoTime));
+          VERBOSE_LOG("writing video frame %lldus to MediaStream %p for %lldus",
+                      v->mTime, mediaStream, v->GetEndTime() - stream->mNextVideoTime);
           WriteVideoToMediaStream(v->mImage,
               v->GetEndTime() - stream->mNextVideoTime, v->mDisplay,
               &output);
           stream->mNextVideoTime = v->GetEndTime();
           stream->mLastVideoImage = v->mImage;
           stream->mLastVideoImageDisplaySize = v->mDisplay;
         } else {
-          DECODER_LOG(PR_LOG_DEBUG, ("%p Decoder skipping writing video frame %lldus (end %lldus) to MediaStream",
-                                     mDecoder.get(), v->mTime, v->GetEndTime()));
+          VERBOSE_LOG("skipping writing video frame %lldus (end %lldus) to MediaStream",
+                      v->mTime, v->GetEndTime());
         }
       }
       if (output.GetDuration() > 0) {
         mediaStream->AppendToTrack(TRACK_VIDEO, &output);
       }
       if (mReader->VideoQueue().IsFinished() && !stream->mHaveSentFinishVideo) {
         mediaStream->EndTrack(TRACK_VIDEO);
         stream->mHaveSentFinishVideo = true;
@@ -593,17 +603,17 @@ MediaDecoderStateMachine::DecodeVideo()
          // don't skip frame when |clock time| <= |mVideoFrameEndTime| for
          // we are still in the safe range without underrunning video frames
          GetClock() > mVideoFrameEndTime &&
         (static_cast<uint32_t>(mReader->VideoQueue().GetSize())
           < LOW_VIDEO_FRAMES * mPlaybackRate))) &&
       !HasLowUndecodedData())
   {
     mSkipToNextKeyFrame = true;
-    DECODER_LOG(PR_LOG_DEBUG, ("%p Skipping video decode to the next keyframe", mDecoder.get()));
+    DECODER_LOG(PR_LOG_DEBUG, "Skipping video decode to the next keyframe");
   }
 
   // Time the video decode, so that if it's slow, we can increase our low
   // audio threshold to reduce the chance of an audio underrun while we're
   // waiting for a video decode to complete.
   TimeDuration decodeTime;
   {
     int64_t currentTime = GetMediaTime();
@@ -620,19 +630,18 @@ MediaDecoderStateMachine::DecodeVideo()
 
   if (THRESHOLD_FACTOR * DurationToUsecs(decodeTime) > mLowAudioThresholdUsecs &&
       !HasLowUndecodedData())
   {
     mLowAudioThresholdUsecs =
       std::min(THRESHOLD_FACTOR * DurationToUsecs(decodeTime), AMPLE_AUDIO_USECS);
     mAmpleAudioThresholdUsecs = std::max(THRESHOLD_FACTOR * mLowAudioThresholdUsecs,
                                           mAmpleAudioThresholdUsecs);
-    DECODER_LOG(PR_LOG_DEBUG,
-                ("Slow video decode, set mLowAudioThresholdUsecs=%lld mAmpleAudioThresholdUsecs=%lld",
-                mLowAudioThresholdUsecs, mAmpleAudioThresholdUsecs));
+    DECODER_LOG(PR_LOG_DEBUG, "Slow video decode, set mLowAudioThresholdUsecs=%lld mAmpleAudioThresholdUsecs=%lld",
+                mLowAudioThresholdUsecs, mAmpleAudioThresholdUsecs);
   }
 
   SendStreamData();
 
   // The ready state can change when we've decoded data, so update the
   // ready state, so that DOM events can fire.
   UpdateReadyState();
 
@@ -710,19 +719,18 @@ MediaDecoderStateMachine::CheckIfDecodeC
   MOZ_ASSERT(!mReader->VideoQueue().IsFinished() || !mIsVideoDecoding);
   if (!mIsVideoDecoding && !mIsAudioDecoding) {
     // We've finished decoding all active streams,
     // so move to COMPLETED state.
     mState = DECODER_STATE_COMPLETED;
     DispatchDecodeTasksIfNeeded();
     ScheduleStateMachine();
   }
-  DECODER_LOG(PR_LOG_DEBUG,
-    ("%p CheckIfDecodeComplete %scompleted", mDecoder.get(),
-    ((mState == DECODER_STATE_COMPLETED) ? "" : "NOT ")));
+  DECODER_LOG(PR_LOG_DEBUG, "CheckIfDecodeComplete %scompleted",
+              ((mState == DECODER_STATE_COMPLETED) ? "" : "NOT "));
 }
 
 bool MediaDecoderStateMachine::IsPlaying()
 {
   AssertCurrentThreadInMonitor();
 
   return !mPlayStartTime.IsNull();
 }
@@ -748,17 +756,17 @@ static void WriteSilence(AudioStream* aS
   aStream->Write(buf.Elements(), aFrames);
 
   StartAudioStreamPlaybackIfNeeded(aStream);
 }
 
 void MediaDecoderStateMachine::AudioLoop()
 {
   NS_ASSERTION(OnAudioThread(), "Should be on audio thread.");
-  DECODER_LOG(PR_LOG_DEBUG, ("%p Begun audio thread/loop", mDecoder.get()));
+  DECODER_LOG(PR_LOG_DEBUG, "Begun audio thread/loop");
   int64_t audioDuration = 0;
   int64_t audioStartTime = -1;
   uint32_t channels, rate;
   double volume = -1;
   bool setVolume;
   double playbackRate = -1;
   bool setPlaybackRate;
   bool preservesPitch;
@@ -886,18 +894,17 @@ void MediaDecoderStateMachine::AudioLoop
 
     int64_t framesWritten = 0;
     if (missingFrames.value() > 0) {
       // The next audio chunk begins some time after the end of the last chunk
       // we pushed to the audio hardware. We must push silence into the audio
       // hardware so that the next audio chunk begins playback at the correct
       // time.
       missingFrames = std::min<int64_t>(UINT32_MAX, missingFrames.value());
-      DECODER_LOG(PR_LOG_DEBUG, ("%p Decoder playing %d frames of silence",
-                                 mDecoder.get(), int32_t(missingFrames.value())));
+      VERBOSE_LOG("playing %d frames of silence", int32_t(missingFrames.value()));
       framesWritten = PlaySilence(static_cast<uint32_t>(missingFrames.value()),
                                   channels, playedFrames.value());
     } else {
       framesWritten = PlayFromAudioQueue(sampleTime.value(), channels);
     }
     audioDuration += framesWritten;
     {
       ReentrantMonitorAutoEnter mon(mDecoder->GetReentrantMonitor());
@@ -940,32 +947,32 @@ void MediaDecoderStateMachine::AudioLoop
       if (!seeking && !mAudioStream->IsPaused()) {
         {
           ReentrantMonitorAutoExit exit(mDecoder->GetReentrantMonitor());
           mAudioStream->Drain();
         }
       }
     }
   }
-  DECODER_LOG(PR_LOG_DEBUG, ("%p Reached audio stream end.", mDecoder.get()));
+  DECODER_LOG(PR_LOG_DEBUG, "Reached audio stream end.");
   {
     // Must hold lock while shutting down and anulling the audio stream to prevent
     // state machine thread trying to use it while we're destroying it.
     ReentrantMonitorAutoEnter mon(mDecoder->GetReentrantMonitor());
     mAudioStream->Shutdown();
     mAudioStream = nullptr;
     if (!mAudioCaptured) {
       mAudioCompleted = true;
       UpdateReadyState();
       // Kick the decode thread; it may be sleeping waiting for this to finish.
       mDecoder->GetReentrantMonitor().NotifyAll();
     }
   }
 
-  DECODER_LOG(PR_LOG_DEBUG, ("%p Audio stream finished playing, audio thread exit", mDecoder.get()));
+  DECODER_LOG(PR_LOG_DEBUG, "Audio stream finished playing, audio thread exit");
 }
 
 uint32_t MediaDecoderStateMachine::PlaySilence(uint32_t aFrames,
                                                    uint32_t aChannels,
                                                    uint64_t aFrameOffset)
 
 {
   NS_ASSERTION(OnAudioThread(), "Only call on audio thread.");
@@ -986,20 +993,18 @@ uint32_t MediaDecoderStateMachine::PlayF
     ReentrantMonitorAutoEnter mon(mDecoder->GetReentrantMonitor());
     NS_WARN_IF_FALSE(IsPlaying(), "Should be playing");
     // Awaken the decode loop if it's waiting for space to free up in the
     // audio queue.
     mDecoder->GetReentrantMonitor().NotifyAll();
   }
   int64_t offset = -1;
   uint32_t frames = 0;
-  if (!PR_GetEnv("MOZ_QUIET")) {
-    DECODER_LOG(PR_LOG_DEBUG, ("%p Decoder playing %d frames of data to stream for AudioData at %lld",
-                               mDecoder.get(), audio->mFrames, audio->mTime));
-  }
+  VERBOSE_LOG("playing %d frames of data to stream for AudioData at %lld",
+              audio->mFrames, audio->mTime);
   mAudioStream->Write(audio->mAudioData,
                       audio->mFrames);
 
   aChannels = mAudioStream->GetOutChannels();
 
   StartAudioStreamPlaybackIfNeeded(mAudioStream);
 
   offset = audio->mOffset;
@@ -1040,17 +1045,17 @@ nsresult MediaDecoderStateMachine::Init(
   rv = mTimer->SetTarget(GetStateMachineThread());
   NS_ENSURE_SUCCESS(rv, rv);
 
   return mReader->Init(cloneReader);
 }
 
 void MediaDecoderStateMachine::StopPlayback()
 {
-  DECODER_LOG(PR_LOG_DEBUG, ("%p StopPlayback()", mDecoder.get()));
+  DECODER_LOG(PR_LOG_DEBUG, "StopPlayback()");
 
   AssertCurrentThreadInMonitor();
 
   mDecoder->NotifyPlaybackStopped();
 
   if (IsPlaying()) {
     mPlayDuration = GetClock();
     mPlayStartTime = TimeStamp();
@@ -1083,17 +1088,17 @@ int64_t MediaDecoderStateMachine::GetCur
   NS_ASSERTION(mSyncPointInDecodedStream >= 0, "Should have set up sync point");
   DecodedStreamData* stream = mDecoder->GetDecodedStream();
   StreamTime streamDelta = stream->GetLastOutputTime() - mSyncPointInMediaStream;
   return mSyncPointInDecodedStream + MediaTimeToMicroseconds(streamDelta);
 }
 
 void MediaDecoderStateMachine::StartPlayback()
 {
-  DECODER_LOG(PR_LOG_DEBUG, ("%p StartPlayback()", mDecoder.get()));
+  DECODER_LOG(PR_LOG_DEBUG, "StartPlayback()");
 
   NS_ASSERTION(!IsPlaying(), "Shouldn't be playing when StartPlayback() is called");
   AssertCurrentThreadInMonitor();
 
   mDecoder->NotifyPlaybackStarted();
   mPlayStartTime = TimeStamp::Now();
 
   NS_ASSERTION(IsPlaying(), "Should report playing by end of StartPlayback()");
@@ -1295,17 +1300,17 @@ void MediaDecoderStateMachine::Shutdown(
 {
   NS_ASSERTION(NS_IsMainThread(), "Should be on main thread.");
 
   // Once we've entered the shutdown state here there's no going back.
   ReentrantMonitorAutoEnter mon(mDecoder->GetReentrantMonitor());
 
   // Change state before issuing shutdown request to threads so those
   // threads can start exiting cleanly during the Shutdown call.
-  DECODER_LOG(PR_LOG_DEBUG, ("%p Changed state to SHUTDOWN", mDecoder.get()));
+  DECODER_LOG(PR_LOG_DEBUG, "Changed state to SHUTDOWN");
   ScheduleStateMachine();
   mState = DECODER_STATE_SHUTDOWN;
   mDecoder->GetReentrantMonitor().NotifyAll();
 }
 
 void MediaDecoderStateMachine::StartDecoding()
 {
   NS_ASSERTION(OnStateMachineThread() || OnDecodeThread(),
@@ -1363,17 +1368,17 @@ void MediaDecoderStateMachine::NotifyWai
 void MediaDecoderStateMachine::Play()
 {
   NS_ASSERTION(NS_IsMainThread(), "Should be on main thread.");
   // When asked to play, switch to decoding state only if
   // we are currently buffering. In other cases, we'll start playing anyway
   // when the state machine notices the decoder's state change to PLAYING.
   ReentrantMonitorAutoEnter mon(mDecoder->GetReentrantMonitor());
   if (mState == DECODER_STATE_BUFFERING) {
-    DECODER_LOG(PR_LOG_DEBUG, ("%p Changed state from BUFFERING to DECODING", mDecoder.get()));
+    DECODER_LOG(PR_LOG_DEBUG, "Changed state from BUFFERING to DECODING");
     mState = DECODER_STATE_DECODING;
     mDecodeStartTime = TimeStamp::Now();
   }
   // Once we start playing, we don't want to minimize our prerolling, as we
   // assume the user is likely to want to keep playing in future.
   mMinimizePreroll = false;
   ScheduleStateMachine();
 }
@@ -1437,17 +1442,17 @@ void MediaDecoderStateMachine::Seek(cons
   int64_t seekTime = aTarget.mTime + mStartTime;
   seekTime = std::min(seekTime, mEndTime);
   seekTime = std::max(mStartTime, seekTime);
   NS_ASSERTION(seekTime >= mStartTime && seekTime <= mEndTime,
                "Can only seek in range [0,duration]");
   mSeekTarget = SeekTarget(seekTime, aTarget.mType);
 
   mBasePosition = seekTime - mStartTime;
-  DECODER_LOG(PR_LOG_DEBUG, ("%p Changed state to SEEKING (to %ld)", mDecoder.get(), mSeekTarget.mTime));
+  DECODER_LOG(PR_LOG_DEBUG, "Changed state to SEEKING (to %ld)", mSeekTarget.mTime);
   mState = DECODER_STATE_SEEKING;
   if (mDecoder->GetDecodedStream()) {
     mDecoder->RecreateDecodedStream(seekTime - mStartTime);
   }
   ScheduleStateMachine();
 }
 
 void MediaDecoderStateMachine::StopAudioThread()
@@ -1459,17 +1464,17 @@ void MediaDecoderStateMachine::StopAudio
   if (mStopAudioThread) {
     // Nothing to do, since the thread is already stopping
     return;
   }
 
   mStopAudioThread = true;
   mDecoder->GetReentrantMonitor().NotifyAll();
   if (mAudioThread) {
-    DECODER_LOG(PR_LOG_DEBUG, ("%p Shutdown audio thread", mDecoder.get()));
+    DECODER_LOG(PR_LOG_DEBUG, "Shutdown audio thread");
     {
       ReentrantMonitorAutoExit exitMon(mDecoder->GetReentrantMonitor());
       mAudioThread->Shutdown();
     }
     mAudioThread = nullptr;
     // Now that the audio thread is dead, try sending data to our MediaStream(s).
     // That may have been waiting for the audio thread to stop.
     SendStreamData();
@@ -1507,30 +1512,29 @@ MediaDecoderStateMachine::EnsureActive()
 }
 
 void
 MediaDecoderStateMachine::SetReaderIdle()
 {
 #ifdef PR_LOGGING
   {
     ReentrantMonitorAutoEnter mon(mDecoder->GetReentrantMonitor());
-    DECODER_LOG(PR_LOG_DEBUG, ("%p SetReaderIdle() audioQueue=%lld videoQueue=%lld",
-                               mDecoder.get(),
-                               GetDecodedAudioDuration(),
-                               mReader->VideoQueue().Duration()));
+    DECODER_LOG(PR_LOG_DEBUG, "SetReaderIdle() audioQueue=%lld videoQueue=%lld",
+                GetDecodedAudioDuration(),
+                mReader->VideoQueue().Duration());
   }
 #endif
   MOZ_ASSERT(OnDecodeThread());
   mReader->SetIdle();
 }
 
 void
 MediaDecoderStateMachine::SetReaderActive()
 {
-  DECODER_LOG(PR_LOG_DEBUG, ("%p SetReaderActive()", mDecoder.get()));
+  DECODER_LOG(PR_LOG_DEBUG, "SetReaderActive()");
   MOZ_ASSERT(OnDecodeThread());
   mReader->SetActive();
 }
 
 void
 MediaDecoderStateMachine::DispatchDecodeTasksIfNeeded()
 {
   AssertCurrentThreadInMonitor();
@@ -1694,17 +1698,17 @@ MediaDecoderStateMachine::StartAudioThre
 
   mStopAudioThread = false;
   if (HasAudio() && !mAudioThread) {
     nsresult rv = NS_NewNamedThread("Media Audio",
                                     getter_AddRefs(mAudioThread),
                                     nullptr,
                                     MEDIA_THREAD_STACK_SIZE);
     if (NS_FAILED(rv)) {
-      DECODER_LOG(PR_LOG_DEBUG, ("%p Changed state to SHUTDOWN because failed to create audio thread", mDecoder.get()));
+      DECODER_LOG(PR_LOG_WARNING, "Changed state to SHUTDOWN because failed to create audio thread");
       mState = DECODER_STATE_SHUTDOWN;
       return rv;
     }
 
     nsCOMPtr<nsIRunnable> event =
       NS_NewRunnableMethod(this, &MediaDecoderStateMachine::AudioLoop);
     mAudioThread->Dispatch(event, NS_DISPATCH_NORMAL);
   }
@@ -1771,17 +1775,17 @@ void
 MediaDecoderStateMachine::DecodeError()
 {
   AssertCurrentThreadInMonitor();
   NS_ASSERTION(OnDecodeThread(), "Should be on decode thread.");
 
   // Change state to shutdown before sending error report to MediaDecoder
   // and the HTMLMediaElement, so that our pipeline can start exiting
   // cleanly during the sync dispatch below.
-  DECODER_LOG(PR_LOG_DEBUG, ("%p Changed state to SHUTDOWN", mDecoder.get()));
+  DECODER_LOG(PR_LOG_WARNING, "Decode error, changed state to SHUTDOWN");
   ScheduleStateMachine();
   mState = DECODER_STATE_SHUTDOWN;
   mDecoder->GetReentrantMonitor().NotifyAll();
 
   // Dispatch the event to call DecodeError synchronously. This ensures
   // we're in shutdown state by the time we exit the decode thread.
   // If we just moved to shutdown state here on the decode thread, we may
   // cause the state machine to shutdown/free memory without closing its
@@ -1798,26 +1802,26 @@ MediaDecoderStateMachine::DecodeError()
 void
 MediaDecoderStateMachine::CallDecodeMetadata()
 {
   ReentrantMonitorAutoEnter mon(mDecoder->GetReentrantMonitor());
   if (mState != DECODER_STATE_DECODING_METADATA) {
     return;
   }
   if (NS_FAILED(DecodeMetadata())) {
-    DECODER_LOG(PR_LOG_DEBUG, ("Decode metadata failed, shutting down decoder"));
+    DECODER_LOG(PR_LOG_WARNING, "Decode metadata failed, shutting down decoder");
     DecodeError();
   }
 }
 
 nsresult MediaDecoderStateMachine::DecodeMetadata()
 {
   AssertCurrentThreadInMonitor();
   NS_ASSERTION(OnDecodeThread(), "Should be on decode thread.");
-  DECODER_LOG(PR_LOG_DEBUG, ("%p Decoding Media Headers", mDecoder.get()));
+  DECODER_LOG(PR_LOG_DEBUG, "Decoding Media Headers");
   if (mState != DECODER_STATE_DECODING_METADATA) {
     return NS_ERROR_FAILURE;
   }
   EnsureActive();
 
   nsresult res;
   MediaInfo info;
   MetadataTags* tags;
@@ -1852,20 +1856,19 @@ nsresult MediaDecoderStateMachine::Decod
   }
 
   NS_ASSERTION(mStartTime != -1, "Must have start time");
   MOZ_ASSERT((!HasVideo() && !HasAudio()) ||
               !(mMediaSeekable && mTransportSeekable) || mEndTime != -1,
               "Active seekable media should have end time");
   MOZ_ASSERT(!(mMediaSeekable && mTransportSeekable) ||
              GetDuration() != -1, "Seekable media should have duration");
-  DECODER_LOG(PR_LOG_DEBUG, ("%p Media goes from %lld to %lld (duration %lld)"
-                             " transportSeekable=%d, mediaSeekable=%d",
-                             mDecoder.get(), mStartTime, mEndTime, GetDuration(),
-                             mTransportSeekable, mMediaSeekable));
+  DECODER_LOG(PR_LOG_DEBUG, "Media goes from %lld to %lld (duration %lld) "
+              "transportSeekable=%d, mediaSeekable=%d",
+              mStartTime, mEndTime, GetDuration(), mTransportSeekable, mMediaSeekable);
 
   if (HasAudio() && !HasVideo()) {
     // We're playing audio only. We don't need to worry about slow video
     // decodes causing audio underruns, so don't buffer so much audio in
     // order to reduce memory usage.
     mAmpleAudioThresholdUsecs /= NO_VIDEO_AMPLE_AUDIO_DIVISOR;
     mLowAudioThresholdUsecs /= NO_VIDEO_AMPLE_AUDIO_DIVISOR;
   }
@@ -1887,17 +1890,17 @@ nsresult MediaDecoderStateMachine::Decod
   }
   if (HasVideo()) {
     RefPtr<nsIRunnable> decodeTask(
       NS_NewRunnableMethod(this, &MediaDecoderStateMachine::DispatchVideoDecodeTaskIfNeeded));
     mReader->VideoQueue().AddPopListener(decodeTask, mDecodeTaskQueue);
   }
 
   if (mState == DECODER_STATE_DECODING_METADATA) {
-    DECODER_LOG(PR_LOG_DEBUG, ("%p Changed state from DECODING_METADATA to DECODING", mDecoder.get()));
+    DECODER_LOG(PR_LOG_DEBUG, "Changed state from DECODING_METADATA to DECODING");
     StartDecoding();
   }
 
   // For very short media FindStartTime() can decode the entire media.
   // So we need to check if this has occurred, else our decode pipeline won't
   // run (since it doesn't need to) and we won't detect end of stream.
   CheckIfDecodeComplete();
 
@@ -2020,42 +2023,39 @@ void MediaDecoderStateMachine::DecodeSee
   // if we need to seek again.
 
   nsCOMPtr<nsIRunnable> stopEvent;
   bool isLiveStream = mDecoder->GetResource()->GetLength() == -1;
   if (GetMediaTime() == mEndTime && !isLiveStream) {
     // Seeked to end of media, move to COMPLETED state. Note we don't do
     // this if we're playing a live stream, since the end of media will advance
     // once we download more data!
-    DECODER_LOG(PR_LOG_DEBUG, ("%p Changed state from SEEKING (to %lld) to COMPLETED",
-                               mDecoder.get(), seekTime));
+    DECODER_LOG(PR_LOG_DEBUG, "Changed state from SEEKING (to %lld) to COMPLETED", seekTime);
     stopEvent = NS_NewRunnableMethod(mDecoder, &MediaDecoder::SeekingStoppedAtEnd);
     // Explicitly set our state so we don't decode further, and so
     // we report playback ended to the media element.
     mState = DECODER_STATE_COMPLETED;
     mIsAudioDecoding = false;
     mIsVideoDecoding = false;
     DispatchDecodeTasksIfNeeded();
   } else {
-    DECODER_LOG(PR_LOG_DEBUG, ("%p Changed state from SEEKING (to %lld) to DECODING",
-                               mDecoder.get(), seekTime));
+    DECODER_LOG(PR_LOG_DEBUG, "Changed state from SEEKING (to %lld) to DECODING", seekTime);
     stopEvent = NS_NewRunnableMethod(mDecoder, &MediaDecoder::SeekingStopped);
     StartDecoding();
   }
 
   if (newCurrentTime != mediaTime) {
     UpdatePlaybackPositionInternal(newCurrentTime);
     if (mDecoder->GetDecodedStream()) {
       SetSyncPointForMediaStream();
     }
   }
 
   // Try to decode another frame to detect if we're at the end...
-  DECODER_LOG(PR_LOG_DEBUG, ("%p Seek completed, mCurrentFrameTime=%lld\n",
-              mDecoder.get(), mCurrentFrameTime));
+  DECODER_LOG(PR_LOG_DEBUG, "Seek completed, mCurrentFrameTime=%lld", mCurrentFrameTime);
 
   {
     ReentrantMonitorAutoExit exitMon(mDecoder->GetReentrantMonitor());
     NS_DispatchToMainThread(stopEvent, NS_DISPATCH_SYNC);
   }
 
   // Reset quick buffering status. This ensures that if we began the
   // seek while quick-buffering, we won't bypass quick buffering mode
@@ -2221,29 +2221,24 @@ nsresult MediaDecoderStateMachine::RunSt
       bool isLiveStream = resource->GetLength() == -1;
       if ((isLiveStream || !mDecoder->CanPlayThrough()) &&
             elapsed < TimeDuration::FromSeconds(mBufferingWait * mPlaybackRate) &&
             (mQuickBuffering ? HasLowDecodedData(QUICK_BUFFERING_LOW_DATA_USECS)
                             : HasLowUndecodedData(mBufferingWait * USECS_PER_S)) &&
             !mDecoder->IsDataCachedToEndOfResource() &&
             !resource->IsSuspended())
       {
-        DECODER_LOG(PR_LOG_DEBUG,
-                    ("%p Buffering: wait %ds, timeout in %.3lfs %s",
-                      mDecoder.get(),
-                      mBufferingWait,
-                      mBufferingWait - elapsed.ToSeconds(),
-                      (mQuickBuffering ? "(quick exit)" : "")));
+        DECODER_LOG(PR_LOG_DEBUG, "Buffering: wait %ds, timeout in %.3lfs %s",
+                    mBufferingWait, mBufferingWait - elapsed.ToSeconds(),
+                    (mQuickBuffering ? "(quick exit)" : ""));
         ScheduleStateMachine(USECS_PER_S);
         return NS_OK;
       } else {
-        DECODER_LOG(PR_LOG_DEBUG, ("%p Changed state from BUFFERING to DECODING", mDecoder.get()));
-        DECODER_LOG(PR_LOG_DEBUG, ("%p Buffered for %.3lfs",
-                                   mDecoder.get(),
-                                   (now - mBufferingStart).ToSeconds()));
+        DECODER_LOG(PR_LOG_DEBUG, "Changed state from BUFFERING to DECODING");
+        DECODER_LOG(PR_LOG_DEBUG, "Buffered for %.3lfs", (now - mBufferingStart).ToSeconds());
         StartDecoding();
       }
 
       // Notify to allow blocked decoder thread to continue
       mDecoder->GetReentrantMonitor().NotifyAll();
       UpdateReadyState();
       if (mDecoder->GetState() == MediaDecoder::PLAY_STATE_PLAYING &&
           !IsPlaying())
@@ -2319,20 +2314,17 @@ void MediaDecoderStateMachine::RenderVid
   NS_ASSERTION(OnStateMachineThread() || OnDecodeThread(),
                "Should be on state machine or decode thread.");
   mDecoder->GetReentrantMonitor().AssertNotCurrentThreadIn();
 
   if (aData->mDuplicate) {
     return;
   }
 
-  if (!PR_GetEnv("MOZ_QUIET")) {
-    DECODER_LOG(PR_LOG_DEBUG, ("%p Decoder playing video frame %lld",
-                               mDecoder.get(), aData->mTime));
-  }
+  VERBOSE_LOG("playing video frame %lld", aData->mTime);
 
   VideoFrameContainer* container = mDecoder->GetVideoFrameContainer();
   if (container) {
     container->SetCurrentFrame(ThebesIntSize(aData->mDisplay), aData->mImage,
                                aTarget);
   }
 }
 
@@ -2433,22 +2425,19 @@ void MediaDecoderStateMachine::AdvanceFr
   int32_t droppedFrames = 0;
 #endif
   if (mReader->VideoQueue().GetSize() > 0) {
     VideoData* frame = mReader->VideoQueue().PeekFront();
     while (mRealTime || clock_time >= frame->mTime) {
       mVideoFrameEndTime = frame->GetEndTime();
       currentFrame = frame;
 #ifdef PR_LOGGING
-      if (!PR_GetEnv("MOZ_QUIET")) {
-        DECODER_LOG(PR_LOG_DEBUG, ("%p Decoder discarding video frame %lld", mDecoder.get(), frame->mTime));
-        if (droppedFrames++) {
-          DECODER_LOG(PR_LOG_DEBUG, ("%p Decoder discarding video frame %lld (%d so far)",
-                      mDecoder.get(), frame->mTime, droppedFrames - 1));
-        }
+      VERBOSE_LOG("discarding video frame %lld", frame->mTime);
+      if (droppedFrames++) {
+        VERBOSE_LOG("discarding video frame %lld (%d so far)", frame->mTime, droppedFrames-1);
       }
 #endif
       mReader->VideoQueue().PopFront();
       // Notify the decode thread that the video queue's buffers may have
       // free'd up space for more frames.
       mDecoder->GetReentrantMonitor().NotifyAll();
       mDecoder->UpdatePlaybackOffset(frame->mOffset);
       if (mReader->VideoQueue().GetSize() == 0)
@@ -2576,17 +2565,17 @@ VideoData* MediaDecoderStateMachine::Fin
       // duration.
       mEndTime = mStartTime + mEndTime;
     }
   }
   // Set the audio start time to be start of media. If this lies before the
   // first actual audio frame we have, we'll inject silence during playback
   // to ensure the audio starts at the correct time.
   mAudioStartTime = mStartTime;
-  DECODER_LOG(PR_LOG_DEBUG, ("%p Media start time is %lld", mDecoder.get(), mStartTime));
+  DECODER_LOG(PR_LOG_DEBUG, "Media start time is %lld", mStartTime);
   return v;
 }
 
 void MediaDecoderStateMachine::UpdateReadyState() {
   AssertCurrentThreadInMonitor();
 
   MediaDecoderOwner::NextFrameStatus nextFrameStatus = GetNextFrameStatus();
   if (nextFrameStatus == mLastFrameStatus) {
@@ -2646,24 +2635,23 @@ void MediaDecoderStateMachine::StartBuff
   // there might be pending main-thread events, such as "data
   // received" notifications, that mean we're not actually still
   // buffering by the time this runnable executes. So instead
   // we just trigger UpdateReadyStateForData; when it runs, it
   // will check the current state and decide whether to tell
   // the element we're buffering or not.
   UpdateReadyState();
   mState = DECODER_STATE_BUFFERING;
-  DECODER_LOG(PR_LOG_DEBUG, ("%p Changed state from DECODING to BUFFERING, decoded for %.3lfs",
-                             mDecoder.get(), decodeDuration.ToSeconds()));
+  DECODER_LOG(PR_LOG_DEBUG, "Changed state from DECODING to BUFFERING, decoded for %.3lfs",
+              decodeDuration.ToSeconds());
 #ifdef PR_LOGGING
   MediaDecoder::Statistics stats = mDecoder->GetStatistics();
-  DECODER_LOG(PR_LOG_DEBUG, ("%p Playback rate: %.1lfKB/s%s download rate: %.1lfKB/s%s",
-              mDecoder.get(),
+  DECODER_LOG(PR_LOG_DEBUG, "Playback rate: %.1lfKB/s%s download rate: %.1lfKB/s%s",
               stats.mPlaybackRate/1024, stats.mPlaybackRateReliable ? "" : " (unreliable)",
-              stats.mDownloadRate/1024, stats.mDownloadRateReliable ? "" : " (unreliable)"));
+              stats.mDownloadRate/1024, stats.mDownloadRateReliable ? "" : " (unreliable)");
 #endif
 }
 
 nsresult MediaDecoderStateMachine::GetBuffered(dom::TimeRanges* aBuffered) {
   MediaResource* resource = mDecoder->GetResource();
   NS_ENSURE_TRUE(resource, NS_ERROR_FAILURE);
   resource->Pin();
   nsresult res = mReader->GetBuffered(aBuffered, mStartTime);
@@ -2822,8 +2810,11 @@ void MediaDecoderStateMachine::QueueMeta
   metadata->mHasAudio = aHasAudio;
   metadata->mHasVideo = aHasVideo;
   metadata->mTags = aTags;
   mMetadataManager.QueueMetadata(metadata);
 }
 
 } // namespace mozilla
 
+// avoid redefined macro in unified build
+#undef DECODER_LOG
+#undef VERBOSE_LOG