diff options
author | Andy Hung <hunga@google.com> | 2018-09-12 18:03:44 -0700 |
---|---|---|
committer | Andy Hung <hunga@google.com> | 2018-09-13 17:54:07 -0700 |
commit | 9d84af54244f7ff086afdcc6e477fe4d04874652 (patch) | |
tree | dc3f3d5c5bc956b413fe3cc234ed45cc20cff1d9 | |
parent | c06913801424b90dfbc94b401039352869f20e3e (diff) | |
download | frameworks_av-9d84af54244f7ff086afdcc6e477fe4d04874652.tar.gz frameworks_av-9d84af54244f7ff086afdcc6e477fe4d04874652.tar.bz2 frameworks_av-9d84af54244f7ff086afdcc6e477fe4d04874652.zip |
AudioFlinger: Use track ids in log messages
Test: Audio sanity test, check logcat
Bug: 115400221
Change-Id: I6b3ed72c3a2584f03bb2183b099c5a42d2d49527
-rw-r--r-- | services/audioflinger/Tracks.cpp | 135 |
1 files changed, 85 insertions, 50 deletions
diff --git a/services/audioflinger/Tracks.cpp b/services/audioflinger/Tracks.cpp index 8792b63b29..6a3b06df2c 100644 --- a/services/audioflinger/Tracks.cpp +++ b/services/audioflinger/Tracks.cpp @@ -56,6 +56,8 @@ using media::VolumeShaper; // ---------------------------------------------------------------------------- // TrackBase // ---------------------------------------------------------------------------- +#undef LOG_TAG +#define LOG_TAG "AF::TrackBase" static volatile int32_t nextTrackId = 55; @@ -104,7 +106,8 @@ AudioFlinger::ThreadBase::TrackBase::TrackBase( const uid_t callingUid = IPCThreadState::self()->getCallingUid(); if (!isAudioServerOrMediaServerUid(callingUid) || clientUid == AUDIO_UID_INVALID) { ALOGW_IF(clientUid != AUDIO_UID_INVALID && clientUid != callingUid, - "%s uid %d tried to pass itself off as %d", __FUNCTION__, callingUid, clientUid); + "%s(%d): uid %d tried to pass itself off as %d", + __func__, mId, callingUid, clientUid); clientUid = callingUid; } // clientUid contains the uid of the app that is responsible for this track, so we can blame @@ -144,7 +147,7 @@ AudioFlinger::ThreadBase::TrackBase::TrackBase( mCblkMemory = client->heap()->allocate(size); if (mCblkMemory == 0 || (mCblk = static_cast<audio_track_cblk_t *>(mCblkMemory->pointer())) == NULL) { - ALOGE("not enough memory for AudioTrack size=%zu", size); + ALOGE("%s(%d): not enough memory for AudioTrack size=%zu", __func__, mId, size); client->heap()->dump("AudioTrack"); mCblkMemory.clear(); return; @@ -152,7 +155,7 @@ AudioFlinger::ThreadBase::TrackBase::TrackBase( } else { mCblk = (audio_track_cblk_t *) malloc(size); if (mCblk == NULL) { - ALOGE("not enough memory for AudioTrack size=%zu", size); + ALOGE("%s(%d): not enough memory for AudioTrack size=%zu", __func__, mId, size); return; } } @@ -166,7 +169,8 @@ AudioFlinger::ThreadBase::TrackBase::TrackBase( if (roHeap == 0 || (mBufferMemory = roHeap->allocate(bufferSize)) == 0 || (mBuffer = mBufferMemory->pointer()) == NULL) { - ALOGE("not enough memory for read-only buffer size=%zu", bufferSize); + ALOGE("%s(%d): not enough memory for read-only buffer size=%zu", + __func__, mId, bufferSize); if (roHeap != 0) { roHeap->dump("buffer"); } @@ -205,7 +209,7 @@ AudioFlinger::ThreadBase::TrackBase::TrackBase( mBuffer = buffer; break; default: - LOG_ALWAYS_FATAL("invalid allocation type: %d", (int)alloc); + LOG_ALWAYS_FATAL("%s(%d): invalid allocation type: %d", __func__, mId, (int)alloc); } mBufferSize = bufferSize; @@ -276,6 +280,8 @@ status_t AudioFlinger::ThreadBase::TrackBase::setSyncEvent(const sp<SyncEvent>& // ---------------------------------------------------------------------------- // Playback // ---------------------------------------------------------------------------- +#undef LOG_TAG +#define LOG_TAG "AF::TrackHandle" AudioFlinger::TrackHandle::TrackHandle(const sp<AudioFlinger::PlaybackThread::Track>& track) : BnAudioTrack(), @@ -348,6 +354,8 @@ status_t AudioFlinger::TrackHandle::onTransact( } // ---------------------------------------------------------------------------- +#undef LOG_TAG +#define LOG_TAG "AF::Track" // Track constructor must be called with AudioFlinger::mLock and ThreadBase::mLock held AudioFlinger::PlaybackThread::Track::Track( @@ -396,8 +404,8 @@ AudioFlinger::PlaybackThread::Track::Track( // client == 0 implies sharedBuffer == 0 ALOG_ASSERT(!(client == 0 && sharedBuffer != 0)); - ALOGV_IF(sharedBuffer != 0, "sharedBuffer: %p, size: %zu", sharedBuffer->pointer(), - sharedBuffer->size()); + ALOGV_IF(sharedBuffer != 0, "%s(%d): sharedBuffer: %p, size: %zu", + __func__, mId, sharedBuffer->pointer(), sharedBuffer->size()); if (mCblk == NULL) { return; @@ -413,7 +421,7 @@ AudioFlinger::PlaybackThread::Track::Track( mServerProxy = mAudioTrackServerProxy; if (!thread->isTrackAllowed_l(channelMask, format, sessionId, uid)) { - ALOGE("no more tracks available"); + ALOGE("%s(%d): no more tracks available", __func__, mId); return; } // only allocate a fast track index if we were able to allocate a normal track name @@ -443,7 +451,7 @@ AudioFlinger::PlaybackThread::Track::Track( AudioFlinger::PlaybackThread::Track::~Track() { - ALOGV("PlaybackThread::Track destructor"); + ALOGV("%s(%d)", __func__, mId); // The destructor would clear mSharedBuffer, // but it will not push the decremented reference count, @@ -640,8 +648,8 @@ status_t AudioFlinger::PlaybackThread::Track::getNextBuffer( buffer->frameCount = buf.mFrameCount; buffer->raw = buf.mRaw; if (buf.mFrameCount == 0 && !isStopping() && !isStopped() && !isPaused()) { - ALOGV("underrun, framesReady(%zu) < framesDesired(%zd), state: %d", - buf.mFrameCount, desiredFrames, mState); + ALOGV("%s(%d): underrun, framesReady(%zu) < framesDesired(%zd), state: %d", + __func__, mId, buf.mFrameCount, desiredFrames, mState); mAudioTrackServerProxy->tallyUnderrunFrames(desiredFrames); } else { mAudioTrackServerProxy->tallyUnderrunFrames(0); @@ -888,11 +896,12 @@ void AudioFlinger::PlaybackThread::Track::flush() return; } - ALOGV("flush: offload flush"); + ALOGV("%s(%d): offload flush", __func__, mId); reset(); if (mState == STOPPING_1 || mState == STOPPING_2) { - ALOGV("flushed in STOPPING_1 or 2 state, change state to ACTIVE"); + ALOGV("%s(%d): flushed in STOPPING_1 or 2 state, change state to ACTIVE", + __func__, mId); mState = ACTIVE; } @@ -957,7 +966,7 @@ status_t AudioFlinger::PlaybackThread::Track::setParameters(const String8& keyVa { sp<ThreadBase> thread = mThread.promote(); if (thread == 0) { - ALOGE("thread is dead"); + ALOGE("%s(%d): thread is dead", __func__, mId); return FAILED_TRANSACTION; } else if ((thread->type() == ThreadBase::DIRECT) || (thread->type() == ThreadBase::OFFLOAD)) { @@ -977,8 +986,10 @@ VolumeShaper::Status AudioFlinger::PlaybackThread::Track::applyVolumeShaper( const VolumeShaper::Configuration::OptionFlag optionFlag = configuration->getOptionFlags(); if ((optionFlag & VolumeShaper::Configuration::OPTION_FLAG_CLOCK_TIME) == 0) { - ALOGW("%s tracks do not support frame counted VolumeShaper," - " using clock time instead", isOffloaded() ? "Offload" : "Direct"); + ALOGW("%s(%d): %s tracks do not support frame counted VolumeShaper," + " using clock time instead", + __func__, mId, + isOffloaded() ? "Offload" : "Direct"); newConfiguration = new VolumeShaper::Configuration(*configuration); newConfiguration->setOptionFlags( VolumeShaper::Configuration::OptionFlag(optionFlag @@ -1113,11 +1124,14 @@ bool AudioFlinger::PlaybackThread::Track::presentationComplete( // to detect when all frames have been played. In this case framesWritten isn't // useful because it doesn't always reflect whether there is data in the h/w // buffers, particularly if a track has been paused and resumed during draining - ALOGV("presentationComplete() mPresentationCompleteFrames %lld framesWritten %lld", + ALOGV("%s(%d): presentationComplete() mPresentationCompleteFrames %lld framesWritten %lld", + __func__, mId, (long long)mPresentationCompleteFrames, (long long)framesWritten); if (mPresentationCompleteFrames == 0) { mPresentationCompleteFrames = framesWritten + audioHalFrames; - ALOGV("presentationComplete() reset: mPresentationCompleteFrames %lld audioHalFrames %zu", + ALOGV("%s(%d): presentationComplete() reset:" + " mPresentationCompleteFrames %lld audioHalFrames %zu", + __func__, mId, (long long)mPresentationCompleteFrames, audioHalFrames); } @@ -1183,7 +1197,8 @@ status_t AudioFlinger::PlaybackThread::Track::setSyncEvent(const sp<SyncEvent>& if (isTerminated() || mState == PAUSED || ((framesReady() == 0) && ((mSharedBuffer != 0) || (mState == STOPPED)))) { - ALOGW("Track::setSyncEvent() in invalid state %d on session %d %s mode, framesReady %zu", + ALOGW("%s(%d): in invalid state %d on session %d %s mode, framesReady %zu", + __func__, mId, mState, mSessionId, (mSharedBuffer != 0) ? "static" : "stream", framesReady()); event->cancel(); return INVALID_OPERATION; @@ -1304,6 +1319,8 @@ void AudioFlinger::PlaybackThread::Track::updateTrackFrameInfo( } // ---------------------------------------------------------------------------- +#undef LOG_TAG +#define LOG_TAG "AF::OutputTrack" AudioFlinger::PlaybackThread::OutputTrack::OutputTrack( PlaybackThread *playbackThread, @@ -1325,9 +1342,9 @@ AudioFlinger::PlaybackThread::OutputTrack::OutputTrack( if (mCblk != NULL) { mOutBuffer.frameCount = 0; playbackThread->mTracks.add(this); - ALOGV("OutputTrack constructor mCblk %p, mBuffer %p, " + ALOGV("%s(): mCblk %p, mBuffer %p, " "frameCount %zu, mChannelMask 0x%08x", - mCblk, mBuffer, + __func__, mCblk, mBuffer, frameCount, mChannelMask); // since client and server are in the same process, // the buffer has the same virtual address on both sides @@ -1337,7 +1354,8 @@ AudioFlinger::PlaybackThread::OutputTrack::OutputTrack( mClientProxy->setSendLevel(0.0); mClientProxy->setSampleRate(sampleRate); } else { - ALOGW("Error creating output track on thread %p", playbackThread); + ALOGW("%s(%d): Error creating output track on thread %d", + __func__, mId, (int)mThreadIoHandle); } } @@ -1399,8 +1417,9 @@ ssize_t AudioFlinger::PlaybackThread::OutputTrack::write(void* data, uint32_t fr nsecs_t startTime = systemTime(); status_t status = obtainBuffer(&mOutBuffer, waitTimeLeftMs); if (status != NO_ERROR && status != NOT_ENOUGH_DATA) { - ALOGV("OutputTrack::write() %p thread %p no more output buffers; status %d", this, - mThread.unsafe_get(), status); + ALOGV("%s(%d): thread %d no more output buffers; status %d", + __func__, mId, + (int)mThreadIoHandle, status); outputBufferFull = true; break; } @@ -1436,8 +1455,9 @@ ssize_t AudioFlinger::PlaybackThread::OutputTrack::write(void* data, uint32_t fr if (pInBuffer != &inBuffer) { delete pInBuffer; } - ALOGV("OutputTrack::write() %p thread %p released overflow buffer %zu", this, - mThread.unsafe_get(), mBufferQueue.size()); + ALOGV("%s(%d): thread %d released overflow buffer %zu", + __func__, mId, + (int)mThreadIoHandle, mBufferQueue.size()); } else { break; } @@ -1455,13 +1475,13 @@ ssize_t AudioFlinger::PlaybackThread::OutputTrack::write(void* data, uint32_t fr pInBuffer->raw = pInBuffer->mBuffer; memcpy(pInBuffer->raw, inBuffer.raw, inBuffer.frameCount * mFrameSize); mBufferQueue.add(pInBuffer); - ALOGV("OutputTrack::write() %p thread %p adding overflow buffer %zu", this, - mThread.unsafe_get(), mBufferQueue.size()); + ALOGV("%s(%d): thread %d adding overflow buffer %zu", __func__, mId, + (int)mThreadIoHandle, mBufferQueue.size()); // audio data is consumed (stored locally); set frameCount to 0. inBuffer.frameCount = 0; } else { - ALOGW("OutputTrack::write() %p thread %p no more overflow buffers", - mThread.unsafe_get(), this); + ALOGW("%s(%d): thread %d no more overflow buffers", + __func__, mId, (int)mThreadIoHandle); // TODO: return error for this. } } @@ -1525,6 +1545,10 @@ void AudioFlinger::PlaybackThread::OutputTrack::restartIfDisabled() } } +// ---------------------------------------------------------------------------- +#undef LOG_TAG +#define LOG_TAG "AF::PatchTrack" + AudioFlinger::PlaybackThread::PatchTrack::PatchTrack(PlaybackThread *playbackThread, audio_stream_type_t streamType, uint32_t sampleRate, @@ -1546,8 +1570,8 @@ AudioFlinger::PlaybackThread::PatchTrack::PatchTrack(PlaybackThread *playbackThr mPeerTimeout.tv_sec = mixBufferNs / 1000000000; mPeerTimeout.tv_nsec = (int) (mixBufferNs % 1000000000); - ALOGV("PatchTrack %p sampleRate %d mPeerTimeout %d.%03d sec", - this, sampleRate, + ALOGV("%s(%d): sampleRate %d mPeerTimeout %d.%03d sec", + __func__, mId, sampleRate, (int)mPeerTimeout.tv_sec, (int)(mPeerTimeout.tv_nsec / 1000000)); } @@ -1571,11 +1595,11 @@ status_t AudioFlinger::PlaybackThread::PatchTrack::start(AudioSystem::sync_event status_t AudioFlinger::PlaybackThread::PatchTrack::getNextBuffer( AudioBufferProvider::Buffer* buffer) { - ALOG_ASSERT(mPeerProxy != 0, "PatchTrack::getNextBuffer() called without peer proxy"); + ALOG_ASSERT(mPeerProxy != 0, "%s(%d): called without peer proxy", __func__, mId); Proxy::Buffer buf; buf.mFrameCount = buffer->frameCount; status_t status = mPeerProxy->obtainBuffer(&buf, &mPeerTimeout); - ALOGV_IF(status != NO_ERROR, "PatchTrack() %p getNextBuffer status %d", this, status); + ALOGV_IF(status != NO_ERROR, "%s(%d): getNextBuffer status %d", __func__, mId, status); buffer->frameCount = buf.mFrameCount; if (buf.mFrameCount == 0) { return WOULD_BLOCK; @@ -1586,7 +1610,7 @@ status_t AudioFlinger::PlaybackThread::PatchTrack::getNextBuffer( void AudioFlinger::PlaybackThread::PatchTrack::releaseBuffer(AudioBufferProvider::Buffer* buffer) { - ALOG_ASSERT(mPeerProxy != 0, "PatchTrack::releaseBuffer() called without peer proxy"); + ALOG_ASSERT(mPeerProxy != 0, "%s(%d): called without peer proxy", __func__, mId); Proxy::Buffer buf; buf.mFrameCount = buffer->frameCount; buf.mRaw = buffer->raw; @@ -1621,7 +1645,7 @@ void AudioFlinger::PlaybackThread::PatchTrack::releaseBuffer(Proxy::Buffer* buff void AudioFlinger::PlaybackThread::PatchTrack::restartIfDisabled() { if (android_atomic_and(~CBLK_DISABLED, &mCblk->mFlags) & CBLK_DISABLED) { - ALOGW("PatchTrack::releaseBuffer() disabled due to previous underrun, restarting"); + ALOGW("%s(%d): disabled due to previous underrun, restarting", __func__, mId); start(); } } @@ -1629,6 +1653,8 @@ void AudioFlinger::PlaybackThread::PatchTrack::restartIfDisabled() // ---------------------------------------------------------------------------- // Record // ---------------------------------------------------------------------------- +#undef LOG_TAG +#define LOG_TAG "AF::RecordHandle" AudioFlinger::RecordHandle::RecordHandle( const sp<AudioFlinger::RecordThread::RecordTrack>& recordTrack) @@ -1644,7 +1670,7 @@ AudioFlinger::RecordHandle::~RecordHandle() { binder::Status AudioFlinger::RecordHandle::start(int /*AudioSystem::sync_event_t*/ event, int /*audio_session_t*/ triggerSession) { - ALOGV("RecordHandle::start()"); + ALOGV("%s()", __func__); return binder::Status::fromStatusT( mRecordTrack->start((AudioSystem::sync_event_t)event, (audio_session_t) triggerSession)); } @@ -1655,18 +1681,20 @@ binder::Status AudioFlinger::RecordHandle::stop() { } void AudioFlinger::RecordHandle::stop_nonvirtual() { - ALOGV("RecordHandle::stop()"); + ALOGV("%s()", __func__); mRecordTrack->stop(); } binder::Status AudioFlinger::RecordHandle::getActiveMicrophones( std::vector<media::MicrophoneInfo>* activeMicrophones) { - ALOGV("RecordHandle::getActiveMicrophones()"); + ALOGV("%s()", __func__); return binder::Status::fromStatusT( mRecordTrack->getActiveMicrophones(activeMicrophones)); } // ---------------------------------------------------------------------------- +#undef LOG_TAG +#define LOG_TAG "AF::RecordTrack" // RecordTrack constructor must be called with AudioFlinger::mLock and ThreadBase::mLock held AudioFlinger::RecordThread::RecordTrack::RecordTrack( @@ -1712,7 +1740,7 @@ AudioFlinger::RecordThread::RecordTrack::RecordTrack( // for the current device, but a pending or future device change would make // the record track configuration valid. if (mRecordBufferConverter->initCheck() != NO_ERROR) { - ALOGE("RecordTrack unable to create record buffer converter"); + ALOGE("%s(%d): RecordTrack unable to create record buffer converter", __func__, mId); return; } } @@ -1738,7 +1766,7 @@ AudioFlinger::RecordThread::RecordTrack::RecordTrack( AudioFlinger::RecordThread::RecordTrack::~RecordTrack() { - ALOGV("%s", __func__); + ALOGV("%s()", __func__); delete mRecordBufferConverter; delete mResamplerBufferProvider; } @@ -1824,19 +1852,20 @@ void AudioFlinger::RecordThread::RecordTrack::invalidate() void AudioFlinger::RecordThread::RecordTrack::appendDumpHeader(String8& result) { - result.appendFormat("Active Client Session S Flags " - " Format Chn mask SRate Source " + result.appendFormat("Active Id Client Session S Flags " + " Format Chn mask SRate Source " " Server FrmCnt FrmRdy Sil%s\n", isServerLatencySupported() ? " Latency" : ""); } void AudioFlinger::RecordThread::RecordTrack::appendDump(String8& result, bool active) { - result.appendFormat("%c%5s %6u %7u %2s 0x%03X " + result.appendFormat("%c%5s %6d %6u %7u %2s 0x%03X " "%08X %08X %6u %6X " "%08X %6zu %6zu %3c", isFastTrack() ? 'F' : ' ', active ? "yes" : "no", + mId, (mClient == 0) ? getpid() : mClient->pid(), mSessionId, getTrackStateString(), @@ -1939,6 +1968,10 @@ status_t AudioFlinger::RecordThread::RecordTrack::getActiveMicrophones( } } +// ---------------------------------------------------------------------------- +#undef LOG_TAG +#define LOG_TAG "AF::PatchRecord" + AudioFlinger::RecordThread::PatchRecord::PatchRecord(RecordThread *recordThread, uint32_t sampleRate, audio_channel_mask_t channelMask, @@ -1959,8 +1992,8 @@ AudioFlinger::RecordThread::PatchRecord::PatchRecord(RecordThread *recordThread, mPeerTimeout.tv_sec = mixBufferNs / 1000000000; mPeerTimeout.tv_nsec = (int) (mixBufferNs % 1000000000); - ALOGV("PatchRecord %p sampleRate %d mPeerTimeout %d.%03d sec", - this, sampleRate, + ALOGV("%s(%d): sampleRate %d mPeerTimeout %d.%03d sec", + __func__, mId, sampleRate, (int)mPeerTimeout.tv_sec, (int)(mPeerTimeout.tv_nsec / 1000000)); } @@ -1973,12 +2006,12 @@ AudioFlinger::RecordThread::PatchRecord::~PatchRecord() status_t AudioFlinger::RecordThread::PatchRecord::getNextBuffer( AudioBufferProvider::Buffer* buffer) { - ALOG_ASSERT(mPeerProxy != 0, "PatchRecord::getNextBuffer() called without peer proxy"); + ALOG_ASSERT(mPeerProxy != 0, "%s(%d): called without peer proxy", __func__, mId); Proxy::Buffer buf; buf.mFrameCount = buffer->frameCount; status_t status = mPeerProxy->obtainBuffer(&buf, &mPeerTimeout); ALOGV_IF(status != NO_ERROR, - "PatchRecord() %p mPeerProxy->obtainBuffer status %d", this, status); + "%s(%d): mPeerProxy->obtainBuffer status %d", __func__, mId, status); buffer->frameCount = buf.mFrameCount; if (buf.mFrameCount == 0) { return WOULD_BLOCK; @@ -1989,7 +2022,7 @@ status_t AudioFlinger::RecordThread::PatchRecord::getNextBuffer( void AudioFlinger::RecordThread::PatchRecord::releaseBuffer(AudioBufferProvider::Buffer* buffer) { - ALOG_ASSERT(mPeerProxy != 0, "PatchRecord::releaseBuffer() called without peer proxy"); + ALOG_ASSERT(mPeerProxy != 0, "%s(%d): called without peer proxy", __func__, mId); Proxy::Buffer buf; buf.mFrameCount = buffer->frameCount; buf.mRaw = buffer->raw; @@ -2008,7 +2041,9 @@ void AudioFlinger::RecordThread::PatchRecord::releaseBuffer(Proxy::Buffer* buffe mProxy->releaseBuffer(buffer); } - +// ---------------------------------------------------------------------------- +#undef LOG_TAG +#define LOG_TAG "AF::MmapTrack" AudioFlinger::MmapThread::MmapTrack::MmapTrack(ThreadBase *thread, const audio_attributes_t& attr, |