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

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 = 20 * 1024;
		sp<MemoryDealer> mLogMemoryDealer; // == 0 when NBLog is disabled
		public:

services/audioflinger/AudioMixer.cpp

+6 −2

Original line number	Diff line number	Diff line
		@@ -209,6 +209,7 @@ int AudioMixer::getTrackName(audio_channel_mask_t channelMask, int sessionId)
		t->mainBuffer = NULL;
		t->auxBuffer = NULL;
		t->downmixerBufferProvider = NULL;
		t->fastIndex = -1;

		status_t status = initTrackDownmix(&mState.tracks[n], n, channelMask);
		if (status == OK) {
		@@ -455,6 +456,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");
		}
		@@ -1111,8 +1115,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

+3 −1

Original line number	Diff line number	Diff line
		@@ -76,6 +76,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.
		@@ -200,7 +201,8 @@ private:

		int32_t sessionId;

		int32_t padding[2];
		int32_t fastIndex;
		int32_t padding[1];

		// 16-byte boundary

services/audioflinger/FastMixer.cpp

+28 −2

Original line number	Diff line number	Diff line
		@@ -120,6 +120,7 @@ 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
		@@ -301,12 +302,19 @@ bool FastMixer::threadLoop()
		const FastTrack* fastTrack = &current->mFastTracks[i];
		AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider;
		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);
		@@ -322,22 +330,31 @@ bool FastMixer::threadLoop()
		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;
		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 +377,9 @@ bool FastMixer::threadLoop()
		generations[i] = fastTrack->mGeneration;
		}
		}
		if (actuallyModifiedTracks) {
		logWriter->logf("act. mod. %#x", actuallyModifiedTracks);
		}

		fastTracksGen = current->mFastTracksGen;

		@@ -423,6 +443,12 @@ bool FastMixer::threadLoop()
		}
		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;

services/audioflinger/Threads.cpp

+22 −6

Original line number	Diff line number	Diff line
		@@ -1196,6 +1196,8 @@ sp<AudioFlinger::PlaybackThread::Track> AudioFlinger::PlaybackThread::createTrac

		{ // scope for mLock
		Mutex::Autolock _l(mLock);
		mNBLogWriter->logf("createTrack_l isFast=%d caller=%d",
		(*flags & IAudioFlinger::TRACK_FAST) != 0, IPCThreadState::self()->getCallingPid());

		// all tracks in same audio session must share the same routing strategy otherwise
		// conflicts will happen when tracks are moved from one output to another by audio policy
		@@ -1249,7 +1251,6 @@ Exit:
		if (status) {
		*status = lStatus;
		}
		mNBLogWriter->logf("createTrack_l");
		return track;
		}

		@@ -1317,7 +1318,8 @@ float AudioFlinger::PlaybackThread::streamVolume(audio_stream_type_t stream) con
		// addTrack_l() must be called with ThreadBase::mLock held
		status_t AudioFlinger::PlaybackThread::addTrack_l(const sp<Track>& track)
		{
		mNBLogWriter->logf("addTrack_l mName=%d", track->mName);
		mNBLogWriter->logf("addTrack_l mName=%d mFastIndex=%d caller=%d", track->mName,
		track->mFastIndex, IPCThreadState::self()->getCallingPid());
		status_t status = ALREADY_EXISTS;

		// set retry count for buffer fill
		@@ -1351,7 +1353,9 @@ status_t AudioFlinger::PlaybackThread::addTrack_l(const sp<Track>& track)
		// destroyTrack_l() must be called with ThreadBase::mLock held
		void AudioFlinger::PlaybackThread::destroyTrack_l(const sp<Track>& track)
		{
		mNBLogWriter->logf("destroyTrack_l mName=%d", track->mName);
		mNBLogWriter->logTimestamp();
		mNBLogWriter->logf("destroyTrack_l mName=%d mFastIndex=%d mClientPid=%d", track->mName,
		track->mFastIndex, track->mClient != 0 ? track->mClient->pid() : -1);
		track->mState = TrackBase::TERMINATED;
		// active tracks are removed by threadLoop()
		if (mActiveTracks.indexOf(track) < 0) {
		@@ -1361,7 +1365,9 @@ void AudioFlinger::PlaybackThread::destroyTrack_l(const sp<Track>& track)

		void AudioFlinger::PlaybackThread::removeTrack_l(const sp<Track>& track)
		{
		mNBLogWriter->logf("removeTrack_l mName=%d", track->mName);
		mNBLogWriter->logTimestamp();
		mNBLogWriter->logf("removeTrack_l mName=%d mFastIndex=%d clientPid=%d", track->mName,
		track->mFastIndex, track->mClient != 0 ? track->mClient->pid() : -1);
		track->triggerEvents(AudioSystem::SYNC_EVENT_PRESENTATION_COMPLETE);
		mTracks.remove(track);
		deleteTrackName_l(track->name());
		@@ -2839,11 +2845,19 @@ track_is_ready: ;
		block = FastMixerStateQueue::BLOCK_UNTIL_ACKED;
		pauseAudioWatchdog = true;
		}
		sq->end();
		}
		if (sq != NULL) {
		unsigned trackMask = state->mTrackMask;
		sq->end(didModify);
		if (didModify) {
		mNBLogWriter->logTimestamp();
		mNBLogWriter->logf("push trackMask=%#x block=%d", trackMask, block);
		}
		sq->push(block);
		if (didModify) {
		mNBLogWriter->logTimestamp();
		mNBLogWriter->log("pushed");
		}
		}
		#ifdef AUDIO_WATCHDOG
		if (pauseAudioWatchdog && mAudioWatchdog != 0) {
		@@ -2870,7 +2884,9 @@ track_is_ready: ;
		if (CC_UNLIKELY(count)) {
		for (size_t i=0 ; i<count ; i++) {
		const sp<Track>& track = tracksToRemove->itemAt(i);
		mNBLogWriter->logf("prepareTracks_l remove name=%u", track->name());
		mNBLogWriter->logTimestamp();
		mNBLogWriter->logf("prepareTracks_l remove name=%u mFastIndex=%d", track->name(),
		track->mFastIndex);
		mActiveTracks.remove(track);
		if (track->mainBuffer() != mMixBuffer) {
		chain = getEffectChain_l(track->sessionId());