AudioFlinger: Add thread statistics for process and io timing (446f4df5) · Commits · e / os / android_frameworks_av

services/audioflinger/Threads.cpp

+100 −39

Original line number	Diff line number	Diff line
		@@ -872,6 +872,22 @@ void AudioFlinger::ThreadBase::dumpBase(int fd, const Vector<String16>& args __u
		dprintf(fd, " Timestamp corrected: %s\n", isTimestampCorrectionEnabled() ? "yes" : "no");
		}

		if (mLastIoBeginNs > 0) { // MMAP may not set this
		dprintf(fd, " Last %s occurred (msecs): %lld\n",
		isOutput() ? "write" : "read",
		(long long) (systemTime() - mLastIoBeginNs) / NANOS_PER_MILLISECOND);
		}

		if (mProcessTimeMs.getN() > 0) {
		dprintf(fd, " Process time ms stats: %s\n", mProcessTimeMs.toString().c_str());
		}

		if (mIoJitterMs.getN() > 0) {
		dprintf(fd, " Hal %s jitter ms stats: %s\n",
		isOutput() ? "write" : "read",
		mIoJitterMs.toString().c_str());
		}

		if (locked) {
		mLock.unlock();
		}
		@@ -1704,7 +1720,7 @@ AudioFlinger::PlaybackThread::PlaybackThread(const sp<AudioFlinger>& audioFlinge
		// mStreamTypes[] initialized in constructor body
		mTracks(type == MIXER),
		mOutput(output),
		mLastWriteTime(-1), mNumWrites(0), mNumDelayedWrites(0), mInWrite(false),
		mNumWrites(0), mNumDelayedWrites(0), mInWrite(false),
		mMixerStatus(MIXER_IDLE),
		mMixerStatusIgnoringFastTracks(MIXER_IDLE),
		mStandbyDelayNs(AudioFlinger::mStandbyTimeInNsecs),
		@@ -1857,8 +1873,6 @@ void AudioFlinger::PlaybackThread::dumpInternals(int fd, const Vector<String16>&
		channelMaskToString(mHapticChannelMask, true /* output */).c_str());
		}
		dprintf(fd, " Normal frame count: %zu\n", mNormalFrameCount);
		dprintf(fd, " Last write occurred (msecs): %llu\n",
		(unsigned long long) ns2ms(systemTime() - mLastWriteTime));
		dprintf(fd, " Total writes: %d\n", mNumWrites);
		dprintf(fd, " Delayed writes: %d\n", mNumDelayedWrites);
		dprintf(fd, " Blocked in write: %s\n", mInWrite ? "yes" : "no");
		@@ -3189,7 +3203,7 @@ bool AudioFlinger::PlaybackThread::threadLoop()
		Vector< sp<Track> > tracksToRemove;

		mStandbyTimeNs = systemTime();
		nsecs_t lastWriteFinished = -1; // time last server write completed
		int64_t lastLoopCountWritten = -2; // never matches "previous" loop, when loopCount = 0.
		int64_t lastFramesWritten = -1; // track changes in timestamp server frames written

		// MIXER
		@@ -3236,7 +3250,8 @@ bool AudioFlinger::PlaybackThread::threadLoop()
		}
		audio_patch_handle_t lastDownstreamPatchHandle = AUDIO_PATCH_HANDLE_NONE;

		while (!exitPending())
		// loopCount is used for statistics and diagnostics.
		for (int64_t loopCount = 0; !exitPending(); ++loopCount)
		{
		// Log merge requests are performed during AudioFlinger binder transactions, but
		// that does not cover audio playback. It's requested here for that reason.
		@@ -3394,11 +3409,11 @@ bool AudioFlinger::PlaybackThread::threadLoop()
		// use the time before we called the HAL write - it is a bit more accurate
		// to when the server last read data than the current time here.
		//
		// If we haven't written anything, mLastWriteTime will be -1
		// If we haven't written anything, mLastIoBeginNs will be -1
		// and we use systemTime().
		mTimestamp.mPosition[ExtendedTimestamp::LOCATION_SERVER] = mFramesWritten;
		mTimestamp.mTimeNs[ExtendedTimestamp::LOCATION_SERVER] = mLastWriteTime == -1
		? systemTime() : mLastWriteTime;
		mTimestamp.mTimeNs[ExtendedTimestamp::LOCATION_SERVER] = mLastIoBeginNs == -1
		? systemTime() : mLastIoBeginNs;
		}

		for (const sp<Track> &t : mActiveTracks) {
		@@ -3635,43 +3650,68 @@ bool AudioFlinger::PlaybackThread::threadLoop()
		// mSleepTimeUs == 0 means we must write to audio hardware
		if (mSleepTimeUs == 0) {
		ssize_t ret = 0;
		// We save lastWriteFinished here, as previousLastWriteFinished,
		// for throttling. On thread start, previousLastWriteFinished will be
		// set to -1, which properly results in no throttling after the first write.
		nsecs_t previousLastWriteFinished = lastWriteFinished;
		nsecs_t delta = 0;
		// writePeriodNs is updated >= 0 when ret > 0.
		int64_t writePeriodNs = -1;
		if (mBytesRemaining) {
		// FIXME rewrite to reduce number of system calls
		mLastWriteTime = systemTime(); // also used for dumpsys
		const int64_t lastIoBeginNs = systemTime();
		ret = threadLoop_write();
		lastWriteFinished = systemTime();
		delta = lastWriteFinished - mLastWriteTime;
		const int64_t lastIoEndNs = systemTime();
		if (ret < 0) {
		mBytesRemaining = 0;
		} else {
		} else if (ret > 0) {
		mBytesWritten += ret;
		mBytesRemaining -= ret;
		mFramesWritten += ret / mFrameSize;
		}
		} else if ((mMixerStatus == MIXER_DRAIN_TRACK) \|\|
		(mMixerStatus == MIXER_DRAIN_ALL)) {
		threadLoop_drain();
		const int64_t frames = ret / mFrameSize;
		mFramesWritten += frames;

		writePeriodNs = lastIoEndNs - mLastIoEndNs;
		// process information relating to write time.
		if (audio_has_proportional_frames(mFormat)) {
		// we are in a continuous mixing cycle
		if (mMixerStatus == MIXER_TRACKS_READY &&
		loopCount == lastLoopCountWritten + 1) {

		const double jitterMs =
		TimestampVerifier<int64_t, int64_t>::computeJitterMs(
		{frames, writePeriodNs},
		{0, 0} /* lastTimestamp */, mSampleRate);
		const double processMs =
		(lastIoBeginNs - mLastIoEndNs) * 1e-6;

		Mutex::Autolock _l(mLock);
		mIoJitterMs.add(jitterMs);
		mProcessTimeMs.add(processMs);
		}
		if (mType == MIXER && !mStandby) {

		// write blocked detection
		if (delta > maxPeriod) {
		const int64_t deltaWriteNs = lastIoEndNs - lastIoBeginNs;
		if (mType == MIXER && deltaWriteNs > maxPeriod) {
		mNumDelayedWrites++;
		if ((lastWriteFinished - lastWarning) > kWarningThrottleNs) {
		if ((lastIoEndNs - lastWarning) > kWarningThrottleNs) {
		ATRACE_NAME("underrun");
		ALOGW("write blocked for %llu msecs, %d delayed writes, thread %p",
		(unsigned long long) ns2ms(delta), mNumDelayedWrites, this);
		lastWarning = lastWriteFinished;
		ALOGW("write blocked for %lld msecs, "
		"%d delayed writes, thread %d",
		(long long)deltaWriteNs / NANOS_PER_MILLISECOND,
		mNumDelayedWrites, mId);
		lastWarning = lastIoEndNs;
		}
		}
		}
		// update timing info.
		mLastIoBeginNs = lastIoBeginNs;
		mLastIoEndNs = lastIoEndNs;
		lastLoopCountWritten = loopCount;
		}
		} else if ((mMixerStatus == MIXER_DRAIN_TRACK) \|\|
		(mMixerStatus == MIXER_DRAIN_ALL)) {
		threadLoop_drain();
		}
		if (mType == MIXER && !mStandby) {

		if (mThreadThrottle
		&& mMixerStatus == MIXER_TRACKS_READY // we are mixing (active tracks)
		&& ret > 0) { // we wrote something
		&& writePeriodNs > 0) { // we have write period info
		// Limit MixerThread data processing to no more than twice the
		// expected processing rate.
		//
		@@ -3690,12 +3730,9 @@ bool AudioFlinger::PlaybackThread::threadLoop()
		// 2. threadLoop_mix (significant for heavy mixing, especially
		// on low tier processors)

		// it's OK if deltaMs (and deltaNs) is an overestimate.
		nsecs_t deltaNs;
		// deltaNs = lastWriteFinished - previousLastWriteFinished;
		__builtin_sub_overflow(
		lastWriteFinished,previousLastWriteFinished, &deltaNs);
		const int32_t deltaMs = deltaNs / 1000000;
		// it's OK if deltaMs is an overestimate.

		const int32_t deltaMs = writePeriodNs / NANOS_PER_MILLISECOND;

		const int32_t throttleMs = (int32_t)mHalfBufferMs - deltaMs;
		if ((signed)mHalfBufferMs >= throttleMs && throttleMs > 0) {
		@@ -3708,7 +3745,8 @@ bool AudioFlinger::PlaybackThread::threadLoop()
		mThreadThrottleTimeMs += throttleMs;
		// Throttle must be attributed to the previous mixer loop's write time
		// to allow back-to-back throttling.
		lastWriteFinished += throttleMs * 1000000;
		// This also ensures proper timing statistics.
		mLastIoEndNs = systemTime(); // we fetch the write end time again.
		} else {
		uint32_t diff = mThreadThrottleTimeMs - mThreadThrottleEndMs;
		if (diff > 0) {
		@@ -6751,8 +6789,10 @@ reacquire_wakelock:
		// used to request a deferred sleep, to be executed later while mutex is unlocked
		uint32_t sleepUs = 0;

		int64_t lastLoopCountRead = -2; // never matches "previous" loop, when loopCount = 0.

		// loop while there is work to do
		for (;;) {
		for (int64_t loopCount = 0;; ++loopCount) { // loopCount used for statistics tracking
		Vector< sp<EffectChain> > effectChains;

		// activeTracks accumulates a copy of a subset of mActiveTracks
		@@ -6951,6 +6991,7 @@ reacquire_wakelock:

		int32_t rear = mRsmpInRear & (mRsmpInFramesP2 - 1);
		ssize_t framesRead;
		const int64_t lastIoBeginNs = systemTime(); // start IO timing

		// If an NBAIO source is present, use it to read the normal capture's data
		if (mPipeSource != 0) {
		@@ -7008,10 +7049,12 @@ reacquire_wakelock:
		}
		}

		const int64_t lastIoEndNs = systemTime(); // end IO timing

		// Update server timestamp with server stats
		// systemTime() is optional if the hardware supports timestamps.
		mTimestamp.mPosition[ExtendedTimestamp::LOCATION_SERVER] += framesRead;
		mTimestamp.mTimeNs[ExtendedTimestamp::LOCATION_SERVER] = systemTime();
		mTimestamp.mTimeNs[ExtendedTimestamp::LOCATION_SERVER] = lastIoEndNs;

		// Update server timestamp with kernel stats
		if (mPipeSource.get() == nullptr /* don't obtain for FastCapture, could block */) {
		@@ -7060,6 +7103,24 @@ reacquire_wakelock:
		ALOG_ASSERT(framesRead > 0);
		mFramesRead += framesRead;

		if (audio_has_proportional_frames(mFormat)
		&& loopCount == lastLoopCountRead + 1) {
		const int64_t readPeriodNs = lastIoEndNs - mLastIoEndNs;
		const double jitterMs =
		TimestampVerifier<int64_t, int64_t>::computeJitterMs(
		{framesRead, readPeriodNs},
		{0, 0} /* lastTimestamp */, mSampleRate);
		const double processMs = (lastIoBeginNs - mLastIoEndNs) * 1e-6;

		Mutex::Autolock _l(mLock);
		mIoJitterMs.add(jitterMs);
		mProcessTimeMs.add(processMs);
		}
		// update timing info.
		mLastIoBeginNs = lastIoBeginNs;
		mLastIoEndNs = lastIoEndNs;
		lastLoopCountRead = loopCount;

		#ifdef TEE_SINK
		(void)mTee.write((uint8_t)mRsmpInBuffer + rear mFrameSize, framesRead);
		#endif

services/audioflinger/Threads.h

+9 −1

Original line number	Diff line number	Diff line
		@@ -512,6 +512,15 @@ protected:
		TimestampVerifier< // For timestamp statistics.
		int64_t /* frame count /, int64_t / time ns */> mTimestampVerifier;
		audio_devices_t mTimestampCorrectedDevices = AUDIO_DEVICE_NONE;

		// ThreadLoop statistics per iteration.
		int64_t mLastIoBeginNs = -1;
		int64_t mLastIoEndNs = -1;

		// This should be read under ThreadBase lock (if not on the threadLoop thread).
		audio_utils::Statistics<double> mIoJitterMs{0.995 /* alpha */};
		audio_utils::Statistics<double> mProcessTimeMs{0.995 /* alpha */};

		bool mIsMsdDevice = false;
		// A condition that must be evaluated by the thread loop has changed and
		// we must not wait for async write callback in the thread loop before evaluating it
		@@ -1030,7 +1039,6 @@ private:
		float mMasterVolume;
		std::atomic<float> mMasterBalance{};
		audio_utils::Balance mBalance;
		nsecs_t mLastWriteTime;
		int mNumWrites;
		int mNumDelayedWrites;
		bool mInWrite;