Merge "Temporary additional logging to investigate bug" (159967da) · Commits · e / os / android_frameworks_av

include/media/nbaio/NBLog.h

+2 −2

Original line number	Diff line number	Diff line
		@@ -115,7 +115,7 @@ public:
		virtual ~Writer() { }

		virtual void log(const char *string);
		virtual void logf(const char *fmt, ...);
		virtual void logf(const char *fmt, ...) __attribute__ ((format (printf, 2, 3)));
		virtual void logvf(const char *fmt, va_list ap);
		virtual void logTimestamp();
		virtual void logTimestamp(const struct timespec& ts);
		@@ -149,7 +149,7 @@ public:
		LockedWriter(size_t size, void *shared);

		virtual void log(const char *string);
		virtual void logf(const char *fmt, ...);
		virtual void logf(const char *fmt, ...) __attribute__ ((format (printf, 2, 3)));
		virtual void logvf(const char *fmt, va_list ap);
		virtual void logTimestamp();
		virtual void logTimestamp(const struct timespec& ts);

services/audioflinger/AudioFlinger.h

+1 −1

Original line number	Diff line number	Diff line
		@@ -227,7 +227,7 @@ public:
		sp<NBLog::Writer> newWriter_l(size_t size, const char *name);
		void unregisterWriter(const sp<NBLog::Writer>& writer);
		private:
		static const size_t kLogMemorySize = 10 * 1024;
		static const size_t kLogMemorySize = 30 * 1024;
		sp<MemoryDealer> mLogMemoryDealer; // == 0 when NBLog is disabled
		public:

services/audioflinger/AudioMixer.cpp

+43 −3

Original line number	Diff line number	Diff line
		@@ -98,7 +98,7 @@ effect_descriptor_t AudioMixer::dwnmFxDesc;

		AudioMixer::AudioMixer(size_t frameCount, uint32_t sampleRate, uint32_t maxNumTracks)
		: mTrackNames(0), mConfiguredNames((maxNumTracks >= 32 ? 0 : 1 << maxNumTracks) - 1),
		mSampleRate(sampleRate)
		mSampleRate(sampleRate), mLog(&mDummyLog)
		{
		// AudioMixer is not yet capable of multi-channel beyond stereo
		COMPILE_TIME_ASSERT_FUNCTION_SCOPE(2 == MAX_NUM_CHANNELS);
		@@ -122,6 +122,7 @@ AudioMixer::AudioMixer(size_t frameCount, uint32_t sampleRate, uint32_t maxNumTr
		mState.hook = process__nop;
		mState.outputTemp = NULL;
		mState.resampleTemp = NULL;
		mState.mLog = &mDummyLog;
		// mState.reserved

		// FIXME Most of the following initialization is probably redundant since
		@@ -131,6 +132,7 @@ AudioMixer::AudioMixer(size_t frameCount, uint32_t sampleRate, uint32_t maxNumTr
		for (unsigned i=0 ; i < MAX_NUM_TRACKS ; i++) {
		t->resampler = NULL;
		t->downmixerBufferProvider = NULL;
		t->magic = track_t::kMagic;
		t++;
		}

		@@ -169,6 +171,12 @@ AudioMixer::~AudioMixer()
		delete [] mState.resampleTemp;
		}

		void AudioMixer::setLog(NBLog::Writer *log)
		{
		mLog = log;
		mState.mLog = log;
		}

		int AudioMixer::getTrackName(audio_channel_mask_t channelMask, int sessionId)
		{
		uint32_t names = (~mTrackNames) & mConfiguredNames;
		@@ -209,9 +217,12 @@ int AudioMixer::getTrackName(audio_channel_mask_t channelMask, int sessionId)
		t->mainBuffer = NULL;
		t->auxBuffer = NULL;
		t->downmixerBufferProvider = NULL;
		t->fastIndex = -1;
		// t->magic unchanged

		status_t status = initTrackDownmix(&mState.tracks[n], n, channelMask);
		if (status == OK) {
		mLog->logf("getTrackName %d", n);
		return TRACK0 + n;
		}
		ALOGE("AudioMixer::getTrackName(0x%x) failed, error preparing track for downmix",
		@@ -366,9 +377,11 @@ void AudioMixer::deleteTrackName(int name)
		{
		ALOGV("AudioMixer::deleteTrackName(%d)", name);
		name -= TRACK0;
		mLog->logf("deleteTrackName %d", name);
		ALOG_ASSERT(uint32_t(name) < MAX_NUM_TRACKS, "bad track name %d", name);
		ALOGV("deleteTrackName(%d)", name);
		track_t& track(mState.tracks[ name ]);
		track.checkMagic();
		if (track.enabled) {
		track.enabled = false;
		invalidateState(1<<name);
		@@ -387,8 +400,10 @@ void AudioMixer::enable(int name)
		name -= TRACK0;
		ALOG_ASSERT(uint32_t(name) < MAX_NUM_TRACKS, "bad track name %d", name);
		track_t& track = mState.tracks[name];
		track.checkMagic();

		if (!track.enabled) {
		mLog->logf("enable %d", name);
		track.enabled = true;
		ALOGV("enable(%d)", name);
		invalidateState(1 << name);
		@@ -400,19 +415,32 @@ void AudioMixer::disable(int name)
		name -= TRACK0;
		ALOG_ASSERT(uint32_t(name) < MAX_NUM_TRACKS, "bad track name %d", name);
		track_t& track = mState.tracks[name];
		track.checkMagic();

		if (track.enabled) {
		mLog->logf("disable %d", name);
		track.enabled = false;
		ALOGV("disable(%d)", name);
		invalidateState(1 << name);
		}
		}

		bool AudioMixer::enabled(int name)
		{
		name -= TRACK0;
		ALOG_ASSERT(uint32_t(name) < MAX_NUM_TRACKS, "bad track name %d", name);
		track_t& track = mState.tracks[name];
		track.checkMagic();

		return track.enabled;
		}

		void AudioMixer::setParameter(int name, int target, int param, void *value)
		{
		name -= TRACK0;
		ALOG_ASSERT(uint32_t(name) < MAX_NUM_TRACKS, "bad track name %d", name);
		track_t& track = mState.tracks[name];
		track.checkMagic();

		int valueInt = (int)value;
		int32_t valueBuf = (int32_t )value;
		@@ -455,6 +483,9 @@ void AudioMixer::setParameter(int name, int target, int param, void *value)
		// for a specific track? or per mixer?
		/* case DOWNMIX_TYPE:
		break */
		case FAST_INDEX:
		track.fastIndex = valueInt;
		break;
		default:
		LOG_FATAL("bad param");
		}
		@@ -540,6 +571,7 @@ void AudioMixer::setParameter(int name, int target, int param, void *value)

		bool AudioMixer::track_t::setResampler(uint32_t value, uint32_t devSampleRate)
		{
		checkMagic();
		if (value != devSampleRate \|\| resampler != NULL) {
		if (sampleRate != value) {
		sampleRate = value;
		@@ -572,6 +604,7 @@ bool AudioMixer::track_t::setResampler(uint32_t value, uint32_t devSampleRate)
		inline
		void AudioMixer::track_t::adjustVolumeRamp(bool aux)
		{
		checkMagic();
		for (uint32_t i=0 ; i<MAX_NUM_CHANNELS ; i++) {
		if (((volumeInc[i]>0) && (((prevVolume[i]+volumeInc[i])>>16) >= volume[i])) \|\|
		((volumeInc[i]<0) && (((prevVolume[i]+volumeInc[i])>>16) <= volume[i]))) {
		@@ -600,8 +633,10 @@ size_t AudioMixer::getUnreleasedFrames(int name) const
		void AudioMixer::setBufferProvider(int name, AudioBufferProvider* bufferProvider)
		{
		name -= TRACK0;
		mLog->logf("bp %d-%p", name, bufferProvider);
		ALOG_ASSERT(uint32_t(name) < MAX_NUM_TRACKS, "bad track name %d", name);

		mState.tracks[name].checkMagic();
		if (mState.tracks[name].downmixerBufferProvider != NULL) {
		// update required?
		if (mState.tracks[name].downmixerBufferProvider->mTrackBufferProvider != bufferProvider) {
		@@ -623,6 +658,9 @@ void AudioMixer::setBufferProvider(int name, AudioBufferProvider* bufferProvider

		void AudioMixer::process(int64_t pts)
		{
		if (mState.needsChanged) {
		mLog->logf("process needs=%#x", mState.needsChanged);
		}
		mState.hook(&mState, pts);
		}

		@@ -647,6 +685,7 @@ void AudioMixer::process__validate(state_t* state, int64_t pts)
		}
		state->enabledTracks &= ~disabled;
		state->enabledTracks \|= enabled;
		state->mLog->logf("process_validate ena=%#x", state->enabledTracks);

		// compute everything we need...
		int countActiveTracks = 0;
		@@ -1103,6 +1142,7 @@ void AudioMixer::process__genericNoResampling(state_t* state, int64_t pts)

		// acquire each track's buffer
		uint32_t enabledTracks = state->enabledTracks;
		state->mLog->logf("process_gNR ena=%#x", enabledTracks);
		uint32_t e0 = enabledTracks;
		while (e0) {
		const int i = 31 - __builtin_clz(e0);
		@@ -1111,8 +1151,8 @@ void AudioMixer::process__genericNoResampling(state_t* state, int64_t pts)
		t.buffer.frameCount = state->frameCount;
		int valid = t.bufferProvider->getValid();
		if (valid != AudioBufferProvider::kValid) {
		ALOGE("invalid bufferProvider=%p name=%d frameCount=%d valid=%#x enabledTracks=%#x",
		t.bufferProvider, i, t.buffer.frameCount, valid, enabledTracks);
		ALOGE("invalid bufferProvider=%p name=%d fastIndex=%d frameCount=%d valid=%#x enabledTracks=%#x",
		t.bufferProvider, i, t.fastIndex, t.buffer.frameCount, valid, enabledTracks);
		// expect to crash
		}
		t.bufferProvider->getNextBuffer(&t.buffer, pts);

services/audioflinger/AudioMixer.h

+20 −2

Original line number	Diff line number	Diff line
		@@ -28,6 +28,7 @@

		#include <audio_effects/effect_downmix.h>
		#include <system/audio.h>
		#include <media/nbaio/NBLog.h>

		namespace android {

		@@ -76,6 +77,7 @@ public:
		MAIN_BUFFER = 0x4002,
		AUX_BUFFER = 0x4003,
		DOWNMIX_TYPE = 0X4004,
		FAST_INDEX = 0x4005, // for debugging only
		// for target RESAMPLE
		SAMPLE_RATE = 0x4100, // Configure sample rate conversion on this track name;
		// parameter 'value' is the new sample rate in Hz.
		@@ -106,6 +108,7 @@ public:
		// Enable or disable an allocated track by name
		void enable(int name);
		void disable(int name);
		bool enabled(int name);

		void setParameter(int name, int target, int param, void *value);

		@@ -200,7 +203,10 @@ private:

		int32_t sessionId;

		int32_t padding[2];
		int32_t fastIndex;
		int32_t magic;
		static const int kMagic = 0x54637281;
		//int32_t padding[1];

		// 16-byte boundary

		@@ -210,6 +216,12 @@ private:
		void adjustVolumeRamp(bool aux);
		size_t getUnreleasedFrames() const { return resampler != NULL ?
		resampler->getUnreleasedFrames() : 0; };
		void checkMagic() {
		if (magic != kMagic) {
		ALOGE("magic=%#x fastIndex=%d", magic, fastIndex);
		}
		}

		};

		// pad to 32-bytes to fill cache line
		@@ -220,7 +232,8 @@ private:
		void (hook)(state_t state, int64_t pts); // one of process__*, never NULL
		int32_t *outputTemp;
		int32_t *resampleTemp;
		int32_t reserved[2];
		NBLog::Writer* mLog;
		int32_t reserved[1];
		// FIXME allocate dynamically to save some memory when maxNumTracks < MAX_NUM_TRACKS
		track_t tracks[MAX_NUM_TRACKS]; __attribute__((aligned(32)));
		};
		@@ -247,6 +260,11 @@ private:

		const uint32_t mSampleRate;

		NBLog::Writer* mLog;
		NBLog::Writer mDummyLog;
		public:
		void setLog(NBLog::Writer* log);
		private:
		state_t mState __attribute__((aligned(32)));

		// effect descriptor for the downmixer used by the mixer

services/audioflinger/FastMixer.cpp

+43 −2

Original line number	Diff line number	Diff line
		@@ -120,12 +120,16 @@ bool FastMixer::threadLoop()
		FastMixerState::Command command = next->mCommand;
		if (next != current) {

		logWriter->logTimestamp();
		logWriter->log("next != current");

		// As soon as possible of learning of a new dump area, start using it
		dumpState = next->mDumpState != NULL ? next->mDumpState : &dummyDumpState;
		teeSink = next->mTeeSink;
		logWriter = next->mNBLogWriter != NULL ? next->mNBLogWriter : &dummyLogWriter;
		if (mixer != NULL) {
		mixer->setLog(logWriter);
		}

		// We want to always have a valid reference to the previous (non-idle) state.
		// However, the state queue only guarantees access to current and previous states.
		@@ -300,13 +304,21 @@ bool FastMixer::threadLoop()
		addedTracks &= ~(1 << i);
		const FastTrack* fastTrack = &current->mFastTracks[i];
		AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider;
		logWriter->logf("bp %d i=%d %p", __LINE__, i, bufferProvider);
		ALOG_ASSERT(bufferProvider != NULL && fastTrackNames[i] == -1);
		if (bufferProvider == NULL \|\|
		bufferProvider->getValid() != AudioBufferProvider::kValid) {
		logWriter->logTimestamp();
		logWriter->logf("added invalid %#x", i);
		}
		if (mixer != NULL) {
		// calling getTrackName with default channel mask and a random invalid
		// sessionId (no effects here)
		name = mixer->getTrackName(AUDIO_CHANNEL_OUT_STEREO, -555);
		ALOG_ASSERT(name >= 0);
		fastTrackNames[i] = name;
		mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::FAST_INDEX,
		(void *) i);
		mixer->setBufferProvider(name, bufferProvider);
		mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::MAIN_BUFFER,
		(void *) mixBuffer);
		@@ -317,27 +329,40 @@ bool FastMixer::threadLoop()
		}
		mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::CHANNEL_MASK,
		(void *) fastTrack->mChannelMask);
		if (!mixer->enabled(name)) {
		logWriter->logf("enable %d i=%d name=%d", __LINE__, i, name);
		}
		mixer->enable(name);
		}
		generations[i] = fastTrack->mGeneration;
		}

		// finally process modified tracks; these use the same slot
		// finally process (potentially) modified tracks; these use the same slot
		// but may have a different buffer provider or volume provider
		unsigned modifiedTracks = currentTrackMask & previousTrackMask;
		if (modifiedTracks) {
		logWriter->logf("modified %#x", modifiedTracks);
		logWriter->logf("pot. mod. %#x", modifiedTracks);
		}
		unsigned actuallyModifiedTracks = 0;
		while (modifiedTracks != 0) {
		i = __builtin_ctz(modifiedTracks);
		modifiedTracks &= ~(1 << i);
		const FastTrack* fastTrack = &current->mFastTracks[i];
		if (fastTrack->mGeneration != generations[i]) {
		actuallyModifiedTracks \|= 1 << i;
		AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider;
		logWriter->logf("bp %d i=%d %p", __LINE__, i, bufferProvider);
		ALOG_ASSERT(bufferProvider != NULL);
		if (bufferProvider == NULL \|\|
		bufferProvider->getValid() != AudioBufferProvider::kValid) {
		logWriter->logTimestamp();
		logWriter->logf("modified invalid %#x", i);
		}
		if (mixer != NULL) {
		name = fastTrackNames[i];
		ALOG_ASSERT(name >= 0);
		mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::FAST_INDEX,
		(void *) i);
		mixer->setBufferProvider(name, bufferProvider);
		if (fastTrack->mVolumeProvider == NULL) {
		mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME0,
		@@ -360,6 +385,9 @@ bool FastMixer::threadLoop()
		generations[i] = fastTrack->mGeneration;
		}
		}
		if (actuallyModifiedTracks) {
		logWriter->logf("act. mod. %#x", actuallyModifiedTracks);
		}

		fastTracksGen = current->mFastTracksGen;

		@@ -377,6 +405,7 @@ bool FastMixer::threadLoop()
		ALOG_ASSERT(mixBuffer != NULL);
		// for each track, update volume and check for underrun
		unsigned currentTrackMask = current->mTrackMask;
		logWriter->logf("ctm %#x", currentTrackMask);
		while (currentTrackMask != 0) {
		i = __builtin_ctz(currentTrackMask);
		currentTrackMask &= ~(1 << i);
		@@ -414,15 +443,27 @@ bool FastMixer::threadLoop()
		// allow mixing partial buffer
		underruns.mBitFields.mPartial++;
		underruns.mBitFields.mMostRecent = UNDERRUN_PARTIAL;
		if (!mixer->enabled(name)) {
		logWriter->logf("enable %d i=%d name=%d", __LINE__, i, name);
		}
		mixer->enable(name);
		}
		} else {
		underruns.mBitFields.mFull++;
		underruns.mBitFields.mMostRecent = UNDERRUN_FULL;
		if (!mixer->enabled(name)) {
		logWriter->logf("enable %d i=%d name=%d", __LINE__, i, name);
		}
		mixer->enable(name);
		}
		ftDump->mUnderruns = underruns;
		ftDump->mFramesReady = framesReady;
		AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider;
		if (bufferProvider == NULL \|\|
		bufferProvider->getValid() != AudioBufferProvider::kValid) {
		logWriter->logTimestamp();
		logWriter->logf("mixing invalid %#x", i);
		}
		}

		int64_t pts;