Log audio information to ensure complete delivery (2148bf0e) · Commits · e / os / android_frameworks_av

media/libaudioclient/AudioTrack.cpp

+2 −0

Original line number	Diff line number	Diff line
		@@ -671,6 +671,8 @@ void AudioTrack::stop()
		mState = STATE_STOPPING;
		} else {
		mState = STATE_STOPPED;
		ALOGD_IF(mSharedBuffer == nullptr,
		"stop() called with %u frames delivered", mReleased.value());
		mReleased = 0;
		}

services/audioflinger/AudioFlinger.h

+1 −0

Original line number	Diff line number	Diff line
		@@ -19,6 +19,7 @@
		#define ANDROID_AUDIO_FLINGER_H

		#include "Configuration.h"
		#include <deque>
		#include <stdint.h>
		#include <sys/types.h>
		#include <limits.h>

services/audioflinger/Threads.cpp

+23 −0

Original line number	Diff line number	Diff line
		@@ -1602,6 +1602,7 @@ void AudioFlinger::PlaybackThread::dump(int fd, const Vector<String16>& args)
		dumpInternals(fd, args);
		dumpTracks(fd, args);
		dumpEffectChains(fd, args);
		mLocalLog.dump(fd, args, " " /* prefix */);
		}

		void AudioFlinger::PlaybackThread::dumpTracks(int fd, const Vector<String16>& args __unused)
		@@ -2072,6 +2073,10 @@ status_t AudioFlinger::PlaybackThread::addTrack_l(const sp<Track>& track)
		chain->incActiveTrackCnt();
		}

		char buffer[256];
		track->dump(buffer, ARRAY_SIZE(buffer), false /* active */);
		mLocalLog.log("addTrack_l (%p) %s", track.get(), buffer + 4); // log for analysis

		status = NO_ERROR;
		}

		@@ -2097,6 +2102,11 @@ bool AudioFlinger::PlaybackThread::destroyTrack_l(const sp<Track>& track)
		void AudioFlinger::PlaybackThread::removeTrack_l(const sp<Track>& track)
		{
		track->triggerEvents(AudioSystem::SYNC_EVENT_PRESENTATION_COMPLETE);

		char buffer[256];
		track->dump(buffer, ARRAY_SIZE(buffer), false /* active */);
		mLocalLog.log("removeTrack_l (%p) %s", track.get(), buffer + 4); // log for analysis

		mTracks.remove(track);
		deleteTrackName_l(track->name());
		// redundant as track is about to be destroyed, for dumpsys only
		@@ -3264,6 +3274,10 @@ void AudioFlinger::PlaybackThread::removeTracks_l(const Vector< sp<Track> >& tra
		}
		if (track->isTerminated()) {
		removeTrack_l(track);
		} else { // inactive but not terminated
		char buffer[256];
		track->dump(buffer, ARRAY_SIZE(buffer), false /* active */);
		mLocalLog.log("removeTracks_l(%p) %s", track.get(), buffer + 4);
		}
		}
		}
		@@ -3710,6 +3724,15 @@ void AudioFlinger::MixerThread::threadLoop_standby()
		FastMixerStateQueue *sq = mFastMixer->sq();
		FastMixerState *state = sq->begin();
		if (!(state->mCommand & FastMixerState::IDLE)) {
		// Report any frames trapped in the Monopipe
		MonoPipe monoPipe = (MonoPipe )mPipeSink.get();
		const long long pipeFrames = monoPipe->maxFrames() - monoPipe->availableToWrite();
		mLocalLog.log("threadLoop_standby: framesWritten:%lld suspendedFrames:%lld "
		"monoPipeWritten:%lld monoPipeLeft:%lld",
		(long long)mFramesWritten, (long long)mSuspendedFrames,
		(long long)mPipeSink->framesWritten(), pipeFrames);
		mLocalLog.log("threadLoop_standby: %s", mTimestamp.toString().c_str());

		state->mCommand = FastMixerState::COLD_IDLE;
		state->mColdFutexAddr = &mFastMixerFutex;
		state->mColdGen++;

services/audioflinger/Threads.h

+72 −0

Original line number	Diff line number	Diff line
		@@ -861,6 +861,78 @@ private:
		uint32_t mScreenState; // cached copy of gScreenState
		static const size_t kFastMixerLogSize = 4 * 1024;
		sp<NBLog::Writer> mFastMixerNBLogWriter;

		// Do not call from a sched_fifo thread as it uses a system time call
		// and obtains a local mutex.
		class LocalLog {
		public:
		void log(const char *fmt, ...) {
		va_list val;
		va_start(val, fmt);

		// format to buffer
		char buffer[512];
		int length = vsnprintf(buffer, sizeof(buffer), fmt, val);
		if (length >= (signed)sizeof(buffer)) {
		length = sizeof(buffer) - 1;
		}

		// strip out trailing newline
		while (length > 0 && buffer[length - 1] == '\n') {
		buffer[--length] = 0;
		}

		// store in circular array
		AutoMutex _l(mLock);
		mLog.emplace_back(
		std::make_pair(systemTime(SYSTEM_TIME_REALTIME), std::string(buffer)));
		if (mLog.size() > kLogSize) {
		mLog.pop_front();
		}

		va_end(val);
		}

		void dump(int fd, const Vector<String16>& args, const char *prefix = "") {
		if (!AudioFlinger::dumpTryLock(mLock)) return; // a local lock, shouldn't happen
		if (mLog.size() > 0) {
		bool dumpAll = false;
		for (const auto &arg : args) {
		if (arg == String16("--locallog")) {
		dumpAll = true;
		}
		}

		dprintf(fd, "Local Log:\n");
		auto it = mLog.begin();
		if (!dumpAll && mLog.size() > kLogPrint) {
		it += (mLog.size() - kLogPrint);
		}
		for (; it != mLog.end(); ++it) {
		const int64_t ns = it->first;
		const int ns_per_sec = 1000000000;
		const time_t sec = ns / ns_per_sec;
		struct tm tm;
		localtime_r(&sec, &tm);

		dprintf(fd, "%s%02d-%02d %02d:%02d:%02d.%03d %s\n",
		prefix,
		tm.tm_mon + 1, // localtime_r uses months in 0 - 11 range
		tm.tm_mday, tm.tm_hour, tm.tm_min, tm.tm_sec,
		(int)(ns % ns_per_sec / 1000000),
		it->second.c_str());
		}
		}
		mLock.unlock();
		}

		private:
		Mutex mLock;
		static const size_t kLogSize = 256; // full history
		static const size_t kLogPrint = 32; // default print history
		std::deque<std::pair<int64_t, std::string>> mLog;
		} mLocalLog;

		public:
		virtual bool hasFastMixer() const = 0;
		virtual FastTrackUnderruns getFastTrackUnderruns(size_t fastIndex __unused) const

services/audioflinger/Tracks.cpp

+6 −5

Original line number	Diff line number	Diff line
		@@ -459,7 +459,7 @@ void AudioFlinger::PlaybackThread::Track::destroy()
		/static/ void AudioFlinger::PlaybackThread::Track::appendDumpHeader(String8& result)
		{
		result.append(" Name Active Client Type Fmt Chn mask Session fCount S F SRate "
		"L dB R dB Server Main buf Aux Buf Flags UndFrmCnt\n");
		"L dB R dB Server Main buf Aux buf Flags UndFrmCnt Flushed\n");
		}

		void AudioFlinger::PlaybackThread::Track::dump(char* buffer, size_t size, bool active)
		@@ -526,7 +526,7 @@ void AudioFlinger::PlaybackThread::Track::dump(char* buffer, size_t size, bool a
		break;
		}
		snprintf(&buffer[8], size-8, " %6s %6u %4u %08X %08X %7u %6zu %1c %1d %5u %5.2g %5.2g "
		"%08X %p %p 0x%03X %9u%c\n",
		"%08X %08zX %08zX 0x%03X %9u%c %7u\n",
		active ? "yes" : "no",
		(mClient == 0) ? getpid_cached : mClient->pid(),
		mStreamType,
		@@ -540,11 +540,12 @@ void AudioFlinger::PlaybackThread::Track::dump(char* buffer, size_t size, bool a
		20.0 * log10(float_from_gain(gain_minifloat_unpack_left(vlr))),
		20.0 * log10(float_from_gain(gain_minifloat_unpack_right(vlr))),
		mCblk->mServer,
		mMainBuffer,
		mAuxBuffer,
		(size_t)mMainBuffer, // use %zX as %p appends 0x
		(size_t)mAuxBuffer, // use %zX as %p appends 0x
		mCblk->mFlags,
		mAudioTrackServerProxy->getUnderrunFrames(),
		nowInUnderrun);
		nowInUnderrun,
		(unsigned)mAudioTrackServerProxy->framesFlushed() % 10000000); // 7 digits
		}

		uint32_t AudioFlinger::PlaybackThread::Track::sampleRate() const {