From 19e990e480245af25ec03ff3a3f53b820b0732cd Mon Sep 17 00:00:00 2001 From: Phil Burk Date: Thu, 22 Mar 2018 13:59:34 -0700 Subject: [PATCH] aaudio: improve logging to help debugging Use __func__ more often. Show thread entry and exit. Log illegal state transitions. Remove some unnecessary logs. Bug: 64310586 Test: use AAudio then look at the logs Change-Id: I2e289698efc897640588ba534b5513ac39b15043 --- .../src/client/AudioStreamInternal.cpp | 9 +-- .../src/client/AudioStreamInternalPlay.cpp | 27 +++----- media/libaaudio/src/core/AudioStream.cpp | 26 +++++-- media/libaaudio/src/core/AudioStream.h | 11 +-- .../oboeservice/AAudioEndpointManager.cpp | 14 ++-- services/oboeservice/AAudioService.cpp | 1 - .../oboeservice/AAudioServiceEndpoint.cpp | 2 +- .../oboeservice/AAudioServiceEndpointMMAP.cpp | 67 +++++++++---------- .../oboeservice/AAudioServiceEndpointPlay.cpp | 5 ++ .../oboeservice/AAudioServiceEndpointShared.h | 5 +- .../oboeservice/AAudioServiceStreamBase.cpp | 28 ++++---- .../oboeservice/AAudioServiceStreamBase.h | 4 +- .../oboeservice/AAudioServiceStreamMMAP.h | 4 +- .../oboeservice/AAudioServiceStreamShared.h | 4 +- services/oboeservice/AAudioThread.h | 2 +- 15 files changed, 105 insertions(+), 104 deletions(-) diff --git a/media/libaaudio/src/client/AudioStreamInternal.cpp b/media/libaaudio/src/client/AudioStreamInternal.cpp index 6b253025fc..2a3e66881e 100644 --- a/media/libaaudio/src/client/AudioStreamInternal.cpp +++ b/media/libaaudio/src/client/AudioStreamInternal.cpp @@ -67,8 +67,6 @@ AudioStreamInternal::AudioStreamInternal(AAudioServiceInterface &serviceInterfa , mWakeupDelayNanos(AAudioProperty_getWakeupDelayMicros() * AAUDIO_NANOS_PER_MICROSECOND) , mMinimumSleepNanos(AAudioProperty_getMinimumSleepMicros() * AAUDIO_NANOS_PER_MICROSECOND) { - ALOGD("%s - mWakeupDelayNanos = %d, mMinimumSleepNanos = %d", - __func__, mWakeupDelayNanos, mMinimumSleepNanos); } AudioStreamInternal::~AudioStreamInternal() { @@ -231,8 +229,7 @@ error: aaudio_result_t AudioStreamInternal::close() { aaudio_result_t result = AAUDIO_OK; - ALOGD("close(): mServiceStreamHandle = 0x%08X", - mServiceStreamHandle); + ALOGD("%s(): mServiceStreamHandle = 0x%08X", __func__, mServiceStreamHandle); if (mServiceStreamHandle != AAUDIO_HANDLE_INVALID) { // Don't close a stream while it is running. aaudio_stream_state_t currentState = getState(); @@ -243,8 +240,8 @@ aaudio_result_t AudioStreamInternal::close() { result = waitForStateChange(currentState, &nextState, timeoutNanoseconds); if (result != AAUDIO_OK) { - ALOGE("close() waitForStateChange() returned %d %s", - result, AAudio_convertResultToText(result)); + ALOGE("%s() waitForStateChange() returned %d %s", + __func__, result, AAudio_convertResultToText(result)); } } setState(AAUDIO_STREAM_STATE_CLOSING); diff --git a/media/libaaudio/src/client/AudioStreamInternalPlay.cpp b/media/libaaudio/src/client/AudioStreamInternalPlay.cpp index 11b43c3966..0c3b1fa182 100644 --- a/media/libaaudio/src/client/AudioStreamInternalPlay.cpp +++ b/media/libaaudio/src/client/AudioStreamInternalPlay.cpp @@ -57,8 +57,7 @@ aaudio_result_t AudioStreamInternalPlay::requestPause() return result; } if (mServiceStreamHandle == AAUDIO_HANDLE_INVALID) { - ALOGE("requestPauseInternal() mServiceStreamHandle invalid = 0x%08X", - mServiceStreamHandle); + ALOGE("%s() mServiceStreamHandle invalid", __func__); return AAUDIO_ERROR_INVALID_STATE; } @@ -70,8 +69,7 @@ aaudio_result_t AudioStreamInternalPlay::requestPause() aaudio_result_t AudioStreamInternalPlay::requestFlush() { if (mServiceStreamHandle == AAUDIO_HANDLE_INVALID) { - ALOGE("AudioStreamInternal::requestFlush() mServiceStreamHandle invalid = 0x%08X", - mServiceStreamHandle); + ALOGE("%s() mServiceStreamHandle invalid", __func__); return AAUDIO_ERROR_INVALID_STATE; } @@ -86,7 +84,7 @@ void AudioStreamInternalPlay::advanceClientToMatchServerPosition() { // Bump offset so caller does not see the retrograde motion in getFramesRead(). int64_t offset = writeCounter - readCounter; mFramesOffsetFromService += offset; - ALOGD("advanceClientToMatchServerPosition() readN = %lld, writeN = %lld, offset = %lld", + ALOGV("%s() readN = %lld, writeN = %lld, offset = %lld", __func__, (long long)readCounter, (long long)writeCounter, (long long)mFramesOffsetFromService); // Force writeCounter to match readCounter. @@ -100,9 +98,7 @@ void AudioStreamInternalPlay::onFlushFromServer() { // Write the data, block if needed and timeoutMillis > 0 aaudio_result_t AudioStreamInternalPlay::write(const void *buffer, int32_t numFrames, - int64_t timeoutNanoseconds) - -{ + int64_t timeoutNanoseconds) { return processData((void *)buffer, numFrames, timeoutNanoseconds); } @@ -121,7 +117,7 @@ aaudio_result_t AudioStreamInternalPlay::processDataNow(void *buffer, int32_t nu // Still haven't got any timestamps from server. // Keep waiting until we get some valid timestamps then start writing to the // current buffer position. - ALOGD("processDataNow() wait for valid timestamps"); + ALOGD("%s() wait for valid timestamps", __func__); // Sleep very briefly and hope we get a timestamp soon. *wakeTimePtr = currentNanoTime + (2000 * AAUDIO_NANOS_PER_MICROSECOND); ATRACE_END(); @@ -203,8 +199,6 @@ aaudio_result_t AudioStreamInternalPlay::processDataNow(void *buffer, int32_t nu aaudio_result_t AudioStreamInternalPlay::writeNowWithConversion(const void *buffer, int32_t numFrames) { - // ALOGD("AudioStreamInternal::writeNowWithConversion(%p, %d)", - // buffer, numFrames); WrappingBuffer wrappingBuffer; uint8_t *byteBuffer = (uint8_t *) buffer; int32_t framesLeft = numFrames; @@ -249,7 +243,6 @@ aaudio_result_t AudioStreamInternalPlay::writeNowWithConversion(const void *buff int32_t framesWritten = numFrames - framesLeft; mAudioEndpoint.advanceWriteIndex(framesWritten); - // ALOGD("AudioStreamInternal::writeNowWithConversion() returns %d", framesWritten); return framesWritten; } @@ -268,7 +261,6 @@ int64_t AudioStreamInternalPlay::getFramesRead() } else { mLastFramesRead = framesRead; } - //ALOGD("AudioStreamInternalPlay::getFramesRead() returns %lld", (long long)framesRead); return framesRead; } @@ -276,13 +268,13 @@ int64_t AudioStreamInternalPlay::getFramesWritten() { int64_t framesWritten = mAudioEndpoint.getDataWriteCounter() + mFramesOffsetFromService; - //ALOGD("AudioStreamInternalPlay::getFramesWritten() returns %lld", (long long)framesWritten); return framesWritten; } // Render audio in the application callback and then write the data to the stream. void *AudioStreamInternalPlay::callbackLoop() { + ALOGD("%s() entering >>>>>>>>>>>>>>>", __func__); aaudio_result_t result = AAUDIO_OK; aaudio_data_callback_result_t callbackResult = AAUDIO_CALLBACK_RESULT_CONTINUE; if (!isDataCallbackSet()) return NULL; @@ -297,7 +289,6 @@ void *AudioStreamInternalPlay::callbackLoop() { // Write audio data to stream. This is a BLOCKING WRITE! result = write(mCallbackBuffer, mCallbackFrames, timeoutNanos); if ((result != mCallbackFrames)) { - ALOGE("AudioStreamInternalPlay(): callbackLoop: write() returned %d", result); if (result >= 0) { // Only wrote some of the frames requested. Must have timed out. result = AAUDIO_ERROR_TIMEOUT; @@ -306,13 +297,13 @@ void *AudioStreamInternalPlay::callbackLoop() { break; } } else if (callbackResult == AAUDIO_CALLBACK_RESULT_STOP) { - ALOGD("AudioStreamInternalPlay(): callback returned AAUDIO_CALLBACK_RESULT_STOP"); + ALOGV("%s(): callback returned AAUDIO_CALLBACK_RESULT_STOP", __func__); break; } } - ALOGD("AudioStreamInternalPlay(): callbackLoop() exiting, result = %d, isActive() = %d", - result, (int) isActive()); + ALOGD("%s() exiting, result = %d, isActive() = %d <<<<<<<<<<<<<<", + __func__, result, (int) isActive()); return NULL; } diff --git a/media/libaaudio/src/core/AudioStream.cpp b/media/libaaudio/src/core/AudioStream.cpp index c4465fd3d8..61e03dbf2c 100644 --- a/media/libaaudio/src/core/AudioStream.cpp +++ b/media/libaaudio/src/core/AudioStream.cpp @@ -104,17 +104,17 @@ aaudio_result_t AudioStream::open(const AudioStreamBuilder& builder) mErrorCallbackUserData = builder.getErrorCallbackUserData(); // This is very helpful for debugging in the future. Please leave it in. - ALOGI("open() rate = %d, channels = %d, format = %d, sharing = %s, dir = %s", + ALOGI("open() rate = %d, channels = %d, format = %d, sharing = %s, dir = %s", mSampleRate, mSamplesPerFrame, mFormat, AudioStream_convertSharingModeToShortText(mSharingMode), (getDirection() == AAUDIO_DIRECTION_OUTPUT) ? "OUTPUT" : "INPUT"); - ALOGI("open() device = %d, sessionId = %d, perfMode = %d, callback: %s with frames = %d", + ALOGI("open() device = %d, sessionId = %d, perfMode = %d, callback: %s with frames = %d", mDeviceId, mSessionId, mPerformanceMode, (isDataCallbackSet() ? "ON" : "OFF"), mFramesPerDataCallback); - ALOGI("open() usage = %d, contentType = %d, inputPreset = %d", + ALOGI("open() usage = %d, contentType = %d, inputPreset = %d", mUsage, mContentType, mInputPreset); return AAUDIO_OK; @@ -242,6 +242,22 @@ aaudio_result_t AudioStream::safeClose() { return close(); } +void AudioStream::setState(aaudio_stream_state_t state) { + ALOGV("%s(%p) from %d to %d", __func__, this, mState, state); + // CLOSED is a final state + if (mState == AAUDIO_STREAM_STATE_CLOSED) { + ALOGE("%s(%p) tried to set to %d but already CLOSED", __func__, this, state); + + // Once DISCONNECTED, we can only move to CLOSED state. + } else if (mState == AAUDIO_STREAM_STATE_DISCONNECTED + && state != AAUDIO_STREAM_STATE_CLOSED) { + ALOGE("%s(%p) tried to set to %d but already DISCONNECTED", __func__, this, state); + + } else { + mState = state; + } +} + aaudio_result_t AudioStream::waitForStateChange(aaudio_stream_state_t currentState, aaudio_stream_state_t *nextState, int64_t timeoutNanoseconds) @@ -313,7 +329,9 @@ aaudio_result_t AudioStream::createThread(int64_t periodNanoseconds, setPeriodNanoseconds(periodNanoseconds); int err = pthread_create(&mThread, nullptr, AudioStream_internalThreadProc, this); if (err != 0) { - return AAudioConvert_androidToAAudioResult(-errno); + android::status_t status = -errno; + ALOGE("createThread() - pthread_create() failed, %d", status); + return AAudioConvert_androidToAAudioResult(status); } else { // TODO Use AAudioThread or maybe AndroidThread // Name the thread with an increasing index, "AAudio_#", for debugging. diff --git a/media/libaaudio/src/core/AudioStream.h b/media/libaaudio/src/core/AudioStream.h index c0db0f9114..5273e36fc7 100644 --- a/media/libaaudio/src/core/AudioStream.h +++ b/media/libaaudio/src/core/AudioStream.h @@ -471,16 +471,7 @@ protected: mFormat = format; } - void setState(aaudio_stream_state_t state) { - if (mState == AAUDIO_STREAM_STATE_CLOSED) { - ; // CLOSED is a final state - } else if (mState == AAUDIO_STREAM_STATE_DISCONNECTED - && state != AAUDIO_STREAM_STATE_CLOSED) { - ; // Once DISCONNECTED, we can only move to CLOSED state. - } else { - mState = state; - } - } + void setState(aaudio_stream_state_t state); void setDeviceId(int32_t deviceId) { mDeviceId = deviceId; diff --git a/services/oboeservice/AAudioEndpointManager.cpp b/services/oboeservice/AAudioEndpointManager.cpp index 7b8d817c0b..11fd9f6251 100644 --- a/services/oboeservice/AAudioEndpointManager.cpp +++ b/services/oboeservice/AAudioEndpointManager.cpp @@ -201,14 +201,14 @@ sp AAudioEndpointManager::openSharedEndpoint( if (endpoint.get() != nullptr) { aaudio_result_t result = endpoint->open(request); if (result != AAUDIO_OK) { - ALOGE("openSharedEndpoint(), open failed"); + ALOGE("%s(), open failed", __func__); endpoint.clear(); } else { mSharedStreams.push_back(endpoint); } } - ALOGD("openSharedEndpoint(), created %p, requested device = %d, dir = %d", - endpoint.get(), configuration.getDeviceId(), (int)direction); + ALOGD("%s(), created endpoint %p, requested device = %d, dir = %d", + __func__, endpoint.get(), configuration.getDeviceId(), (int)direction); IPCThreadState::self()->restoreCallingIdentity(token); } @@ -244,8 +244,8 @@ void AAudioEndpointManager::closeExclusiveEndpoint(sp ser mExclusiveStreams.end()); serviceEndpoint->close(); - ALOGD("closeExclusiveEndpoint() %p for device %d", - serviceEndpoint.get(), serviceEndpoint->getDeviceId()); + ALOGD("%s() %p for device %d", + __func__, serviceEndpoint.get(), serviceEndpoint->getDeviceId()); } } @@ -266,7 +266,7 @@ void AAudioEndpointManager::closeSharedEndpoint(sp servic mSharedStreams.end()); serviceEndpoint->close(); - ALOGD("closeSharedEndpoint() %p for device %d", - serviceEndpoint.get(), serviceEndpoint->getDeviceId()); + ALOGD("%s() %p for device %d", + __func__, serviceEndpoint.get(), serviceEndpoint->getDeviceId()); } } diff --git a/services/oboeservice/AAudioService.cpp b/services/oboeservice/AAudioService.cpp index c708fee2fc..ad5bb3a452 100644 --- a/services/oboeservice/AAudioService.cpp +++ b/services/oboeservice/AAudioService.cpp @@ -165,7 +165,6 @@ aaudio_result_t AAudioService::checkForPendingClose( } aaudio_result_t AAudioService::closeStream(aaudio_handle_t streamHandle) { - ALOGD("closeStream(0x%08X)", streamHandle); // Check permission and ownership first. sp serviceStream = convertHandleToServiceStream(streamHandle); if (serviceStream.get() == nullptr) { diff --git a/services/oboeservice/AAudioServiceEndpoint.cpp b/services/oboeservice/AAudioServiceEndpoint.cpp index 33439fc25c..96e621a1ee 100644 --- a/services/oboeservice/AAudioServiceEndpoint.cpp +++ b/services/oboeservice/AAudioServiceEndpoint.cpp @@ -39,7 +39,7 @@ using namespace android; // TODO just import names needed using namespace aaudio; // TODO just import names needed AAudioServiceEndpoint::~AAudioServiceEndpoint() { - ALOGD("AAudioServiceEndpoint::~AAudioServiceEndpoint() destroying endpoint %p", this); + ALOGD("%s(%p) destroyed", __func__, this); } std::string AAudioServiceEndpoint::dump() const { diff --git a/services/oboeservice/AAudioServiceEndpointMMAP.cpp b/services/oboeservice/AAudioServiceEndpointMMAP.cpp index db01c8861e..52990da180 100644 --- a/services/oboeservice/AAudioServiceEndpointMMAP.cpp +++ b/services/oboeservice/AAudioServiceEndpointMMAP.cpp @@ -98,8 +98,8 @@ aaudio_result_t AAudioServiceEndpointMMAP::open(const aaudio::AAudioStreamReques .flags = AUDIO_FLAG_LOW_LATENCY, .tags = "" }; - ALOGV("open() MMAP attributes.usage = %d, content_type = %d, source = %d", - attributes.usage, attributes.content_type, attributes.source); + ALOGD("%s(%p) MMAP attributes.usage = %d, content_type = %d, source = %d", + __func__, this, attributes.usage, attributes.content_type, attributes.source); mMmapClient.clientUid = request.getUserId(); mMmapClient.clientPid = request.getProcessId(); @@ -135,7 +135,7 @@ aaudio_result_t AAudioServiceEndpointMMAP::open(const aaudio::AAudioStreamReques mHardwareTimeOffsetNanos = INPUT_ESTIMATED_HARDWARE_OFFSET_NANOS; // frames at ADC earlier } else { - ALOGE("openMmapStream - invalid direction = %d", direction); + ALOGE("%s() invalid direction = %d", __func__, direction); return AAUDIO_ERROR_ILLEGAL_ARGUMENT; } @@ -157,20 +157,20 @@ aaudio_result_t AAudioServiceEndpointMMAP::open(const aaudio::AAudioStreamReques this, // callback mMmapStream, &mPortHandle); - ALOGD("open() mMapClient.uid = %d, pid = %d => portHandle = %d\n", - mMmapClient.clientUid, mMmapClient.clientPid, mPortHandle); + ALOGD("%s() mMapClient.uid = %d, pid = %d => portHandle = %d\n", + __func__, mMmapClient.clientUid, mMmapClient.clientPid, mPortHandle); if (status != OK) { - ALOGE("openMmapStream returned status %d", status); + ALOGE("%s() openMmapStream() returned status %d", __func__, status); return AAUDIO_ERROR_UNAVAILABLE; } if (deviceId == AAUDIO_UNSPECIFIED) { - ALOGW("open() - openMmapStream() failed to set deviceId"); + ALOGW("%s() openMmapStream() failed to set deviceId", __func__); } setDeviceId(deviceId); if (sessionId == AUDIO_SESSION_ALLOCATE) { - ALOGW("open() - openMmapStream() failed to set sessionId"); + ALOGW("%s() - openMmapStream() failed to set sessionId", __func__); } aaudio_session_id_t actualSessionId = @@ -178,7 +178,7 @@ aaudio_result_t AAudioServiceEndpointMMAP::open(const aaudio::AAudioStreamReques ? AAUDIO_SESSION_ID_NONE : (aaudio_session_id_t) sessionId; setSessionId(actualSessionId); - ALOGD("open() deviceId = %d, sessionId = %d", getDeviceId(), getSessionId()); + ALOGD("%s() deviceId = %d, sessionId = %d", __func__, getDeviceId(), getSessionId()); // Create MMAP/NOIRQ buffer. int32_t minSizeFrames = getBufferCapacity(); @@ -187,14 +187,14 @@ aaudio_result_t AAudioServiceEndpointMMAP::open(const aaudio::AAudioStreamReques } status = mMmapStream->createMmapBuffer(minSizeFrames, &mMmapBufferinfo); if (status != OK) { - ALOGE("open() - createMmapBuffer() failed with status %d %s", - status, strerror(-status)); + ALOGE("%s() - createMmapBuffer() failed with status %d %s", + __func__, status, strerror(-status)); result = AAUDIO_ERROR_UNAVAILABLE; goto error; } else { - ALOGD("createMmapBuffer status = %d, buffer_size = %d, burst_size %d" + ALOGD("%s() createMmapBuffer() returned = %d, buffer_size = %d, burst_size %d" ", Sharable FD: %s", - status, + __func__, status, abs(mMmapBufferinfo.buffer_size_frames), mMmapBufferinfo.burst_size_frames, mMmapBufferinfo.buffer_size_frames < 0 ? "Yes" : "No"); @@ -214,7 +214,7 @@ aaudio_result_t AAudioServiceEndpointMMAP::open(const aaudio::AAudioStreamReques // Fallback is handled by caller but indicate what is possible in case // this is used in the future setSharingMode(AAUDIO_SHARING_MODE_SHARED); - ALOGW("open() - exclusive FD cannot be used by client"); + ALOGW("%s() - exclusive FD cannot be used by client", __func__); result = AAUDIO_ERROR_UNAVAILABLE; goto error; } @@ -229,7 +229,7 @@ aaudio_result_t AAudioServiceEndpointMMAP::open(const aaudio::AAudioStreamReques // Assume that AudioFlinger will close the original shared_memory_fd. mAudioDataFileDescriptor.reset(dup(mMmapBufferinfo.shared_memory_fd)); if (mAudioDataFileDescriptor.get() == -1) { - ALOGE("open() - could not dup shared_memory_fd"); + ALOGE("%s() - could not dup shared_memory_fd", __func__); result = AAUDIO_ERROR_INTERNAL; goto error; } @@ -247,12 +247,12 @@ aaudio_result_t AAudioServiceEndpointMMAP::open(const aaudio::AAudioStreamReques burstMicros = mFramesPerBurst * static_cast(1000000) / getSampleRate(); } while (burstMicros < burstMinMicros); - ALOGD("open() original burst = %d, minMicros = %d, to burst = %d\n", - mMmapBufferinfo.burst_size_frames, burstMinMicros, mFramesPerBurst); + ALOGD("%s() original burst = %d, minMicros = %d, to burst = %d\n", + __func__, mMmapBufferinfo.burst_size_frames, burstMinMicros, mFramesPerBurst); - ALOGD("open() actual rate = %d, channels = %d" + ALOGD("%s() actual rate = %d, channels = %d" ", deviceId = %d, capacity = %d\n", - getSampleRate(), getSamplesPerFrame(), deviceId, getBufferCapacity()); + __func__, getSampleRate(), getSamplesPerFrame(), deviceId, getBufferCapacity()); return result; @@ -262,9 +262,8 @@ error: } aaudio_result_t AAudioServiceEndpointMMAP::close() { - if (mMmapStream != 0) { - ALOGD("close() clear() endpoint"); + ALOGD("%s() clear() endpoint", __func__); // Needs to be explicitly cleared or CTS will fail but it is not clear why. mMmapStream.clear(); // Apparently the above close is asynchronous. An attempt to open a new device @@ -299,20 +298,18 @@ aaudio_result_t AAudioServiceEndpointMMAP::stopStream(spstart(client, clientHandle); aaudio_result_t result = AAudioConvert_androidToAAudioResult(status); - ALOGD("startClient() , %d => %d returns %d", - originalHandle, *clientHandle, result); + ALOGV("%s() , %d => %d returns %d", __func__, originalHandle, *clientHandle, result); return result; } aaudio_result_t AAudioServiceEndpointMMAP::stopClient(audio_port_handle_t clientHandle) { if (mMmapStream == nullptr) return AAUDIO_ERROR_NULL; aaudio_result_t result = AAudioConvert_androidToAAudioResult(mMmapStream->stop(clientHandle)); - ALOGD("stopClient(%d) returns %d", clientHandle, result); + ALOGV("%s(%d) returns %d", __func__, clientHandle, result); return result; } @@ -324,13 +321,13 @@ aaudio_result_t AAudioServiceEndpointMMAP::getFreeRunningPosition(int64_t *posit return AAUDIO_ERROR_NULL; } status_t status = mMmapStream->getMmapPosition(&position); - ALOGV("getFreeRunningPosition() status= %d, pos = %d, nanos = %lld\n", - status, position.position_frames, (long long) position.time_nanoseconds); + ALOGV("%s() status= %d, pos = %d, nanos = %lld\n", + __func__, status, position.position_frames, (long long) position.time_nanoseconds); aaudio_result_t result = AAudioConvert_androidToAAudioResult(status); if (result == AAUDIO_ERROR_UNAVAILABLE) { - ALOGW("sendCurrentTimestamp(): getMmapPosition() has no position data available"); + ALOGW("%s(): getMmapPosition() has no position data available", __func__); } else if (result != AAUDIO_OK) { - ALOGE("sendCurrentTimestamp(): getMmapPosition() returned status %d", status); + ALOGE("%s(): getMmapPosition() returned status %d", __func__, status); } else { // Convert 32-bit position to 64-bit position. mFramesTransferred.update32(position.position_frames); @@ -347,15 +344,16 @@ aaudio_result_t AAudioServiceEndpointMMAP::getTimestamp(int64_t *positionFrames, void AAudioServiceEndpointMMAP::onTearDown() { - ALOGD("onTearDown() called"); + ALOGD("%s(%p) called", __func__, this); disconnectRegisteredStreams(); }; void AAudioServiceEndpointMMAP::onVolumeChanged(audio_channel_mask_t channels, android::Vector values) { - // TODO do we really need a different volume for each channel? + // TODO Do we really need a different volume for each channel? + // We get called with an array filled with a single value! float volume = values[0]; - ALOGD("onVolumeChanged() volume[0] = %f", volume); + ALOGD("%s(%p) volume[0] = %f", __func__, this, volume); std::lock_guard lock(mLockStreams); for(const auto stream : mRegisteredStreams) { stream->onVolumeChanged(volume); @@ -363,8 +361,7 @@ void AAudioServiceEndpointMMAP::onVolumeChanged(audio_channel_mask_t channels, }; void AAudioServiceEndpointMMAP::onRoutingChanged(audio_port_handle_t deviceId) { - ALOGD("onRoutingChanged() called with dev %d, old = %d", - deviceId, getDeviceId()); + ALOGD("%s(%p) called with dev %d, old = %d", __func__, this, deviceId, getDeviceId()); if (getDeviceId() != AUDIO_PORT_HANDLE_NONE && getDeviceId() != deviceId) { disconnectRegisteredStreams(); } diff --git a/services/oboeservice/AAudioServiceEndpointPlay.cpp b/services/oboeservice/AAudioServiceEndpointPlay.cpp index 2601f3f4c2..a274466c3e 100644 --- a/services/oboeservice/AAudioServiceEndpointPlay.cpp +++ b/services/oboeservice/AAudioServiceEndpointPlay.cpp @@ -43,10 +43,12 @@ using namespace aaudio; // TODO just import names needed AAudioServiceEndpointPlay::AAudioServiceEndpointPlay(AAudioService &audioService) : mStreamInternalPlay(audioService, true) { + ALOGD("%s(%p) created", __func__, this); mStreamInternal = &mStreamInternalPlay; } AAudioServiceEndpointPlay::~AAudioServiceEndpointPlay() { + ALOGD("%s(%p) destroyed", __func__, this); } aaudio_result_t AAudioServiceEndpointPlay::open(const aaudio::AAudioStreamRequest &request) { @@ -68,6 +70,7 @@ aaudio_result_t AAudioServiceEndpointPlay::open(const aaudio::AAudioStreamReques // Mix data from each application stream and write result to the shared MMAP stream. void *AAudioServiceEndpointPlay::callbackLoop() { + ALOGD("%s() entering >>>>>>>>>>>>>>> MIXER", __func__); aaudio_result_t result = AAUDIO_OK; int64_t timeoutNanos = getStreamInternal()->calculateReasonableTimeout(); @@ -152,5 +155,7 @@ void *AAudioServiceEndpointPlay::callbackLoop() { } } + ALOGD("%s() exiting, enabled = %d, state = %d, result = %d <<<<<<<<<<<<< MIXER", + __func__, mCallbackEnabled.load(), getStreamInternal()->getState(), result); return NULL; // TODO review } diff --git a/services/oboeservice/AAudioServiceEndpointShared.h b/services/oboeservice/AAudioServiceEndpointShared.h index 74cd817e7d..227250c651 100644 --- a/services/oboeservice/AAudioServiceEndpointShared.h +++ b/services/oboeservice/AAudioServiceEndpointShared.h @@ -54,12 +54,13 @@ public: virtual void *callbackLoop() = 0; + +protected: + AudioStreamInternal *getStreamInternal() const { return mStreamInternal; }; -protected: - aaudio_result_t startSharingThread_l(); aaudio_result_t stopSharingThread(); diff --git a/services/oboeservice/AAudioServiceStreamBase.cpp b/services/oboeservice/AAudioServiceStreamBase.cpp index e8c9e4128d..18f14ee9e0 100644 --- a/services/oboeservice/AAudioServiceStreamBase.cpp +++ b/services/oboeservice/AAudioServiceStreamBase.cpp @@ -93,7 +93,7 @@ aaudio_result_t AAudioServiceStreamBase::open(const aaudio::AAudioStreamRequest { std::lock_guard lock(mUpMessageQueueLock); if (mUpMessageQueue != nullptr) { - ALOGE("open() called twice"); + ALOGE("%s() called twice", __func__); return AAUDIO_ERROR_INVALID_STATE; } @@ -108,7 +108,7 @@ aaudio_result_t AAudioServiceStreamBase::open(const aaudio::AAudioStreamRequest request, sharingMode); if (mServiceEndpoint == nullptr) { - ALOGE("open() openEndpoint() failed"); + ALOGE("%s() openEndpoint() failed", __func__); result = AAUDIO_ERROR_UNAVAILABLE; goto error; } @@ -167,7 +167,7 @@ aaudio_result_t AAudioServiceStreamBase::start() { } if (mServiceEndpoint == nullptr) { - ALOGE("start() missing endpoint"); + ALOGE("%s() missing endpoint", __func__); result = AAUDIO_ERROR_INVALID_STATE; goto error; } @@ -201,7 +201,7 @@ aaudio_result_t AAudioServiceStreamBase::pause() { return result; } if (mServiceEndpoint == nullptr) { - ALOGE("pause() missing endpoint"); + ALOGE("%s() missing endpoint", __func__); return AAUDIO_ERROR_INVALID_STATE; } @@ -217,7 +217,7 @@ aaudio_result_t AAudioServiceStreamBase::pause() { result = mServiceEndpoint->stopStream(this, mClientHandle); if (result != AAUDIO_OK) { - ALOGE("pause() mServiceEndpoint returned %d", result); + ALOGE("%s() mServiceEndpoint returned %d, %s", __func__, result, getTypeText()); disconnect(); // TODO should we return or pause Base first? } @@ -233,7 +233,7 @@ aaudio_result_t AAudioServiceStreamBase::stop() { } if (mServiceEndpoint == nullptr) { - ALOGE("stop() missing endpoint"); + ALOGE("%s() missing endpoint", __func__); return AAUDIO_ERROR_INVALID_STATE; } @@ -251,7 +251,7 @@ aaudio_result_t AAudioServiceStreamBase::stop() { // TODO wait for data to be played out result = mServiceEndpoint->stopStream(this, mClientHandle); if (result != AAUDIO_OK) { - ALOGE("stop() mServiceEndpoint returned %d", result); + ALOGE("%s() mServiceEndpoint returned %d, %s", __func__, result, getTypeText()); disconnect(); // TODO what to do with result here? } @@ -284,7 +284,7 @@ aaudio_result_t AAudioServiceStreamBase::flush() { // implement Runnable, periodically send timestamps to client void AAudioServiceStreamBase::run() { - ALOGD("run() entering ----------------"); + ALOGD("%s() %s entering >>>>>>>>>>>>>> TIMESTAMPS", __func__, getTypeText()); TimestampScheduler timestampScheduler; timestampScheduler.setBurstPeriod(mFramesPerBurst, getSampleRate()); timestampScheduler.start(AudioClock::getNanoseconds()); @@ -302,7 +302,7 @@ void AAudioServiceStreamBase::run() { AudioClock::sleepUntilNanoTime(nextTime); } } - ALOGD("run() exiting ----------------"); + ALOGD("%s() %s exiting <<<<<<<<<<<<<< TIMESTAMPS", __func__, getTypeText()); } void AAudioServiceStreamBase::disconnect() { @@ -333,12 +333,12 @@ aaudio_result_t AAudioServiceStreamBase::sendServiceEvent(aaudio_service_event_t aaudio_result_t AAudioServiceStreamBase::writeUpMessageQueue(AAudioServiceMessage *command) { std::lock_guard lock(mUpMessageQueueLock); if (mUpMessageQueue == nullptr) { - ALOGE("writeUpMessageQueue(): mUpMessageQueue null! - stream not open"); + ALOGE("%s(): mUpMessageQueue null! - stream not open", __func__); return AAUDIO_ERROR_NULL; } int32_t count = mUpMessageQueue->getFifoBuffer()->write(command, 1); if (count != 1) { - ALOGE("writeUpMessageQueue(): Queue full. Did client die?"); + ALOGE("%s(): Queue full. Did client die? %s", __func__, getTypeText()); return AAUDIO_ERROR_WOULD_BLOCK; } else { return AAUDIO_OK; @@ -355,7 +355,7 @@ aaudio_result_t AAudioServiceStreamBase::sendCurrentTimestamp() { aaudio_result_t result = getFreeRunningPosition(&command.timestamp.position, &command.timestamp.timestamp); if (result == AAUDIO_OK) { - ALOGV("sendCurrentTimestamp() SERVICE %8lld at %lld", + ALOGV("%s() SERVICE %8lld at %lld", __func__, (long long) command.timestamp.position, (long long) command.timestamp.timestamp); command.what = AAudioServiceMessage::code::TIMESTAMP_SERVICE; @@ -366,7 +366,7 @@ aaudio_result_t AAudioServiceStreamBase::sendCurrentTimestamp() { result = getHardwareTimestamp(&command.timestamp.position, &command.timestamp.timestamp); if (result == AAUDIO_OK) { - ALOGV("sendCurrentTimestamp() HARDWARE %8lld at %lld", + ALOGV("%s() HARDWARE %8lld at %lld", __func__, (long long) command.timestamp.position, (long long) command.timestamp.timestamp); command.what = AAudioServiceMessage::code::TIMESTAMP_HARDWARE; @@ -389,7 +389,7 @@ aaudio_result_t AAudioServiceStreamBase::getDescription(AudioEndpointParcelable { std::lock_guard lock(mUpMessageQueueLock); if (mUpMessageQueue == nullptr) { - ALOGE("getDescription(): mUpMessageQueue null! - stream not open"); + ALOGE("%s(): mUpMessageQueue null! - stream not open", __func__); return AAUDIO_ERROR_NULL; } // Gather information on the message queue. diff --git a/services/oboeservice/AAudioServiceStreamBase.h b/services/oboeservice/AAudioServiceStreamBase.h index 5f5bb98eb0..3720596030 100644 --- a/services/oboeservice/AAudioServiceStreamBase.h +++ b/services/oboeservice/AAudioServiceStreamBase.h @@ -55,7 +55,7 @@ class AAudioServiceStreamBase , public Runnable { public: - AAudioServiceStreamBase(android::AAudioService &aAudioService); + explicit AAudioServiceStreamBase(android::AAudioService &aAudioService); virtual ~AAudioServiceStreamBase(); @@ -219,6 +219,8 @@ public: mCloseNeeded.store(needed); } + virtual const char *getTypeText() const { return "Base"; } + protected: /** diff --git a/services/oboeservice/AAudioServiceStreamMMAP.h b/services/oboeservice/AAudioServiceStreamMMAP.h index e2415d06dd..1509f7dc79 100644 --- a/services/oboeservice/AAudioServiceStreamMMAP.h +++ b/services/oboeservice/AAudioServiceStreamMMAP.h @@ -69,9 +69,7 @@ public: aaudio_result_t close() override; - /** - * Send a MMAP/NOIRQ buffer timestamp to the client. - */ + const char *getTypeText() const override { return "MMAP"; } protected: diff --git a/services/oboeservice/AAudioServiceStreamShared.h b/services/oboeservice/AAudioServiceStreamShared.h index 3b12e61de7..61769b56cd 100644 --- a/services/oboeservice/AAudioServiceStreamShared.h +++ b/services/oboeservice/AAudioServiceStreamShared.h @@ -43,7 +43,7 @@ class SharedRingBuffer; class AAudioServiceStreamShared : public AAudioServiceStreamBase { public: - AAudioServiceStreamShared(android::AAudioService &aAudioService); + explicit AAudioServiceStreamShared(android::AAudioService &aAudioService); virtual ~AAudioServiceStreamShared() = default; static std::string dumpHeader(); @@ -87,6 +87,8 @@ public: return mXRunCount.load(); } + const char *getTypeText() const override { return "Shared"; } + protected: aaudio_result_t getAudioDataDescription(AudioEndpointParcelable &parcelable) override; diff --git a/services/oboeservice/AAudioThread.h b/services/oboeservice/AAudioThread.h index ffc9b7b02d..dcce68a948 100644 --- a/services/oboeservice/AAudioThread.h +++ b/services/oboeservice/AAudioThread.h @@ -44,7 +44,7 @@ class AAudioThread public: AAudioThread(); - AAudioThread(const char *prefix); + explicit AAudioThread(const char *prefix); virtual ~AAudioThread() = default;