From 6b1c612162ce290c54e0b0a418e1791410f95d47 Mon Sep 17 00:00:00 2001 From: Andy Hung Date: Wed, 12 Sep 2018 19:09:07 -0700 Subject: [PATCH] AudioRecord: Add client side track id for logging Test: Audio sanity test, check logcat Bug: 115400221 Change-Id: Ifa9c05c0df66e372e773b5149a0f1ed49a21ef3a --- media/libaudioclient/AudioRecord.cpp | 112 ++++++++++-------- .../include/media/AudioRecord.h | 1 + .../include/media/IAudioFlinger.h | 3 + services/audioflinger/AudioFlinger.cpp | 1 + 4 files changed, 69 insertions(+), 48 deletions(-) diff --git a/media/libaudioclient/AudioRecord.cpp b/media/libaudioclient/AudioRecord.cpp index e2de8e731f..17f17a3cc3 100644 --- a/media/libaudioclient/AudioRecord.cpp +++ b/media/libaudioclient/AudioRecord.cpp @@ -48,8 +48,9 @@ status_t AudioRecord::getMinFrameCount( size_t size; status_t status = AudioSystem::getInputBufferSize(sampleRate, format, channelMask, &size); if (status != NO_ERROR) { - ALOGE("AudioSystem could not query the input buffer size for sampleRate %u, format %#x, " - "channelMask %#x; status %d", sampleRate, format, channelMask, status); + ALOGE("%s(): AudioSystem could not query the input buffer size for" + " sampleRate %u, format %#x, channelMask %#x; status %d", + __func__, sampleRate, format, channelMask, status); return status; } @@ -57,8 +58,8 @@ status_t AudioRecord::getMinFrameCount( // Assumes audio_is_linear_pcm(format) if ((*frameCount = (size * 2) / (audio_channel_count_from_in_mask(channelMask) * audio_bytes_per_sample(format))) == 0) { - ALOGE("Unsupported configuration: sampleRate %u, format %#x, channelMask %#x", - sampleRate, format, channelMask); + ALOGE("%s(): Unsupported configuration: sampleRate %u, format %#x, channelMask %#x", + __func__, sampleRate, format, channelMask); return BAD_VALUE; } @@ -208,8 +209,8 @@ AudioRecord::~AudioRecord() mCblkMemory.clear(); mBufferMemory.clear(); IPCThreadState::self()->flushCommands(); - ALOGV("~AudioRecord, releasing session id %d", - mSessionId); + ALOGV("%s(%d): releasing session id %d", + __func__, mId, mSessionId); AudioSystem::releaseAudioSessionId(mSessionId, -1 /*pid*/); } } @@ -237,9 +238,11 @@ status_t AudioRecord::set( pid_t callingPid; pid_t myPid; - ALOGV("set(): inputSource %d, sampleRate %u, format %#x, channelMask %#x, frameCount %zu, " + // Note mId is not valid until the track is created, so omit mId in ALOG for set. + ALOGV("%s(): inputSource %d, sampleRate %u, format %#x, channelMask %#x, frameCount %zu, " "notificationFrames %u, sessionId %d, transferType %d, flags %#x, opPackageName %s " "uid %d, pid %d", + __func__, inputSource, sampleRate, format, channelMask, frameCount, notificationFrames, sessionId, transferType, flags, String8(mOpPackageName).string(), uid, pid); @@ -255,7 +258,7 @@ status_t AudioRecord::set( break; case TRANSFER_CALLBACK: if (cbf == NULL) { - ALOGE("Transfer type TRANSFER_CALLBACK but cbf == NULL"); + ALOGE("%s(): Transfer type TRANSFER_CALLBACK but cbf == NULL", __func__); status = BAD_VALUE; goto exit; } @@ -264,7 +267,7 @@ status_t AudioRecord::set( case TRANSFER_SYNC: break; default: - ALOGE("Invalid transfer type %d", transferType); + ALOGE("%s(): Invalid transfer type %d", __func__, transferType); status = BAD_VALUE; goto exit; } @@ -272,7 +275,7 @@ status_t AudioRecord::set( // invariant that mAudioRecord != 0 is true only after set() returns successfully if (mAudioRecord != 0) { - ALOGE("Track already in use"); + ALOGE("%s(): Track already in use", __func__); status = INVALID_OPERATION; goto exit; } @@ -283,8 +286,8 @@ status_t AudioRecord::set( } else { // stream type shouldn't be looked at, this track has audio attributes memcpy(&mAttributes, pAttributes, sizeof(audio_attributes_t)); - ALOGV("Building AudioRecord with attributes: source=%d flags=0x%x tags=[%s]", - mAttributes.source, mAttributes.flags, mAttributes.tags); + ALOGV("%s(): Building AudioRecord with attributes: source=%d flags=0x%x tags=[%s]", + __func__, mAttributes.source, mAttributes.flags, mAttributes.tags); } mSampleRate = sampleRate; @@ -297,14 +300,14 @@ status_t AudioRecord::set( // validate parameters // AudioFlinger capture only supports linear PCM if (!audio_is_valid_format(format) || !audio_is_linear_pcm(format)) { - ALOGE("Format %#x is not linear pcm", format); + ALOGE("%s(): Format %#x is not linear pcm", __func__, format); status = BAD_VALUE; goto exit; } mFormat = format; if (!audio_is_input_channel(channelMask)) { - ALOGE("Invalid channel mask %#x", channelMask); + ALOGE("%s(): Invalid channel mask %#x", __func__, channelMask); status = BAD_VALUE; goto exit; } @@ -325,7 +328,7 @@ status_t AudioRecord::set( // mNotificationFramesAct is initialized in createRecord_l mSessionId = sessionId; - ALOGV("set(): mSessionId %d", mSessionId); + ALOGV("%s(): mSessionId %d", __func__, mSessionId); callingPid = IPCThreadState::self()->getCallingPid(); myPid = getpid(); @@ -352,6 +355,8 @@ status_t AudioRecord::set( // create the IAudioRecord status = createRecord_l(0 /*epoch*/, mOpPackageName); + ALOGV("%s(%d): status %d", __func__, mId, status); + if (status != NO_ERROR) { if (mAudioRecordThread != 0) { mAudioRecordThread->requestExit(); // see comment in AudioRecord.h @@ -387,7 +392,7 @@ exit: status_t AudioRecord::start(AudioSystem::sync_event_t event, audio_session_t triggerSession) { - ALOGV("start, sync event %d trigger session %d", event, triggerSession); + ALOGV("%s(%d): sync event %d trigger session %d", __func__, mId, event, triggerSession); AutoMutex lock(mLock); if (mActive) { @@ -428,7 +433,7 @@ status_t AudioRecord::start(AudioSystem::sync_event_t event, audio_session_t tri if (status != NO_ERROR) { mActive = false; - ALOGE("start() status %d", status); + ALOGE("%s(%d): status %d", __func__, mId, status); } else { sp t = mAudioRecordThread; if (t != 0) { @@ -452,6 +457,7 @@ status_t AudioRecord::start(AudioSystem::sync_event_t event, audio_session_t tri void AudioRecord::stop() { AutoMutex lock(mLock); + ALOGV("%s(%d): mActive:%d\n", __func__, mId, mActive); if (!mActive) { return; } @@ -630,8 +636,8 @@ status_t AudioRecord::dump(int fd, const Vector& args __unused) const String8 result; result.append(" AudioRecord::dump\n"); - result.appendFormat(" status(%d), active(%d), session Id(%d)\n", - mStatus, mActive, mSessionId); + result.appendFormat(" id(%d) status(%d), active(%d), session Id(%d)\n", + mId, mStatus, mActive, mSessionId); result.appendFormat(" flags(%#x), req. flags(%#x), audio source(%d)\n", mFlags, mOrigFlags, mAttributes.source); result.appendFormat(" format(%#x), channel mask(%#x), channel count(%u), sample rate(%u)\n", @@ -673,7 +679,7 @@ status_t AudioRecord::createRecord_l(const Modulo &epoch, const String status_t status; if (audioFlinger == 0) { - ALOGE("Could not get audioflinger"); + ALOGE("%s(%d): Could not get audioflinger", __func__, mId); status = NO_INIT; goto exit; } @@ -700,7 +706,8 @@ status_t AudioRecord::createRecord_l(const Modulo &epoch, const String // use case 3: obtain/release mode (mTransfer == TRANSFER_OBTAIN); if (!useCaseAllowed) { - ALOGW("AUDIO_INPUT_FLAG_FAST denied, incompatible transfer = %s", + ALOGW("%s(%d): AUDIO_INPUT_FLAG_FAST denied, incompatible transfer = %s", + __func__, mId, convertTransferToText(mTransfer)); mFlags = (audio_input_flags_t) (mFlags & ~(AUDIO_INPUT_FLAG_FAST | AUDIO_INPUT_FLAG_RAW)); @@ -735,7 +742,8 @@ status_t AudioRecord::createRecord_l(const Modulo &epoch, const String &status); if (status != NO_ERROR) { - ALOGE("AudioFlinger could not create record track, status: %d", status); + ALOGE("%s(%d): AudioFlinger could not create record track, status: %d", + __func__, mId, status); goto exit; } ALOG_ASSERT(record != 0); @@ -745,7 +753,8 @@ status_t AudioRecord::createRecord_l(const Modulo &epoch, const String mAwaitBoost = false; if (output.flags & AUDIO_INPUT_FLAG_FAST) { - ALOGI("AUDIO_INPUT_FLAG_FAST successful; frameCount %zu -> %zu", + ALOGI("%s(%d): AUDIO_INPUT_FLAG_FAST successful; frameCount %zu -> %zu", + __func__, mId, mReqFrameCount, output.frameCount); mAwaitBoost = true; } @@ -755,13 +764,13 @@ status_t AudioRecord::createRecord_l(const Modulo &epoch, const String mSampleRate = output.sampleRate; if (output.cblk == 0) { - ALOGE("Could not get control block"); + ALOGE("%s(%d): Could not get control block", __func__, mId); status = NO_INIT; goto exit; } iMemPointer = output.cblk ->pointer(); if (iMemPointer == NULL) { - ALOGE("Could not get control block pointer"); + ALOGE("%s(%d): Could not get control block pointer", __func__, mId); status = NO_INIT; goto exit; } @@ -776,7 +785,7 @@ status_t AudioRecord::createRecord_l(const Modulo &epoch, const String } else { buffers = output.buffers->pointer(); if (buffers == NULL) { - ALOGE("Could not get buffer pointer"); + ALOGE("%s(%d): Could not get buffer pointer", __func__, mId); status = NO_INIT; goto exit; } @@ -790,19 +799,22 @@ status_t AudioRecord::createRecord_l(const Modulo &epoch, const String mAudioRecord = record; mCblkMemory = output.cblk; mBufferMemory = output.buffers; + mId = output.trackId; IPCThreadState::self()->flushCommands(); mCblk = cblk; // note that output.frameCount is the (possibly revised) value of mReqFrameCount if (output.frameCount < mReqFrameCount || (mReqFrameCount == 0 && output.frameCount == 0)) { - ALOGW("Requested frameCount %zu but received frameCount %zu", + ALOGW("%s(%d): Requested frameCount %zu but received frameCount %zu", + __func__, mId, mReqFrameCount, output.frameCount); } // Make sure that application is notified with sufficient margin before overrun. // The computation is done on server side. if (mNotificationFramesReq > 0 && output.notificationFrameCount != mNotificationFramesReq) { - ALOGW("Server adjusted notificationFrames from %u to %zu for frameCount %zu", + ALOGW("%s(%d): Server adjusted notificationFrames from %u to %zu for frameCount %zu", + __func__, mId, mNotificationFramesReq, output.notificationFrameCount, output.frameCount); } mNotificationFramesAct = (uint32_t)output.notificationFrameCount; @@ -870,7 +882,7 @@ status_t AudioRecord::obtainBuffer(Buffer* audioBuffer, int32_t waitCount, size_ timeout.tv_nsec = (long) (ms % 1000) * 1000000; requested = &timeout; } else { - ALOGE("%s invalid waitCount %d", __func__, waitCount); + ALOGE("%s(%d): invalid waitCount %d", __func__, mId, waitCount); requested = NULL; } return obtainBuffer(audioBuffer, requested, NULL /*elapsed*/, nonContig); @@ -979,7 +991,8 @@ ssize_t AudioRecord::read(void* buffer, size_t userSize, bool blocking) if (ssize_t(userSize) < 0 || (buffer == NULL && userSize != 0)) { // sanity-check. user is most-likely passing an error code, and it would // make the return value ambiguous (actualSize vs error). - ALOGE("AudioRecord::read(buffer=%p, size=%zu (%zu)", buffer, userSize, userSize); + ALOGE("%s(%d) (buffer=%p, size=%zu (%zu)", + __func__, mId, buffer, userSize, userSize); return BAD_VALUE; } @@ -1036,7 +1049,7 @@ nsecs_t AudioRecord::processAudioBuffer() pollUs <<= 1; } while (tryCounter-- > 0); if (tryCounter < 0) { - ALOGE("did not receive expected priority boost on time"); + ALOGE("%s(%d): did not receive expected priority boost on time", __func__, mId); } // Run again immediately return 0; @@ -1159,7 +1172,8 @@ nsecs_t AudioRecord::processAudioBuffer() if (ns != NS_WHENEVER) { timeout.tv_sec = ns / 1000000000LL; timeout.tv_nsec = ns % 1000000000LL; - ALOGV("timeout %ld.%03d", timeout.tv_sec, (int) timeout.tv_nsec / 1000000); + ALOGV("%s(%d): timeout %ld.%03d", + __func__, mId, timeout.tv_sec, (int) timeout.tv_nsec / 1000000); requested = &timeout; } @@ -1171,16 +1185,18 @@ nsecs_t AudioRecord::processAudioBuffer() size_t nonContig; status_t err = obtainBuffer(&audioBuffer, requested, NULL, &nonContig); LOG_ALWAYS_FATAL_IF((err != NO_ERROR) != (audioBuffer.frameCount == 0), - "obtainBuffer() err=%d frameCount=%zu", err, audioBuffer.frameCount); + "%s(%d): obtainBuffer() err=%d frameCount=%zu", + __func__, mId, err, audioBuffer.frameCount); requested = &ClientProxy::kNonBlocking; size_t avail = audioBuffer.frameCount + nonContig; - ALOGV("obtainBuffer(%u) returned %zu = %zu + %zu err %d", - mRemainingFrames, avail, audioBuffer.frameCount, nonContig, err); + ALOGV("%s(%d): obtainBuffer(%u) returned %zu = %zu + %zu err %d", + __func__, mId, mRemainingFrames, avail, audioBuffer.frameCount, nonContig, err); if (err != NO_ERROR) { if (err == TIMED_OUT || err == WOULD_BLOCK || err == -EINTR) { break; } - ALOGE("Error %d obtaining an audio buffer, giving up.", err); + ALOGE("%s(%d): Error %d obtaining an audio buffer, giving up.", + __func__, mId, err); return NS_NEVER; } @@ -1202,8 +1218,8 @@ nsecs_t AudioRecord::processAudioBuffer() // Sanity check on returned size if (ssize_t(readSize) < 0 || readSize > reqSize) { - ALOGE("EVENT_MORE_DATA requested %zu bytes but callback returned %zd bytes", - reqSize, ssize_t(readSize)); + ALOGE("%s(%d): EVENT_MORE_DATA requested %zu bytes but callback returned %zd bytes", + __func__, mId, reqSize, ssize_t(readSize)); return NS_NEVER; } @@ -1263,7 +1279,7 @@ nsecs_t AudioRecord::processAudioBuffer() status_t AudioRecord::restoreRecord_l(const char *from) { - ALOGW("dead IAudioRecord, creating a new one from %s()", from); + ALOGW("%s(%d): dead IAudioRecord, creating a new one from %s()", __func__, mId, from); ++mSequence; const int INITIAL_RETRIES = 3; @@ -1284,7 +1300,7 @@ retry: status_t result = createRecord_l(position, mOpPackageName); if (result != NO_ERROR) { - ALOGW("%s(): createRecord_l failed, do not retry", __func__); + ALOGW("%s(%d): createRecord_l failed, do not retry", __func__, mId); retries = 0; } else { if (mActive) { @@ -1297,14 +1313,14 @@ retry: } if (result != NO_ERROR) { - ALOGW("%s() failed status %d, retries %d", __func__, result, retries); + ALOGW("%s(%d): failed status %d, retries %d", __func__, mId, result, retries); if (--retries > 0) { goto retry; } } if (result != NO_ERROR) { - ALOGW("restoreRecord_l() failed status %d", result); + ALOGW("%s(%d): failed status %d", __func__, mId, result); mActive = false; } @@ -1314,18 +1330,18 @@ retry: status_t AudioRecord::addAudioDeviceCallback(const sp& callback) { if (callback == 0) { - ALOGW("%s adding NULL callback!", __FUNCTION__); + ALOGW("%s(%d): adding NULL callback!", __func__, mId); return BAD_VALUE; } AutoMutex lock(mLock); if (mDeviceCallback.unsafe_get() == callback.get()) { - ALOGW("%s adding same callback!", __FUNCTION__); + ALOGW("%s(%d): adding same callback!", __func__, mId); return INVALID_OPERATION; } status_t status = NO_ERROR; if (mInput != AUDIO_IO_HANDLE_NONE) { if (mDeviceCallback != 0) { - ALOGW("%s callback already present!", __FUNCTION__); + ALOGW("%s(%d): callback already present!", __func__, mId); AudioSystem::removeAudioDeviceCallback(this, mInput); } status = AudioSystem::addAudioDeviceCallback(this, mInput); @@ -1338,12 +1354,12 @@ status_t AudioRecord::removeAudioDeviceCallback( const sp& callback) { if (callback == 0) { - ALOGW("%s removing NULL callback!", __FUNCTION__); + ALOGW("%s(%d): removing NULL callback!", __func__, mId); return BAD_VALUE; } AutoMutex lock(mLock); if (mDeviceCallback.unsafe_get() != callback.get()) { - ALOGW("%s removing different callback!", __FUNCTION__); + ALOGW("%s(%d): removing different callback!", __func__, mId); return INVALID_OPERATION; } mDeviceCallback.clear(); @@ -1448,7 +1464,7 @@ bool AudioRecord::AudioRecordThread::threadLoop() ns = INT64_MAX; // fall through default: - LOG_ALWAYS_FATAL_IF(ns < 0, "processAudioBuffer() returned %" PRId64, ns); + LOG_ALWAYS_FATAL_IF(ns < 0, "%s() returned %lld", __func__, (long long)ns); pauseInternal(ns); return true; } diff --git a/media/libaudioclient/include/media/AudioRecord.h b/media/libaudioclient/include/media/AudioRecord.h index 806280a40d..c226557c5f 100644 --- a/media/libaudioclient/include/media/AudioRecord.h +++ b/media/libaudioclient/include/media/AudioRecord.h @@ -654,6 +654,7 @@ private: audio_input_flags_t mOrigFlags; // as specified in constructor or set(), const audio_session_t mSessionId; + int mId; // Id from AudioFlinger transfer_type mTransfer; // Next 5 fields may be changed if IAudioRecord is re-created, but always != 0 diff --git a/media/libaudioclient/include/media/IAudioFlinger.h b/media/libaudioclient/include/media/IAudioFlinger.h index fb988e5510..52cc860bdb 100644 --- a/media/libaudioclient/include/media/IAudioFlinger.h +++ b/media/libaudioclient/include/media/IAudioFlinger.h @@ -274,6 +274,7 @@ public: return BAD_VALUE; } } + (void)parcel->readInt32(&trackId); return NO_ERROR; } @@ -300,6 +301,7 @@ public: } else { (void)parcel->writeInt32(0); } + (void)parcel->writeInt32(trackId); return NO_ERROR; } @@ -316,6 +318,7 @@ public: audio_io_handle_t inputId; sp cblk; sp buffers; + int32_t trackId; }; // invariant on exit for all APIs that return an sp<>: diff --git a/services/audioflinger/AudioFlinger.cpp b/services/audioflinger/AudioFlinger.cpp index f299d8361b..7db7d9f37d 100644 --- a/services/audioflinger/AudioFlinger.cpp +++ b/services/audioflinger/AudioFlinger.cpp @@ -1808,6 +1808,7 @@ sp AudioFlinger::createRecord(const CreateRecordInput& inpu output.cblk = recordTrack->getCblk(); output.buffers = recordTrack->getBuffers(); + output.trackId = recordTrack->id(); // return handle to client recordHandle = new RecordHandle(recordTrack);