AudioFlinger: Log Record and MMap thread events
Also update track dump for better grouping and consistency.
Test: adb shell dumpsys media.audio_flinger
Bug: 62700410
Bug: 62701585
Change-Id: I3a6e76eac871cb08ff14d45f7d3992a6e7fba045
diff --git a/services/audioflinger/MmapTracks.h b/services/audioflinger/MmapTracks.h
index 2a27dfd..366a164 100644
--- a/services/audioflinger/MmapTracks.h
+++ b/services/audioflinger/MmapTracks.h
@@ -28,6 +28,7 @@
audio_channel_mask_t channelMask,
audio_session_t sessionId,
uid_t uid,
+ pid_t pid,
audio_port_handle_t portId = AUDIO_PORT_HANDLE_NONE);
virtual ~MmapTrack();
@@ -39,7 +40,7 @@
virtual bool isFastTrack() const { return false; }
static void appendDumpHeader(String8& result);
- void dump(char* buffer, size_t size);
+ void appendDump(String8& result, bool active);
private:
friend class MmapThread;
@@ -55,5 +56,6 @@
virtual int64_t framesReleased() const;
virtual void onTimestamp(const ExtendedTimestamp ×tamp);
+ pid_t mPid;
}; // end of Track
diff --git a/services/audioflinger/PlaybackTracks.h b/services/audioflinger/PlaybackTracks.h
index af644ed..1c1a989 100644
--- a/services/audioflinger/PlaybackTracks.h
+++ b/services/audioflinger/PlaybackTracks.h
@@ -41,7 +41,7 @@
virtual status_t initCheck() const;
static void appendDumpHeader(String8& result);
- void dump(char* buffer, size_t size, bool active);
+ void appendDump(String8& result, bool active);
virtual status_t start(AudioSystem::sync_event_t event =
AudioSystem::SYNC_EVENT_NONE,
audio_session_t triggerSession = AUDIO_SESSION_NONE);
diff --git a/services/audioflinger/RecordTracks.h b/services/audioflinger/RecordTracks.h
index 071a329..f8da780 100644
--- a/services/audioflinger/RecordTracks.h
+++ b/services/audioflinger/RecordTracks.h
@@ -51,7 +51,7 @@
return tmp; }
static void appendDumpHeader(String8& result);
- void dump(char* buffer, size_t size, bool active);
+ void appendDump(String8& result, bool active);
void handleSyncStartEvent(const sp<SyncEvent>& event);
void clearSyncStartEvent();
diff --git a/services/audioflinger/Threads.cpp b/services/audioflinger/Threads.cpp
index 753901f..a9fb766 100644
--- a/services/audioflinger/Threads.cpp
+++ b/services/audioflinger/Threads.cpp
@@ -1549,6 +1549,7 @@
ALOGW("ActiveTracks<T>::add track %p already there", track.get());
return index;
}
+ logTrack("add", track);
mActiveTracksGeneration++;
mLatestActiveTrack = track;
++mBatteryCounter[track->uid()].second;
@@ -1562,6 +1563,7 @@
ALOGW("ActiveTracks<T>::remove nonexistent track %p", track.get());
return index;
}
+ logTrack("remove", track);
mActiveTracksGeneration++;
--mBatteryCounter[track->uid()].second;
// mLatestActiveTrack is not cleared even if is the same as track.
@@ -1572,6 +1574,7 @@
void AudioFlinger::ThreadBase::ActiveTracks<T>::clear() {
for (const sp<T> &track : mActiveTracks) {
BatteryNotifier::getInstance().noteStopAudio(track->uid());
+ logTrack("clear", track);
}
mLastActiveTracksGeneration = mActiveTracksGeneration;
mActiveTracks.clear();
@@ -1610,6 +1613,16 @@
}
}
+template <typename T>
+void AudioFlinger::ThreadBase::ActiveTracks<T>::logTrack(
+ const char *funcName, const sp<T> &track) const {
+ if (mLocalLog != nullptr) {
+ String8 result;
+ track->appendDump(result, false /* active */);
+ mLocalLog->log("AT::%-10s(%p) %s", funcName, track.get(), result.string());
+ }
+}
+
void AudioFlinger::ThreadBase::broadcast_l()
{
// Thread could be blocked waiting for async
@@ -1645,6 +1658,7 @@
mSuspended(0), mBytesWritten(0),
mFramesWritten(0),
mSuspendedFrames(0),
+ mActiveTracks(&this->mLocalLog),
// mStreamTypes[] initialized in constructor body
mOutput(output),
mLastWriteTime(-1), mNumWrites(0), mNumDelayedWrites(0), mInWrite(false),
@@ -1712,8 +1726,6 @@
void AudioFlinger::PlaybackThread::dumpTracks(int fd, const Vector<String16>& args __unused)
{
- const size_t SIZE = 256;
- char buffer[SIZE];
String8 result;
result.appendFormat(" Stream volumes in dB: ");
@@ -1740,8 +1752,10 @@
size_t numactive = mActiveTracks.size();
dprintf(fd, " %zu Tracks", numtracks);
size_t numactiveseen = 0;
+ const char *prefix = " ";
if (numtracks) {
dprintf(fd, " of which %zu are active\n", numactive);
+ result.append(prefix);
Track::appendDumpHeader(result);
for (size_t i = 0; i < numtracks; ++i) {
sp<Track> track = mTracks[i];
@@ -1750,8 +1764,8 @@
if (active) {
numactiveseen++;
}
- track->dump(buffer, SIZE, active);
- result.append(buffer);
+ result.append(prefix);
+ track->appendDump(result, active);
}
}
} else {
@@ -1759,15 +1773,15 @@
}
if (numactiveseen != numactive) {
// some tracks in the active list were not in the tracks list
- snprintf(buffer, SIZE, " The following tracks are in the active list but"
+ result.append(" The following tracks are in the active list but"
" not in the track list\n");
- result.append(buffer);
+ result.append(prefix);
Track::appendDumpHeader(result);
for (size_t i = 0; i < numactive; ++i) {
sp<Track> track = mActiveTracks[i];
if (mTracks.indexOf(track) < 0) {
- track->dump(buffer, SIZE, true);
- result.append(buffer);
+ result.append(prefix);
+ track->appendDump(result, true /* active */);
}
}
}
@@ -2178,10 +2192,6 @@
chain->incActiveTrackCnt();
}
- char buffer[256];
- track->dump(buffer, arraysize(buffer), false /* active */);
- mLocalLog.log("addTrack_l (%p) %s", track.get(), buffer + 4); // log for analysis
-
status = NO_ERROR;
}
@@ -2208,9 +2218,9 @@
{
track->triggerEvents(AudioSystem::SYNC_EVENT_PRESENTATION_COMPLETE);
- char buffer[256];
- track->dump(buffer, arraysize(buffer), false /* active */);
- mLocalLog.log("removeTrack_l (%p) %s", track.get(), buffer + 4); // log for analysis
+ String8 result;
+ track->appendDump(result, false /* active */);
+ mLocalLog.log("removeTrack_l (%p) %s", track.get(), result.string());
mTracks.remove(track);
deleteTrackName_l(track->name());
@@ -3410,10 +3420,6 @@
}
if (track->isTerminated()) {
removeTrack_l(track);
- } else { // inactive but not terminated
- char buffer[256];
- track->dump(buffer, arraysize(buffer), false /* active */);
- mLocalLog.log("removeTracks_l(%p) %s", track.get(), buffer + 4);
}
}
}
@@ -5931,7 +5937,9 @@
#endif
) :
ThreadBase(audioFlinger, id, outDevice, inDevice, RECORD, systemReady),
- mInput(input), mRsmpInBuffer(NULL),
+ mInput(input),
+ mActiveTracks(&this->mLocalLog),
+ mRsmpInBuffer(NULL),
// mRsmpInFrames, mRsmpInFramesP2, and mRsmpInFramesOA are set by readInputParameters_l()
mRsmpInRear(0)
#ifdef TEE_SINK
@@ -6900,6 +6908,10 @@
void AudioFlinger::RecordThread::removeTrack_l(const sp<RecordTrack>& track)
{
+ String8 result;
+ track->appendDump(result, false /* active */);
+ mLocalLog.log("removeTrack_l (%p) %s", track.get(), result.string());
+
mTracks.remove(track);
// need anything related to effects here?
if (track->isFastTrack()) {
@@ -6913,6 +6925,8 @@
dumpInternals(fd, args);
dumpTracks(fd, args);
dumpEffectChains(fd, args);
+ dprintf(fd, " Local log:\n");
+ mLocalLog.dump(fd, " " /* prefix */, 40 /* lines */);
}
void AudioFlinger::RecordThread::dumpInternals(int fd, const Vector<String16>& args)
@@ -6946,16 +6960,15 @@
void AudioFlinger::RecordThread::dumpTracks(int fd, const Vector<String16>& args __unused)
{
- const size_t SIZE = 256;
- char buffer[SIZE];
String8 result;
-
size_t numtracks = mTracks.size();
size_t numactive = mActiveTracks.size();
size_t numactiveseen = 0;
dprintf(fd, " %zu Tracks", numtracks);
+ const char *prefix = " ";
if (numtracks) {
dprintf(fd, " of which %zu are active\n", numactive);
+ result.append(prefix);
RecordTrack::appendDumpHeader(result);
for (size_t i = 0; i < numtracks ; ++i) {
sp<RecordTrack> track = mTracks[i];
@@ -6964,8 +6977,8 @@
if (active) {
numactiveseen++;
}
- track->dump(buffer, SIZE, active);
- result.append(buffer);
+ result.append(prefix);
+ track->appendDump(result, active);
}
}
} else {
@@ -6973,15 +6986,15 @@
}
if (numactiveseen != numactive) {
- snprintf(buffer, SIZE, " The following tracks are in the active list but"
+ result.append(" The following tracks are in the active list but"
" not in the track list\n");
- result.append(buffer);
+ result.append(prefix);
RecordTrack::appendDumpHeader(result);
for (size_t i = 0; i < numactive; ++i) {
sp<RecordTrack> track = mActiveTracks[i];
if (mTracks.indexOf(track) < 0) {
- track->dump(buffer, SIZE, true);
- result.append(buffer);
+ result.append(prefix);
+ track->appendDump(result, true /* active */);
}
}
@@ -7563,7 +7576,8 @@
AudioHwDevice *hwDev, sp<StreamHalInterface> stream,
audio_devices_t outDevice, audio_devices_t inDevice, bool systemReady)
: ThreadBase(audioFlinger, id, outDevice, inDevice, MMAP, systemReady),
- mHalStream(stream), mHalDevice(hwDev->hwDevice()), mAudioHwDev(hwDev)
+ mHalStream(stream), mHalDevice(hwDev->hwDevice()), mAudioHwDev(hwDev),
+ mActiveTracks(&this->mLocalLog)
{
mStandby = true;
readHalParameters_l();
@@ -7711,7 +7725,8 @@
}
sp<MmapTrack> track = new MmapTrack(this, mSampleRate, mFormat, mChannelMask, sessionId,
- client.clientUid, portId);
+ client.clientUid, client.clientPid,
+ portId);
mActiveTracks.add(track);
sp<EffectChain> chain = getEffectChain_l(sessionId);
@@ -8182,6 +8197,8 @@
dumpInternals(fd, args);
dumpTracks(fd, args);
dumpEffectChains(fd, args);
+ dprintf(fd, " Local log:\n");
+ mLocalLog.dump(fd, " " /* prefix */, 40 /* lines */);
}
void AudioFlinger::MmapThread::dumpInternals(int fd, const Vector<String16>& args)
@@ -8198,18 +8215,17 @@
void AudioFlinger::MmapThread::dumpTracks(int fd, const Vector<String16>& args __unused)
{
- const size_t SIZE = 256;
- char buffer[SIZE];
String8 result;
-
size_t numtracks = mActiveTracks.size();
- dprintf(fd, " %zu Tracks", numtracks);
+ dprintf(fd, " %zu Tracks\n", numtracks);
+ const char *prefix = " ";
if (numtracks) {
+ result.append(prefix);
MmapTrack::appendDumpHeader(result);
for (size_t i = 0; i < numtracks ; ++i) {
sp<MmapTrack> track = mActiveTracks[i];
- track->dump(buffer, SIZE);
- result.append(buffer);
+ result.append(prefix);
+ track->appendDump(result, true /* active */);
}
} else {
dprintf(fd, "\n");
diff --git a/services/audioflinger/Threads.h b/services/audioflinger/Threads.h
index 9db19d6..cc11ddb 100644
--- a/services/audioflinger/Threads.h
+++ b/services/audioflinger/Threads.h
@@ -509,9 +509,10 @@
template <typename T>
class ActiveTracks {
public:
- ActiveTracks()
+ explicit ActiveTracks(SimpleLog *localLog = nullptr)
: mActiveTracksGeneration(0)
, mLastActiveTracksGeneration(0)
+ , mLocalLog(localLog)
{ }
~ActiveTracks() {
@@ -563,6 +564,8 @@
void updatePowerState(sp<ThreadBase> thread, bool force = false);
private:
+ void logTrack(const char *funcName, const sp<T> &track) const;
+
SortedVector<uid_t> getWakeLockUids() {
SortedVector<uid_t> wakeLockUids;
for (const sp<T> &track : mActiveTracks) {
@@ -577,6 +580,7 @@
int mActiveTracksGeneration;
int mLastActiveTracksGeneration;
wp<T> mLatestActiveTrack; // latest track added to ActiveTracks
+ SimpleLog * const mLocalLog;
};
SimpleLog mLocalLog;
diff --git a/services/audioflinger/TrackBase.h b/services/audioflinger/TrackBase.h
index 9c27be8..d4ce0b4 100644
--- a/services/audioflinger/TrackBase.h
+++ b/services/audioflinger/TrackBase.h
@@ -135,6 +135,40 @@
mTerminated = true;
}
+ // Upper case characters are final states.
+ // Lower case characters are transitory.
+ const char *getTrackStateString() const {
+ if (isTerminated()) {
+ return "T ";
+ }
+ switch (mState) {
+ case IDLE:
+ return "I ";
+ case STOPPING_1: // for Fast and Offload
+ return "s1";
+ case STOPPING_2: // for Fast and Offload
+ return "s2";
+ case STOPPED:
+ return "S ";
+ case RESUMING:
+ return "r ";
+ case ACTIVE:
+ return "A ";
+ case PAUSING:
+ return "p ";
+ case PAUSED:
+ return "P ";
+ case FLUSHED:
+ return "F ";
+ case STARTING_1: // for RecordTrack
+ return "r1";
+ case STARTING_2: // for RecordTrack
+ return "r2";
+ default:
+ return "? ";
+ }
+ }
+
bool isOut() const { return mIsOut; }
// true for Track, false for RecordTrack,
// this could be a track type if needed later
diff --git a/services/audioflinger/Tracks.cpp b/services/audioflinger/Tracks.cpp
index 37c5764..b682517 100644
--- a/services/audioflinger/Tracks.cpp
+++ b/services/audioflinger/Tracks.cpp
@@ -502,58 +502,40 @@
/*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 VS dB Server Main buf Aux buf Flags UndFrmCnt Flushed\n");
+ result.append("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");
}
-void AudioFlinger::PlaybackThread::Track::dump(char* buffer, size_t size, bool active)
+void AudioFlinger::PlaybackThread::Track::appendDump(String8& result, bool active)
{
- gain_minifloat_packed_t vlr = mAudioTrackServerProxy->getVolumeLR();
- if (isFastTrack()) {
- sprintf(buffer, " F %2d", mFastIndex);
- } else if (mName >= AudioMixer::TRACK0) {
- sprintf(buffer, " %4d", mName - AudioMixer::TRACK0);
- } else {
- sprintf(buffer, " none");
- }
- track_state state = mState;
- char stateChar;
- if (isTerminated()) {
- stateChar = 'T';
- } else {
- switch (state) {
- case IDLE:
- stateChar = 'I';
- break;
- case STOPPING_1:
- stateChar = 's';
- break;
- case STOPPING_2:
- stateChar = '5';
- break;
- case STOPPED:
- stateChar = 'S';
- break;
- case RESUMING:
- stateChar = 'R';
- break;
- case ACTIVE:
- stateChar = 'A';
- break;
- case PAUSING:
- stateChar = 'p';
- break;
- case PAUSED:
- stateChar = 'P';
- break;
- case FLUSHED:
- stateChar = 'F';
- break;
- default:
- stateChar = '?';
- break;
+ char trackType;
+ switch (mType) {
+ case TYPE_DEFAULT:
+ case TYPE_OUTPUT:
+ if (mSharedBuffer.get() != nullptr) {
+ trackType = 'S'; // static
+ } else {
+ trackType = ' '; // normal
}
+ break;
+ case TYPE_PATCH:
+ trackType = 'P';
+ break;
+ default:
+ trackType = '?';
}
+
+ if (isFastTrack()) {
+ result.appendFormat("F%c %3d", trackType, mFastIndex);
+ } else if (mName >= AudioMixer::TRACK0) {
+ result.appendFormat("%c %4d", trackType, mName - AudioMixer::TRACK0);
+ } else {
+ result.appendFormat("%c none", trackType);
+ }
+
char nowInUnderrun;
switch (mObservedUnderruns.mBitFields.mMostRecent) {
case UNDERRUN_FULL:
@@ -570,31 +552,75 @@
break;
}
- std::pair<float /* volume */, bool /* active */> vsVolume = mVolumeHandler->getLastVolume();
- snprintf(&buffer[8], size - 8, " %6s %6u %4u %08X %08X %7u %6zu %1c %1d %5u "
- "%5.2g %5.2g %5.2g%c "
- "%08X %08zX %08zX 0x%03X %9u%c %7u\n",
+ char fillingStatus;
+ switch (mFillingUpStatus) {
+ case FS_INVALID:
+ fillingStatus = 'I';
+ break;
+ case FS_FILLING:
+ fillingStatus = 'f';
+ break;
+ case FS_FILLED:
+ fillingStatus = 'F';
+ break;
+ case FS_ACTIVE:
+ fillingStatus = 'A';
+ break;
+ default:
+ fillingStatus = '?';
+ break;
+ }
+
+ // clip framesReadySafe to max representation in dump
+ const size_t framesReadySafe =
+ std::min(mAudioTrackServerProxy->framesReadySafe(), (size_t)99999999);
+
+ // obtain volumes
+ const gain_minifloat_packed_t vlr = mAudioTrackServerProxy->getVolumeLR();
+ const std::pair<float /* volume */, bool /* active */> vsVolume =
+ mVolumeHandler->getLastVolume();
+
+ // Our effective frame count is obtained by ServerProxy::getBufferSizeInFrames()
+ // as it may be reduced by the application.
+ const size_t bufferSizeInFrames = (size_t)mAudioTrackServerProxy->getBufferSizeInFrames();
+ // Check whether the buffer size has been modified by the app.
+ const char modifiedBufferChar = bufferSizeInFrames < mFrameCount
+ ? 'r' /* buffer reduced */: bufferSizeInFrames > mFrameCount
+ ? 'e' /* error */ : ' ' /* identical */;
+
+ 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",
active ? "yes" : "no",
(mClient == 0) ? getpid_cached : mClient->pid(),
- mStreamType,
+ mSessionId,
+ getTrackStateString(),
+ mCblk->mFlags,
+
mFormat,
mChannelMask,
- mSessionId,
- mFrameCount,
- stateChar,
- mFillingUpStatus,
mAudioTrackServerProxy->getSampleRate(),
+
+ mStreamType,
20.0 * log10(float_from_gain(gain_minifloat_unpack_left(vlr))),
20.0 * log10(float_from_gain(gain_minifloat_unpack_right(vlr))),
20.0 * log10(vsVolume.first), // VolumeShaper(s) total volume
vsVolume.second ? 'A' : ' ', // if any VolumeShapers active
+
mCblk->mServer,
- (size_t)mMainBuffer, // use %zX as %p appends 0x
- (size_t)mAuxBuffer, // use %zX as %p appends 0x
- mCblk->mFlags,
+ bufferSizeInFrames,
+ modifiedBufferChar,
+ framesReadySafe,
+ fillingStatus,
mAudioTrackServerProxy->getUnderrunFrames(),
nowInUnderrun,
- (unsigned)mAudioTrackServerProxy->framesFlushed() % 10000000); // 7 digits
+ (unsigned)mAudioTrackServerProxy->framesFlushed() % 10000000,
+
+ (size_t)mMainBuffer, // use %zX as %p appends 0x
+ (size_t)mAuxBuffer // use %zX as %p appends 0x
+ );
}
uint32_t AudioFlinger::PlaybackThread::Track::sampleRate() const {
@@ -1706,22 +1732,28 @@
/*static*/ void AudioFlinger::RecordThread::RecordTrack::appendDumpHeader(String8& result)
{
- result.append(" Active Client Fmt Chn mask Session S Server fCount SRate\n");
+ result.append("Active Client Session S Flags Format Chn mask SRate Server FrmCnt\n");
}
-void AudioFlinger::RecordThread::RecordTrack::dump(char* buffer, size_t size, bool active)
+void AudioFlinger::RecordThread::RecordTrack::appendDump(String8& result, bool active)
{
- snprintf(buffer, size, " %6s %6u %3u %08X %7u %1d %08X %6zu %5u\n",
+ result.appendFormat("%c%5s %6u %7u %2s 0x%03X "
+ "%08X %08X %6u "
+ "%08X %6zu\n",
+ isFastTrack() ? 'F' : ' ',
active ? "yes" : "no",
(mClient == 0) ? getpid_cached : mClient->pid(),
+ mSessionId,
+ getTrackStateString(),
+ mCblk->mFlags,
+
mFormat,
mChannelMask,
- mSessionId,
- mState,
- mCblk->mServer,
- mFrameCount,
- mSampleRate);
+ mSampleRate,
+ mCblk->mServer,
+ mFrameCount
+ );
}
void AudioFlinger::RecordThread::RecordTrack::handleSyncStartEvent(const sp<SyncEvent>& event)
@@ -1840,13 +1872,15 @@
audio_channel_mask_t channelMask,
audio_session_t sessionId,
uid_t uid,
+ pid_t pid,
audio_port_handle_t portId)
: TrackBase(thread, NULL, sampleRate, format,
channelMask, (size_t)0 /* frameCount */,
nullptr /* buffer */, (size_t)0 /* bufferSize */,
sessionId, uid, false /* isOut */,
ALLOC_NONE,
- TYPE_DEFAULT, portId)
+ TYPE_DEFAULT, portId),
+ mPid(pid)
{
}
@@ -1893,17 +1927,17 @@
/*static*/ void AudioFlinger::MmapThread::MmapTrack::appendDumpHeader(String8& result)
{
- result.append(" Client Fmt Chn mask SRate\n");
+ result.append("Client Session Format Chn mask SRate\n");
}
-void AudioFlinger::MmapThread::MmapTrack::dump(char* buffer, size_t size)
+void AudioFlinger::MmapThread::MmapTrack::appendDump(String8& result, bool active __unused)
{
- snprintf(buffer, size, " %6u %3u %08X %5u\n",
- mUid,
+ result.appendFormat("%6u %7u %08X %08X %6u\n",
+ mPid,
+ mSessionId,
mFormat,
mChannelMask,
mSampleRate);
-
}
} // namespace android