gugelfrei
/
android_frameworks_av
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

Merge "AudioFlinger: Add thread statistics for process and io timing"

Browse Source
gugelfrei
Andy Hung 5 years ago committed by Android (Google) Code Review
parent ea69bfb0f5 446f4df547
commit a666d61efb
2 changed files with 109 additions and 40 deletions
Show Stats Download Patch File Download Diff File

139
services/audioflinger/Threads.cpp
Unescape View File

@ -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,8 +3203,8 @@ bool AudioFlinger::PlaybackThread::threadLoop()
Vector< sp<Track> > tracksToRemove;
mStandbyTimeNs = systemTime();
nsecs_t lastWriteFinished = -1; // time last server write completed
int64_t lastFramesWritten = -1; // track changes in timestamp server frames written
int64_t lastLoopCountWritten = -2; // never matches "previous" loop, when loopCount = 0.
int64_t lastFramesWritten = -1; // track changes in timestamp server frames written
// MIXER
nsecs_t lastWarning = 0;
@ -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;
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);
}
// write blocked detection
const int64_t deltaWriteNs = lastIoEndNs - lastIoBeginNs;
if (mType == MIXER && deltaWriteNs > maxPeriod) {
mNumDelayedWrites++;
if ((lastIoEndNs - lastWarning) > kWarningThrottleNs) {
ATRACE_NAME("underrun");
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) {
// write blocked detection
if (delta > maxPeriod) {
mNumDelayedWrites++;
if ((lastWriteFinished - 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;
}
}
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

10
services/audioflinger/Threads.h
Unescape View File

@ -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;

Write Preview
Loading…
Cancel
Save