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

include/media/nbaio/NBLog.h

+2 −2

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

	virtual void log(const char *string);		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 logvf(const char *fmt, va_list ap);
	virtual void logTimestamp();		virtual void logTimestamp();
	virtual void logTimestamp(const struct timespec& ts);		virtual void logTimestamp(const struct timespec& ts);
	@@ -149,7 +149,7 @@ public:
	LockedWriter(size_t size, void *shared);		LockedWriter(size_t size, void *shared);

	virtual void log(const char *string);		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 logvf(const char *fmt, va_list ap);
	virtual void logTimestamp();		virtual void logTimestamp();
	virtual void logTimestamp(const struct timespec& ts);		virtual void logTimestamp(const struct timespec& ts);

services/audioflinger/AudioFlinger.h

+1 −1

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

services/audioflinger/AudioMixer.cpp

+68 −4

Original line number	Original line	Diff line number	Diff line
	@@ -16,7 +16,7 @@
	*/		*/

	#define LOG_TAG "AudioMixer"		#define LOG_TAG "AudioMixer"
	//#define LOG_NDEBUG 0		#define LOG_NDEBUG 0

	#include <stdint.h>		#include <stdint.h>
	#include <string.h>		#include <string.h>
	@@ -25,6 +25,8 @@

	#include <utils/Errors.h>		#include <utils/Errors.h>
	#include <utils/Log.h>		#include <utils/Log.h>
			#undef ALOGV
			#define ALOGV(a...) do { } while (0)

	#include <cutils/bitops.h>		#include <cutils/bitops.h>
	#include <cutils/compiler.h>		#include <cutils/compiler.h>
	@@ -98,7 +100,7 @@ effect_descriptor_t AudioMixer::dwnmFxDesc;

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

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

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

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

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

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

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

	if (track.enabled) {		if (track.enabled) {
			mLog->logf("disable %d", name);
	track.enabled = false;		track.enabled = false;
	ALOGV("disable(%d)", name);		ALOGV("disable(%d)", name);
	invalidateState(1 << 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();
			#if 0
			// can't do this because mState.enabledTracks is updated lazily
			ALOG_ASSERT(track.enabled == ((mState.enabledTracks & (1 << name)) != 0));
			#endif

			return track.enabled;
			}

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

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

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

			mState.tracks[name].checkMagic();
	if (mState.tracks[name].downmixerBufferProvider != NULL) {		if (mState.tracks[name].downmixerBufferProvider != NULL) {
	// update required?		// update required?
	if (mState.tracks[name].downmixerBufferProvider->mTrackBufferProvider != bufferProvider) {		if (mState.tracks[name].downmixerBufferProvider->mTrackBufferProvider != bufferProvider) {
	@@ -619,10 +660,27 @@ void AudioMixer::setBufferProvider(int name, AudioBufferProvider* bufferProvider
	}		}
	}		}

			AudioBufferProvider* AudioMixer::getBufferProvider(int name)
			{
			name -= TRACK0;
			ALOG_ASSERT(uint32_t(name) < MAX_NUM_TRACKS, "bad track name %d", name);
			mState.tracks[name].checkMagic();
			return mState.tracks[name].bufferProvider;
			}

			int AudioMixer::getFastIndex(int name)
			{
			name -= TRACK0;
			ALOG_ASSERT(uint32_t(name) < MAX_NUM_TRACKS, "bad track name %d", name);
			mState.tracks[name].checkMagic();
			return mState.tracks[name].fastIndex;
			}

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

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

	// compute everything we need...		// compute everything we need...
	int countActiveTracks = 0;		int countActiveTracks = 0;
	@@ -1058,6 +1117,7 @@ void AudioMixer::track__16BitsMono(track_t* t, int32_t* out, size_t frameCount,
	void AudioMixer::process__nop(state_t* state, int64_t pts)		void AudioMixer::process__nop(state_t* state, int64_t pts)
	{		{
	uint32_t e0 = state->enabledTracks;		uint32_t e0 = state->enabledTracks;
			state->mLog->logf("process_nop ena=%#x", e0);
	size_t bufSize = state->frameCount * sizeof(int16_t) * MAX_NUM_CHANNELS;		size_t bufSize = state->frameCount * sizeof(int16_t) * MAX_NUM_CHANNELS;
	while (e0) {		while (e0) {
	// process by group of tracks with same output buffer to		// process by group of tracks with same output buffer to
	@@ -1103,6 +1163,7 @@ void AudioMixer::process__genericNoResampling(state_t* state, int64_t pts)

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

	uint32_t e0 = state->enabledTracks;		uint32_t e0 = state->enabledTracks;
			state->mLog->logf("process_gR ena=%#x", e0);
	while (e0) {		while (e0) {
	// process by group of tracks with same output buffer		// process by group of tracks with same output buffer
	// to optimize cache use		// to optimize cache use
	@@ -1275,6 +1337,7 @@ void AudioMixer::process__genericResampling(state_t* state, int64_t pts)
	void AudioMixer::process__OneTrack16BitsStereoNoResampling(state_t* state,		void AudioMixer::process__OneTrack16BitsStereoNoResampling(state_t* state,
	int64_t pts)		int64_t pts)
	{		{
			state->mLog->logf("process_1TSNR ena=%#x", state->enabledTracks);
	// This method is only called when state->enabledTracks has exactly		// This method is only called when state->enabledTracks has exactly
	// one bit set. The asserts below would verify this, but are commented out		// one bit set. The asserts below would verify this, but are commented out
	// since the whole point of this method is to optimize performance.		// since the whole point of this method is to optimize performance.
	@@ -1344,6 +1407,7 @@ void AudioMixer::process__TwoTracks16BitsStereoNoResampling(state_t* state,
	{		{
	int i;		int i;
	uint32_t en = state->enabledTracks;		uint32_t en = state->enabledTracks;
			state->mLog->logf("process_2TSNR ena=%#x", en);

	i = 31 - __builtin_clz(en);		i = 31 - __builtin_clz(en);
	const track_t& t0 = state->tracks[i];		const track_t& t0 = state->tracks[i];

services/audioflinger/AudioMixer.h

+23 −2

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

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

	namespace android {		namespace android {

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

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

	void setBufferProvider(int name, AudioBufferProvider* bufferProvider);		void setBufferProvider(int name, AudioBufferProvider* bufferProvider);
			AudioBufferProvider* getBufferProvider(int name);
	void process(int64_t pts);		void process(int64_t pts);

	uint32_t trackNames() const { return mTrackNames; }		uint32_t trackNames() const { return mTrackNames; }
			uint32_t enabledTrackNames() const { return mState.enabledTracks; }
			int getFastIndex(int name);

	size_t getUnreleasedFrames(int name) const;		size_t getUnreleasedFrames(int name) const;

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

	int32_t sessionId;		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		// 16-byte boundary

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

	};		};

	// pad to 32-bytes to fill cache line		// pad to 32-bytes to fill cache line
	@@ -220,7 +235,8 @@ private:
	void (hook)(state_t state, int64_t pts); // one of process__*, never NULL		void (hook)(state_t state, int64_t pts); // one of process__*, never NULL
	int32_t *outputTemp;		int32_t *outputTemp;
	int32_t *resampleTemp;		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		// FIXME allocate dynamically to save some memory when maxNumTracks < MAX_NUM_TRACKS
	track_t tracks[MAX_NUM_TRACKS]; __attribute__((aligned(32)));		track_t tracks[MAX_NUM_TRACKS]; __attribute__((aligned(32)));
	};		};
	@@ -247,6 +263,11 @@ private:

	const uint32_t mSampleRate;		const uint32_t mSampleRate;

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

	// effect descriptor for the downmixer used by the mixer		// effect descriptor for the downmixer used by the mixer

services/audioflinger/FastMixer.cpp

+89 −4

Original line number	Original line	Diff line number	Diff line
	@@ -21,13 +21,15 @@
	// </IMPORTANT_WARNING>		// </IMPORTANT_WARNING>

	#define LOG_TAG "FastMixer"		#define LOG_TAG "FastMixer"
	//#define LOG_NDEBUG 0		#define LOG_NDEBUG 0

	#define ATRACE_TAG ATRACE_TAG_AUDIO		#define ATRACE_TAG ATRACE_TAG_AUDIO

	#include <sys/atomics.h>		#include <sys/atomics.h>
	#include <time.h>		#include <time.h>
	#include <utils/Log.h>		#include <utils/Log.h>
			#undef ALOGV
			#define ALOGV(a...) do { } while (0)
	#include <utils/Trace.h>		#include <utils/Trace.h>
	#include <system/audio.h>		#include <system/audio.h>
	#ifdef FAST_MIXER_STATISTICS		#ifdef FAST_MIXER_STATISTICS
	@@ -93,6 +95,8 @@ bool FastMixer::threadLoop()
	uint32_t warmupCycles = 0; // counter of number of loop cycles required to warmup		uint32_t warmupCycles = 0; // counter of number of loop cycles required to warmup
	NBAIO_Sink* teeSink = NULL; // if non-NULL, then duplicate write() to this non-blocking sink		NBAIO_Sink* teeSink = NULL; // if non-NULL, then duplicate write() to this non-blocking sink
	NBLog::Writer dummyLogWriter, *logWriter = &dummyLogWriter;		NBLog::Writer dummyLogWriter, *logWriter = &dummyLogWriter;
			bool myEnabled[FastMixerState::kMaxFastTracks];
			memset(myEnabled, 0, sizeof(myEnabled));

	for (;;) {		for (;;) {

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

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

	// As soon as possible of learning of a new dump area, start using it		// As soon as possible of learning of a new dump area, start using it
	dumpState = next->mDumpState != NULL ? next->mDumpState : &dummyDumpState;		dumpState = next->mDumpState != NULL ? next->mDumpState : &dummyDumpState;
	teeSink = next->mTeeSink;		teeSink = next->mTeeSink;
	logWriter = next->mNBLogWriter != NULL ? next->mNBLogWriter : &dummyLogWriter;		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.		// 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.		// However, the state queue only guarantees access to current and previous states.
	@@ -300,13 +308,21 @@ bool FastMixer::threadLoop()
	addedTracks &= ~(1 << i);		addedTracks &= ~(1 << i);
	const FastTrack* fastTrack = &current->mFastTracks[i];		const FastTrack* fastTrack = &current->mFastTracks[i];
	AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider;		AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider;
			logWriter->logf("bp %d i=%d %p", __LINE__, i, bufferProvider);
	ALOG_ASSERT(bufferProvider != NULL && fastTrackNames[i] == -1);		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) {		if (mixer != NULL) {
	// calling getTrackName with default channel mask and a random invalid		// calling getTrackName with default channel mask and a random invalid
	// sessionId (no effects here)		// sessionId (no effects here)
	name = mixer->getTrackName(AUDIO_CHANNEL_OUT_STEREO, -555);		name = mixer->getTrackName(AUDIO_CHANNEL_OUT_STEREO, -555);
	ALOG_ASSERT(name >= 0);		ALOG_ASSERT(name >= 0);
	fastTrackNames[i] = name;		fastTrackNames[i] = name;
			mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::FAST_INDEX,
			(void *) i);
	mixer->setBufferProvider(name, bufferProvider);		mixer->setBufferProvider(name, bufferProvider);
	mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::MAIN_BUFFER,		mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::MAIN_BUFFER,
	(void *) mixBuffer);		(void *) mixBuffer);
	@@ -317,27 +333,41 @@ bool FastMixer::threadLoop()
	}		}
	mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::CHANNEL_MASK,		mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::CHANNEL_MASK,
	(void *) fastTrack->mChannelMask);		(void *) fastTrack->mChannelMask);
			if (!mixer->enabled(name)) {
			logWriter->logf("enable %d i=%d name=%d", __LINE__, i, name);
			}
	mixer->enable(name);		mixer->enable(name);
			myEnabled[i] = true;
	}		}
	generations[i] = fastTrack->mGeneration;		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		// but may have a different buffer provider or volume provider
	unsigned modifiedTracks = currentTrackMask & previousTrackMask;		unsigned modifiedTracks = currentTrackMask & previousTrackMask;
	if (modifiedTracks) {		if (modifiedTracks) {
	logWriter->logf("modified %#x", modifiedTracks);		logWriter->logf("pot. mod. %#x", modifiedTracks);
	}		}
			unsigned actuallyModifiedTracks = 0;
	while (modifiedTracks != 0) {		while (modifiedTracks != 0) {
	i = __builtin_ctz(modifiedTracks);		i = __builtin_ctz(modifiedTracks);
	modifiedTracks &= ~(1 << i);		modifiedTracks &= ~(1 << i);
	const FastTrack* fastTrack = &current->mFastTracks[i];		const FastTrack* fastTrack = &current->mFastTracks[i];
	if (fastTrack->mGeneration != generations[i]) {		if (fastTrack->mGeneration != generations[i]) {
			actuallyModifiedTracks \|= 1 << i;
	AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider;		AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider;
			logWriter->logf("bp %d i=%d %p", __LINE__, i, bufferProvider);
	ALOG_ASSERT(bufferProvider != NULL);		ALOG_ASSERT(bufferProvider != NULL);
			if (bufferProvider == NULL \|\|
			bufferProvider->getValid() != AudioBufferProvider::kValid) {
			logWriter->logTimestamp();
			logWriter->logf("modified invalid %#x", i);
			}
	if (mixer != NULL) {		if (mixer != NULL) {
	name = fastTrackNames[i];		name = fastTrackNames[i];
	ALOG_ASSERT(name >= 0);		ALOG_ASSERT(name >= 0);
			mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::FAST_INDEX,
			(void *) i);
	mixer->setBufferProvider(name, bufferProvider);		mixer->setBufferProvider(name, bufferProvider);
	if (fastTrack->mVolumeProvider == NULL) {		if (fastTrack->mVolumeProvider == NULL) {
	mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME0,		mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME0,
	@@ -360,6 +390,9 @@ bool FastMixer::threadLoop()
	generations[i] = fastTrack->mGeneration;		generations[i] = fastTrack->mGeneration;
	}		}
	}		}
			if (actuallyModifiedTracks) {
			logWriter->logf("act. mod. %#x", actuallyModifiedTracks);
			}

	fastTracksGen = current->mFastTracksGen;		fastTracksGen = current->mFastTracksGen;

	@@ -377,6 +410,7 @@ bool FastMixer::threadLoop()
	ALOG_ASSERT(mixBuffer != NULL);		ALOG_ASSERT(mixBuffer != NULL);
	// for each track, update volume and check for underrun		// for each track, update volume and check for underrun
	unsigned currentTrackMask = current->mTrackMask;		unsigned currentTrackMask = current->mTrackMask;
			logWriter->logf("ctm %#x", currentTrackMask);
	while (currentTrackMask != 0) {		while (currentTrackMask != 0) {
	i = __builtin_ctz(currentTrackMask);		i = __builtin_ctz(currentTrackMask);
	currentTrackMask &= ~(1 << i);		currentTrackMask &= ~(1 << i);
	@@ -410,25 +444,76 @@ bool FastMixer::threadLoop()
	underruns.mBitFields.mEmpty++;		underruns.mBitFields.mEmpty++;
	underruns.mBitFields.mMostRecent = UNDERRUN_EMPTY;		underruns.mBitFields.mMostRecent = UNDERRUN_EMPTY;
	mixer->disable(name);		mixer->disable(name);
			myEnabled[i] = false;
	} else {		} else {
	// allow mixing partial buffer		// allow mixing partial buffer
	underruns.mBitFields.mPartial++;		underruns.mBitFields.mPartial++;
	underruns.mBitFields.mMostRecent = UNDERRUN_PARTIAL;		underruns.mBitFields.mMostRecent = UNDERRUN_PARTIAL;
			if (!mixer->enabled(name)) {
			logWriter->logf("enable %d i=%d name=%d", __LINE__, i, name);
			}
	mixer->enable(name);		mixer->enable(name);
			myEnabled[i] = true;
	}		}
	} else {		} else {
	underruns.mBitFields.mFull++;		underruns.mBitFields.mFull++;
	underruns.mBitFields.mMostRecent = UNDERRUN_FULL;		underruns.mBitFields.mMostRecent = UNDERRUN_FULL;
			if (!mixer->enabled(name)) {
			logWriter->logf("enable %d i=%d name=%d", __LINE__, i, name);
			}
	mixer->enable(name);		mixer->enable(name);
			myEnabled[i] = true;
	}		}
	ftDump->mUnderruns = underruns;		ftDump->mUnderruns = underruns;
	ftDump->mFramesReady = framesReady;		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;		int64_t pts;
	if (outputSink == NULL \|\| (OK != outputSink->getNextWriteTimestamp(&pts)))		if (outputSink == NULL \|\| (OK != outputSink->getNextWriteTimestamp(&pts)))
	pts = AudioBufferProvider::kInvalidPTS;		pts = AudioBufferProvider::kInvalidPTS;

			// validate that mixer state is correct
			currentTrackMask = current->mTrackMask;
			unsigned expectedMixerEnabled = 0;
			while (currentTrackMask != 0) {
			i = __builtin_ctz(currentTrackMask);
			currentTrackMask &= ~(1 << i);
			const FastTrack* fastTrack = &current->mFastTracks[i];
			int name = fastTrackNames[i];
			ALOG_ASSERT(name >= 0);
			bool isEnabled = mixer->enabled(name);
			if (isEnabled != myEnabled[i]) {
			logWriter->logTimestamp();
			logWriter->logf("? i=%d name=%d mixena=%d ftena=%d", i, name, isEnabled,
			myEnabled[i]);
			}
			if (myEnabled[i]) {
			expectedMixerEnabled \|= 1 << name;
			}
			AudioBufferProvider *abp = mixer->getBufferProvider(name);
			if (abp != fastTrack->mBufferProvider) {
			logWriter->logTimestamp();
			logWriter->logf("? i=%d name=%d mixbp=%p ftbp=%p", i, name, abp,
			fastTrack->mBufferProvider);
			}
			int fastIndex = mixer->getFastIndex(name);
			if (fastIndex != (int) i) {
			logWriter->logTimestamp();
			logWriter->logf("? i=%d name=%d fastIndex=%d", i, name, fastIndex);
			}
			}
			unsigned mixerEnabled = mixer->enabledTrackNames();
			if (mixerEnabled != expectedMixerEnabled) {
			logWriter->logTimestamp();
			logWriter->logf("? mixena=%#x expected=%#x", mixerEnabled, expectedMixerEnabled);
			}

	// process() is CPU-bound		// process() is CPU-bound
	mixer->process(pts);		mixer->process(pts);
	mixBufferState = MIXED;		mixBufferState = MIXED;
	@@ -453,7 +538,7 @@ bool FastMixer::threadLoop()
	ATRACE_END();		ATRACE_END();
	dumpState->mWriteSequence++;		dumpState->mWriteSequence++;
	if (framesWritten >= 0) {		if (framesWritten >= 0) {
	ALOG_ASSERT(framesWritten <= frameCount);		ALOG_ASSERT((size_t) framesWritten <= frameCount);
	dumpState->mFramesWritten += framesWritten;		dumpState->mFramesWritten += framesWritten;
	//if ((size_t) framesWritten == frameCount) {		//if ((size_t) framesWritten == frameCount) {
	// didFullWrite = true;		// didFullWrite = true;