Merge "Temporary additional logging to investigate bug" (752502c0) · 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/FastMixer.cpp

+16 −0

Original line number	Diff line number	Diff line
		@@ -301,6 +301,11 @@ 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)
		@@ -335,6 +340,11 @@ bool FastMixer::threadLoop()
		if (fastTrack->mGeneration != generations[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);
		@@ -423,6 +433,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

+13 −5

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());
		@@ -2870,7 +2876,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());

services/audioflinger/Threads.h

+1 −1

Original line number	Diff line number	Diff line
		@@ -315,7 +315,7 @@ protected:
		// keyed by session ID, the second by type UUID timeLow field
		KeyedVector< int, KeyedVector< int, sp<SuspendedSessionDesc> > >
		mSuspendedSessions;
		static const size_t kLogSize = 512;
		static const size_t kLogSize = 4096;
		sp<NBLog::Writer> mNBLogWriter;
		};

services/audioflinger/Tracks.cpp

+10 −4

Original line number	Diff line number	Diff line
		@@ -351,6 +351,7 @@ AudioFlinger::PlaybackThread::Track::Track(
		// Read the initial underruns because this field is never cleared by the fast mixer
		mObservedUnderruns = thread->getFastTrackUnderruns(i);
		thread->mFastTrackAvailMask &= ~(1 << i);
		thread->mNBLogWriter->logf("new Track mName=%d mFastIndex=%d", mName, mFastIndex);
		}
		}
		ALOGV("Track constructor name %d, calling pid %d", mName,
		@@ -360,6 +361,7 @@ AudioFlinger::PlaybackThread::Track::Track(
		AudioFlinger::PlaybackThread::Track::~Track()
		{
		ALOGV("PlaybackThread::Track destructor");
		// FIXME not sure if safe to log here, would need a lock on thread to do it
		}

		void AudioFlinger::PlaybackThread::Track::destroy()
		@@ -569,7 +571,8 @@ status_t AudioFlinger::PlaybackThread::Track::start(AudioSystem::sync_event_t ev
		sp<ThreadBase> thread = mThread.promote();
		if (thread != 0) {
		Mutex::Autolock _l(thread->mLock);
		thread->mNBLogWriter->logf("start mName=%d", mName);
		thread->mNBLogWriter->logf("start mName=%d mFastIndex=%d caller=%d", mName, mFastIndex,
		IPCThreadState::self()->getCallingPid());
		track_state state = mState;
		// here the track could be either new, or restarted
		// in both cases "unstop" the track
		@@ -612,7 +615,8 @@ void AudioFlinger::PlaybackThread::Track::stop()
		sp<ThreadBase> thread = mThread.promote();
		if (thread != 0) {
		Mutex::Autolock _l(thread->mLock);
		thread->mNBLogWriter->logf("stop mName=%d", mName);
		thread->mNBLogWriter->logf("stop mName=%d mFastIndex=%d caller=%d", mName, mFastIndex,
		IPCThreadState::self()->getCallingPid());
		track_state state = mState;
		if (state == RESUMING \|\| state == ACTIVE \|\| state == PAUSING \|\| state == PAUSED) {
		// If the track is not active (PAUSED and buffers full), flush buffers
		@@ -649,7 +653,8 @@ void AudioFlinger::PlaybackThread::Track::pause()
		sp<ThreadBase> thread = mThread.promote();
		if (thread != 0) {
		Mutex::Autolock _l(thread->mLock);
		thread->mNBLogWriter->logf("pause mName=%d", mName);
		thread->mNBLogWriter->logf("pause mName=%d mFastIndex=%d caller=%d", mName, mFastIndex,
		IPCThreadState::self()->getCallingPid());
		if (mState == ACTIVE \|\| mState == RESUMING) {
		mState = PAUSING;
		ALOGV("ACTIVE/RESUMING => PAUSING (%d) on thread %p", mName, thread.get());
		@@ -673,7 +678,8 @@ void AudioFlinger::PlaybackThread::Track::flush()
		sp<ThreadBase> thread = mThread.promote();
		if (thread != 0) {
		Mutex::Autolock _l(thread->mLock);
		thread->mNBLogWriter->logf("flush mName=%d", mName);
		thread->mNBLogWriter->logf("flush mName=%d mFastIndex=%d caller=%d", mName, mFastIndex,
		IPCThreadState::self()->getCallingPid());
		if (mState != STOPPING_1 && mState != STOPPING_2 && mState != STOPPED && mState != PAUSED &&
		mState != PAUSING && mState != IDLE && mState != FLUSHED) {
		return;