aaudio: improve error logging

Report when INVALID_STATE returned.
This was used to debug monkey test errors.
Cleanup some log messages.
Improve "dumpsys media.aaudio"

Bug: 64310586
Test: CTS nativemedia/aaudio
Change-Id: Ifbcac4794cda22cccbacff6352243c0ef4589c53

diff --git a/media/libaaudio/examples/utils/AAudioArgsParser.h b/media/libaaudio/examples/utils/AAudioArgsParser.h
index 46bc99e..30c3ccd 100644 (file)
--- a/media/libaaudio/examples/utils/AAudioArgsParser.h
+++ b/media/libaaudio/examples/utils/AAudioArgsParser.h
@@ -24,7 +24,8 @@
 
 #include <aaudio/AAudio.h>
 #include <aaudio/AAudioTesting.h>
-#include <AAudioExampleUtils.h>
+
+#include "AAudioExampleUtils.h"
 
 // TODO use this as a base class within AAudio
 class AAudioParameters {
@@ -239,7 +240,7 @@ public:
      * Print stream parameters in comparison with requested values.
      * @param stream
      */
-    void compareWithStream(AAudioStream *stream) {
+    void compareWithStream(AAudioStream *stream) const {
 
         printf("  DeviceId:     requested = %d, actual = %d\n",
                getDeviceId(), AAudioStream_getDeviceId(stream));

diff --git a/media/libaaudio/src/client/AudioStreamInternal.cpp b/media/libaaudio/src/client/AudioStreamInternal.cpp
index 8c3045a..a136c0d 100644 (file)
--- a/media/libaaudio/src/client/AudioStreamInternal.cpp
+++ b/media/libaaudio/src/client/AudioStreamInternal.cpp
@@ -241,9 +241,11 @@ aaudio_result_t AudioStreamInternal::requestStart()
     int64_t startTime;
     ALOGD("AudioStreamInternal()::requestStart()");
     if (mServiceStreamHandle == AAUDIO_HANDLE_INVALID) {
+        ALOGE("AudioStreamInternal::requestStart() mServiceStreamHandle invalid");
         return AAUDIO_ERROR_INVALID_STATE;
     }
     if (isActive()) {
+        ALOGE("AudioStreamInternal::requestStart() already active");
         return AAUDIO_ERROR_INVALID_STATE;
     }
     aaudio_stream_state_t originalState = getState();
@@ -320,6 +322,7 @@ aaudio_result_t AudioStreamInternal::requestStop()
 
 aaudio_result_t AudioStreamInternal::registerThread() {
     if (mServiceStreamHandle == AAUDIO_HANDLE_INVALID) {
+        ALOGE("AudioStreamInternal::registerThread() mServiceStreamHandle invalid");
         return AAUDIO_ERROR_INVALID_STATE;
     }
     return mServiceInterface.registerAudioThread(mServiceStreamHandle,
@@ -329,6 +332,7 @@ aaudio_result_t AudioStreamInternal::registerThread() {
 
 aaudio_result_t AudioStreamInternal::unregisterThread() {
     if (mServiceStreamHandle == AAUDIO_HANDLE_INVALID) {
+        ALOGE("AudioStreamInternal::unregisterThread() mServiceStreamHandle invalid");
         return AAUDIO_ERROR_INVALID_STATE;
     }
     return mServiceInterface.unregisterAudioThread(mServiceStreamHandle, gettid());
@@ -407,19 +411,19 @@ aaudio_result_t AudioStreamInternal::onEventFromServer(AAudioServiceMessage *mes
     aaudio_result_t result = AAUDIO_OK;
     switch (message->event.event) {
         case AAUDIO_SERVICE_EVENT_STARTED:
-            ALOGD("AudioStreamInternal::onEventFromServergot() AAUDIO_SERVICE_EVENT_STARTED");
+            ALOGD("AudioStreamInternal::onEventFromServer() got AAUDIO_SERVICE_EVENT_STARTED");
             if (getState() == AAUDIO_STREAM_STATE_STARTING) {
                 setState(AAUDIO_STREAM_STATE_STARTED);
             }
             break;
         case AAUDIO_SERVICE_EVENT_PAUSED:
-            ALOGD("AudioStreamInternal::onEventFromServergot() AAUDIO_SERVICE_EVENT_PAUSED");
+            ALOGD("AudioStreamInternal::onEventFromServer() got AAUDIO_SERVICE_EVENT_PAUSED");
             if (getState() == AAUDIO_STREAM_STATE_PAUSING) {
                 setState(AAUDIO_STREAM_STATE_PAUSED);
             }
             break;
         case AAUDIO_SERVICE_EVENT_STOPPED:
-            ALOGD("AudioStreamInternal::onEventFromServergot() AAUDIO_SERVICE_EVENT_STOPPED");
+            ALOGD("AudioStreamInternal::onEventFromServer() got AAUDIO_SERVICE_EVENT_STOPPED");
             if (getState() == AAUDIO_STREAM_STATE_STOPPING) {
                 setState(AAUDIO_STREAM_STATE_STOPPED);
             }

diff --git a/media/libaaudio/src/core/AAudioAudio.cpp b/media/libaaudio/src/core/AAudioAudio.cpp
index ca42444..82d96e0 100644 (file)
--- a/media/libaaudio/src/core/AAudioAudio.cpp
+++ b/media/libaaudio/src/core/AAudioAudio.cpp
@@ -248,7 +248,7 @@ AAUDIO_API aaudio_result_t  AAudioStream_requestStart(AAudioStream* stream)
     AudioStream *audioStream = convertAAudioStreamToAudioStream(stream);
     ALOGD("AAudioStream_requestStart(%p) called --------------", stream);
     aaudio_result_t result = audioStream->requestStart();
-    ALOGD("AAudioStream_requestStart(%p) returned ------------", stream);
+    ALOGD("AAudioStream_requestStart(%p) returned %d ---------", stream, result);
     return result;
 }
 

diff --git a/media/libaaudio/src/core/AudioStream.cpp b/media/libaaudio/src/core/AudioStream.cpp
index 6c4a193..4f1cc37 100644 (file)
--- a/media/libaaudio/src/core/AudioStream.cpp
+++ b/media/libaaudio/src/core/AudioStream.cpp
@@ -153,6 +153,7 @@ aaudio_result_t AudioStream::createThread(int64_t periodNanoseconds,
                                      void* threadArg)
 {
     if (mHasThread) {
+        ALOGE("AudioStream::createThread() - mHasThread already true");
         return AAUDIO_ERROR_INVALID_STATE;
     }
     if (threadProc == nullptr) {
@@ -174,6 +175,7 @@ aaudio_result_t AudioStream::createThread(int64_t periodNanoseconds,
 aaudio_result_t AudioStream::joinThread(void** returnArg, int64_t timeoutNanoseconds)
 {
     if (!mHasThread) {
+        ALOGE("AudioStream::joinThread() - but has no thread");
         return AAUDIO_ERROR_INVALID_STATE;
     }
 #if 0

diff --git a/media/libaaudio/src/legacy/AudioStreamTrack.cpp b/media/libaaudio/src/legacy/AudioStreamTrack.cpp
index 525537f..51440d6 100644 (file)
--- a/media/libaaudio/src/legacy/AudioStreamTrack.cpp
+++ b/media/libaaudio/src/legacy/AudioStreamTrack.cpp
@@ -230,6 +230,7 @@ aaudio_result_t AudioStreamTrack::requestStart()
     std::lock_guard<std::mutex> lock(mStreamMutex);
 
     if (mAudioTrack.get() == nullptr) {
+        ALOGE("AudioStreamTrack::requestStart() no AudioTrack");
         return AAUDIO_ERROR_INVALID_STATE;
     }
     // Get current position so we can detect when the track is playing.
@@ -253,6 +254,7 @@ aaudio_result_t AudioStreamTrack::requestPause()
     std::lock_guard<std::mutex> lock(mStreamMutex);
 
     if (mAudioTrack.get() == nullptr) {
+        ALOGE("AudioStreamTrack::requestPause() no AudioTrack");
         return AAUDIO_ERROR_INVALID_STATE;
     } else if (getState() != AAUDIO_STREAM_STATE_STARTING
             && getState() != AAUDIO_STREAM_STATE_STARTED) {
@@ -274,8 +276,10 @@ aaudio_result_t AudioStreamTrack::requestFlush() {
     std::lock_guard<std::mutex> lock(mStreamMutex);
 
     if (mAudioTrack.get() == nullptr) {
+        ALOGE("AudioStreamTrack::requestFlush() no AudioTrack");
         return AAUDIO_ERROR_INVALID_STATE;
     } else if (getState() != AAUDIO_STREAM_STATE_PAUSED) {
+        ALOGE("AudioStreamTrack::requestFlush() not paused");
         return AAUDIO_ERROR_INVALID_STATE;
     }
     setState(AAUDIO_STREAM_STATE_FLUSHING);
@@ -289,6 +293,7 @@ aaudio_result_t AudioStreamTrack::requestStop() {
     std::lock_guard<std::mutex> lock(mStreamMutex);
 
     if (mAudioTrack.get() == nullptr) {
+        ALOGE("AudioStreamTrack::requestStop() no AudioTrack");
         return AAUDIO_ERROR_INVALID_STATE;
     }
     onStop();

diff --git a/services/oboeservice/AAudioServiceEndpoint.cpp b/services/oboeservice/AAudioServiceEndpoint.cpp
index 6c345cd..81f1d1b 100644 (file)
--- a/services/oboeservice/AAudioServiceEndpoint.cpp
+++ b/services/oboeservice/AAudioServiceEndpoint.cpp
@@ -64,8 +64,9 @@ std::string AAudioServiceEndpoint::dump() const {
     }
 
     result << "    Registered Streams:" << "\n";
+    result << AAudioServiceStreamShared::dumpHeader() << "\n";
     for (sp<AAudioServiceStreamShared> sharedStream : mRegisteredStreams) {
-        result << sharedStream->dump();
+        result << sharedStream->dump() << "\n";
     }
 
     if (isLocked) {

diff --git a/services/oboeservice/AAudioServiceEndpointPlay.cpp b/services/oboeservice/AAudioServiceEndpointPlay.cpp
index 20cc5b8..8b1cc9f 100644 (file)
--- a/services/oboeservice/AAudioServiceEndpointPlay.cpp
+++ b/services/oboeservice/AAudioServiceEndpointPlay.cpp
@@ -65,7 +65,6 @@ aaudio_result_t AAudioServiceEndpointPlay::open(const AAudioStreamConfiguration&
 
 // Mix data from each application stream and write result to the shared MMAP stream.
 void *AAudioServiceEndpointPlay::callbackLoop() {
-    int32_t underflowCount = 0;
     aaudio_result_t result = AAUDIO_OK;
     int64_t timeoutNanos = getStreamInternal()->calculateReasonableTimeout();
 
@@ -90,14 +89,16 @@ void *AAudioServiceEndpointPlay::callbackLoop() {
 
                     float volume = 1.0; // to match legacy volume
                     bool underflowed = mMixer.mix(index, fifo, volume);
-                    underflowCount += underflowed ? 1 : 0;
-                    // TODO log underflows in each stream
 
                     // This timestamp represents the completion of data being read out of the
                     // client buffer. It is sent to the client and used in the timing model
                     // to decide when the client has room to write more data.
                     Timestamp timestamp(fifo->getReadCounter(), AudioClock::getNanoseconds());
                     clientStream->markTransferTime(timestamp);
+
+                    if (underflowed) {
+                        clientStream->incrementXRunCount();
+                    }
                 }
                 index++;
             }
@@ -116,8 +117,5 @@ void *AAudioServiceEndpointPlay::callbackLoop() {
         }
     }
 
-    ALOGW_IF((underflowCount > 0),
-             "AAudioServiceEndpointPlay(): callbackLoop() had %d underflows", underflowCount);
-
     return NULL; // TODO review
 }

diff --git a/services/oboeservice/AAudioServiceStreamBase.cpp b/services/oboeservice/AAudioServiceStreamBase.cpp
index 3fc5957..e5f916c 100644 (file)
--- a/services/oboeservice/AAudioServiceStreamBase.cpp
+++ b/services/oboeservice/AAudioServiceStreamBase.cpp
@@ -18,6 +18,8 @@
 //#define LOG_NDEBUG 0
 #include <utils/Log.h>
 
+#include <iomanip>
+#include <iostream>
 #include <mutex>
 
 #include "binding/IAAudioService.h"
@@ -54,16 +56,22 @@ AAudioServiceStreamBase::~AAudioServiceStreamBase() {
                         "service stream still open, state = %d", mState);
 }
 
+std::string AAudioServiceStreamBase::dumpHeader() {
+    return std::string("    T   Handle   UId Run State Format Burst Chan Capacity");
+}
+
 std::string AAudioServiceStreamBase::dump() const {
     std::stringstream result;
 
-    result << "      -------- handle = 0x" << std::hex << mHandle << std::dec << "\n";
-    result << "      state          = " << AAudio_convertStreamStateToText(mState) << "\n";
-    result << "      format         = " << mAudioFormat << "\n";
-    result << "      framesPerBurst = " << mFramesPerBurst << "\n";
-    result << "      channelCount   = " << mSamplesPerFrame << "\n";
-    result << "      capacityFrames = " << mCapacityInFrames << "\n";
-    result << "      owner uid      = " << mMmapClient.clientUid << "\n";
+    result << "    0x" << std::setfill('0') << std::setw(8) << std::hex << mHandle
+           << std::dec << std::setfill(' ') ;
+    result << std::setw(6) << mMmapClient.clientUid;
+    result << std::setw(4) << (isRunning() ? "yes" : " no");
+    result << std::setw(6) << mState;
+    result << std::setw(7) << mAudioFormat;
+    result << std::setw(6) << mFramesPerBurst;
+    result << std::setw(5) << mSamplesPerFrame;
+    result << std::setw(9) << mCapacityInFrames;
 
     return result.str();
 }

diff --git a/services/oboeservice/AAudioServiceStreamBase.h b/services/oboeservice/AAudioServiceStreamBase.h
index e91ea82..2f94614 100644 (file)
--- a/services/oboeservice/AAudioServiceStreamBase.h
+++ b/services/oboeservice/AAudioServiceStreamBase.h
@@ -54,7 +54,10 @@ public:
         ILLEGAL_THREAD_ID = 0
     };
 
-    std::string dump() const;
+    static std::string dumpHeader();
+
+    // does not include EOL
+    virtual std::string dump() const;
 
     // -------------------------------------------------------------------
     /**

diff --git a/services/oboeservice/AAudioServiceStreamShared.cpp b/services/oboeservice/AAudioServiceStreamShared.cpp
index 07c4faf..d648c6d 100644 (file)
--- a/services/oboeservice/AAudioServiceStreamShared.cpp
+++ b/services/oboeservice/AAudioServiceStreamShared.cpp
@@ -18,6 +18,8 @@
 //#define LOG_NDEBUG 0
 #include <utils/Log.h>
 
+#include <iomanip>
+#include <iostream>
 #include <mutex>
 
 #include <aaudio/AAudio.h>
@@ -42,9 +44,32 @@ using namespace aaudio;
 AAudioServiceStreamShared::AAudioServiceStreamShared(AAudioService &audioService)
     : mAudioService(audioService)
     , mTimestampPositionOffset(0)
+    , mXRunCount(0)
     {
 }
 
+std::string AAudioServiceStreamShared::dumpHeader() {
+    std::stringstream result;
+    result << AAudioServiceStreamBase::dumpHeader();
+    result << "    Write#     Read#   Avail   XRuns";
+    return result.str();
+}
+
+std::string AAudioServiceStreamShared::dump() const {
+    std::stringstream result;
+    result << AAudioServiceStreamBase::dump();
+
+    auto fifo = mAudioDataQueue->getFifoBuffer();
+    int32_t readCounter = fifo->getReadCounter();
+    int32_t writeCounter = fifo->getWriteCounter();
+    result << std::setw(10) << writeCounter;
+    result << std::setw(10) << readCounter;
+    result << std::setw(8) << (writeCounter - readCounter);
+    result << std::setw(8) << getXRunCount();
+
+    return result.str();
+}
+
 int32_t AAudioServiceStreamShared::calculateBufferCapacity(int32_t requestedCapacityFrames,
                                                            int32_t framesPerBurst) {
 
@@ -197,6 +222,7 @@ aaudio_result_t AAudioServiceStreamShared::start()  {
     }
     AAudioServiceEndpoint *endpoint = mServiceEndpoint;
     if (endpoint == nullptr) {
+        ALOGE("AAudioServiceStreamShared::start() missing endpoint");
         return AAUDIO_ERROR_INVALID_STATE;
     }
     // For output streams, this will add the stream to the mixer.
@@ -224,6 +250,7 @@ aaudio_result_t AAudioServiceStreamShared::pause()  {
     }
     AAudioServiceEndpoint *endpoint = mServiceEndpoint;
     if (endpoint == nullptr) {
+        ALOGE("AAudioServiceStreamShared::pause() missing endpoint");
         return AAUDIO_ERROR_INVALID_STATE;
     }
     endpoint->getStreamInternal()->stopClient(mClientHandle);
@@ -241,6 +268,7 @@ aaudio_result_t AAudioServiceStreamShared::stop()  {
     }
     AAudioServiceEndpoint *endpoint = mServiceEndpoint;
     if (endpoint == nullptr) {
+        ALOGE("AAudioServiceStreamShared::stop() missing endpoint");
         return AAUDIO_ERROR_INVALID_STATE;
     }
     endpoint->getStreamInternal()->stopClient(mClientHandle);
@@ -260,6 +288,7 @@ aaudio_result_t AAudioServiceStreamShared::stop()  {
 aaudio_result_t AAudioServiceStreamShared::flush()  {
     AAudioServiceEndpoint *endpoint = mServiceEndpoint;
     if (endpoint == nullptr) {
+        ALOGE("AAudioServiceStreamShared::flush() missing endpoint");
         return AAUDIO_ERROR_INVALID_STATE;
     }
     if (mState != AAUDIO_STREAM_STATE_PAUSED) {

diff --git a/services/oboeservice/AAudioServiceStreamShared.h b/services/oboeservice/AAudioServiceStreamShared.h
index 8caccda..36a56b8 100644 (file)
--- a/services/oboeservice/AAudioServiceStreamShared.h
+++ b/services/oboeservice/AAudioServiceStreamShared.h
@@ -46,6 +46,10 @@ public:
     AAudioServiceStreamShared(android::AAudioService &aAudioService);
     virtual ~AAudioServiceStreamShared() = default;
 
+    static std::string dumpHeader();
+
+    std::string dump() const override;
+
     aaudio_result_t open(const aaudio::AAudioStreamRequest &request,
                          aaudio::AAudioStreamConfiguration &configurationOutput) override;
 
@@ -91,6 +95,14 @@ public:
         mTimestampPositionOffset.store(deltaFrames);
     }
 
+    void incrementXRunCount() {
+        mXRunCount++;
+    }
+
+    int32_t getXRunCount() const {
+        return mXRunCount.load();
+    }
+
 protected:
 
     aaudio_result_t getDownDataDescription(AudioEndpointParcelable &parcelable) override;
@@ -114,6 +126,7 @@ private:
     SharedRingBuffer        *mAudioDataQueue = nullptr;
 
     std::atomic<int64_t>     mTimestampPositionOffset;
+    std::atomic<int32_t>     mXRunCount;
 };
 
 } /* namespace aaudio */

diff --git a/services/oboeservice/AAudioThread.cpp b/services/oboeservice/AAudioThread.cpp
index ebb50f8..c6fb57d 100644 (file)
--- a/services/oboeservice/AAudioThread.cpp
+++ b/services/oboeservice/AAudioThread.cpp
@@ -53,7 +53,7 @@ static void * AAudioThread_internalThreadProc(void *arg) {
 
 aaudio_result_t AAudioThread::start(Runnable *runnable) {
     if (mHasThread) {
-        ALOGE("AAudioThread::start() - mHasThread.load() already true");
+        ALOGE("AAudioThread::start() - mHasThread already true");
         return AAUDIO_ERROR_INVALID_STATE;
     }
     // mRunnable will be read by the new thread when it starts.
@@ -71,6 +71,7 @@ aaudio_result_t AAudioThread::start(Runnable *runnable) {
 
 aaudio_result_t AAudioThread::stop() {
     if (!mHasThread) {
+        ALOGE("AAudioThread::stop() but no thread running");
         return AAUDIO_ERROR_INVALID_STATE;
     }
     int err = pthread_join(mThread, nullptr);