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
--- 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 @@
* 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
--- a/media/libaaudio/src/client/AudioStreamInternal.cpp
+++ b/media/libaaudio/src/client/AudioStreamInternal.cpp
@@ -241,9 +241,11 @@
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::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::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 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
--- a/media/libaaudio/src/core/AAudioAudio.cpp
+++ b/media/libaaudio/src/core/AAudioAudio.cpp
@@ -248,7 +248,7 @@
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
--- a/media/libaaudio/src/core/AudioStream.cpp
+++ b/media/libaaudio/src/core/AudioStream.cpp
@@ -153,6 +153,7 @@
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::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
--- a/media/libaaudio/src/legacy/AudioStreamTrack.cpp
+++ b/media/libaaudio/src/legacy/AudioStreamTrack.cpp
@@ -230,6 +230,7 @@
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 @@
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 @@
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 @@
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
--- a/services/oboeservice/AAudioServiceEndpoint.cpp
+++ b/services/oboeservice/AAudioServiceEndpoint.cpp
@@ -64,8 +64,9 @@
}
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
--- a/services/oboeservice/AAudioServiceEndpointPlay.cpp
+++ b/services/oboeservice/AAudioServiceEndpointPlay.cpp
@@ -65,7 +65,6 @@
// 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 @@
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 @@
}
}
- 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
--- 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 @@
"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
--- a/services/oboeservice/AAudioServiceStreamBase.h
+++ b/services/oboeservice/AAudioServiceStreamBase.h
@@ -54,7 +54,10 @@
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
--- 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 @@
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 @@
}
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 @@
}
AAudioServiceEndpoint *endpoint = mServiceEndpoint;
if (endpoint == nullptr) {
+ ALOGE("AAudioServiceStreamShared::pause() missing endpoint");
return AAUDIO_ERROR_INVALID_STATE;
}
endpoint->getStreamInternal()->stopClient(mClientHandle);
@@ -241,6 +268,7 @@
}
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::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
--- a/services/oboeservice/AAudioServiceStreamShared.h
+++ b/services/oboeservice/AAudioServiceStreamShared.h
@@ -46,6 +46,10 @@
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 @@
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 @@
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
--- a/services/oboeservice/AAudioThread.cpp
+++ b/services/oboeservice/AAudioThread.cpp
@@ -53,7 +53,7 @@
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::stop() {
if (!mHasThread) {
+ ALOGE("AAudioThread::stop() but no thread running");
return AAUDIO_ERROR_INVALID_STATE;
}
int err = pthread_join(mThread, nullptr);