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/services/oboeservice/AAudioEndpointManager.cpp b/services/oboeservice/AAudioEndpointManager.cpp
index 7b8d817..11fd9f6 100644
--- a/services/oboeservice/AAudioEndpointManager.cpp
+++ b/services/oboeservice/AAudioEndpointManager.cpp
@@ -201,14 +201,14 @@
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 @@
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 @@
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 c708fee..ad5bb3a 100644
--- a/services/oboeservice/AAudioService.cpp
+++ b/services/oboeservice/AAudioService.cpp
@@ -165,7 +165,6 @@
}
aaudio_result_t AAudioService::closeStream(aaudio_handle_t streamHandle) {
- ALOGD("closeStream(0x%08X)", streamHandle);
// Check permission and ownership first.
sp<AAudioServiceStreamBase> serviceStream = convertHandleToServiceStream(streamHandle);
if (serviceStream.get() == nullptr) {
diff --git a/services/oboeservice/AAudioServiceEndpoint.cpp b/services/oboeservice/AAudioServiceEndpoint.cpp
index 33439fc..96e621a 100644
--- a/services/oboeservice/AAudioServiceEndpoint.cpp
+++ b/services/oboeservice/AAudioServiceEndpoint.cpp
@@ -39,7 +39,7 @@
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 db01c88..52990da 100644
--- a/services/oboeservice/AAudioServiceEndpointMMAP.cpp
+++ b/services/oboeservice/AAudioServiceEndpointMMAP.cpp
@@ -98,8 +98,8 @@
.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 @@
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 @@
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_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 @@
}
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 @@
// 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 @@
// 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 @@
burstMicros = mFramesPerBurst * static_cast<int64_t>(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 @@
}
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::startClient(const android::AudioClient& client,
audio_port_handle_t *clientHandle) {
if (mMmapStream == nullptr) return AAUDIO_ERROR_NULL;
- ALOGD("startClient(%p(uid=%d, pid=%d))",
- &client, client.clientUid, client.clientPid);
+ ALOGV("%s(%p(uid=%d, pid=%d))", __func__, &client, client.clientUid, client.clientPid);
audio_port_handle_t originalHandle = *clientHandle;
status_t status = mMmapStream->start(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 @@
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 @@
void AAudioServiceEndpointMMAP::onTearDown() {
- ALOGD("onTearDown() called");
+ ALOGD("%s(%p) called", __func__, this);
disconnectRegisteredStreams();
};
void AAudioServiceEndpointMMAP::onVolumeChanged(audio_channel_mask_t channels,
android::Vector<float> 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<std::mutex> lock(mLockStreams);
for(const auto stream : mRegisteredStreams) {
stream->onVolumeChanged(volume);
@@ -363,8 +361,7 @@
};
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 2601f3f..a274466 100644
--- a/services/oboeservice/AAudioServiceEndpointPlay.cpp
+++ b/services/oboeservice/AAudioServiceEndpointPlay.cpp
@@ -43,10 +43,12 @@
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 @@
// 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 @@
}
}
+ 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 74cd817..227250c 100644
--- a/services/oboeservice/AAudioServiceEndpointShared.h
+++ b/services/oboeservice/AAudioServiceEndpointShared.h
@@ -54,12 +54,13 @@
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 e8c9e41..18f14ee 100644
--- a/services/oboeservice/AAudioServiceStreamBase.cpp
+++ b/services/oboeservice/AAudioServiceStreamBase.cpp
@@ -93,7 +93,7 @@
{
std::lock_guard<std::mutex> lock(mUpMessageQueueLock);
if (mUpMessageQueue != nullptr) {
- ALOGE("open() called twice");
+ ALOGE("%s() called twice", __func__);
return AAUDIO_ERROR_INVALID_STATE;
}
@@ -108,7 +108,7 @@
request,
sharingMode);
if (mServiceEndpoint == nullptr) {
- ALOGE("open() openEndpoint() failed");
+ ALOGE("%s() openEndpoint() failed", __func__);
result = AAUDIO_ERROR_UNAVAILABLE;
goto error;
}
@@ -167,7 +167,7 @@
}
if (mServiceEndpoint == nullptr) {
- ALOGE("start() missing endpoint");
+ ALOGE("%s() missing endpoint", __func__);
result = AAUDIO_ERROR_INVALID_STATE;
goto error;
}
@@ -201,7 +201,7 @@
return result;
}
if (mServiceEndpoint == nullptr) {
- ALOGE("pause() missing endpoint");
+ ALOGE("%s() missing endpoint", __func__);
return AAUDIO_ERROR_INVALID_STATE;
}
@@ -217,7 +217,7 @@
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 @@
}
if (mServiceEndpoint == nullptr) {
- ALOGE("stop() missing endpoint");
+ ALOGE("%s() missing endpoint", __func__);
return AAUDIO_ERROR_INVALID_STATE;
}
@@ -251,7 +251,7 @@
// 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 @@
// 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 @@
AudioClock::sleepUntilNanoTime(nextTime);
}
}
- ALOGD("run() exiting ----------------");
+ ALOGD("%s() %s exiting <<<<<<<<<<<<<< TIMESTAMPS", __func__, getTypeText());
}
void AAudioServiceStreamBase::disconnect() {
@@ -333,12 +333,12 @@
aaudio_result_t AAudioServiceStreamBase::writeUpMessageQueue(AAudioServiceMessage *command) {
std::lock_guard<std::mutex> 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 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 @@
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 @@
{
std::lock_guard<std::mutex> 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 5f5bb98..3720596 100644
--- a/services/oboeservice/AAudioServiceStreamBase.h
+++ b/services/oboeservice/AAudioServiceStreamBase.h
@@ -55,7 +55,7 @@
, public Runnable {
public:
- AAudioServiceStreamBase(android::AAudioService &aAudioService);
+ explicit AAudioServiceStreamBase(android::AAudioService &aAudioService);
virtual ~AAudioServiceStreamBase();
@@ -219,6 +219,8 @@
mCloseNeeded.store(needed);
}
+ virtual const char *getTypeText() const { return "Base"; }
+
protected:
/**
diff --git a/services/oboeservice/AAudioServiceStreamMMAP.h b/services/oboeservice/AAudioServiceStreamMMAP.h
index e2415d0..1509f7d 100644
--- a/services/oboeservice/AAudioServiceStreamMMAP.h
+++ b/services/oboeservice/AAudioServiceStreamMMAP.h
@@ -69,9 +69,7 @@
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 3b12e61..61769b5 100644
--- a/services/oboeservice/AAudioServiceStreamShared.h
+++ b/services/oboeservice/AAudioServiceStreamShared.h
@@ -43,7 +43,7 @@
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 @@
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 ffc9b7b..dcce68a 100644
--- a/services/oboeservice/AAudioThread.h
+++ b/services/oboeservice/AAudioThread.h
@@ -44,7 +44,7 @@
public:
AAudioThread();
- AAudioThread(const char *prefix);
+ explicit AAudioThread(const char *prefix);
virtual ~AAudioThread() = default;