diff --git a/include/private/media/AudioTrackShared.h b/include/private/media/AudioTrackShared.h index ca119d5da1..518cc632cb 100644 --- a/include/private/media/AudioTrackShared.h +++ b/include/private/media/AudioTrackShared.h @@ -538,6 +538,10 @@ public: mTimestampMutator.push(timestamp); } + virtual ExtendedTimestamp getTimestamp() const { + return mTimestampMutator.last(); + } + // Flushes the shared ring buffer if the client had requested it using mStreaming.mFlush. // If flush occurs then: // cblk->u.mStreaming.mFront, ServerProxy::mFlush and ServerProxy::mFlushed will be modified diff --git a/media/libaudioclient/include/media/AudioTimestamp.h b/media/libaudioclient/include/media/AudioTimestamp.h index 498de8e071..bdffdac9ca 100644 --- a/media/libaudioclient/include/media/AudioTimestamp.h +++ b/media/libaudioclient/include/media/AudioTimestamp.h @@ -135,6 +135,21 @@ struct alignas(8) /* bug 29096183, bug 29108507 */ ExtendedTimestamp { return INVALID_OPERATION; } + double getOutputServerLatencyMs(uint32_t sampleRate) const { + return getLatencyMs(sampleRate, LOCATION_SERVER, LOCATION_KERNEL); + } + + double getLatencyMs(uint32_t sampleRate, Location location1, Location location2) const { + if (mTimeNs[location1] > 0 && mTimeNs[location2] > 0) { + const int64_t frameDifference = + mPosition[location1] - mPosition[location2]; + const int64_t timeDifferenceNs = + mTimeNs[location1] - mTimeNs[location2]; + return ((double)frameDifference * 1e9 / sampleRate - timeDifferenceNs) * 1e-6; + } + return 0.; + } + // convert fields to a printable string std::string toString() { std::stringstream ss; diff --git a/services/audioflinger/FastMixer.cpp b/services/audioflinger/FastMixer.cpp index 7a029637de..caeede9263 100644 --- a/services/audioflinger/FastMixer.cpp +++ b/services/audioflinger/FastMixer.cpp @@ -489,6 +489,10 @@ void FastMixer::onWork() timestamp.mPosition[ExtendedTimestamp::LOCATION_KERNEL]; mTimestamp.mTimeNs[ExtendedTimestamp::LOCATION_KERNEL] = timestamp.mTimeNs[ExtendedTimestamp::LOCATION_KERNEL]; + // We don't compensate for server - kernel time difference and + // only update latency if we have valid info. + dumpState->mLatencyMs = + (double)mNativeFramesWrittenButNotPresented * 1000 / mSampleRate; } else { // HAL reported that more frames were presented than were written mNativeFramesWrittenButNotPresented = 0; diff --git a/services/audioflinger/FastMixerDumpState.cpp b/services/audioflinger/FastMixerDumpState.cpp index 2e4fb8ceb5..b3a25203e6 100644 --- a/services/audioflinger/FastMixerDumpState.cpp +++ b/services/audioflinger/FastMixerDumpState.cpp @@ -68,11 +68,11 @@ void FastMixerDumpState::dump(int fd) const dprintf(fd, " FastMixer command=%s writeSequence=%u framesWritten=%u\n" " numTracks=%u writeErrors=%u underruns=%u overruns=%u\n" " sampleRate=%u frameCount=%zu measuredWarmup=%.3g ms, warmupCycles=%u\n" - " mixPeriod=%.2f ms\n", + " mixPeriod=%.2f ms latency=%.2f ms\n", FastMixerState::commandToString(mCommand), mWriteSequence, mFramesWritten, mNumTracks, mWriteErrors, mUnderruns, mOverruns, mSampleRate, mFrameCount, measuredWarmupMs, mWarmupCycles, - mixPeriodSec * 1e3); + mixPeriodSec * 1e3, mLatencyMs); #ifdef FAST_THREAD_STATISTICS // find the interval of valid samples uint32_t bounds = mBounds; diff --git a/services/audioflinger/FastMixerDumpState.h b/services/audioflinger/FastMixerDumpState.h index 8ef31d1f7a..aed6bc598c 100644 --- a/services/audioflinger/FastMixerDumpState.h +++ b/services/audioflinger/FastMixerDumpState.h @@ -66,6 +66,7 @@ struct FastMixerDumpState : FastThreadDumpState { void dump(int fd) const; // should only be called on a stable copy, not the original + double mLatencyMs = 0.; // measured latency, default of 0 if no valid timestamp read. uint32_t mWriteSequence; // incremented before and after each write() uint32_t mFramesWritten; // total number of frames written successfully uint32_t mNumTracks; // total number of active fast tracks diff --git a/services/audioflinger/PlaybackTracks.h b/services/audioflinger/PlaybackTracks.h index ff9444da56..9a8a1544e9 100644 --- a/services/audioflinger/PlaybackTracks.h +++ b/services/audioflinger/PlaybackTracks.h @@ -41,7 +41,7 @@ public: virtual ~Track(); virtual status_t initCheck() const; - static void appendDumpHeader(String8& result); + void appendDumpHeader(String8& result); void appendDump(String8& result, bool active); virtual status_t start(AudioSystem::sync_event_t event = AudioSystem::SYNC_EVENT_NONE, @@ -75,6 +75,7 @@ public: bool isOffloadedOrDirect() const { return (mFlags & (AUDIO_OUTPUT_FLAG_COMPRESS_OFFLOAD | AUDIO_OUTPUT_FLAG_DIRECT)) != 0; } + bool isStatic() const { return mSharedBuffer.get() != nullptr; } status_t setParameters(const String8& keyValuePairs); status_t attachAuxEffect(int EffectId); @@ -93,6 +94,11 @@ public: virtual bool isFastTrack() const { return (mFlags & AUDIO_OUTPUT_FLAG_FAST) != 0; } + virtual double bufferLatencyMs() { + return isStatic() ? 0. + : (double)mAudioTrackServerProxy->framesReadySafe() * 1000 / sampleRate(); + } + // implement volume handling. media::VolumeShaper::Status applyVolumeShaper( const sp& configuration, @@ -194,6 +200,7 @@ protected: sp mVolumeHandler; // handles multiple VolumeShaper configs and operations + bool mDumpLatency = false; // true if track supports latency dumps. private: // The following fields are only for fast tracks, and should be in a subclass int mFastIndex; // index within FastMixerState::mFastTracks[]; diff --git a/services/audioflinger/Threads.cpp b/services/audioflinger/Threads.cpp index 90e2e8e746..e9721fa1d5 100644 --- a/services/audioflinger/Threads.cpp +++ b/services/audioflinger/Threads.cpp @@ -1784,7 +1784,7 @@ void AudioFlinger::PlaybackThread::dumpTracks(int fd, const Vector& ar if (numtracks) { dprintf(fd, " of which %zu are active\n", numactive); result.append(prefix); - Track::appendDumpHeader(result); + mTracks[0]->appendDumpHeader(result); for (size_t i = 0; i < numtracks; ++i) { sp track = mTracks[i]; if (track != 0) { @@ -1804,7 +1804,7 @@ void AudioFlinger::PlaybackThread::dumpTracks(int fd, const Vector& ar result.append(" The following tracks are in the active list but" " not in the track list\n"); result.append(prefix); - Track::appendDumpHeader(result); + mActiveTracks[0]->appendDumpHeader(result); for (size_t i = 0; i < numactive; ++i) { sp track = mActiveTracks[i]; if (mTracks.indexOf(track) < 0) { @@ -5054,6 +5054,10 @@ void AudioFlinger::MixerThread::dumpInternals(int fd, const Vector& ar dprintf(fd, " Thread throttle time (msecs): %u\n", mThreadThrottleTimeMs); dprintf(fd, " AudioMixer tracks: %s\n", mAudioMixer->trackNames().c_str()); dprintf(fd, " Master mono: %s\n", mMasterMono ? "on" : "off"); + const double latencyMs = mTimestamp.getOutputServerLatencyMs(mSampleRate); + if (latencyMs > 0.) { + dprintf(fd, " NormalMixer latency ms: %.2lf\n", latencyMs); + } if (hasFastMixer()) { dprintf(fd, " FastMixer thread %p tid=%d", mFastMixer.get(), mFastMixer->getTid()); diff --git a/services/audioflinger/Tracks.cpp b/services/audioflinger/Tracks.cpp index 824dac767d..6953ebfb53 100644 --- a/services/audioflinger/Tracks.cpp +++ b/services/audioflinger/Tracks.cpp @@ -435,6 +435,7 @@ AudioFlinger::PlaybackThread::Track::Track( } mName = TRACK_NAME_PENDING; + mDumpLatency = thread->type() == ThreadBase::MIXER; #ifdef TEE_SINK mTee.setId(std::string("_") + std::to_string(mThreadIoHandle) + "_" + std::to_string(mId) + @@ -489,13 +490,14 @@ void AudioFlinger::PlaybackThread::Track::destroy() } } -/*static*/ void AudioFlinger::PlaybackThread::Track::appendDumpHeader(String8& result) +void AudioFlinger::PlaybackThread::Track::appendDumpHeader(String8& result) { - result.append("T Name Active Client Session S Flags " + result.appendFormat("T Name Active Client Session S Flags " " Format Chn mask SRate " "ST L dB R dB VS dB " - " Server FrmCnt FrmRdy F Underruns Flushed " - "Main Buf Aux Buf\n"); + " Server FrmCnt FrmRdy F Underruns Flushed" + "%s\n", + mDumpLatency ? " Latency" : ""); } void AudioFlinger::PlaybackThread::Track::appendDump(String8& result, bool active) @@ -504,7 +506,7 @@ void AudioFlinger::PlaybackThread::Track::appendDump(String8& result, bool activ switch (mType) { case TYPE_DEFAULT: case TYPE_OUTPUT: - if (mSharedBuffer.get() != nullptr) { + if (isStatic()) { trackType = 'S'; // static } else { trackType = ' '; // normal @@ -582,8 +584,7 @@ void AudioFlinger::PlaybackThread::Track::appendDump(String8& result, bool activ result.appendFormat("%7s %6u %7u %2s 0x%03X " "%08X %08X %6u " "%2u %5.2g %5.2g %5.2g%c " - "%08X %6zu%c %6zu %c %9u%c %7u " - "%08zX %08zX\n", + "%08X %6zu%c %6zu %c %9u%c %7u", active ? "yes" : "no", (mClient == 0) ? getpid() : mClient->pid(), mSessionId, @@ -607,11 +608,19 @@ void AudioFlinger::PlaybackThread::Track::appendDump(String8& result, bool activ fillingStatus, mAudioTrackServerProxy->getUnderrunFrames(), nowInUnderrun, - (unsigned)mAudioTrackServerProxy->framesFlushed() % 10000000, - - (size_t)mMainBuffer, // use %zX as %p appends 0x - (size_t)mAuxBuffer // use %zX as %p appends 0x + (unsigned)mAudioTrackServerProxy->framesFlushed() % 10000000 ); + if (mDumpLatency) { + double latencyMs = + mAudioTrackServerProxy->getTimestamp().getOutputServerLatencyMs(mSampleRate); + if (latencyMs > 0.) { + latencyMs += bufferLatencyMs(); + result.appendFormat(" %7.3f", latencyMs); + } else { + result.appendFormat(" Unknown"); + } + } + result.append("\n"); } uint32_t AudioFlinger::PlaybackThread::Track::sampleRate() const {