Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 19e990e4 authored by Phil Burk's avatar Phil Burk
Browse files

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
parent ce6c8479

media/libaaudio/src/client/AudioStreamInternal.cpp

+3 −6
Original line number Diff line number Diff line
@@ -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);

media/libaaudio/src/client/AudioStreamInternalPlay.cpp

+9 −18
Original line number Diff line number Diff line
@@ -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;

}

media/libaaudio/src/core/AudioStream.cpp

+22 −4
Original line number Diff line number Diff line
@@ -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.

media/libaaudio/src/core/AudioStream.h

+1 −10
Original line number Diff line number Diff line
@@ -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;

services/oboeservice/AAudioEndpointManager.cpp

+7 −7
Original line number Diff line number Diff line
@@ -201,14 +201,14 @@ sp<AAudioServiceEndpoint> 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<AAudioServiceEndpoint> 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<AAudioServiceEndpoint> 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());

    }

}