aaudio: reduce logspam, improve critical logs
This will make AAudio less annoying and easier to debug.
Bug: 62080950
Test: look in logcat
Change-Id: Id7ae26a212f83ea8be0b285bd20334eb48607be8
Signed-off-by: Phil Burk <philburk@google.com>
diff --git a/media/libaaudio/src/client/AudioStreamInternal.cpp b/media/libaaudio/src/client/AudioStreamInternal.cpp
index 701f698..ca36e1a 100644
--- a/media/libaaudio/src/client/AudioStreamInternal.cpp
+++ b/media/libaaudio/src/client/AudioStreamInternal.cpp
@@ -14,7 +14,9 @@
* limitations under the License.
*/
-#define LOG_TAG "AAudio"
+// This file is used in both client and server processes.
+// This is needed to make sense of the logs more easily.
+#define LOG_TAG (mInService ? "AAudioService" : "AAudio")
//#define LOG_NDEBUG 0
#include <utils/Log.h>
@@ -52,11 +54,6 @@
// Wait at least this many times longer than the operation should take.
#define MIN_TIMEOUT_OPERATIONS 4
-//static int64_t s_logCounter = 0;
-//#define MYLOG_CONDITION (mInService == true && s_logCounter++ < 500)
-//#define MYLOG_CONDITION (s_logCounter++ < 500000)
-#define MYLOG_CONDITION (1)
-
#define LOG_TIMESTAMPS 0
AudioStreamInternal::AudioStreamInternal(AAudioServiceInterface &serviceInterface, bool inService)
@@ -106,7 +103,7 @@
mServiceStreamHandle = mServiceInterface.openStream(request, configuration);
if (mServiceStreamHandle < 0) {
result = mServiceStreamHandle;
- ALOGE("AudioStreamInternal.open(): %s openStream() returned %d", getLocationName(), result);
+ ALOGE("AudioStreamInternal.open(): openStream() returned %d", result);
} else {
result = configuration.validate();
if (result != AAUDIO_OK) {
@@ -123,8 +120,6 @@
result = mServiceInterface.getStreamDescription(mServiceStreamHandle, mEndPointParcelable);
if (result != AAUDIO_OK) {
- ALOGE("AudioStreamInternal.open(): %s getStreamDescriptor returns %d",
- getLocationName(), result);
mServiceInterface.closeStream(mServiceStreamHandle);
return result;
}
@@ -132,7 +127,6 @@
// resolve parcelable into a descriptor
result = mEndPointParcelable.resolve(&mEndpointDescriptor);
if (result != AAUDIO_OK) {
- ALOGE("AudioStreamInternal.open(): resolve() returns %d", result);
mServiceInterface.closeStream(mServiceStreamHandle);
return result;
}
@@ -143,8 +137,6 @@
mFramesPerBurst = mEndpointDescriptor.dataQueueDescriptor.framesPerBurst;
int32_t capacity = mEndpointDescriptor.dataQueueDescriptor.capacityInFrames;
- ALOGD_IF(MYLOG_CONDITION, "AudioStreamInternal.open() %s framesPerBurst = %d, capacity = %d",
- getLocationName(), mFramesPerBurst, capacity);
// Validate result from server.
if (mFramesPerBurst < 16 || mFramesPerBurst > 16 * 1024) {
ALOGE("AudioStream::open(): framesPerBurst out of range = %d", mFramesPerBurst);
@@ -188,7 +180,7 @@
}
aaudio_result_t AudioStreamInternal::close() {
- ALOGD_IF(MYLOG_CONDITION, "AudioStreamInternal.close(): mServiceStreamHandle = 0x%08X",
+ ALOGD("AudioStreamInternal.close(): mServiceStreamHandle = 0x%08X",
mServiceStreamHandle);
if (mServiceStreamHandle != AAUDIO_HANDLE_INVALID) {
// Don't close a stream while it is running.
@@ -231,7 +223,7 @@
aaudio_result_t AudioStreamInternal::requestStart()
{
int64_t startTime;
- ALOGD_IF(MYLOG_CONDITION, "AudioStreamInternal(): start()");
+ ALOGD("AudioStreamInternal(): start()");
if (mServiceStreamHandle == AAUDIO_HANDLE_INVALID) {
return AAUDIO_ERROR_INVALID_STATE;
}
@@ -294,18 +286,15 @@
aaudio_result_t AudioStreamInternal::requestPause()
{
- ALOGD_IF(MYLOG_CONDITION, "AudioStreamInternal(): %s requestPause()", getLocationName());
aaudio_result_t result = stopCallback();
if (result != AAUDIO_OK) {
return result;
}
result = requestPauseInternal();
- ALOGD("AudioStreamInternal(): requestPause() returns %d", result);
return result;
}
aaudio_result_t AudioStreamInternal::requestFlush() {
- ALOGD_IF(MYLOG_CONDITION, "AudioStreamInternal(): requestFlush()");
if (mServiceStreamHandle == AAUDIO_HANDLE_INVALID) {
ALOGE("AudioStreamInternal(): requestFlush() mServiceStreamHandle invalid = 0x%08X",
mServiceStreamHandle);
@@ -318,7 +307,7 @@
// TODO for Play only
void AudioStreamInternal::onFlushFromServer() {
- ALOGD_IF(MYLOG_CONDITION, "AudioStreamInternal(): onFlushFromServer()");
+ ALOGD("AudioStreamInternal(): onFlushFromServer()");
int64_t readCounter = mAudioEndpoint.getDataReadCounter();
int64_t writeCounter = mAudioEndpoint.getDataWriteCounter();
@@ -346,13 +335,11 @@
aaudio_result_t AudioStreamInternal::requestStop()
{
- ALOGD_IF(MYLOG_CONDITION, "AudioStreamInternal(): %s requestStop()", getLocationName());
aaudio_result_t result = stopCallback();
if (result != AAUDIO_OK) {
return result;
}
result = requestStopInternal();
- ALOGD("AudioStreamInternal(): requestStop() returns %d", result);
return result;
}
@@ -397,16 +384,16 @@
static int64_t oldTime = 0;
int64_t framePosition = command.timestamp.position;
int64_t nanoTime = command.timestamp.timestamp;
- ALOGD_IF(MYLOG_CONDITION, "AudioStreamInternal() timestamp says framePosition = %08lld at nanoTime %llu",
+ ALOGD("AudioStreamInternal() timestamp says framePosition = %08lld at nanoTime %lld",
(long long) framePosition,
(long long) nanoTime);
int64_t nanosDelta = nanoTime - oldTime;
if (nanosDelta > 0 && oldTime > 0) {
int64_t framesDelta = framePosition - oldPosition;
int64_t rate = (framesDelta * AAUDIO_NANOS_PER_SECOND) / nanosDelta;
- ALOGD_IF(MYLOG_CONDITION, "AudioStreamInternal() - framesDelta = %08lld", (long long) framesDelta);
- ALOGD_IF(MYLOG_CONDITION, "AudioStreamInternal() - nanosDelta = %08lld", (long long) nanosDelta);
- ALOGD_IF(MYLOG_CONDITION, "AudioStreamInternal() - measured rate = %llu", (unsigned long long) rate);
+ ALOGD("AudioStreamInternal() - framesDelta = %08lld", (long long) framesDelta);
+ ALOGD("AudioStreamInternal() - nanosDelta = %08lld", (long long) nanosDelta);
+ ALOGD("AudioStreamInternal() - measured rate = %lld", (long long) rate);
}
oldPosition = framePosition;
oldTime = nanoTime;
@@ -423,35 +410,34 @@
aaudio_result_t AudioStreamInternal::onEventFromServer(AAudioServiceMessage *message) {
aaudio_result_t result = AAUDIO_OK;
- ALOGD_IF(MYLOG_CONDITION, "processCommands() got event %d", message->event.event);
switch (message->event.event) {
case AAUDIO_SERVICE_EVENT_STARTED:
- ALOGD_IF(MYLOG_CONDITION, "processCommands() got AAUDIO_SERVICE_EVENT_STARTED");
+ ALOGD("processCommands() got AAUDIO_SERVICE_EVENT_STARTED");
if (getState() == AAUDIO_STREAM_STATE_STARTING) {
setState(AAUDIO_STREAM_STATE_STARTED);
}
break;
case AAUDIO_SERVICE_EVENT_PAUSED:
- ALOGD_IF(MYLOG_CONDITION, "processCommands() got AAUDIO_SERVICE_EVENT_PAUSED");
+ ALOGD("processCommands() got AAUDIO_SERVICE_EVENT_PAUSED");
if (getState() == AAUDIO_STREAM_STATE_PAUSING) {
setState(AAUDIO_STREAM_STATE_PAUSED);
}
break;
case AAUDIO_SERVICE_EVENT_STOPPED:
- ALOGD_IF(MYLOG_CONDITION, "processCommands() got AAUDIO_SERVICE_EVENT_STOPPED");
+ ALOGD("processCommands() got AAUDIO_SERVICE_EVENT_STOPPED");
if (getState() == AAUDIO_STREAM_STATE_STOPPING) {
setState(AAUDIO_STREAM_STATE_STOPPED);
}
break;
case AAUDIO_SERVICE_EVENT_FLUSHED:
- ALOGD_IF(MYLOG_CONDITION, "processCommands() got AAUDIO_SERVICE_EVENT_FLUSHED");
+ ALOGD("processCommands() got AAUDIO_SERVICE_EVENT_FLUSHED");
if (getState() == AAUDIO_STREAM_STATE_FLUSHING) {
setState(AAUDIO_STREAM_STATE_FLUSHED);
onFlushFromServer();
}
break;
case AAUDIO_SERVICE_EVENT_CLOSED:
- ALOGD_IF(MYLOG_CONDITION, "processCommands() got AAUDIO_SERVICE_EVENT_CLOSED");
+ ALOGD("processCommands() got AAUDIO_SERVICE_EVENT_CLOSED");
setState(AAUDIO_STREAM_STATE_CLOSED);
break;
case AAUDIO_SERVICE_EVENT_DISCONNECTED:
@@ -461,7 +447,7 @@
break;
case AAUDIO_SERVICE_EVENT_VOLUME:
mVolumeRamp.setTarget((float) message->event.dataDouble);
- ALOGD_IF(MYLOG_CONDITION, "processCommands() AAUDIO_SERVICE_EVENT_VOLUME %f",
+ ALOGD("processCommands() AAUDIO_SERVICE_EVENT_VOLUME %lf",
message->event.dataDouble);
break;
default:
@@ -477,7 +463,7 @@
aaudio_result_t result = AAUDIO_OK;
while (result == AAUDIO_OK) {
- //ALOGD_IF(MYLOG_CONDITION, "AudioStreamInternal::processCommands() - looping, %d", result);
+ //ALOGD("AudioStreamInternal::processCommands() - looping, %d", result);
AAudioServiceMessage message;
if (mAudioEndpoint.readUpCommand(&message) != 1) {
break; // no command this time, no problem
@@ -544,19 +530,17 @@
}
if (wakeTimeNanos > deadlineNanos) {
// If we time out, just return the framesWritten so far.
+ // TODO remove after we fix the deadline bug
ALOGE("AudioStreamInternal::processData(): timed out after %lld nanos",
(long long) timeoutNanoseconds);
ALOGE("AudioStreamInternal::processData(): wakeTime = %lld, deadline = %lld nanos",
(long long) wakeTimeNanos, (long long) deadlineNanos);
ALOGE("AudioStreamInternal::processData(): past deadline by %d micros",
(int)((wakeTimeNanos - deadlineNanos) / AAUDIO_NANOS_PER_MICROSECOND));
-
break;
}
int64_t sleepForNanos = wakeTimeNanos - currentTimeNanos;
- //ALOGE("AudioStreamInternal::processData(): sleep for %d micros",
- // (int)(sleepForNanos / AAUDIO_NANOS_PER_MICROSECOND));
AudioClock::sleepForNanos(sleepForNanos);
currentTimeNanos = AudioClock::getNanoseconds();
}
@@ -581,8 +565,7 @@
}
aaudio_result_t result = mAudioEndpoint.setBufferSizeInFrames(requestedFrames, &actualFrames);
- ALOGD_IF(MYLOG_CONDITION, "AudioStreamInternal::setBufferSize() %s req = %d => %d",
- getLocationName(), requestedFrames, actualFrames);
+ ALOGD("AudioStreamInternal::setBufferSize() req = %d => %d", requestedFrames, actualFrames);
if (result < 0) {
return result;
} else {
diff --git a/media/libaaudio/src/client/AudioStreamInternal.h b/media/libaaudio/src/client/AudioStreamInternal.h
index 377f9c7..fe4431c 100644
--- a/media/libaaudio/src/client/AudioStreamInternal.h
+++ b/media/libaaudio/src/client/AudioStreamInternal.h
@@ -155,10 +155,6 @@
// Adjust timing model based on timestamp from service.
void processTimestamp(uint64_t position, int64_t time);
- const char *getLocationName() const {
- return mInService ? "SERVICE" : "CLIENT";
- }
-
AudioEndpointParcelable mEndPointParcelable; // description of the buffers filled by service
EndpointDescriptor mEndpointDescriptor; // buffer description with resolved addresses
AAudioServiceInterface &mServiceInterface; // abstract interface to the service
diff --git a/media/libaaudio/src/core/AAudioAudio.cpp b/media/libaaudio/src/core/AAudioAudio.cpp
index 471935e..c644ee5 100644
--- a/media/libaaudio/src/core/AAudioAudio.cpp
+++ b/media/libaaudio/src/core/AAudioAudio.cpp
@@ -206,11 +206,12 @@
AAudioStream** streamPtr)
{
AudioStream *audioStream = nullptr;
- ALOGD("AAudioStreamBuilder_openStream() ----------------------------------------------");
+ // Please leave these logs because they are very helpful when debugging.
+ ALOGD("AAudioStreamBuilder_openStream() called ----------------------------------------");
AudioStreamBuilder *streamBuilder = COMMON_GET_FROM_BUILDER_OR_RETURN(streamPtr);
aaudio_result_t result = streamBuilder->build(&audioStream);
- ALOGD("AAudioStreamBuilder_openStream() returns %d -----------------------------------",
- result);
+ ALOGD("AAudioStreamBuilder_openStream() returns %d = %s for (%p) ----------------",
+ result, AAudio_convertResultToText(result), audioStream);
if (result == AAUDIO_OK) {
*streamPtr = (AAudioStream*) audioStream;
} else {
@@ -236,7 +237,6 @@
if (audioStream != nullptr) {
audioStream->close();
delete audioStream;
- ALOGD("AAudioStream_close() ----------------------------------------------");
return AAUDIO_OK;
}
return AAUDIO_ERROR_INVALID_HANDLE;
@@ -300,7 +300,6 @@
}
aaudio_result_t result = audioStream->read(buffer, numFrames, timeoutNanoseconds);
- // ALOGD("AAudioStream_read(): read returns %d", result);
return result;
}
@@ -328,7 +327,6 @@
}
aaudio_result_t result = audioStream->write(buffer, numFrames, timeoutNanoseconds);
- // ALOGD("AAudioStream_write(): write returns %d", result);
return result;
}
diff --git a/media/libaaudio/src/core/AudioStream.cpp b/media/libaaudio/src/core/AudioStream.cpp
index 66b64a6..03f1a5c 100644
--- a/media/libaaudio/src/core/AudioStream.cpp
+++ b/media/libaaudio/src/core/AudioStream.cpp
@@ -55,9 +55,12 @@
mDataCallbackUserData = builder.getDataCallbackUserData();
mErrorCallbackUserData = builder.getErrorCallbackUserData();
- // This is very helpful for debugging in the future.
- ALOGI("AudioStream.open(): rate = %d, channels = %d, format = %d, sharing = %d",
- mSampleRate, mSamplesPerFrame, mFormat, mSharingMode);
+ // This is very helpful for debugging in the future. Please leave it in.
+ ALOGI("AudioStream::open() rate = %d, channels = %d, format = %d, sharing = %d, dir = %s",
+ mSampleRate, mSamplesPerFrame, mFormat, mSharingMode,
+ (getDirection() == AAUDIO_DIRECTION_OUTPUT) ? "OUTPUT" : "INPUT");
+ ALOGI("AudioStream::open() device = %d, perfMode = %d, callbackFrames = %d",
+ mDeviceId, mPerformanceMode, mFramesPerDataCallback);
// Check for values that are ridiculously out of range to prevent math overflow exploits.
// The service will do a better check.
diff --git a/media/libaaudio/src/core/AudioStreamBuilder.cpp b/media/libaaudio/src/core/AudioStreamBuilder.cpp
index 06f2d70..e6d5d74 100644
--- a/media/libaaudio/src/core/AudioStreamBuilder.cpp
+++ b/media/libaaudio/src/core/AudioStreamBuilder.cpp
@@ -84,8 +84,6 @@
int32_t mmapEnabled = AAudioProperty_getMMapEnabled();
int32_t mmapExclusiveEnabled = AAudioProperty_getMMapExclusiveEnabled();
- ALOGD("AudioStreamBuilder(): mmapEnabled = %d, mmapExclusiveEnabled = %d",
- mmapEnabled, mmapExclusiveEnabled);
aaudio_sharing_mode_t sharingMode = getSharingMode();
if ((sharingMode == AAUDIO_SHARING_MODE_EXCLUSIVE)
@@ -127,6 +125,5 @@
}
}
- ALOGD("AudioStreamBuilder(): returned %d", result);
return result;
}
diff --git a/media/libaaudio/src/legacy/AudioStreamRecord.cpp b/media/libaaudio/src/legacy/AudioStreamRecord.cpp
index b3d01d6..7a5dcda 100644
--- a/media/libaaudio/src/legacy/AudioStreamRecord.cpp
+++ b/media/libaaudio/src/legacy/AudioStreamRecord.cpp
@@ -14,7 +14,7 @@
* limitations under the License.
*/
-#define LOG_TAG "AudioStreamRecord"
+#define LOG_TAG "AAudio"
//#define LOG_NDEBUG 0
#include <utils/Log.h>
@@ -95,6 +95,8 @@
}
mCallbackBufferSize = builder.getFramesPerDataCallback();
+ ALOGD("AudioStreamRecord::open(), request notificationFrames = %u, frameCount = %u",
+ notificationFrames, (uint)frameCount);
mAudioRecord = new AudioRecord(
AUDIO_SOURCE_VOICE_RECOGNITION,
getSampleRate(),
@@ -123,9 +125,14 @@
// Get the actual rate.
setSampleRate(mAudioRecord->getSampleRate());
- setSamplesPerFrame(mAudioRecord->channelCount());
setFormat(AAudioConvert_androidToAAudioDataFormat(mAudioRecord->format()));
+ int32_t actualSampleRate = mAudioRecord->getSampleRate();
+ ALOGW_IF(actualSampleRate != getSampleRate(),
+ "AudioStreamRecord::open() sampleRate changed from %d to %d",
+ getSampleRate(), actualSampleRate);
+ setSampleRate(actualSampleRate);
+
// We may need to pass the data through a block size adapter to guarantee constant size.
if (mCallbackBufferSize != AAUDIO_UNSPECIFIED) {
int callbackSizeBytes = getBytesPerFrame() * mCallbackBufferSize;
@@ -152,8 +159,6 @@
}
void AudioStreamRecord::processCallback(int event, void *info) {
-
- ALOGD("AudioStreamRecord::processCallback(), event %d", event);
switch (event) {
case AudioRecord::EVENT_MORE_DATA:
processCallbackCommon(AAUDIO_CALLBACK_OPERATION_PROCESS_DATA, info);
diff --git a/media/libaaudio/src/legacy/AudioStreamTrack.cpp b/media/libaaudio/src/legacy/AudioStreamTrack.cpp
index 9c433cd..e566332 100644
--- a/media/libaaudio/src/legacy/AudioStreamTrack.cpp
+++ b/media/libaaudio/src/legacy/AudioStreamTrack.cpp
@@ -14,7 +14,7 @@
* limitations under the License.
*/
-#define LOG_TAG "AudioStreamTrack"
+#define LOG_TAG "AAudio"
//#define LOG_NDEBUG 0
#include <utils/Log.h>
@@ -58,15 +58,11 @@
return result;
}
- ALOGD("AudioStreamTrack::open = %p", this);
-
// Try to create an AudioTrack
// Use stereo if unspecified.
int32_t samplesPerFrame = (getSamplesPerFrame() == AAUDIO_UNSPECIFIED)
? 2 : getSamplesPerFrame();
audio_channel_mask_t channelMask = audio_channel_out_mask_from_count(samplesPerFrame);
- ALOGD("AudioStreamTrack::open(), samplesPerFrame = %d, channelMask = 0x%08x",
- samplesPerFrame, channelMask);
audio_output_flags_t flags = AUDIO_OUTPUT_FLAG_NONE;
aaudio_performance_mode_t perfMode = getPerformanceMode();
@@ -87,8 +83,7 @@
break;
}
- int32_t frameCount = builder.getBufferCapacity();
- ALOGD("AudioStreamTrack::open(), requested buffer capacity %d", frameCount);
+ size_t frameCount = (size_t)builder.getBufferCapacity();
int32_t notificationFrames = 0;
@@ -118,7 +113,8 @@
}
mCallbackBufferSize = builder.getFramesPerDataCallback();
- ALOGD("AudioStreamTrack::open(), notificationFrames = %d", notificationFrames);
+ ALOGD("AudioStreamTrack::open(), request notificationFrames = %d, frameCount = %u",
+ notificationFrames, (uint)frameCount);
mAudioTrack = new AudioTrack(
(audio_stream_type_t) AUDIO_STREAM_MUSIC,
getSampleRate(),
@@ -135,7 +131,6 @@
// Did we get a valid track?
status_t status = mAudioTrack->initCheck();
- ALOGD("AudioStreamTrack::open(), initCheck() returned %d", status);
if (status != NO_ERROR) {
close();
ALOGE("AudioStreamTrack::open(), initCheck() returned %d", status);
@@ -144,11 +139,16 @@
// Get the actual values from the AudioTrack.
setSamplesPerFrame(mAudioTrack->channelCount());
- setSampleRate(mAudioTrack->getSampleRate());
aaudio_audio_format_t aaudioFormat =
AAudioConvert_androidToAAudioDataFormat(mAudioTrack->format());
setFormat(aaudioFormat);
+ int32_t actualSampleRate = mAudioTrack->getSampleRate();
+ ALOGW_IF(actualSampleRate != getSampleRate(),
+ "AudioStreamTrack::open() sampleRate changed from %d to %d",
+ getSampleRate(), actualSampleRate);
+ setSampleRate(actualSampleRate);
+
// We may need to pass the data through a block size adapter to guarantee constant size.
if (mCallbackBufferSize != AAUDIO_UNSPECIFIED) {
int callbackSizeBytes = getBytesPerFrame() * mCallbackBufferSize;