debug draft
authorJohn Lin <jolin@mozilla.com>
Tue, 07 Mar 2017 20:12:04 +0800
changeset 650244 60b14c9d149f633c08c10bab455f7afe7bec1bec
parent 650243 d537d9fa417259c4e0700b48e218b2cd8919e24c
child 650245 fee0090596a42d411a82ab1929bc4627e8eeca74
push id75302
push userbmo:jolin@mozilla.com
push dateTue, 22 Aug 2017 02:08:52 +0000
milestone57.0a1
debug MozReview-Commit-ID: BlbZ72Jfyse
dom/media/mediasink/VideoSink.cpp
dom/media/platforms/android/RemoteDataDecoder.cpp
mobile/android/geckoview/src/main/java/org/mozilla/gecko/media/Codec.java
mobile/android/geckoview/src/main/java/org/mozilla/gecko/media/CodecProxy.java
mobile/android/geckoview/src/main/java/org/mozilla/gecko/media/LollipopAsyncCodec.java
mobile/android/geckoview/src/main/java/org/mozilla/gecko/media/RemoteManager.java
mobile/android/geckoview/src/main/java/org/mozilla/gecko/media/SamplePool.java
--- a/dom/media/mediasink/VideoSink.cpp
+++ b/dom/media/mediasink/VideoSink.cpp
@@ -12,18 +12,23 @@
 
 namespace mozilla {
 
 extern LazyLogModule gMediaDecoderLog;
 
 #undef FMT
 
 #define FMT(x, ...) "VideoSink=%p " x, this, ##__VA_ARGS__
+#ifdef MOZ_WIDGET_ANDROID
+#define VSINK_LOG(x, ...)   __android_log_print(ANDROID_LOG_DEBUG, "VideoSink", FMT(x, ##__VA_ARGS__))
+#define VSINK_LOG_V(x, ...) __android_log_print(ANDROID_LOG_VERBOSE, "VideoSink", FMT(x, ##__VA_ARGS__))
+#else
 #define VSINK_LOG(x, ...)   MOZ_LOG(gMediaDecoderLog, LogLevel::Debug,   (FMT(x, ##__VA_ARGS__)))
 #define VSINK_LOG_V(x, ...) MOZ_LOG(gMediaDecoderLog, LogLevel::Verbose, (FMT(x, ##__VA_ARGS__)))
+#endif
 
 using namespace mozilla::layers;
 
 namespace media {
 
 // Minimum update frequency is 1/120th of a second, i.e. half the
 // duration of a 60-fps frame.
 static const int64_t MIN_UPDATE_INTERVAL_US = 1000000 / (60 * 2);
--- a/dom/media/platforms/android/RemoteDataDecoder.cpp
+++ b/dom/media/platforms/android/RemoteDataDecoder.cpp
@@ -19,16 +19,20 @@
 #include <jni.h>
 
 #undef LOG
 #define LOG(arg, ...)                                                          \
   MOZ_LOG(sAndroidDecoderModuleLog,                                            \
           mozilla::LogLevel::Debug,                                            \
           ("RemoteDataDecoder(%p)::%s: " arg, this, __func__, ##__VA_ARGS__))
 
+#define TYPE_STR() (mType == MediaData::Type::VIDEO_DATA ? "video" : "audio")
+
+#define ANDLOG(...) __android_log_print(ANDROID_LOG_INFO, "NativeRemoteCodec", ##__VA_ARGS__)
+
 using namespace mozilla;
 using namespace mozilla::gl;
 using namespace mozilla::java;
 using namespace mozilla::java::sdk;
 using media::TimeUnit;
 
 namespace mozilla {
 
@@ -91,37 +95,41 @@ public:
 
   class CallbacksSupport final : public JavaCallbacksSupport
   {
   public:
     CallbacksSupport(RemoteVideoDecoder* aDecoder) : mDecoder(aDecoder) { }
 
     void HandleInput(int64_t aTimestamp, bool aProcessed) override
     {
+      ANDLOG("HandleInput: %lld", aTimestamp);
       mDecoder->UpdateInputStatus(aTimestamp, aProcessed);
     }
 
     void HandleOutput(Sample::Param aSample) override
     {
       UniquePtr<VideoData::Listener> releaseSample(
         new RenderOrReleaseOutput(mDecoder->mJavaDecoder, aSample));
 
       BufferInfo::LocalRef info = aSample->Info();
 
       int32_t flags;
       bool ok = NS_SUCCEEDED(info->Flags(&flags));
+      if (!ok) { ANDLOG("**** INFO ERROR: flags:%x", flags); }
 
       int32_t offset;
       ok &= NS_SUCCEEDED(info->Offset(&offset));
+      if (!ok) { ANDLOG("**** INFO ERROR: offset:%d", offset); }
 
       int32_t size;
       ok &= NS_SUCCEEDED(info->Size(&size));
 
       int64_t presentationTimeUs;
       ok &= NS_SUCCEEDED(info->PresentationTimeUs(&presentationTimeUs));
+      if (!ok) { ANDLOG("**** INFO ERROR: pts:%lld", presentationTimeUs); }
 
       if (!ok) {
         HandleError(MediaResult(NS_ERROR_DOM_MEDIA_FATAL_ERR,
                                 RESULT_DETAIL("VideoCallBack::HandleOutput")));
         return;
       }
 
 
@@ -141,20 +149,26 @@ public:
         RefPtr<VideoData> v = VideoData::CreateFromImage(
           inputInfo.mDisplaySize, offset,
           TimeUnit::FromMicroseconds(presentationTimeUs),
           TimeUnit::FromMicroseconds(inputInfo.mDurationUs),
           img, !!(flags & MediaCodec::BUFFER_FLAG_SYNC_FRAME),
           TimeUnit::FromMicroseconds(presentationTimeUs));
 
         v->SetListener(Move(releaseSample));
+        ANDLOG("Output %s %08lld(%lld): %dx%d -> %dx%d EOS=%d",
+               !!(flags & MediaCodec::BUFFER_FLAG_SYNC_FRAME) ? "[I]" : "[P]",
+               presentationTimeUs, inputInfo.mDurationUs,
+               inputInfo.mImageSize.width, inputInfo.mImageSize.height,
+               inputInfo.mDisplaySize.width, inputInfo.mDisplaySize.height, isEOS);
         mDecoder->UpdateOutputStatus(v);
       }
 
       if (isEOS) {
+        ANDLOG("EOS pts=%lld", presentationTimeUs);
         mDecoder->DrainComplete();
       }
     }
 
     void HandleError(const MediaResult& aError) override
     {
       mDecoder->Error(aError);
     }
@@ -224,16 +238,21 @@ public:
     const VideoInfo* config = aSample->mTrackInfo
                               ? aSample->mTrackInfo->GetAsVideoInfo()
                               : &mConfig;
     MOZ_ASSERT(config);
 
     InputInfo info(
       aSample->mDuration.ToMicroseconds(), config->mImage, config->mDisplay);
     mInputInfos.Insert(aSample->mTime.ToMicroseconds(), info);
+    ANDLOG("Decode video %s pts:%lld(%lld) %dx%d -> %dx%d",
+           aSample->mKeyframe ? "[I]" : "[P]",
+           aSample->mTime.ToMicroseconds(), aSample->mDuration.ToMicroseconds(),
+           config->mImage.width, config->mImage.height,
+           config->mDisplay.width, config->mDisplay.height);
     return RemoteDataDecoder::Decode(aSample);
   }
 
   bool SupportDecoderRecycling() const override
   {
     return mIsCodecSupportAdaptivePlayback;
   }
 
@@ -444,16 +463,17 @@ RemoteDataDecoder::RemoteDataDecoder(Med
 {
 }
 
 RefPtr<MediaDataDecoder::FlushPromise>
 RemoteDataDecoder::Flush()
 {
   RefPtr<RemoteDataDecoder> self = this;
   return InvokeAsync(mTaskQueue, __func__, [self, this]() {
+    ANDLOG("Flush %s", TYPE_STR());
     mDecodedData.Clear();
     mNumPendingInputs = 0;
     mDecodePromise.RejectIfExists(NS_ERROR_DOM_MEDIA_CANCELED, __func__);
     mDrainPromise.RejectIfExists(NS_ERROR_DOM_MEDIA_CANCELED, __func__);
     mDrainStatus = DrainStatus::DRAINED;
     mJavaDecoder->Flush();
     return FlushPromise::CreateAndResolve(true, __func__);
   });
@@ -482,25 +502,26 @@ RemoteDataDecoder::Drain()
 
     BufferInfo::LocalRef bufferInfo;
     nsresult rv = BufferInfo::New(&bufferInfo);
     if (NS_FAILED(rv)) {
       return DecodePromise::CreateAndReject(NS_ERROR_OUT_OF_MEMORY, __func__);
     }
     mDrainStatus = DrainStatus::DRAINING;
     bufferInfo->Set(0, 0, -1, MediaCodec::BUFFER_FLAG_END_OF_STREAM);
+    ANDLOG("Drain %s", TYPE_STR());
     mJavaDecoder->Input(nullptr, bufferInfo, nullptr);
     return p;
   });
 }
 
 RefPtr<ShutdownPromise>
 RemoteDataDecoder::Shutdown()
 {
-  LOG("");
+  ANDLOG("Shutdown %s", TYPE_STR());
   RefPtr<RemoteDataDecoder> self = this;
   return InvokeAsync(mTaskQueue, this, __func__,
                      &RemoteDataDecoder::ProcessShutdown);
 }
 
 RefPtr<ShutdownPromise>
 RemoteDataDecoder::ProcessShutdown()
 {
@@ -520,16 +541,17 @@ RemoteDataDecoder::ProcessShutdown()
   mFormat = nullptr;
 
   return ShutdownPromise::CreateAndResolve(true, __func__);
 }
 
 RefPtr<MediaDataDecoder::DecodePromise>
 RemoteDataDecoder::Decode(MediaRawData* aSample)
 {
+  ANDLOG("%s %s", __func__, TYPE_STR());
   MOZ_ASSERT(aSample != nullptr);
 
   RefPtr<RemoteDataDecoder> self = this;
   RefPtr<MediaRawData> sample = aSample;
   return InvokeAsync(mTaskQueue, __func__, [self, sample, this]() {
     jni::ByteBuffer::LocalRef bytes = jni::ByteBuffer::New(
       const_cast<uint8_t*>(sample->Data()), sample->Size());
 
@@ -564,18 +586,23 @@ RemoteDataDecoder::UpdateInputStatus(int
   }
   AssertOnTaskQueue();
   if (mShutdown) {
     return;
   }
 
   if (!aProcessed) {
     mNumPendingInputs++;
+    ANDLOG("%s not inputed:%lld pending input:%d pending output:%d",
+            TYPE_STR(), aTimestamp, mNumPendingInputs, mDecodedData.Length());
   } else if (mNumPendingInputs > 0) {
     mNumPendingInputs--;
+    ANDLOG("%s inputed:%lld pending input:%d", TYPE_STR(), aTimestamp, mNumPendingInputs);
+  } else {
+    ANDLOG("%s inputed:%lld no pending input", TYPE_STR(), aTimestamp);
   }
 
   if (mNumPendingInputs == 0 || // Input has been processed, request the next one.
       !mDecodedData.IsEmpty()) { // Previous output arrived before Decode().
     ReturnDecodedData();
   }
 }
 
@@ -590,49 +617,66 @@ RemoteDataDecoder::UpdateOutputStatus(Me
                                     aSample));
     return;
   }
   AssertOnTaskQueue();
   if (mShutdown) {
     return;
   }
   mDecodedData.AppendElement(aSample);
+  ANDLOG("%s pending output:%d", TYPE_STR(), mDecodedData.Length());
   ReturnDecodedData();
 }
 
 void
 RemoteDataDecoder::ReturnDecodedData()
 {
   AssertOnTaskQueue();
   MOZ_ASSERT(!mShutdown);
 
   // We only want to clear mDecodedData when we have resolved the promises.
   if (!mDecodePromise.IsEmpty()) {
+    if (mDecodedData.IsEmpty()) {
+      ANDLOG("Request %s input", TYPE_STR());
+    } else {
+      for (auto d: mDecodedData) {
+        ANDLOG("[DECODE] Return %s %lld(%lld)", TYPE_STR(), d->mTime.ToMicroseconds(), d->mDuration.ToMicroseconds());
+      }
+    }
     mDecodePromise.Resolve(mDecodedData, __func__);
     mDecodedData.Clear();
   } else if (!mDrainPromise.IsEmpty() &&
              (!mDecodedData.IsEmpty() || mDrainStatus == DrainStatus::DRAINED)) {
+    for (auto d: mDecodedData) {
+      ANDLOG("[DRAIN] Return %s %lld(%lld)", TYPE_STR(), d->mTime.ToMicroseconds(), d->mDuration.ToMicroseconds());
+    }
+    if (mDrainStatus == DrainStatus::DRAINED) {
+      ANDLOG("[DRAIN] %s complete", TYPE_STR());
+    }
     mDrainPromise.Resolve(mDecodedData, __func__);
     mDecodedData.Clear();
+  } else {
+    ANDLOG("pending decoded %s: %d", TYPE_STR(), mDecodedData.Length());
   }
 }
 
 void
 RemoteDataDecoder::DrainComplete()
 {
   if (!mTaskQueue->IsCurrentThreadIn()) {
     mTaskQueue->Dispatch(
       NewRunnableMethod("RemoteDataDecoder::DrainComplete",
                         this, &RemoteDataDecoder::DrainComplete));
     return;
   }
   AssertOnTaskQueue();
   if (mShutdown) {
     return;
   }
+  ANDLOG("DrainComplete %s", TYPE_STR());
   mDrainStatus = DrainStatus::DRAINED;
   ReturnDecodedData();
   // Make decoder accept input again.
   mJavaDecoder->Flush();
 }
 
 void
 RemoteDataDecoder::Error(const MediaResult& aError)
@@ -642,13 +686,14 @@ RemoteDataDecoder::Error(const MediaResu
       NewRunnableMethod<MediaResult>("RemoteDataDecoder::Error",
                                      this, &RemoteDataDecoder::Error, aError));
     return;
   }
   AssertOnTaskQueue();
   if (mShutdown) {
     return;
   }
+  ANDLOG("Error %s", TYPE_STR());
   mDecodePromise.RejectIfExists(aError, __func__);
   mDrainPromise.RejectIfExists(aError, __func__);
 }
 
 } // mozilla
--- a/mobile/android/geckoview/src/main/java/org/mozilla/gecko/media/Codec.java
+++ b/mobile/android/geckoview/src/main/java/org/mozilla/gecko/media/Codec.java
@@ -21,17 +21,17 @@ import java.util.LinkedList;
 import java.util.List;
 import java.util.Queue;
 import java.util.concurrent.ConcurrentLinkedQueue;
 
 import org.mozilla.gecko.gfx.GeckoSurface;
 
 /* package */ final class Codec extends ICodec.Stub implements IBinder.DeathRecipient {
     private static final String LOGTAG = "GeckoRemoteCodec";
-    private static final boolean DEBUG = false;
+    private static final boolean DEBUG = true;
 
     public enum Error {
         DECODE, FATAL
     }
 
     private final class Callbacks implements AsyncCodec.Callbacks {
         @Override
         public void onInputBufferAvailable(AsyncCodec codec, int index) {
@@ -130,17 +130,17 @@ import org.mozilla.gecko.gfx.GeckoSurfac
             }
 
         }
 
         private boolean isValidBuffer(final int index) {
             try {
                 return mCodec.getInputBuffer(index) != null;
             } catch (IllegalStateException e) {
-                if (DEBUG) { Log.d(LOGTAG, "invalid input buffer#" + index, e); }
+                if (DEBUG) { Log.i(LOGTAG, "invalid input buffer#" + index, e); }
                 return false;
             }
         }
 
         private void feedSampleToBuffer() {
             while (!mAvailableInputBuffers.isEmpty() && !mInputSamples.isEmpty()) {
                 int index = mAvailableInputBuffers.poll();
                 int len = 0;
@@ -245,25 +245,26 @@ import org.mozilla.gecko.gfx.GeckoSurfac
         private synchronized void onBuffer(int index, MediaCodec.BufferInfo info) {
             if (mStopped || !isValidBuffer(index)) {
                 return;
             }
 
             try {
                 Sample output = obtainOutputSample(index, info);
                 mSentOutputs.add(new Output(output, index));
+                Log.i(LOGTAG, "output: " + output);
                 mCallbacks.onOutput(output);
             } catch (Exception e) {
                 e.printStackTrace();
                 mCodec.releaseOutputBuffer(index, false);
             }
 
             boolean eos = (info.flags & MediaCodec.BUFFER_FLAG_END_OF_STREAM) != 0;
             if (DEBUG && eos) {
-                Log.d(LOGTAG, "output EOS");
+                Log.i(LOGTAG, "output EOS");
             }
         }
 
         private boolean isValidBuffer(final int index) {
             try {
                 return (mCodec.getOutputBuffer(index) != null) || mRenderToSurface;
             } catch (IllegalStateException e) {
                 if (DEBUG) { Log.e(LOGTAG, "invalid buffer#" + index, e); }
@@ -296,17 +297,17 @@ import org.mozilla.gecko.gfx.GeckoSurfac
             }
 
             return sample;
         }
 
         private synchronized void onRelease(Sample sample, boolean render) {
             final Output output = mSentOutputs.poll();
             if (output == null) {
-                if (DEBUG) { Log.d(LOGTAG, sample + " already released"); }
+                if (DEBUG) { Log.i(LOGTAG, sample + " already released"); }
                 return;
             }
             mCodec.releaseOutputBuffer(output.index, render);
             mSamplePool.recycleOutput(output.sample);
 
             sample.dispose();
         }
 
@@ -373,21 +374,21 @@ import org.mozilla.gecko.gfx.GeckoSurfac
                                           int flags,
                                           String drmStubId) throws RemoteException {
         if (mCallbacks == null) {
             Log.e(LOGTAG, "FAIL: callbacks must be set before calling configure()");
             return false;
         }
 
         if (mCodec != null) {
-            if (DEBUG) { Log.d(LOGTAG, "release existing codec: " + mCodec); }
+            if (DEBUG) { Log.i(LOGTAG, "release existing codec: " + mCodec); }
             mCodec.release();
         }
 
-        if (DEBUG) { Log.d(LOGTAG, "configure " + this); }
+        if (DEBUG) { Log.i(LOGTAG, "configure " + this); }
 
         final MediaFormat fmt = format.asFormat();
         final String mime = fmt.getString(MediaFormat.KEY_MIME);
         if (mime == null || mime.isEmpty()) {
             Log.e(LOGTAG, "invalid MIME type: " + mime);
             return false;
         }
 
@@ -398,17 +399,17 @@ import org.mozilla.gecko.gfx.GeckoSurfac
                 Log.w(LOGTAG, "unable to configure " + name + ". Try next.");
                 continue;
             }
             mCodec = codec;
             mInputProcessor = new InputProcessor();
             final boolean renderToSurface = surface != null;
             mOutputProcessor = new OutputProcessor(renderToSurface);
             mSamplePool = new SamplePool(name, renderToSurface);
-            if (DEBUG) { Log.d(LOGTAG, codec.toString() + " created. Render to surface?" + renderToSurface); }
+            if (DEBUG) { Log.i(LOGTAG, codec.toString() + " created. Render to surface?" + renderToSurface); }
             return true;
         }
 
         return false;
     }
 
     private List<String> findMatchingCodecNames(final String mimeType, final boolean isEncoder) {
         final int numCodecs = MediaCodecList.getCodecCount();
@@ -419,34 +420,34 @@ import org.mozilla.gecko.gfx.GeckoSurfac
                 continue;
             }
 
             final String[] types = info.getSupportedTypes();
             for (final String t : types) {
                 if (t.equalsIgnoreCase(mimeType)) {
                     found.add(info.getName());
                     if (DEBUG) {
-                        Log.d(LOGTAG, "found " + (isEncoder ? "encoder:" : "decoder:") +
+                        Log.i(LOGTAG, "found " + (isEncoder ? "encoder:" : "decoder:") +
                                 info.getName() + " for mime:" + mimeType);
                     }
                 }
             }
         }
         return found;
     }
 
     private AsyncCodec configureCodec(final String name, final MediaFormat format,
             final Surface surface, final int flags, final String drmStubId) {
         try {
             final AsyncCodec codec = AsyncCodecFactory.create(name);
             codec.setCallbacks(new Callbacks(), null);
 
             final MediaCrypto crypto = RemoteMediaDrmBridgeStub.getMediaCrypto(drmStubId);
             if (DEBUG) {
-                Log.d(LOGTAG, "configure mediacodec with crypto(" + (crypto != null) + ") / Id :" + drmStubId);
+                Log.i(LOGTAG, "configure mediacodec with crypto(" + (crypto != null) + ") / Id :" + drmStubId);
             }
 
             if (surface != null) {
                 setupAdaptivePlayback(codec, format);
             }
 
             codec.configure(format, surface, crypto, flags);
             return codec;
@@ -456,31 +457,31 @@ import org.mozilla.gecko.gfx.GeckoSurfac
         }
     }
 
     private void setupAdaptivePlayback(final AsyncCodec codec, final MediaFormat format) {
         // Video decoder should config with adaptive playback capability.
         mIsAdaptivePlaybackSupported = codec.isAdaptivePlaybackSupported(
                 format.getString(MediaFormat.KEY_MIME));
         if (mIsAdaptivePlaybackSupported) {
-            if (DEBUG) { Log.d(LOGTAG, "codec supports adaptive playback  = " + mIsAdaptivePlaybackSupported); }
+            if (DEBUG) { Log.i(LOGTAG, "codec supports adaptive playback  = " + mIsAdaptivePlaybackSupported); }
             // TODO: may need to find a way to not use hard code to decide the max w/h.
             format.setInteger(MediaFormat.KEY_MAX_WIDTH, 1920);
             format.setInteger(MediaFormat.KEY_MAX_HEIGHT, 1080);
         }
     }
 
     @Override
     public synchronized boolean isAdaptivePlaybackSupported() {
         return mIsAdaptivePlaybackSupported;
     }
 
     @Override
     public synchronized void start() throws RemoteException {
-        if (DEBUG) { Log.d(LOGTAG, "start " + this); }
+        if (DEBUG) { Log.i(LOGTAG, "start " + this); }
         mInputProcessor.start();
         mOutputProcessor.start();
         try {
             mCodec.start();
         } catch (Exception e) {
             reportError(Error.FATAL, e);
         }
     }
@@ -495,36 +496,36 @@ import org.mozilla.gecko.gfx.GeckoSurfac
             // mCallbacks has been disposed by release().
         } catch (RemoteException re) {
             re.printStackTrace();
         }
     }
 
     @Override
     public synchronized void stop() throws RemoteException {
-        if (DEBUG) { Log.d(LOGTAG, "stop " + this); }
+        if (DEBUG) { Log.i(LOGTAG, "stop " + this); }
         try {
             mInputProcessor.stop();
             mOutputProcessor.stop();
 
             mCodec.stop();
         } catch (Exception e) {
             reportError(Error.FATAL, e);
         }
     }
 
     @Override
     public synchronized void flush() throws RemoteException {
-        if (DEBUG) { Log.d(LOGTAG, "flush " + this); }
+        if (DEBUG) { Log.i(LOGTAG, "flush " + this); }
         try {
             mInputProcessor.stop();
             mOutputProcessor.stop();
 
             mCodec.flush();
-            if (DEBUG) { Log.d(LOGTAG, "flushed " + this); }
+            if (DEBUG) { Log.i(LOGTAG, "flushed " + this); }
             mInputProcessor.start();
             mOutputProcessor.start();
             mCodec.resumeReceivingInputs();
         } catch (Exception e) {
             reportError(Error.FATAL, e);
         }
     }
 
@@ -562,17 +563,17 @@ import org.mozilla.gecko.gfx.GeckoSurfac
             mOutputProcessor.onRelease(sample, render);
         } catch (Exception e) {
             reportError(Error.FATAL, e);
         }
     }
 
     @Override
     public synchronized void release() throws RemoteException {
-        if (DEBUG) { Log.d(LOGTAG, "release " + this); }
+        if (DEBUG) { Log.i(LOGTAG, "release " + this); }
         try {
             // In case Codec.stop() is not called yet.
             mInputProcessor.stop();
             mOutputProcessor.stop();
 
             mCodec.release();
         } catch (Exception e) {
             reportError(Error.FATAL, e);
--- a/mobile/android/geckoview/src/main/java/org/mozilla/gecko/media/CodecProxy.java
+++ b/mobile/android/geckoview/src/main/java/org/mozilla/gecko/media/CodecProxy.java
@@ -20,17 +20,17 @@ import org.mozilla.gecko.mozglue.JNIObje
 import java.io.IOException;
 import java.nio.ByteBuffer;
 import java.util.Queue;
 import java.util.concurrent.ConcurrentLinkedQueue;
 
 // Proxy class of ICodec binder.
 public final class CodecProxy {
     private static final String LOGTAG = "GeckoRemoteCodecProxy";
-    private static final boolean DEBUG = false;
+    private static final boolean DEBUG = true;
 
     private ICodec mRemote;
     private boolean mIsEncoder;
     private FormatParam mFormat;
     private GeckoSurface mOutputSurface;
     private CallbacksForwarder mCallbacks;
     private String mRemoteDrmStubId;
     private Queue<Sample> mSurfaceOutputs = new ConcurrentLinkedQueue<>();
@@ -89,16 +89,17 @@ public final class CodecProxy {
         public synchronized void onOutput(Sample sample) throws RemoteException {
             if (mCodecProxyReleased) {
                 sample.dispose();
                 return;
             }
             if (mOutputSurface != null) {
                 // Don't render to surface just yet. Callback will make that happen when it's time.
                 mSurfaceOutputs.offer(sample);
+                Log.i(LOGTAG, "output: " + sample);
                 mCallbacks.onOutput(sample);
             } else {
                 // Non-surface output needs no rendering.
                 try {
                     mCallbacks.onOutput(sample);
                     mRemote.releaseOutput(sample, false);
                     sample.dispose();
                 } catch (Exception e) {
@@ -236,17 +237,17 @@ public final class CodecProxy {
         if (mFlushed) {
             return true;
         }
         if (mRemote == null) {
             Log.e(LOGTAG, "cannot flush an ended codec");
             return false;
         }
         try {
-            if (DEBUG) { Log.d(LOGTAG, "flush " + this); }
+            if (DEBUG) { Log.i(LOGTAG, "flush " + this); }
             mRemote.flush();
             mFlushed = true;
         } catch (DeadObjectException e) {
             return false;
         } catch (RemoteException e) {
             e.printStackTrace();
             return false;
         }
@@ -256,17 +257,17 @@ public final class CodecProxy {
     @WrapForJNI
     public boolean release() {
         mCallbacks.setCodecProxyReleased();
         synchronized (this) {
             if (mRemote == null) {
                 Log.w(LOGTAG, "codec already ended");
                 return true;
             }
-            if (DEBUG) { Log.d(LOGTAG, "release " + this); }
+            if (DEBUG) { Log.i(LOGTAG, "release " + this); }
 
             if (!mSurfaceOutputs.isEmpty()) {
                 // Flushing output buffers to surface may cause some frames to be skipped and
                 // should not happen unless caller release codec before processing all buffers.
                 Log.w(LOGTAG, "release codec when " + mSurfaceOutputs.size() + " output buffers unhandled");
                 try {
                     for (Sample s : mSurfaceOutputs) {
                         mRemote.releaseOutput(s, true);
@@ -323,17 +324,18 @@ public final class CodecProxy {
         }
 
         if (mRemote == null) {
             Log.w(LOGTAG, "codec already ended");
             sample.dispose();
             return true;
         }
 
-        if (DEBUG && !render) { Log.d(LOGTAG, "drop output:" + sample.info.presentationTimeUs); }
+        Log.i(LOGTAG, (render ? "render" : "release") + " output pts=" + sample.info.presentationTimeUs);
+        if (DEBUG && !render) { Log.i(LOGTAG, "drop output:" + sample.info.presentationTimeUs); }
 
         try {
             mRemote.releaseOutput(sample, render);
         } catch (RemoteException e) {
             Log.e(LOGTAG, "remote fail to render output:" + sample.info.presentationTimeUs);
             e.printStackTrace();
         }
         sample.dispose();
--- a/mobile/android/geckoview/src/main/java/org/mozilla/gecko/media/LollipopAsyncCodec.java
+++ b/mobile/android/geckoview/src/main/java/org/mozilla/gecko/media/LollipopAsyncCodec.java
@@ -17,16 +17,18 @@ import android.support.annotation.NonNul
 import android.util.Log;
 import android.view.Surface;
 
 import java.io.IOException;
 import java.nio.ByteBuffer;
 
 /* package */ final class LollipopAsyncCodec implements AsyncCodec {
     private final MediaCodec mCodec;
+    private static final String LOGTAG = "GeckoAsyncCodecv21";
+    private static final boolean DEBUG = true;
 
     private class CodecCallback extends MediaCodec.Callback {
         private final Forwarder mForwarder;
 
         private class Forwarder extends Handler {
             private static final int MSG_INPUT_BUFFER_AVAILABLE = 1;
             private static final int MSG_OUTPUT_BUFFER_AVAILABLE = 2;
             private static final int MSG_OUTPUT_FORMAT_CHANGE = 3;
@@ -38,20 +40,22 @@ import java.nio.ByteBuffer;
                 super(looper);
                 mTarget = target;
             }
 
             @Override
             public void handleMessage(final Message msg) {
                 switch (msg.what) {
                     case MSG_INPUT_BUFFER_AVAILABLE:
+                        if (DEBUG) { Log.i(LOGTAG, "input#" + msg.arg1); }
                         mTarget.onInputBufferAvailable(LollipopAsyncCodec.this,
                                 msg.arg1); // index
                         break;
                     case MSG_OUTPUT_BUFFER_AVAILABLE:
+                        if (DEBUG) { Log.i(LOGTAG, "output#" + msg.arg1); }
                         mTarget.onOutputBufferAvailable(LollipopAsyncCodec.this,
                                 msg.arg1, // index
                                 (MediaCodec.BufferInfo)msg.obj); //  buffer info
                         break;
                     case MSG_OUTPUT_FORMAT_CHANGE:
                         mTarget.onOutputFormatChanged(LollipopAsyncCodec.this,
                                 (MediaFormat) msg.obj); // output format
                         break;
@@ -138,80 +142,91 @@ import java.nio.ByteBuffer;
             return;
         }
 
         mCodec.setCallback(new CodecCallback(callbacks, handler));
     }
 
     @Override
     public void configure(final MediaFormat format, final Surface surface, final MediaCrypto crypto, final int flags) {
+        if (DEBUG) { Log.i(LOGTAG, "configure"); }
         mCodec.configure(format, surface, crypto, flags);
     }
 
     @Override
     public boolean isAdaptivePlaybackSupported(final String mimeType) {
         return HardwareCodecCapabilityUtils.checkSupportsAdaptivePlayback(mCodec, mimeType);
     }
 
     @Override
     public void start() {
+        if (DEBUG) { Log.i(LOGTAG, "start"); }
         mCodec.start();
     }
 
     @Override
     public void stop() {
+        if (DEBUG) { Log.i(LOGTAG, "stop"); }
         mCodec.stop();
     }
 
     @Override
     public void flush() {
+        if (DEBUG) { Log.i(LOGTAG, "flush begin"); }
         mCodec.flush();
+        if (DEBUG) { Log.i(LOGTAG, "flush end"); }
     }
 
     @Override
     public void resumeReceivingInputs() {
+        if (DEBUG) { Log.i(LOGTAG, "resume input"); }
         mCodec.start();
     }
 
     @Override
     public void setRates(final int newBitRate) {
         final Bundle params = new Bundle();
         params.putInt(MediaCodec.PARAMETER_KEY_VIDEO_BITRATE, newBitRate * 1000);
         mCodec.setParameters(params);
     }
 
     @Override
     public void release() {
+        if (DEBUG) { Log.i(LOGTAG, "release"); }
         mCodec.release();
     }
 
     @Override
     public ByteBuffer getInputBuffer(final int index) {
+        if (DEBUG) { Log.i(LOGTAG, "get input#" + index); }
         return mCodec.getInputBuffer(index);
     }
 
     @Override
     public ByteBuffer getOutputBuffer(final int index) {
+        if (DEBUG) { Log.i(LOGTAG, "get output#" + index); }
         return mCodec.getOutputBuffer(index);
     }
 
     @Override
     public void queueInputBuffer(final int index, final int offset, final int size,
             final long presentationTimeUs, final int flags) {
         if ((flags & MediaCodec.BUFFER_FLAG_KEY_FRAME) != 0) {
             Bundle params = new Bundle();
             params.putInt(MediaCodec.PARAMETER_KEY_REQUEST_SYNC_FRAME, 0);
             mCodec.setParameters(params);
         }
+        if (DEBUG) { Log.i(LOGTAG, "queue input#" + index); }
         mCodec.queueInputBuffer(index, offset, size, presentationTimeUs, flags);
     }
 
     @Override
     public void queueSecureInputBuffer(final int index, final int offset, final MediaCodec.CryptoInfo info,
             final long presentationTimeUs, final int flags) {
         mCodec.queueSecureInputBuffer(index, offset, info, presentationTimeUs, flags);
     }
 
     @Override
     public void releaseOutputBuffer(final int index, final boolean render) {
+        if (DEBUG) { Log.i(LOGTAG, (render ? "release#" : "render#") + index); }
         mCodec.releaseOutputBuffer(index, render);
     }
 }
--- a/mobile/android/geckoview/src/main/java/org/mozilla/gecko/media/RemoteManager.java
+++ b/mobile/android/geckoview/src/main/java/org/mozilla/gecko/media/RemoteManager.java
@@ -20,17 +20,17 @@ import android.util.Log;
 import java.util.LinkedList;
 import java.util.List;
 import java.util.NoSuchElementException;
 
 import org.mozilla.gecko.gfx.GeckoSurface;
 
 public final class RemoteManager implements IBinder.DeathRecipient {
     private static final String LOGTAG = "GeckoRemoteManager";
-    private static final boolean DEBUG = false;
+    private static final boolean DEBUG = true;
     private static RemoteManager sRemoteManager = null;
     private static ICrashReporter setCrashReporter = null;
 
     public synchronized static RemoteManager getInstance() {
         if (sRemoteManager == null) {
             sRemoteManager = new RemoteManager();
         }
 
@@ -39,31 +39,31 @@ public final class RemoteManager impleme
     }
 
     private List<CodecProxy> mProxies = new LinkedList<CodecProxy>();
     private volatile IMediaManager mRemote;
 
     private final class RemoteConnection implements ServiceConnection {
         @Override
         public void onServiceConnected(ComponentName name, IBinder service) {
-            if (DEBUG) Log.d(LOGTAG, "service connected");
+            if (DEBUG) Log.i(LOGTAG, "service connected");
             try {
                 service.linkToDeath(RemoteManager.this, 0);
             } catch (RemoteException e) {
                 e.printStackTrace();
             }
             synchronized (this) {
                 mRemote = IMediaManager.Stub.asInterface(service);
                 notify();
             }
         }
 
         @Override
         public void onServiceDisconnected(ComponentName name) {
-            if (DEBUG) Log.d(LOGTAG, "service disconnected");
+            if (DEBUG) Log.i(LOGTAG, "service disconnected");
             unlink();
         }
 
         private boolean connect() {
             Context appCtxt = GeckoAppShell.getApplicationContext();
             appCtxt.bindService(new Intent(appCtxt, MediaManager.class),
                     mConnection, Context.BIND_AUTO_CREATE);
             waitConnect();
@@ -77,17 +77,17 @@ public final class RemoteManager impleme
                 try {
                     wait(1000);
                     waitCount++;
                 } catch (InterruptedException e) {
                     if (DEBUG) { e.printStackTrace(); }
                 }
             }
             if (DEBUG) {
-                Log.d(LOGTAG, "wait ~" + waitCount + "s for connection: " + (mRemote == null ? "fail" : "ok"));
+                Log.i(LOGTAG, "wait ~" + waitCount + "s for connection: " + (mRemote == null ? "fail" : "ok"));
             }
         }
 
         private synchronized void waitDisconnect() {
             while (mRemote != null) {
                 try {
                     wait(1000);
                 } catch (InterruptedException e) {
@@ -112,27 +112,27 @@ public final class RemoteManager impleme
 
     RemoteConnection mConnection = new RemoteConnection();
 
     private synchronized boolean init() {
         if (mRemote != null) {
             return true;
         }
 
-        if (DEBUG) Log.d(LOGTAG, "init remote manager " + this);
+        if (DEBUG) Log.i(LOGTAG, "init remote manager " + this);
         return mConnection.connect();
     }
 
     public synchronized CodecProxy createCodec(boolean isEncoder,
                                                MediaFormat format,
                                                GeckoSurface surface,
                                                CodecProxy.Callbacks callbacks,
                                                String drmStubId) {
         if (mRemote == null) {
-            if (DEBUG) Log.d(LOGTAG, "createCodec failed due to not initialize");
+            if (DEBUG) Log.i(LOGTAG, "createCodec failed due to not initialize");
             return null;
         }
         try {
             ICodec remote = mRemote.createCodec();
             CodecProxy proxy = CodecProxy.createCodecProxy(isEncoder, format, surface, callbacks, drmStubId);
             if (proxy.init(remote)) {
                 mProxies.add(proxy);
                 return proxy;
@@ -157,17 +157,17 @@ public final class RemoteManager impleme
 
     public interface ICrashReporter {
         void reportDecodingProcessCrash();
     }
 
     public synchronized IMediaDrmBridge createRemoteMediaDrmBridge(String keySystem,
                                                                    String stubId) {
         if (mRemote == null) {
-            if (DEBUG) Log.d(LOGTAG, "createRemoteMediaDrmBridge failed due to not initialize");
+            if (DEBUG) Log.i(LOGTAG, "createRemoteMediaDrmBridge failed due to not initialize");
             return null;
         }
         try {
             IMediaDrmBridge remoteBridge =
                 mRemote.createRemoteMediaDrmBridge(keySystem, stubId);
             return remoteBridge;
         } catch (RemoteException e) {
             Log.e(LOGTAG, "Got exception during createRemoteMediaDrmBridge().", e);
@@ -194,40 +194,40 @@ public final class RemoteManager impleme
 
     private synchronized void notifyError(boolean fatal) {
         for (CodecProxy proxy : mProxies) {
             proxy.reportError(fatal);
         }
     }
 
     private synchronized boolean recoverRemoteCodec() {
-        if (DEBUG) Log.d(LOGTAG, "recover codec");
+        if (DEBUG) Log.i(LOGTAG, "recover codec");
         boolean ok = true;
         try {
             for (CodecProxy proxy : mProxies) {
                 ok &= proxy.init(mRemote.createCodec());
             }
             return ok;
         } catch (RemoteException e) {
             return false;
         }
     }
 
     public void releaseCodec(CodecProxy proxy) throws DeadObjectException, RemoteException {
         if (mRemote == null) {
-            if (DEBUG) Log.d(LOGTAG, "releaseCodec called but not initialized yet");
+            if (DEBUG) Log.i(LOGTAG, "releaseCodec called but not initialized yet");
             return;
         }
         proxy.deinit();
         synchronized (this) {
             if (mProxies.remove(proxy) && mProxies.isEmpty()) {
                 release();
             }
         }
     }
 
     private void release() {
-        if (DEBUG) Log.d(LOGTAG, "release remote manager " + this);
+        if (DEBUG) Log.i(LOGTAG, "release remote manager " + this);
         mConnection.unlink();
         Context appCtxt = GeckoAppShell.getApplicationContext();
         appCtxt.unbindService(mConnection);
     }
 } // RemoteManager
\ No newline at end of file
--- a/mobile/android/geckoview/src/main/java/org/mozilla/gecko/media/SamplePool.java
+++ b/mobile/android/geckoview/src/main/java/org/mozilla/gecko/media/SamplePool.java
@@ -42,16 +42,17 @@ final class SamplePool {
             } else {
                 return allocateSharedMemorySample(size);
             }
         }
 
         private Sample allocateSharedMemorySample(int size) {
             SharedMemory shm = null;
             try {
+                android.util.Log.v("SamplePool", mName + " allocate sample#" + mNextId + " size=" + Math.max(size, mDefaultBufferSize));
                 shm = new SharedMemory(mNextId++, Math.max(size, mDefaultBufferSize));
             } catch (NoSuchMethodException | IOException e) {
                 throw new UnsupportedOperationException(e);
             }
 
             return Sample.create(shm);
         }