Merge "aaudio: reduce logspam, improve critical logs" into oc-dev (d08f04f3) · Commits · e / os / android_frameworks_av

media/libaaudio/src/client/AudioStreamInternal.cpp

+20 −37

Original line number	Diff line number	Diff line
		@@ -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 @@ using namespace aaudio;
		// 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 @@ aaudio_result_t AudioStreamInternal::open(const AudioStreamBuilder &builder) {
		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 @@ aaudio_result_t AudioStreamInternal::open(const AudioStreamBuilder &builder) {

		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 @@ aaudio_result_t AudioStreamInternal::open(const AudioStreamBuilder &builder) {
		// 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 @@ aaudio_result_t AudioStreamInternal::open(const AudioStreamBuilder &builder) {
		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::open(const AudioStreamBuilder &builder) {
		}

		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 @@ static void aaudio_callback_thread_proc(void context)
		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::requestPauseInternal()

		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 @@ aaudio_result_t AudioStreamInternal::requestFlush() {

		// 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::requestStopInternal()

		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 void AudioStreamInternal_logTimestamp(AAudioServiceMessage &command) {
		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::onTimestampFromServer(AAudioServiceMessage

		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 @@ aaudio_result_t AudioStreamInternal::onEventFromServer(AAudioServiceMessage *mes
		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 AudioStreamInternal::processCommands() {
		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 @@ aaudio_result_t AudioStreamInternal::processData(void *buffer, int32_t numFrames
		}
		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 AudioStreamInternal::setBufferSize(int32_t requestedFrames) {
		}

		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 {

media/libaaudio/src/client/AudioStreamInternal.h

+0 −4

Original line number	Diff line number	Diff line
		@@ -155,10 +155,6 @@ private:
		// 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

media/libaaudio/src/core/AAudioAudio.cpp

+4 −6

Original line number	Diff line number	Diff line
		@@ -206,11 +206,12 @@ AAUDIO_API aaudio_result_t AAudioStreamBuilder_openStream(AAudioStreamBuilder*
		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 @@ AAUDIO_API aaudio_result_t AAudioStream_close(AAudioStream* stream)
		if (audioStream != nullptr) {
		audioStream->close();
		delete audioStream;
		ALOGD("AAudioStream_close() ----------------------------------------------");
		return AAUDIO_OK;
		}
		return AAUDIO_ERROR_INVALID_HANDLE;
		@@ -300,7 +300,6 @@ AAUDIO_API aaudio_result_t AAudioStream_read(AAudioStream* stream,
		}

		aaudio_result_t result = audioStream->read(buffer, numFrames, timeoutNanoseconds);
		// ALOGD("AAudioStream_read(): read returns %d", result);

		return result;
		}
		@@ -328,7 +327,6 @@ AAUDIO_API aaudio_result_t AAudioStream_write(AAudioStream* stream,
		}

		aaudio_result_t result = audioStream->write(buffer, numFrames, timeoutNanoseconds);
		// ALOGD("AAudioStream_write(): write returns %d", result);

		return result;
		}

media/libaaudio/src/core/AudioStream.cpp

+6 −3

Original line number	Diff line number	Diff line
		@@ -55,9 +55,12 @@ aaudio_result_t AudioStream::open(const AudioStreamBuilder& builder)
		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.

media/libaaudio/src/core/AudioStreamBuilder.cpp

+0 −3

Original line number	Diff line number	Diff line
		@@ -84,8 +84,6 @@ aaudio_result_t AudioStreamBuilder::build(AudioStream** streamPtr) {

		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 @@ aaudio_result_t AudioStreamBuilder::build(AudioStream** streamPtr) {
		}
		}

		ALOGD("AudioStreamBuilder(): returned %d", result);
		return result;
		}