diff options
Diffstat (limited to 'media/libstagefright/omx/OMXNodeInstance.cpp')
-rw-r--r-- | media/libstagefright/omx/OMXNodeInstance.cpp | 570 |
1 files changed, 403 insertions, 167 deletions
diff --git a/media/libstagefright/omx/OMXNodeInstance.cpp b/media/libstagefright/omx/OMXNodeInstance.cpp index d07ec14..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,8 +233,14 @@ 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 + if (mHandle == NULL) { + return OK; + } + // Transition the node from its current state all the way down // to "Loaded". // This ensures that all active buffers are properly freed even @@ -170,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; } @@ -199,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; } @@ -220,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; @@ -265,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); } @@ -274,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); } @@ -293,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); } @@ -310,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"); @@ -324,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(¶ms); + params.nPortIndex = portIndex; + params.enable = enable; err = OMX_SetParameter(mHandle, index, ¶ms); - - 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( @@ -362,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(¶ms); + params.nPortIndex = portIndex; err = OMX_GetParameter(mHandle, index, ¶ms); - 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; @@ -393,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 */); @@ -419,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(¶ms, 0, sizeof(params)); - params.nSize = sizeof(params); + OMX_ERRORTYPE xerr = err; + if (err == OMX_ErrorNone) { + StoreMetaDataInBuffersParams params; + InitOMXParams(¶ms); + params.nPortIndex = portIndex; + params.bStoreMetaData = enable; - // Version: 1.0.0.0 - params.nVersion.s.nVersionMajor = 1; + err = OMX_SetParameter(mHandle, index, ¶ms); + } - params.nPortIndex = portIndex; - params.bStoreMetaData = enable; - if ((err = OMX_SetParameter(mHandle, index, ¶ms)) != 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>( @@ -457,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(¶ms); params.nPortIndex = portIndex; params.bEnable = enable; params.nMaxFrameWidth = maxFrameWidth; params.nMaxFrameHeight = maxFrameHeight; - if ((err = OMX_SetParameter(mHandle, index, ¶ms)) != 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, ¶ms); + 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>( @@ -491,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( @@ -537,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); @@ -558,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; } @@ -567,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); @@ -595,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); @@ -608,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; } @@ -632,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); } @@ -656,15 +749,15 @@ status_t OMXNodeInstance::useGraphicBuffer( err = OMX_SetParameter(mHandle, index, ¶ms); 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); @@ -672,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); @@ -688,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; } @@ -714,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; } @@ -749,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(); } @@ -768,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); @@ -789,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; } @@ -806,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); @@ -827,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); @@ -840,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; @@ -856,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); } @@ -870,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); } @@ -891,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( @@ -912,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: @@ -928,6 +1099,7 @@ status_t OMXNodeInstance::setInternalOption( getGraphicBufferSource(); if (bufferSource == NULL || portIndex != kPortIndexInput) { + CLOGW("setInternalOption is only for Surface input"); return ERROR_UNSUPPORTED; } @@ -937,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){ @@ -945,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){ @@ -954,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)) { @@ -962,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); } @@ -987,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); @@ -1002,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; } @@ -1035,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 @@ -1092,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() { @@ -1129,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); |