AudioFlinger uses media.log service for logging
Change-Id: Ia0f8204334f6b233f644d897762a18c95d936b4b
diff --git a/services/audioflinger/AudioFlinger.cpp b/services/audioflinger/AudioFlinger.cpp
index 5f5b041..52fa576 100644
--- a/services/audioflinger/AudioFlinger.cpp
+++ b/services/audioflinger/AudioFlinger.cpp
@@ -59,6 +59,8 @@
#include <common_time/cc_helper.h>
//#include <common_time/local_clock.h>
+#include <media/IMediaLogService.h>
+
// ----------------------------------------------------------------------------
// Note: the following macro is used for extremely verbose logging message. In
@@ -127,6 +129,11 @@
mMode(AUDIO_MODE_INVALID),
mBtNrecIsOff(false)
{
+ char value[PROPERTY_VALUE_MAX];
+ bool doLog = (property_get("ro.test_harness", value, "0") > 0) && (atoi(value) == 1);
+ if (doLog) {
+ mLogMemoryDealer = new MemoryDealer(kLogMemorySize, "LogWriters");
+ }
}
void AudioFlinger::onFirstRef()
@@ -323,6 +330,17 @@
if (locked) {
mLock.unlock();
}
+
+ // append a copy of media.log here by forwarding fd to it, but don't attempt
+ // to lookup the service if it's not running, as it will block for a second
+ if (mLogMemoryDealer != 0) {
+ sp<IBinder> binder = defaultServiceManager()->getService(String16("media.log"));
+ if (binder != 0) {
+ fdprintf(fd, "\nmedia.log:\n");
+ Vector<String16> args;
+ binder->dump(fd, args);
+ }
+ }
}
return NO_ERROR;
}
@@ -340,6 +358,35 @@
return client;
}
+sp<NBLog::Writer> AudioFlinger::newWriter_l(size_t size, const char *name)
+{
+ if (mLogMemoryDealer == 0) {
+ return new NBLog::Writer();
+ }
+ sp<IMemory> shared = mLogMemoryDealer->allocate(NBLog::Timeline::sharedSize(size));
+ sp<NBLog::Writer> writer = new NBLog::Writer(size, shared);
+ sp<IBinder> binder = defaultServiceManager()->getService(String16("media.log"));
+ if (binder != 0) {
+ interface_cast<IMediaLogService>(binder)->registerWriter(shared, size, name);
+ }
+ return writer;
+}
+
+void AudioFlinger::unregisterWriter(const sp<NBLog::Writer>& writer)
+{
+ sp<IMemory> iMemory(writer->getIMemory());
+ if (iMemory == 0) {
+ return;
+ }
+ sp<IBinder> binder = defaultServiceManager()->getService(String16("media.log"));
+ if (binder != 0) {
+ interface_cast<IMediaLogService>(binder)->unregisterWriter(iMemory);
+ // Now the media.log remote reference to IMemory is gone.
+ // When our last local reference to IMemory also drops to zero,
+ // the IMemory destructor will deallocate the region from mMemoryDealer.
+ }
+}
+
// IAudioFlinger interface
diff --git a/services/audioflinger/AudioFlinger.h b/services/audioflinger/AudioFlinger.h
index a7f5b9e..c3f08f6 100644
--- a/services/audioflinger/AudioFlinger.h
+++ b/services/audioflinger/AudioFlinger.h
@@ -53,6 +53,8 @@
#include <powermanager/IPowerManager.h>
+#include <media/nbaio/NBLog.h>
+
namespace android {
class audio_track_cblk_t;
@@ -222,6 +224,13 @@
// end of IAudioFlinger interface
+ sp<NBLog::Writer> newWriter_l(size_t size, const char *name);
+ void unregisterWriter(const sp<NBLog::Writer>& writer);
+private:
+ static const size_t kLogMemorySize = 10 * 1024;
+ sp<MemoryDealer> mLogMemoryDealer; // == 0 when NBLog is disabled
+public:
+
class SyncEvent;
typedef void (*sync_event_callback_t)(const wp<SyncEvent>& event) ;
diff --git a/services/audioflinger/FastMixer.cpp b/services/audioflinger/FastMixer.cpp
index 9283f53..80e37ca 100644
--- a/services/audioflinger/FastMixer.cpp
+++ b/services/audioflinger/FastMixer.cpp
@@ -92,6 +92,7 @@
struct timespec measuredWarmupTs = {0, 0}; // how long did it take for warmup to complete
uint32_t warmupCycles = 0; // counter of number of loop cycles required to warmup
NBAIO_Sink* teeSink = NULL; // if non-NULL, then duplicate write() to this non-blocking sink
+ NBLog::Writer dummyLogWriter, *logWriter = &dummyLogWriter;
for (;;) {
@@ -119,9 +120,12 @@
FastMixerState::Command command = next->mCommand;
if (next != current) {
+ logWriter->log("next != current");
+
// As soon as possible of learning of a new dump area, start using it
dumpState = next->mDumpState != NULL ? next->mDumpState : &dummyDumpState;
teeSink = next->mTeeSink;
+ logWriter = next->mNBLogWriter != NULL ? next->mNBLogWriter : &dummyLogWriter;
// We want to always have a valid reference to the previous (non-idle) state.
// However, the state queue only guarantees access to current and previous states.
@@ -163,6 +167,7 @@
ALOG_ASSERT(coldFutexAddr != NULL);
int32_t old = android_atomic_dec(coldFutexAddr);
if (old <= 0) {
+ logWriter->log("wait");
__futex_syscall4(coldFutexAddr, FUTEX_WAIT_PRIVATE, old - 1, NULL);
}
// This may be overly conservative; there could be times that the normal mixer
@@ -181,6 +186,7 @@
}
continue;
case FastMixerState::EXIT:
+ logWriter->log("exit");
delete mixer;
delete[] mixBuffer;
return false;
@@ -258,11 +264,15 @@
unsigned currentTrackMask = current->mTrackMask;
dumpState->mTrackMask = currentTrackMask;
if (current->mFastTracksGen != fastTracksGen) {
+ logWriter->logf("gen %d", current->mFastTracksGen);
ALOG_ASSERT(mixBuffer != NULL);
int name;
// process removed tracks first to avoid running out of track names
unsigned removedTracks = previousTrackMask & ~currentTrackMask;
+ if (removedTracks) {
+ logWriter->logf("removed %#x", removedTracks);
+ }
while (removedTracks != 0) {
i = __builtin_ctz(removedTracks);
removedTracks &= ~(1 << i);
@@ -282,6 +292,9 @@
// now process added tracks
unsigned addedTracks = currentTrackMask & ~previousTrackMask;
+ if (addedTracks) {
+ logWriter->logf("added %#x", addedTracks);
+ }
while (addedTracks != 0) {
i = __builtin_ctz(addedTracks);
addedTracks &= ~(1 << i);
@@ -312,6 +325,9 @@
// finally process modified tracks; these use the same slot
// but may have a different buffer provider or volume provider
unsigned modifiedTracks = currentTrackMask & previousTrackMask;
+ if (modifiedTracks) {
+ logWriter->logf("modified %#x", modifiedTracks);
+ }
while (modifiedTracks != 0) {
i = __builtin_ctz(modifiedTracks);
modifiedTracks &= ~(1 << i);
@@ -455,6 +471,7 @@
struct timespec newTs;
int rc = clock_gettime(CLOCK_MONOTONIC, &newTs);
if (rc == 0) {
+ logWriter->logTimestamp(newTs);
if (oldTsValid) {
time_t sec = newTs.tv_sec - oldTs.tv_sec;
long nsec = newTs.tv_nsec - oldTs.tv_nsec;
diff --git a/services/audioflinger/FastMixerState.cpp b/services/audioflinger/FastMixerState.cpp
index 6305a83..c45c81b 100644
--- a/services/audioflinger/FastMixerState.cpp
+++ b/services/audioflinger/FastMixerState.cpp
@@ -31,7 +31,7 @@
FastMixerState::FastMixerState() :
mFastTracksGen(0), mTrackMask(0), mOutputSink(NULL), mOutputSinkGen(0),
mFrameCount(0), mCommand(INITIAL), mColdFutexAddr(NULL), mColdGen(0),
- mDumpState(NULL), mTeeSink(NULL)
+ mDumpState(NULL), mTeeSink(NULL), mNBLogWriter(NULL)
{
}
diff --git a/services/audioflinger/FastMixerState.h b/services/audioflinger/FastMixerState.h
index 6e53f21..f6e7903 100644
--- a/services/audioflinger/FastMixerState.h
+++ b/services/audioflinger/FastMixerState.h
@@ -20,6 +20,7 @@
#include <system/audio.h>
#include <media/ExtendedAudioBufferProvider.h>
#include <media/nbaio/NBAIO.h>
+#include <media/nbaio/NBLog.h>
namespace android {
@@ -77,6 +78,7 @@
// This might be a one-time configuration rather than per-state
FastMixerDumpState* mDumpState; // if non-NULL, then update dump state periodically
NBAIO_Sink* mTeeSink; // if non-NULL, then duplicate write()s to this non-blocking sink
+ NBLog::Writer* mNBLogWriter; // non-blocking logger
}; // struct FastMixerState
} // namespace android
diff --git a/services/audioflinger/Threads.cpp b/services/audioflinger/Threads.cpp
index 744a7df..6f748d7 100644
--- a/services/audioflinger/Threads.cpp
+++ b/services/audioflinger/Threads.cpp
@@ -936,6 +936,7 @@
mFastTrackAvailMask(((1 << FastMixerState::kMaxFastTracks) - 1) & ~1)
{
snprintf(mName, kNameLength, "AudioOut_%X", id);
+ mNBLogWriter = audioFlinger->newWriter_l(kLogSize, mName);
// Assumes constructor is called by AudioFlinger with it's mLock held, but
// it would be safer to explicitly pass initial masterVolume/masterMute as
@@ -971,6 +972,7 @@
AudioFlinger::PlaybackThread::~PlaybackThread()
{
+ mAudioFlinger->unregisterWriter(mNBLogWriter);
delete [] mMixBuffer;
}
@@ -1247,6 +1249,7 @@
if (status) {
*status = lStatus;
}
+ mNBLogWriter->logf("createTrack_l");
return track;
}
@@ -1314,6 +1317,7 @@
// addTrack_l() must be called with ThreadBase::mLock held
status_t AudioFlinger::PlaybackThread::addTrack_l(const sp<Track>& track)
{
+ mNBLogWriter->logf("addTrack_l mName=%d", track->mName);
status_t status = ALREADY_EXISTS;
// set retry count for buffer fill
@@ -1347,6 +1351,7 @@
// destroyTrack_l() must be called with ThreadBase::mLock held
void AudioFlinger::PlaybackThread::destroyTrack_l(const sp<Track>& track)
{
+ mNBLogWriter->logf("destroyTrack_l mName=%d", track->mName);
track->mState = TrackBase::TERMINATED;
// active tracks are removed by threadLoop()
if (mActiveTracks.indexOf(track) < 0) {
@@ -1356,6 +1361,7 @@
void AudioFlinger::PlaybackThread::removeTrack_l(const sp<Track>& track)
{
+ mNBLogWriter->logf("removeTrack_l mName=%d", track->mName);
track->triggerEvents(AudioSystem::SYNC_EVENT_PRESENTATION_COMPLETE);
mTracks.remove(track);
deleteTrackName_l(track->name());
@@ -1892,6 +1898,11 @@
acquireWakeLock();
+ // mNBLogWriter->log can only be called while thread mutex mLock is held.
+ // So if you need to log when mutex is unlocked, set logString to a non-NULL string,
+ // and then that string will be logged at the next convenient opportunity.
+ const char *logString = NULL;
+
while (!exitPending())
{
cpuStats.sample(myName);
@@ -1904,6 +1915,12 @@
Mutex::Autolock _l(mLock);
+ if (logString != NULL) {
+ mNBLogWriter->logTimestamp();
+ mNBLogWriter->log(logString);
+ logString = NULL;
+ }
+
if (checkForNewParameters_l()) {
cacheParameters_l();
}
@@ -1917,6 +1934,7 @@
threadLoop_standby();
+ mNBLogWriter->log("standby");
mStandby = true;
}
@@ -2012,6 +2030,9 @@
// since we can't guarantee the destructors won't acquire that
// same lock. This will also mutate and push a new fast mixer state.
threadLoop_removeTracks(tracksToRemove);
+ if (tracksToRemove.size() > 0) {
+ logString = "remove";
+ }
tracksToRemove.clear();
// FIXME I don't understand the need for this here;
@@ -2143,6 +2164,8 @@
state->mColdGen++;
state->mDumpState = &mFastMixerDumpState;
state->mTeeSink = mTeeSink.get();
+ mFastMixerNBLogWriter = audioFlinger->newWriter_l(kFastMixerLogSize, "FastMixer");
+ state->mNBLogWriter = mFastMixerNBLogWriter.get();
sq->end();
sq->push(FastMixerStateQueue::BLOCK_UNTIL_PUSHED);
@@ -2219,6 +2242,7 @@
}
#endif
}
+ mAudioFlinger->unregisterWriter(mFastMixerNBLogWriter);
delete mAudioMixer;
}
@@ -2846,6 +2870,7 @@
if (CC_UNLIKELY(count)) {
for (size_t i=0 ; i<count ; i++) {
const sp<Track>& track = tracksToRemove->itemAt(i);
+ mNBLogWriter->logf("prepareTracks_l remove name=%u", track->name());
mActiveTracks.remove(track);
if (track->mainBuffer() != mMixBuffer) {
chain = getEffectChain_l(track->sessionId());
@@ -3222,6 +3247,9 @@
// remove all the tracks that need to be...
if (CC_UNLIKELY(trackToRemove != 0)) {
tracksToRemove->add(trackToRemove);
+#if 0
+ mNBLogWriter->logf("prepareTracks_l remove name=%u", trackToRemove->name());
+#endif
mActiveTracks.remove(trackToRemove);
if (!mEffectChains.isEmpty()) {
ALOGV("stopping track on chain %p for session Id: %d", mEffectChains[0].get(),
diff --git a/services/audioflinger/Threads.h b/services/audioflinger/Threads.h
index 06a1c8c..5fa7eaf 100644
--- a/services/audioflinger/Threads.h
+++ b/services/audioflinger/Threads.h
@@ -315,6 +315,8 @@
// keyed by session ID, the second by type UUID timeLow field
KeyedVector< int, KeyedVector< int, sp<SuspendedSessionDesc> > >
mSuspendedSessions;
+ static const size_t kLogSize = 512;
+ sp<NBLog::Writer> mNBLogWriter;
};
// --- PlaybackThread ---
@@ -544,6 +546,8 @@
sp<NBAIO_Sink> mTeeSink;
sp<NBAIO_Source> mTeeSource;
uint32_t mScreenState; // cached copy of gScreenState
+ static const size_t kFastMixerLogSize = 8 * 1024;
+ sp<NBLog::Writer> mFastMixerNBLogWriter;
public:
virtual bool hasFastMixer() const = 0;
virtual FastTrackUnderruns getFastTrackUnderruns(size_t fastIndex) const
diff --git a/services/audioflinger/Tracks.cpp b/services/audioflinger/Tracks.cpp
index c5f0ed7..315cbbc 100644
--- a/services/audioflinger/Tracks.cpp
+++ b/services/audioflinger/Tracks.cpp
@@ -569,6 +569,7 @@
sp<ThreadBase> thread = mThread.promote();
if (thread != 0) {
Mutex::Autolock _l(thread->mLock);
+ thread->mNBLogWriter->logf("start mName=%d", mName);
track_state state = mState;
// here the track could be either new, or restarted
// in both cases "unstop" the track
@@ -611,6 +612,7 @@
sp<ThreadBase> thread = mThread.promote();
if (thread != 0) {
Mutex::Autolock _l(thread->mLock);
+ thread->mNBLogWriter->logf("stop mName=%d", mName);
track_state state = mState;
if (state == RESUMING || state == ACTIVE || state == PAUSING || state == PAUSED) {
// If the track is not active (PAUSED and buffers full), flush buffers
@@ -647,6 +649,7 @@
sp<ThreadBase> thread = mThread.promote();
if (thread != 0) {
Mutex::Autolock _l(thread->mLock);
+ thread->mNBLogWriter->logf("pause mName=%d", mName);
if (mState == ACTIVE || mState == RESUMING) {
mState = PAUSING;
ALOGV("ACTIVE/RESUMING => PAUSING (%d) on thread %p", mName, thread.get());
@@ -670,6 +673,7 @@
sp<ThreadBase> thread = mThread.promote();
if (thread != 0) {
Mutex::Autolock _l(thread->mLock);
+ thread->mNBLogWriter->logf("flush mName=%d", mName);
if (mState != STOPPING_1 && mState != STOPPING_2 && mState != STOPPED && mState != PAUSED &&
mState != PAUSING && mState != IDLE && mState != FLUSHED) {
return;