Log audio information to ensure complete delivery
Test: Audio playback
Bug: 30572472
Change-Id: Ibad6fc202692cd3480ae726627252afdead083f3
diff --git a/media/libmedia/AudioTrack.cpp b/media/libmedia/AudioTrack.cpp
index 7663fef..d322f05 100644
--- a/media/libmedia/AudioTrack.cpp
+++ b/media/libmedia/AudioTrack.cpp
@@ -653,6 +653,8 @@
mState = STATE_STOPPING;
} else {
mState = STATE_STOPPED;
+ ALOGD_IF(mSharedBuffer == nullptr,
+ "stop() called with %u frames delivered", mReleased.value());
mReleased = 0;
}
diff --git a/services/audioflinger/AudioFlinger.h b/services/audioflinger/AudioFlinger.h
index c56dcc1..d791e13 100644
--- a/services/audioflinger/AudioFlinger.h
+++ b/services/audioflinger/AudioFlinger.h
@@ -19,6 +19,7 @@
#define ANDROID_AUDIO_FLINGER_H
#include "Configuration.h"
+#include <deque>
#include <stdint.h>
#include <sys/types.h>
#include <limits.h>
diff --git a/services/audioflinger/Threads.cpp b/services/audioflinger/Threads.cpp
index 0f403ae..14a7b8b 100644
--- a/services/audioflinger/Threads.cpp
+++ b/services/audioflinger/Threads.cpp
@@ -1737,6 +1737,7 @@
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)
@@ -2201,6 +2202,10 @@
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;
}
@@ -2226,6 +2231,11 @@
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
@@ -3421,6 +3431,10 @@
}
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);
}
}
}
@@ -3872,6 +3886,15 @@
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++;
diff --git a/services/audioflinger/Threads.h b/services/audioflinger/Threads.h
index f353f3b..854e203 100644
--- a/services/audioflinger/Threads.h
+++ b/services/audioflinger/Threads.h
@@ -862,6 +862,78 @@
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
diff --git a/services/audioflinger/Tracks.cpp b/services/audioflinger/Tracks.cpp
index ba6e6e5..348cac4 100644
--- a/services/audioflinger/Tracks.cpp
+++ b/services/audioflinger/Tracks.cpp
@@ -461,7 +461,7 @@
/*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)
@@ -528,7 +528,7 @@
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,
@@ -542,11 +542,12 @@
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 {
