stagefright: add runtime debug support

Bug: 18285408
Change-Id: I56346f4652b2c5f7ef5fa3003fd8676051339384

1 files changed, 398 insertions, 167 deletions

diff --git a/media/libstagefright/omx/OMXNodeInstance.cpp b/media/libstagefright/omx/OMXNodeInstance.cpp
index f9c84e2..c04d95f 100644
--- a/media/libstagefright/omx/OMXNodeInstance.cpp
+++ b/media/libstagefright/omx/OMXNodeInstance.cpp
@@ -18,11 +18,15 @@
 #define LOG_TAG "OMXNodeInstance"
 #include <utils/Log.h>
 
+#include <inttypes.h>
+
 #include "../include/OMXNodeInstance.h"
 #include "OMXMaster.h"
 #include "GraphicBufferSource.h"
 
 #include <OMX_Component.h>
+#include <OMX_IndexExt.h>
+#include <OMX_AsString.h>
 
 #include <binder/IMemory.h>
 #include <gui/BufferQueue.h>
@@ -30,7 +34,68 @@
 #include <media/stagefright/foundation/ADebug.h>
 #include <media/stagefright/MediaErrors.h>
 
+#include <utils/misc.h>
+
 static const OMX_U32 kPortIndexInput = 0;
+static const OMX_U32 kPortIndexOutput = 1;
+
+#define CLOGW(fmt, ...) ALOGW("[%x:%s] " fmt, mNodeID, mName, ##__VA_ARGS__)
+
+#define CLOG_ERROR_IF(cond, fn, err, fmt, ...) \
+    ALOGE_IF(cond, #fn "(%x:%s, " fmt ") ERROR: %s(%#x)", \
+    mNodeID, mName, ##__VA_ARGS__, asString(err), err)
+#define CLOG_ERROR(fn, err, fmt, ...) CLOG_ERROR_IF(true, fn, err, fmt, ##__VA_ARGS__)
+#define CLOG_IF_ERROR(fn, err, fmt, ...) \
+    CLOG_ERROR_IF((err) != OMX_ErrorNone, fn, err, fmt, ##__VA_ARGS__)
+
+#define CLOGI_(level, fn, fmt, ...) \
+    ALOGI_IF(DEBUG >= (level), #fn "(%x:%s, " fmt ")", mNodeID, mName, ##__VA_ARGS__)
+#define CLOGD_(level, fn, fmt, ...) \
+    ALOGD_IF(DEBUG >= (level), #fn "(%x:%s, " fmt ")", mNodeID, mName, ##__VA_ARGS__)
+
+#define CLOG_LIFE(fn, fmt, ...)     CLOGI_(ADebug::kDebugLifeCycle,     fn, fmt, ##__VA_ARGS__)
+#define CLOG_STATE(fn, fmt, ...)    CLOGI_(ADebug::kDebugState,         fn, fmt, ##__VA_ARGS__)
+#define CLOG_CONFIG(fn, fmt, ...)   CLOGI_(ADebug::kDebugConfig,        fn, fmt, ##__VA_ARGS__)
+#define CLOG_INTERNAL(fn, fmt, ...) CLOGD_(ADebug::kDebugInternalState, fn, fmt, ##__VA_ARGS__)
+
+#define CLOG_DEBUG_IF(cond, fn, fmt, ...) \
+    ALOGD_IF(cond, #fn "(%x, " fmt ")", mNodeID, ##__VA_ARGS__)
+
+#define CLOG_BUFFER(fn, fmt, ...) \
+    CLOG_DEBUG_IF(DEBUG >= ADebug::kDebugAll, fn, fmt, ##__VA_ARGS__)
+#define CLOG_BUMPED_BUFFER(fn, fmt, ...) \
+    CLOG_DEBUG_IF(DEBUG_BUMP >= ADebug::kDebugAll, fn, fmt, ##__VA_ARGS__)
+
+/* buffer formatting */
+#define BUFFER_FMT(port, fmt, ...) "%s:%u " fmt, portString(port), (port), ##__VA_ARGS__
+#define NEW_BUFFER_FMT(buffer_id, port, fmt, ...) \
+    BUFFER_FMT(port, fmt ") (#%zu => %#x", ##__VA_ARGS__, mActiveBuffers.size(), (buffer_id))
+
+#define SIMPLE_BUFFER(port, size, data) BUFFER_FMT(port, "%zu@%p", (size), (data))
+#define SIMPLE_NEW_BUFFER(buffer_id, port, size, data) \
+    NEW_BUFFER_FMT(buffer_id, port, "%zu@%p", (size), (data))
+
+#define EMPTY_BUFFER(addr, header) "%#x [%u@%p]", \
+    (addr), (header)->nAllocLen, (header)->pBuffer
+#define FULL_BUFFER(addr, header) "%#" PRIxPTR " [%u@%p (%u..+%u) f=%x ts=%lld]", \
+    (intptr_t)(addr), (header)->nAllocLen, (header)->pBuffer, \
+    (header)->nOffset, (header)->nFilledLen, (header)->nFlags, (header)->nTimeStamp
+
+#define WITH_STATS_WRAPPER(fmt, ...) fmt " { IN=%zu/%zu OUT=%zu/%zu }", ##__VA_ARGS__, \
+    mInputBuffersWithCodec.size(), mNumPortBuffers[kPortIndexInput], \
+    mOutputBuffersWithCodec.size(), mNumPortBuffers[kPortIndexOutput]
+// TRICKY: this is needed so formatting macros expand before substitution
+#define WITH_STATS(fmt, ...) WITH_STATS_WRAPPER(fmt, ##__VA_ARGS__)
+
+template<class T>
+static void InitOMXParams(T *params) {
+    memset(params, 0, sizeof(T));
+    params->nSize = sizeof(T);
+    params->nVersion.s.nVersionMajor = 1;
+    params->nVersion.s.nVersionMinor = 0;
+    params->nVersion.s.nRevision = 0;
+    params->nVersion.s.nStep = 0;
+}
 
 namespace android {
 
@@ -56,8 +121,8 @@ struct BufferMeta {
         }
 
         memcpy((OMX_U8 *)mMem->pointer() + header->nOffset,
-               header->pBuffer + header->nOffset,
-               header->nFilledLen);
+                header->pBuffer + header->nOffset,
+                header->nFilledLen);
     }
 
     void CopyToOMX(const OMX_BUFFERHEADERTYPE *header) {
@@ -66,8 +131,8 @@ struct BufferMeta {
         }
 
         memcpy(header->pBuffer + header->nOffset,
-               (const OMX_U8 *)mMem->pointer() + header->nOffset,
-               header->nFilledLen);
+                (const OMX_U8 *)mMem->pointer() + header->nOffset,
+                header->nFilledLen);
     }
 
     void setGraphicBuffer(const sp<GraphicBuffer> &graphicBuffer) {
@@ -89,8 +154,17 @@ OMX_CALLBACKTYPE OMXNodeInstance::kCallbacks = {
     &OnEvent, &OnEmptyBufferDone, &OnFillBufferDone
 };
 
+static inline const char *portString(OMX_U32 portIndex) {
+    switch (portIndex) {
+        case kPortIndexInput:  return "Input";
+        case kPortIndexOutput: return "Output";
+        case ~0:               return "All";
+        default:               return "port";
+    }
+}
+
 OMXNodeInstance::OMXNodeInstance(
-        OMX *owner, const sp<IOMXObserver> &observer)
+        OMX *owner, const sp<IOMXObserver> &observer, const char *name)
     : mOwner(owner),
       mNodeID(0),
       mHandle(NULL),
@@ -100,15 +174,25 @@ OMXNodeInstance::OMXNodeInstance(
       , mBufferIDCount(0)
 #endif
 {
+    mName = ADebug::GetDebugName(name);
+    DEBUG = ADebug::GetDebugLevelFromProperty(name, "debug.stagefright.omx-debug");
+    ALOGV("debug level for %s is %d", name, DEBUG);
+    DEBUG_BUMP = DEBUG;
+    mNumPortBuffers[0] = 0;
+    mNumPortBuffers[1] = 0;
+    mDebugLevelBumpPendingBuffers[0] = 0;
+    mDebugLevelBumpPendingBuffers[1] = 0;
 }
 
 OMXNodeInstance::~OMXNodeInstance() {
+    free(mName);
     CHECK(mHandle == NULL);
 }
 
 void OMXNodeInstance::setHandle(OMX::node_id node_id, OMX_HANDLETYPE handle) {
-    CHECK(mHandle == NULL);
     mNodeID = node_id;
+    CLOG_LIFE(allocateNode, "handle=%p", handle);
+    CHECK(mHandle == NULL);
     mHandle = handle;
 }
 
@@ -120,6 +204,7 @@ sp<GraphicBufferSource> OMXNodeInstance::getGraphicBufferSource() {
 void OMXNodeInstance::setGraphicBufferSource(
         const sp<GraphicBufferSource>& bufferSource) {
     Mutex::Autolock autoLock(mGraphicBufferSourceLock);
+    CLOG_INTERNAL(setGraphicBufferSource, "%p", bufferSource.get());
     mGraphicBufferSource = bufferSource;
 }
 
@@ -140,6 +225,7 @@ static status_t StatusFromOMXError(OMX_ERRORTYPE err) {
         case OMX_ErrorNone:
             return OK;
         case OMX_ErrorUnsupportedSetting:
+        case OMX_ErrorUnsupportedIndex:
             return ERROR_UNSUPPORTED;
         default:
             return UNKNOWN_ERROR;
@@ -147,6 +233,7 @@ static status_t StatusFromOMXError(OMX_ERRORTYPE err) {
 }
 
 status_t OMXNodeInstance::freeNode(OMXMaster *master) {
+    CLOG_LIFE(freeNode, "handle=%p", mHandle);
     static int32_t kMaxNumIterations = 10;
 
     // exit if we have already freed the node
@@ -175,10 +262,11 @@ status_t OMXNodeInstance::freeNode(OMXMaster *master) {
             OMX_ERRORTYPE err;
             int32_t iteration = 0;
             while ((err = OMX_GetState(mHandle, &state)) == OMX_ErrorNone
-                   && state != OMX_StateIdle
-                   && state != OMX_StateInvalid) {
+                    && state != OMX_StateIdle
+                    && state != OMX_StateInvalid) {
                 if (++iteration > kMaxNumIterations) {
-                    ALOGE("component failed to enter Idle state, aborting.");
+                    CLOGW("failed to enter Idle state (now %s(%d), aborting.",
+                            asString(state), state);
                     state = OMX_StateInvalid;
                     break;
                 }
@@ -204,10 +292,11 @@ status_t OMXNodeInstance::freeNode(OMXMaster *master) {
             OMX_ERRORTYPE err;
             int32_t iteration = 0;
             while ((err = OMX_GetState(mHandle, &state)) == OMX_ErrorNone
-                   && state != OMX_StateLoaded
-                   && state != OMX_StateInvalid) {
+                    && state != OMX_StateLoaded
+                    && state != OMX_StateInvalid) {
                 if (++iteration > kMaxNumIterations) {
-                    ALOGE("component failed to enter Loaded state, aborting.");
+                    CLOGW("failed to enter Loaded state (now %s(%d), aborting.",
+                            asString(state), state);
                     state = OMX_StateInvalid;
                     break;
                 }
@@ -225,20 +314,18 @@ status_t OMXNodeInstance::freeNode(OMXMaster *master) {
             break;
 
         default:
-            CHECK(!"should not be here, unknown state.");
+            LOG_ALWAYS_FATAL("unknown state %s(%#x).", asString(state), state);
             break;
     }
 
-    ALOGV("calling destroyComponentInstance");
+    ALOGV("[%x:%s] calling destroyComponentInstance", mNodeID, mName);
     OMX_ERRORTYPE err = master->destroyComponentInstance(
             static_cast<OMX_COMPONENTTYPE *>(mHandle));
-    ALOGV("destroyComponentInstance returned err %d", err);
 
     mHandle = NULL;
-
-    if (err != OMX_ErrorNone) {
-        ALOGE("FreeHandle FAILED with error 0x%08x.", err);
-    }
+    CLOG_IF_ERROR(freeNode, err, "");
+    free(mName);
+    mName = NULL;
 
     mOwner->invalidateNodeID(mNodeID);
     mNodeID = 0;
@@ -270,7 +357,17 @@ status_t OMXNodeInstance::sendCommand(
 
     Mutex::Autolock autoLock(mLock);
 
+    // bump internal-state debug level for 2 input and output frames past a command
+    {
+        Mutex::Autolock _l(mDebugLock);
+        bumpDebugLevel_l(2 /* numInputBuffers */, 2 /* numOutputBuffers */);
+    }
+
+    const char *paramString =
+        cmd == OMX_CommandStateSet ? asString((OMX_STATETYPE)param) : portString(param);
+    CLOG_STATE(sendCommand, "%s(%d), %s(%d)", asString(cmd), cmd, paramString, param);
     OMX_ERRORTYPE err = OMX_SendCommand(mHandle, cmd, param, NULL);
+    CLOG_IF_ERROR(sendCommand, err, "%s(%d), %s(%d)", asString(cmd), cmd, paramString, param);
     return StatusFromOMXError(err);
 }
 
@@ -279,17 +376,23 @@ status_t OMXNodeInstance::getParameter(
     Mutex::Autolock autoLock(mLock);
 
     OMX_ERRORTYPE err = OMX_GetParameter(mHandle, index, params);
-    ALOGE_IF(err != OMX_ErrorNone, "getParameter(%d) ERROR: %#x", index, err);
+    OMX_INDEXEXTTYPE extIndex = (OMX_INDEXEXTTYPE)index;
+    // some errors are expected for getParameter
+    if (err != OMX_ErrorNoMore) {
+        CLOG_IF_ERROR(getParameter, err, "%s(%#x)", asString(extIndex), index);
+    }
     return StatusFromOMXError(err);
 }
 
 status_t OMXNodeInstance::setParameter(
-        OMX_INDEXTYPE index, const void *params, size_t /* size */) {
+        OMX_INDEXTYPE index, const void *params, size_t size) {
     Mutex::Autolock autoLock(mLock);
+    OMX_INDEXEXTTYPE extIndex = (OMX_INDEXEXTTYPE)index;
+    CLOG_CONFIG(setParameter, "%s(%#x), %zu@%p)", asString(extIndex), index, size, params);
 
     OMX_ERRORTYPE err = OMX_SetParameter(
             mHandle, index, const_cast<void *>(params));
-    ALOGE_IF(err != OMX_ErrorNone, "setParameter(%d) ERROR: %#x", index, err);
+    CLOG_IF_ERROR(setParameter, err, "%s(%#x)", asString(extIndex), index);
     return StatusFromOMXError(err);
 }
 
@@ -298,16 +401,23 @@ status_t OMXNodeInstance::getConfig(
     Mutex::Autolock autoLock(mLock);
 
     OMX_ERRORTYPE err = OMX_GetConfig(mHandle, index, params);
+    OMX_INDEXEXTTYPE extIndex = (OMX_INDEXEXTTYPE)index;
+    // some errors are expected for getConfig
+    if (err != OMX_ErrorNoMore) {
+        CLOG_IF_ERROR(getConfig, err, "%s(%#x)", asString(extIndex), index);
+    }
     return StatusFromOMXError(err);
 }
 
 status_t OMXNodeInstance::setConfig(
-        OMX_INDEXTYPE index, const void *params, size_t /* size */) {
+        OMX_INDEXTYPE index, const void *params, size_t size) {
     Mutex::Autolock autoLock(mLock);
+    OMX_INDEXEXTTYPE extIndex = (OMX_INDEXEXTTYPE)index;
+    CLOG_CONFIG(setConfig, "%s(%#x), %zu@%p)", asString(extIndex), index, size, params);
 
     OMX_ERRORTYPE err = OMX_SetConfig(
             mHandle, index, const_cast<void *>(params));
-
+    CLOG_IF_ERROR(setConfig, err, "%s(%#x)", asString(extIndex), index);
     return StatusFromOMXError(err);
 }
 
@@ -315,13 +425,14 @@ status_t OMXNodeInstance::getState(OMX_STATETYPE* state) {
     Mutex::Autolock autoLock(mLock);
 
     OMX_ERRORTYPE err = OMX_GetState(mHandle, state);
-
+    CLOG_IF_ERROR(getState, err, "");
     return StatusFromOMXError(err);
 }
 
 status_t OMXNodeInstance::enableGraphicBuffers(
         OMX_U32 portIndex, OMX_BOOL enable) {
     Mutex::Autolock autoLock(mLock);
+    CLOG_CONFIG(enableGraphicBuffers, "%s:%u, %d", portString(portIndex), portIndex, enable);
     OMX_STRING name = const_cast<OMX_STRING>(
             "OMX.google.android.index.enableAndroidNativeBuffers");
 
@@ -329,32 +440,19 @@ status_t OMXNodeInstance::enableGraphicBuffers(
     OMX_ERRORTYPE err = OMX_GetExtensionIndex(mHandle, name, &index);
 
     if (err != OMX_ErrorNone) {
-        if (enable) {
-            ALOGE("OMX_GetExtensionIndex %s failed", name);
-        }
-
+        CLOG_ERROR_IF(enable, getExtensionIndex, err, "%s", name);
         return StatusFromOMXError(err);
     }
 
-    OMX_VERSIONTYPE ver;
-    ver.s.nVersionMajor = 1;
-    ver.s.nVersionMinor = 0;
-    ver.s.nRevision = 0;
-    ver.s.nStep = 0;
-    EnableAndroidNativeBuffersParams params = {
-        sizeof(EnableAndroidNativeBuffersParams), ver, portIndex, enable,
-    };
+    EnableAndroidNativeBuffersParams params;
+    InitOMXParams(&params);
+    params.nPortIndex = portIndex;
+    params.enable = enable;
 
     err = OMX_SetParameter(mHandle, index, &params);
-
-    if (err != OMX_ErrorNone) {
-        ALOGE("OMX_EnableAndroidNativeBuffers failed with error %d (0x%08x)",
-                err, err);
-
-        return UNKNOWN_ERROR;
-    }
-
-    return OK;
+    CLOG_IF_ERROR(setParameter, err, "%s(%#x): %s:%u en=%d", name, index,
+            portString(portIndex), portIndex, enable);
+    return StatusFromOMXError(err);
 }
 
 status_t OMXNodeInstance::getGraphicBufferUsage(
@@ -367,26 +465,19 @@ status_t OMXNodeInstance::getGraphicBufferUsage(
     OMX_ERRORTYPE err = OMX_GetExtensionIndex(mHandle, name, &index);
 
     if (err != OMX_ErrorNone) {
-        ALOGE("OMX_GetExtensionIndex %s failed", name);
-
+        CLOG_ERROR(getExtensionIndex, err, "%s", name);
         return StatusFromOMXError(err);
     }
 
-    OMX_VERSIONTYPE ver;
-    ver.s.nVersionMajor = 1;
-    ver.s.nVersionMinor = 0;
-    ver.s.nRevision = 0;
-    ver.s.nStep = 0;
-    GetAndroidNativeBufferUsageParams params = {
-        sizeof(GetAndroidNativeBufferUsageParams), ver, portIndex, 0,
-    };
+    GetAndroidNativeBufferUsageParams params;
+    InitOMXParams(&params);
+    params.nPortIndex = portIndex;
 
     err = OMX_GetParameter(mHandle, index, &params);
-
     if (err != OMX_ErrorNone) {
-        ALOGE("OMX_GetAndroidNativeBufferUsage failed with error %d (0x%08x)",
-                err, err);
-        return UNKNOWN_ERROR;
+        CLOG_ERROR(getParameter, err, "%s(%#x): %s:%u", name, index,
+                portString(portIndex), portIndex);
+        return StatusFromOMXError(err);
     }
 
     *usage = params.nUsage;
@@ -398,6 +489,7 @@ status_t OMXNodeInstance::storeMetaDataInBuffers(
         OMX_U32 portIndex,
         OMX_BOOL enable) {
     Mutex::Autolock autolock(mLock);
+    CLOG_CONFIG(storeMetaDataInBuffers, "%s:%u en:%d", portString(portIndex), portIndex, enable);
     return storeMetaDataInBuffers_l(
             portIndex, enable,
             OMX_FALSE /* useGraphicBuffer */, NULL /* usingGraphicBufferInMetadata */);
@@ -424,37 +516,42 @@ status_t OMXNodeInstance::storeMetaDataInBuffers_l(
                 : OMX_ErrorBadParameter;
     if (err == OMX_ErrorNone) {
         *usingGraphicBufferInMetadata = OMX_TRUE;
+        name = graphicBufferName;
     } else {
-        *usingGraphicBufferInMetadata = OMX_FALSE;
         err = OMX_GetExtensionIndex(mHandle, name, &index);
     }
 
-    if (err != OMX_ErrorNone) {
-        ALOGE("OMX_GetExtensionIndex %s failed", name);
-        return StatusFromOMXError(err);
-    }
-
-    StoreMetaDataInBuffersParams params;
-    memset(&params, 0, sizeof(params));
-    params.nSize = sizeof(params);
+    OMX_ERRORTYPE xerr = err;
+    if (err == OMX_ErrorNone) {
+        StoreMetaDataInBuffersParams params;
+        InitOMXParams(&params);
+        params.nPortIndex = portIndex;
+        params.bStoreMetaData = enable;
 
-    // Version: 1.0.0.0
-    params.nVersion.s.nVersionMajor = 1;
+        err = OMX_SetParameter(mHandle, index, &params);
+    }
 
-    params.nPortIndex = portIndex;
-    params.bStoreMetaData = enable;
-    if ((err = OMX_SetParameter(mHandle, index, &params)) != OMX_ErrorNone) {
-        ALOGE("OMX_SetParameter() failed for StoreMetaDataInBuffers: 0x%08x", err);
+    // don't log loud error if component does not support metadata mode on the output
+    if (err != OMX_ErrorNone) {
         *usingGraphicBufferInMetadata = OMX_FALSE;
-        return UNKNOWN_ERROR;
+        if (err == OMX_ErrorUnsupportedIndex && portIndex == kPortIndexOutput) {
+            CLOGW("component does not support metadata mode; using fallback");
+        } else if (xerr != OMX_ErrorNone) {
+            CLOG_ERROR(getExtensionIndex, xerr, "%s", name);
+        } else {
+            CLOG_ERROR(setParameter, err, "%s(%#x): %s:%u en=%d GB=%d", name, index,
+                    portString(portIndex), portIndex, enable, useGraphicBuffer);
+        }
     }
-    return err;
+    return StatusFromOMXError(err);
 }
 
 status_t OMXNodeInstance::prepareForAdaptivePlayback(
         OMX_U32 portIndex, OMX_BOOL enable, OMX_U32 maxFrameWidth,
         OMX_U32 maxFrameHeight) {
     Mutex::Autolock autolock(mLock);
+    CLOG_CONFIG(prepareForAdaptivePlayback, "%s:%u en=%d max=%ux%u",
+            portString(portIndex), portIndex, enable, maxFrameWidth, maxFrameHeight);
 
     OMX_INDEXTYPE index;
     OMX_STRING name = const_cast<OMX_STRING>(
@@ -462,33 +559,29 @@ status_t OMXNodeInstance::prepareForAdaptivePlayback(
 
     OMX_ERRORTYPE err = OMX_GetExtensionIndex(mHandle, name, &index);
     if (err != OMX_ErrorNone) {
-        ALOGW_IF(enable, "OMX_GetExtensionIndex %s failed", name);
+        CLOG_ERROR_IF(enable, getExtensionIndex, err, "%s", name);
         return StatusFromOMXError(err);
     }
 
     PrepareForAdaptivePlaybackParams params;
-    params.nSize = sizeof(params);
-    params.nVersion.s.nVersionMajor = 1;
-    params.nVersion.s.nVersionMinor = 0;
-    params.nVersion.s.nRevision = 0;
-    params.nVersion.s.nStep = 0;
-
+    InitOMXParams(&params);
     params.nPortIndex = portIndex;
     params.bEnable = enable;
     params.nMaxFrameWidth = maxFrameWidth;
     params.nMaxFrameHeight = maxFrameHeight;
-    if ((err = OMX_SetParameter(mHandle, index, &params)) != OMX_ErrorNone) {
-        ALOGW("OMX_SetParameter failed for PrepareForAdaptivePlayback "
-              "with error %d (0x%08x)", err, err);
-        return UNKNOWN_ERROR;
-    }
-    return err;
+
+    err = OMX_SetParameter(mHandle, index, &params);
+    CLOG_IF_ERROR(setParameter, err, "%s(%#x): %s:%u en=%d max=%ux%u", name, index,
+            portString(portIndex), portIndex, enable, maxFrameWidth, maxFrameHeight);
+    return StatusFromOMXError(err);
 }
 
 status_t OMXNodeInstance::configureVideoTunnelMode(
         OMX_U32 portIndex, OMX_BOOL tunneled, OMX_U32 audioHwSync,
         native_handle_t **sidebandHandle) {
     Mutex::Autolock autolock(mLock);
+    CLOG_CONFIG(configureVideoTunnelMode, "%s:%u tun=%d sync=%u",
+            portString(portIndex), portIndex, tunneled, audioHwSync);
 
     OMX_INDEXTYPE index;
     OMX_STRING name = const_cast<OMX_STRING>(
@@ -496,36 +589,33 @@ status_t OMXNodeInstance::configureVideoTunnelMode(
 
     OMX_ERRORTYPE err = OMX_GetExtensionIndex(mHandle, name, &index);
     if (err != OMX_ErrorNone) {
-        ALOGE("configureVideoTunnelMode extension is missing!");
+        CLOG_ERROR_IF(tunneled, getExtensionIndex, err, "%s", name);
         return StatusFromOMXError(err);
     }
 
     ConfigureVideoTunnelModeParams tunnelParams;
-    tunnelParams.nSize = sizeof(tunnelParams);
-    tunnelParams.nVersion.s.nVersionMajor = 1;
-    tunnelParams.nVersion.s.nVersionMinor = 0;
-    tunnelParams.nVersion.s.nRevision = 0;
-    tunnelParams.nVersion.s.nStep = 0;
-
+    InitOMXParams(&tunnelParams);
     tunnelParams.nPortIndex = portIndex;
     tunnelParams.bTunneled = tunneled;
     tunnelParams.nAudioHwSync = audioHwSync;
     err = OMX_SetParameter(mHandle, index, &tunnelParams);
     if (err != OMX_ErrorNone) {
-        ALOGE("configureVideoTunnelMode failed! (err %d).", err);
-        return UNKNOWN_ERROR;
+        CLOG_ERROR(setParameter, err, "%s(%#x): %s:%u tun=%d sync=%u", name, index,
+                portString(portIndex), portIndex, tunneled, audioHwSync);
+        return StatusFromOMXError(err);
     }
 
     err = OMX_GetParameter(mHandle, index, &tunnelParams);
     if (err != OMX_ErrorNone) {
-        ALOGE("GetVideoTunnelWindow failed! (err %d).", err);
-        return UNKNOWN_ERROR;
+        CLOG_ERROR(getParameter, err, "%s(%#x): %s:%u tun=%d sync=%u", name, index,
+                portString(portIndex), portIndex, tunneled, audioHwSync);
+        return StatusFromOMXError(err);
     }
     if (sidebandHandle) {
         *sidebandHandle = (native_handle_t*)tunnelParams.pSidebandWindow;
     }
 
-    return err;
+    return OK;
 }
 
 status_t OMXNodeInstance::useBuffer(
@@ -542,14 +632,14 @@ status_t OMXNodeInstance::useBuffer(
             params->size(), static_cast<OMX_U8 *>(params->pointer()));
 
     if (err != OMX_ErrorNone) {
-        ALOGE("OMX_UseBuffer failed with error %d (0x%08x)", err, err);
+        CLOG_ERROR(useBuffer, err, SIMPLE_BUFFER(portIndex, params->size(), params->pointer()));
 
         delete buffer_meta;
         buffer_meta = NULL;
 
         *buffer = 0;
 
-        return UNKNOWN_ERROR;
+        return StatusFromOMXError(err);
     }
 
     CHECK_EQ(header->pAppPrivate, buffer_meta);
@@ -563,6 +653,8 @@ status_t OMXNodeInstance::useBuffer(
         bufferSource->addCodecBuffer(header);
     }
 
+    CLOG_BUFFER(useBuffer, NEW_BUFFER_FMT(
+            *buffer, portIndex, "%zu@%p", params->size(), params->pointer()));
     return OK;
 }
 
@@ -572,17 +664,14 @@ status_t OMXNodeInstance::useGraphicBuffer2_l(
 
     // port definition
     OMX_PARAM_PORTDEFINITIONTYPE def;
-    def.nSize = sizeof(OMX_PARAM_PORTDEFINITIONTYPE);
-    def.nVersion.s.nVersionMajor = 1;
-    def.nVersion.s.nVersionMinor = 0;
-    def.nVersion.s.nRevision = 0;
-    def.nVersion.s.nStep = 0;
+    InitOMXParams(&def);
     def.nPortIndex = portIndex;
     OMX_ERRORTYPE err = OMX_GetParameter(mHandle, OMX_IndexParamPortDefinition, &def);
-    if (err != OMX_ErrorNone)
-    {
-        ALOGE("%s::%d:Error getting OMX_IndexParamPortDefinition", __FUNCTION__, __LINE__);
-        return err;
+    if (err != OMX_ErrorNone) {
+        OMX_INDEXTYPE index = OMX_IndexParamPortDefinition;
+        CLOG_ERROR(getParameter, err, "%s(%#x): %s:%u",
+                asString(index), index, portString(portIndex), portIndex);
+        return UNKNOWN_ERROR;
     }
 
     BufferMeta *bufferMeta = new BufferMeta(graphicBuffer);
@@ -600,11 +689,11 @@ status_t OMXNodeInstance::useGraphicBuffer2_l(
             bufferHandle);
 
     if (err != OMX_ErrorNone) {
-        ALOGE("OMX_UseBuffer failed with error %d (0x%08x)", err, err);
+        CLOG_ERROR(useBuffer, err, BUFFER_FMT(portIndex, "%u@%p", def.nBufferSize, bufferHandle));
         delete bufferMeta;
         bufferMeta = NULL;
         *buffer = 0;
-        return UNKNOWN_ERROR;
+        return StatusFromOMXError(err);
     }
 
     CHECK_EQ(header->pBuffer, bufferHandle);
@@ -613,7 +702,8 @@ status_t OMXNodeInstance::useGraphicBuffer2_l(
     *buffer = makeBufferID(header);
 
     addActiveBuffer(portIndex, *buffer);
-
+    CLOG_BUFFER(useGraphicBuffer2, NEW_BUFFER_FMT(
+            *buffer, portIndex, "%u@%p", def.nBufferSize, bufferHandle));
     return OK;
 }
 
@@ -637,10 +727,8 @@ status_t OMXNodeInstance::useGraphicBuffer(
     OMX_STRING name = const_cast<OMX_STRING>(
         "OMX.google.android.index.useAndroidNativeBuffer");
     OMX_ERRORTYPE err = OMX_GetExtensionIndex(mHandle, name, &index);
-
     if (err != OMX_ErrorNone) {
-        ALOGE("OMX_GetExtensionIndex %s failed", name);
-
+        CLOG_ERROR(getExtensionIndex, err, "%s", name);
         return StatusFromOMXError(err);
     }
 
@@ -661,15 +749,15 @@ status_t OMXNodeInstance::useGraphicBuffer(
     err = OMX_SetParameter(mHandle, index, &params);
 
     if (err != OMX_ErrorNone) {
-        ALOGE("OMX_UseAndroidNativeBuffer failed with error %d (0x%08x)", err,
-                err);
+        CLOG_ERROR(setParameter, err, "%s(%#x): %s:%u meta=%p GB=%p", name, index,
+                portString(portIndex), portIndex, bufferMeta, graphicBuffer->handle);
 
         delete bufferMeta;
         bufferMeta = NULL;
 
         *buffer = 0;
 
-        return UNKNOWN_ERROR;
+        return StatusFromOMXError(err);
     }
 
     CHECK_EQ(header->pAppPrivate, bufferMeta);
@@ -677,12 +765,13 @@ status_t OMXNodeInstance::useGraphicBuffer(
     *buffer = makeBufferID(header);
 
     addActiveBuffer(portIndex, *buffer);
-
+    CLOG_BUFFER(useGraphicBuffer, NEW_BUFFER_FMT(
+            *buffer, portIndex, "GB=%p", graphicBuffer->handle));
     return OK;
 }
 
 status_t OMXNodeInstance::updateGraphicBufferInMeta(
-        OMX_U32 /* portIndex */, const sp<GraphicBuffer>& graphicBuffer,
+        OMX_U32 portIndex, const sp<GraphicBuffer>& graphicBuffer,
         OMX::buffer_id buffer) {
     Mutex::Autolock autoLock(mLock);
 
@@ -693,7 +782,8 @@ status_t OMXNodeInstance::updateGraphicBufferInMeta(
     bufferMeta->setGraphicBuffer(graphicBuffer);
     metadata->eType = kMetadataBufferTypeGrallocSource;
     metadata->pHandle = graphicBuffer->handle;
-
+    CLOG_BUFFER(updateGraphicBufferInMeta, "%s:%u, %#x := %p",
+            portString(portIndex), portIndex, buffer, graphicBuffer->handle);
     return OK;
 }
 
@@ -719,19 +809,21 @@ status_t OMXNodeInstance::createInputSurface(
     // Retrieve the width and height of the graphic buffer, set when the
     // codec was configured.
     OMX_PARAM_PORTDEFINITIONTYPE def;
-    def.nSize = sizeof(def);
-    def.nVersion.s.nVersionMajor = 1;
-    def.nVersion.s.nVersionMinor = 0;
-    def.nVersion.s.nRevision = 0;
-    def.nVersion.s.nStep = 0;
+    InitOMXParams(&def);
     def.nPortIndex = portIndex;
     OMX_ERRORTYPE oerr = OMX_GetParameter(
             mHandle, OMX_IndexParamPortDefinition, &def);
-    CHECK(oerr == OMX_ErrorNone);
+    if (oerr != OMX_ErrorNone) {
+        OMX_INDEXTYPE index = OMX_IndexParamPortDefinition;
+        CLOG_ERROR(getParameter, oerr, "%s(%#x): %s:%u",
+                asString(index), index, portString(portIndex), portIndex);
+        return UNKNOWN_ERROR;
+    }
 
     if (def.format.video.eColorFormat != OMX_COLOR_FormatAndroidOpaque) {
-        ALOGE("createInputSurface requires COLOR_FormatSurface "
-              "(AndroidOpaque) color format");
+        CLOGW("createInputSurface requires COLOR_FormatSurface "
+                "(AndroidOpaque) color format instead of %s(%#x)",
+                asString(def.format.video.eColorFormat), def.format.video.eColorFormat);
         return INVALID_OPERATION;
     }
 
@@ -754,9 +846,9 @@ status_t OMXNodeInstance::signalEndOfInputStream() {
     // flag set).  Seems easier than doing the equivalent from here.
     sp<GraphicBufferSource> bufferSource(getGraphicBufferSource());
     if (bufferSource == NULL) {
-        ALOGW("signalEndOfInputStream can only be used with Surface input");
+        CLOGW("signalEndOfInputStream can only be used with Surface input");
         return INVALID_OPERATION;
-    };
+    }
     return bufferSource->signalEndOfInputStream();
 }
 
@@ -773,14 +865,13 @@ status_t OMXNodeInstance::allocateBuffer(
             mHandle, &header, portIndex, buffer_meta, size);
 
     if (err != OMX_ErrorNone) {
-        ALOGE("OMX_AllocateBuffer failed with error %d (0x%08x)", err, err);
-
+        CLOG_ERROR(allocateBuffer, err, BUFFER_FMT(portIndex, "%zu@", size));
         delete buffer_meta;
         buffer_meta = NULL;
 
         *buffer = 0;
 
-        return UNKNOWN_ERROR;
+        return StatusFromOMXError(err);
     }
 
     CHECK_EQ(header->pAppPrivate, buffer_meta);
@@ -794,6 +885,7 @@ status_t OMXNodeInstance::allocateBuffer(
     if (bufferSource != NULL && portIndex == kPortIndexInput) {
         bufferSource->addCodecBuffer(header);
     }
+    CLOG_BUFFER(allocateBuffer, NEW_BUFFER_FMT(*buffer, portIndex, "%zu@%p", size, *buffer_data));
 
     return OK;
 }
@@ -811,14 +903,14 @@ status_t OMXNodeInstance::allocateBufferWithBackup(
             mHandle, &header, portIndex, buffer_meta, params->size());
 
     if (err != OMX_ErrorNone) {
-        ALOGE("OMX_AllocateBuffer failed with error %d (0x%08x)", err, err);
-
+        CLOG_ERROR(allocateBufferWithBackup, err,
+                SIMPLE_BUFFER(portIndex, params->size(), params->pointer()));
         delete buffer_meta;
         buffer_meta = NULL;
 
         *buffer = 0;
 
-        return UNKNOWN_ERROR;
+        return StatusFromOMXError(err);
     }
 
     CHECK_EQ(header->pAppPrivate, buffer_meta);
@@ -832,12 +924,16 @@ status_t OMXNodeInstance::allocateBufferWithBackup(
         bufferSource->addCodecBuffer(header);
     }
 
+    CLOG_BUFFER(allocateBufferWithBackup, NEW_BUFFER_FMT(*buffer, portIndex, "%zu@%p :> %p",
+            params->size(), params->pointer(), header->pBuffer));
+
     return OK;
 }
 
 status_t OMXNodeInstance::freeBuffer(
         OMX_U32 portIndex, OMX::buffer_id buffer) {
     Mutex::Autolock autoLock(mLock);
+    CLOG_BUFFER(freeBuffer, "%s:%u %#x", portString(portIndex), portIndex, buffer);
 
     removeActiveBuffer(portIndex, buffer);
 
@@ -845,6 +941,7 @@ status_t OMXNodeInstance::freeBuffer(
     BufferMeta *buffer_meta = static_cast<BufferMeta *>(header->pAppPrivate);
 
     OMX_ERRORTYPE err = OMX_FreeBuffer(mHandle, portIndex, header);
+    CLOG_IF_ERROR(freeBuffer, err, "%s:%u %#x", portString(portIndex), portIndex, buffer);
 
     delete buffer_meta;
     buffer_meta = NULL;
@@ -861,8 +958,18 @@ status_t OMXNodeInstance::fillBuffer(OMX::buffer_id buffer) {
     header->nOffset = 0;
     header->nFlags = 0;
 
-    OMX_ERRORTYPE err = OMX_FillThisBuffer(mHandle, header);
+    {
+        Mutex::Autolock _l(mDebugLock);
+        mOutputBuffersWithCodec.add(header);
+        CLOG_BUMPED_BUFFER(fillBuffer, WITH_STATS(EMPTY_BUFFER(buffer, header)));
+    }
 
+    OMX_ERRORTYPE err = OMX_FillThisBuffer(mHandle, header);
+    if (err != OMX_ErrorNone) {
+        CLOG_ERROR(fillBuffer, err, EMPTY_BUFFER(buffer, header));
+        Mutex::Autolock _l(mDebugLock);
+        mOutputBuffersWithCodec.remove(header);
+    }
     return StatusFromOMXError(err);
 }
 
@@ -875,14 +982,66 @@ status_t OMXNodeInstance::emptyBuffer(
     OMX_BUFFERHEADERTYPE *header = findBufferHeader(buffer);
     header->nFilledLen = rangeLength;
     header->nOffset = rangeOffset;
-    header->nFlags = flags;
-    header->nTimeStamp = timestamp;
 
     BufferMeta *buffer_meta =
         static_cast<BufferMeta *>(header->pAppPrivate);
     buffer_meta->CopyToOMX(header);
 
+    return emptyBuffer_l(header, flags, timestamp, (intptr_t)buffer);
+}
+
+// log queued buffer activity for the next few input and/or output frames
+// if logging at internal state level
+void OMXNodeInstance::bumpDebugLevel_l(size_t numInputBuffers, size_t numOutputBuffers) {
+    if (DEBUG == ADebug::kDebugInternalState) {
+        DEBUG_BUMP = ADebug::kDebugAll;
+        if (numInputBuffers > 0) {
+            mDebugLevelBumpPendingBuffers[kPortIndexInput] = numInputBuffers;
+        }
+        if (numOutputBuffers > 0) {
+            mDebugLevelBumpPendingBuffers[kPortIndexOutput] = numOutputBuffers;
+        }
+    }
+}
+
+void OMXNodeInstance::unbumpDebugLevel_l(size_t portIndex) {
+    if (mDebugLevelBumpPendingBuffers[portIndex]) {
+        --mDebugLevelBumpPendingBuffers[portIndex];
+    }
+    if (!mDebugLevelBumpPendingBuffers[0]
+            && !mDebugLevelBumpPendingBuffers[1]) {
+        DEBUG_BUMP = DEBUG;
+    }
+}
+
+status_t OMXNodeInstance::emptyBuffer_l(
+        OMX_BUFFERHEADERTYPE *header, OMX_U32 flags, OMX_TICKS timestamp, intptr_t debugAddr) {
+    header->nFlags = flags;
+    header->nTimeStamp = timestamp;
+
+    {
+        Mutex::Autolock _l(mDebugLock);
+        mInputBuffersWithCodec.add(header);
+
+        // bump internal-state debug level for 2 input frames past a buffer with CSD
+        if ((flags & OMX_BUFFERFLAG_CODECCONFIG) != 0) {
+            bumpDebugLevel_l(2 /* numInputBuffers */, 0 /* numOutputBuffers */);
+        }
+
+        CLOG_BUMPED_BUFFER(emptyBuffer, WITH_STATS(FULL_BUFFER(debugAddr, header)));
+    }
+
     OMX_ERRORTYPE err = OMX_EmptyThisBuffer(mHandle, header);
+    CLOG_IF_ERROR(emptyBuffer, err, FULL_BUFFER(debugAddr, header));
+
+    {
+        Mutex::Autolock _l(mDebugLock);
+        if (err != OMX_ErrorNone) {
+            mInputBuffersWithCodec.remove(header);
+        } else if (!(flags & OMX_BUFFERFLAG_CODECCONFIG)) {
+            unbumpDebugLevel_l(kPortIndexInput);
+        }
+    }
 
     return StatusFromOMXError(err);
 }
@@ -896,15 +1055,8 @@ status_t OMXNodeInstance::emptyDirectBuffer(
 
     header->nFilledLen = rangeLength;
     header->nOffset = rangeOffset;
-    header->nFlags = flags;
-    header->nTimeStamp = timestamp;
-
-    OMX_ERRORTYPE err = OMX_EmptyThisBuffer(mHandle, header);
-    if (err != OMX_ErrorNone) {
-        ALOGW("emptyDirectBuffer failed, OMX err=0x%x", err);
-    }
 
-    return StatusFromOMXError(err);
+    return emptyBuffer_l(header, flags, timestamp, (intptr_t)header->pBuffer);
 }
 
 status_t OMXNodeInstance::getExtensionIndex(
@@ -917,11 +1069,25 @@ status_t OMXNodeInstance::getExtensionIndex(
     return StatusFromOMXError(err);
 }
 
+inline static const char *asString(IOMX::InternalOptionType i, const char *def = "??") {
+    switch (i) {
+        case IOMX::INTERNAL_OPTION_SUSPEND:           return "SUSPEND";
+        case IOMX::INTERNAL_OPTION_REPEAT_PREVIOUS_FRAME_DELAY:
+            return "REPEAT_PREVIOUS_FRAME_DELAY";
+        case IOMX::INTERNAL_OPTION_MAX_TIMESTAMP_GAP: return "MAX_TIMESTAMP_GAP";
+        case IOMX::INTERNAL_OPTION_START_TIME:        return "START_TIME";
+        case IOMX::INTERNAL_OPTION_TIME_LAPSE:        return "TIME_LAPSE";
+        default:                                      return def;
+    }
+}
+
 status_t OMXNodeInstance::setInternalOption(
         OMX_U32 portIndex,
         IOMX::InternalOptionType type,
         const void *data,
         size_t size) {
+    CLOG_CONFIG(setInternalOption, "%s(%d): %s:%u %zu@%p",
+            asString(type), type, portString(portIndex), portIndex, size, data);
     switch (type) {
         case IOMX::INTERNAL_OPTION_SUSPEND:
         case IOMX::INTERNAL_OPTION_REPEAT_PREVIOUS_FRAME_DELAY:
@@ -933,6 +1099,7 @@ status_t OMXNodeInstance::setInternalOption(
                 getGraphicBufferSource();
 
             if (bufferSource == NULL || portIndex != kPortIndexInput) {
+                CLOGW("setInternalOption is only for Surface input");
                 return ERROR_UNSUPPORTED;
             }
 
@@ -942,6 +1109,7 @@ status_t OMXNodeInstance::setInternalOption(
                 }
 
                 bool suspend = *(bool *)data;
+                CLOG_CONFIG(setInternalOption, "suspend=%d", suspend);
                 bufferSource->suspend(suspend);
             } else if (type ==
                     IOMX::INTERNAL_OPTION_REPEAT_PREVIOUS_FRAME_DELAY){
@@ -950,7 +1118,7 @@ status_t OMXNodeInstance::setInternalOption(
                 }
 
                 int64_t delayUs = *(int64_t *)data;
-
+                CLOG_CONFIG(setInternalOption, "delayUs=%lld", (long long)delayUs);
                 return bufferSource->setRepeatPreviousFrameDelayUs(delayUs);
             } else if (type ==
                     IOMX::INTERNAL_OPTION_MAX_TIMESTAMP_GAP){
@@ -959,7 +1127,7 @@ status_t OMXNodeInstance::setInternalOption(
                 }
 
                 int64_t maxGapUs = *(int64_t *)data;
-
+                CLOG_CONFIG(setInternalOption, "gapUs=%lld", (long long)maxGapUs);
                 return bufferSource->setMaxTimestampGapUs(maxGapUs);
             } else if (type == IOMX::INTERNAL_OPTION_START_TIME) {
                 if (size != sizeof(int64_t)) {
@@ -967,13 +1135,18 @@ status_t OMXNodeInstance::setInternalOption(
                 }
 
                 int64_t skipFramesBeforeUs = *(int64_t *)data;
-
+                CLOG_CONFIG(setInternalOption, "beforeUs=%lld", (long long)skipFramesBeforeUs);
                 bufferSource->setSkipFramesBeforeUs(skipFramesBeforeUs);
             } else { // IOMX::INTERNAL_OPTION_TIME_LAPSE
                 if (size != sizeof(int64_t) * 2) {
                     return INVALID_OPERATION;
                 }
 
+                int64_t timePerFrameUs = ((int64_t *)data)[0];
+                int64_t timePerCaptureUs = ((int64_t *)data)[1];
+                CLOG_CONFIG(setInternalOption, "perFrameUs=%lld perCaptureUs=%lld",
+                        (long long)timePerFrameUs, (long long)timePerCaptureUs);
+
                 bufferSource->setTimeLapseUs((int64_t *)data);
             }
 
@@ -992,6 +1165,16 @@ void OMXNodeInstance::onMessage(const omx_message &msg) {
         OMX_BUFFERHEADERTYPE *buffer =
             findBufferHeader(msg.u.extended_buffer_data.buffer);
 
+        {
+            Mutex::Autolock _l(mDebugLock);
+            mOutputBuffersWithCodec.remove(buffer);
+
+            CLOG_BUMPED_BUFFER(
+                    FBD, WITH_STATS(FULL_BUFFER(msg.u.extended_buffer_data.buffer, buffer)));
+
+            unbumpDebugLevel_l(kPortIndexOutput);
+        }
+
         BufferMeta *buffer_meta =
             static_cast<BufferMeta *>(buffer->pAppPrivate);
 
@@ -1007,16 +1190,23 @@ void OMXNodeInstance::onMessage(const omx_message &msg) {
             return;
         }
     } else if (msg.type == omx_message::EMPTY_BUFFER_DONE) {
+        OMX_BUFFERHEADERTYPE *buffer =
+            findBufferHeader(msg.u.buffer_data.buffer);
+
+        {
+            Mutex::Autolock _l(mDebugLock);
+            mInputBuffersWithCodec.remove(buffer);
+
+            CLOG_BUMPED_BUFFER(
+                    EBD, WITH_STATS(EMPTY_BUFFER(msg.u.buffer_data.buffer, buffer)));
+        }
+
         if (bufferSource != NULL) {
             // This is one of the buffers used exclusively by
             // GraphicBufferSource.
             // Don't dispatch a message back to ACodec, since it doesn't
             // know that anyone asked to have the buffer emptied and will
             // be very confused.
-
-            OMX_BUFFERHEADERTYPE *buffer =
-                findBufferHeader(msg.u.buffer_data.buffer);
-
             bufferSource->codecBufferEmptied(buffer);
             return;
         }
@@ -1040,6 +1230,43 @@ void OMXNodeInstance::onGetHandleFailed() {
 // Don't try to acquire mLock here -- in rare circumstances this will hang.
 void OMXNodeInstance::onEvent(
         OMX_EVENTTYPE event, OMX_U32 arg1, OMX_U32 arg2) {
+    const char *arg1String = "??";
+    const char *arg2String = "??";
+    ADebug::Level level = ADebug::kDebugInternalState;
+
+    switch (event) {
+        case OMX_EventCmdComplete:
+            arg1String = asString((OMX_COMMANDTYPE)arg1);
+            switch (arg1) {
+                case OMX_CommandStateSet:
+                    arg2String = asString((OMX_STATETYPE)arg2);
+                    level = ADebug::kDebugState;
+                    break;
+                case OMX_CommandFlush:
+                case OMX_CommandPortEnable:
+                {
+                    // bump internal-state debug level for 2 input and output frames
+                    Mutex::Autolock _l(mDebugLock);
+                    bumpDebugLevel_l(2 /* numInputBuffers */, 2 /* numOutputBuffers */);
+                }
+                // fall through
+                default:
+                    arg2String = portString(arg2);
+            }
+            break;
+        case OMX_EventError:
+            arg1String = asString((OMX_ERRORTYPE)arg1);
+            level = ADebug::kDebugLifeCycle;
+            break;
+        case OMX_EventPortSettingsChanged:
+            arg2String = asString((OMX_INDEXEXTTYPE)arg2);
+            // fall through
+        default:
+            arg1String = portString(arg1);
+    }
+
+    CLOGI_(level, onEvent, "%s(%x), %s(%x), %s(%x)",
+            asString(event), event, arg1String, arg1, arg2String, arg2);
     const sp<GraphicBufferSource>& bufferSource(getGraphicBufferSource());
 
     if (bufferSource != NULL
@@ -1097,23 +1324,27 @@ void OMXNodeInstance::addActiveBuffer(OMX_U32 portIndex, OMX::buffer_id id) {
     active.mPortIndex = portIndex;
     active.mID = id;
     mActiveBuffers.push(active);
+
+    if (portIndex < NELEM(mNumPortBuffers)) {
+        ++mNumPortBuffers[portIndex];
+    }
 }
 
 void OMXNodeInstance::removeActiveBuffer(
         OMX_U32 portIndex, OMX::buffer_id id) {
-    bool found = false;
     for (size_t i = 0; i < mActiveBuffers.size(); ++i) {
         if (mActiveBuffers[i].mPortIndex == portIndex
-            && mActiveBuffers[i].mID == id) {
-            found = true;
+                && mActiveBuffers[i].mID == id) {
             mActiveBuffers.removeItemsAt(i);
-            break;
+
+            if (portIndex < NELEM(mNumPortBuffers)) {
+                --mNumPortBuffers[portIndex];
+            }
+            return;
         }
     }
 
-    if (!found) {
-        ALOGW("Attempt to remove an active buffer we know nothing about...");
-    }
+     CLOGW("Attempt to remove an active buffer [%#x] we know nothing about...", id);
 }
 
 void OMXNodeInstance::freeActiveBuffers() {
@@ -1134,7 +1365,7 @@ OMX::buffer_id OMXNodeInstance::makeBufferID(OMX_BUFFERHEADERTYPE *bufferHeader)
     OMX::buffer_id buffer;
     do { // handle the very unlikely case of ID overflow
         if (++mBufferIDCount == 0) {
-           ++mBufferIDCount;
+            ++mBufferIDCount;
         }
         buffer = (OMX::buffer_id)mBufferIDCount;
     } while (mBufferIDToBufferHeader.indexOfKey(buffer) >= 0);