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
diff --git a/media/libaaudio/src/client/AudioStreamInternal.cpp b/media/libaaudio/src/client/AudioStreamInternal.cpp
index 6b25302..2a3e668 100644
--- a/media/libaaudio/src/client/AudioStreamInternal.cpp
+++ b/media/libaaudio/src/client/AudioStreamInternal.cpp
@@ -67,8 +67,6 @@
, 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 @@
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 @@
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 11b43c3..0c3b1fa 100644
--- a/media/libaaudio/src/client/AudioStreamInternalPlay.cpp
+++ b/media/libaaudio/src/client/AudioStreamInternalPlay.cpp
@@ -57,8 +57,7 @@
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::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 @@
// 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 @@
// 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 @@
// 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::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 @@
int32_t framesWritten = numFrames - framesLeft;
mAudioEndpoint.advanceWriteIndex(framesWritten);
- // ALOGD("AudioStreamInternal::writeNowWithConversion() returns %d", framesWritten);
return framesWritten;
}
@@ -268,7 +261,6 @@
} else {
mLastFramesRead = framesRead;
}
- //ALOGD("AudioStreamInternalPlay::getFramesRead() returns %lld", (long long)framesRead);
return framesRead;
}
@@ -276,13 +268,13 @@
{
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 @@
// 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 @@
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 c4465fd..61e03db 100644
--- a/media/libaaudio/src/core/AudioStream.cpp
+++ b/media/libaaudio/src/core/AudioStream.cpp
@@ -104,17 +104,17 @@
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 @@
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 @@
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 c0db0f9..5273e36 100644
--- a/media/libaaudio/src/core/AudioStream.h
+++ b/media/libaaudio/src/core/AudioStream.h
@@ -471,16 +471,7 @@
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;