systrace for audio
Trace fast track buffer fill status for underruns etc.
Move the definition of macro to Android.mk.
No overhead if disabled.
Change-Id: If0e83e21b61b059ca38f543f8a6ffb58e08c79ee
diff --git a/services/audioflinger/Android.mk b/services/audioflinger/Android.mk
index 48b35cf..0d7f06a 100644
--- a/services/audioflinger/Android.mk
+++ b/services/audioflinger/Android.mk
@@ -82,4 +82,7 @@
LOCAL_CFLAGS += -DHAVE_REQUEST_PRIORITY -UFAST_TRACKS_AT_NON_NATIVE_SAMPLE_RATE -USOAKER
+# uncomment for systrace
+# LOCAL_CFLAGS += -DATRACE_TAG=ATRACE_TAG_AUDIO
+
include $(BUILD_SHARED_LIBRARY)
diff --git a/services/audioflinger/AudioFlinger.cpp b/services/audioflinger/AudioFlinger.cpp
index 7e15823..339f6ea 100644
--- a/services/audioflinger/AudioFlinger.cpp
+++ b/services/audioflinger/AudioFlinger.cpp
@@ -19,8 +19,6 @@
#define LOG_TAG "AudioFlinger"
//#define LOG_NDEBUG 0
-//#define ATRACE_TAG ATRACE_TAG_AUDIO
-
#include <math.h>
#include <signal.h>
#include <sys/time.h>
@@ -2557,7 +2555,9 @@
if (!mStandby && delta > maxPeriod) {
mNumDelayedWrites++;
if ((now - lastWarning) > kWarningThrottleNs) {
+#if defined(ATRACE_TAG) && (ATRACE_TAG != ATRACE_TAG_NEVER)
ScopedTrace st(ATRACE_TAG, "underrun");
+#endif
ALOGW("write blocked for %llu msecs, %d delayed writes, thread %p",
ns2ms(delta), mNumDelayedWrites, this);
lastWarning = now;
@@ -2652,9 +2652,13 @@
#define mBitShift 2 // FIXME
size_t count = mixBufferSize >> mBitShift;
+#if defined(ATRACE_TAG) && (ATRACE_TAG != ATRACE_TAG_NEVER)
Tracer::traceBegin(ATRACE_TAG, "write");
+#endif
ssize_t framesWritten = mNormalSink->write(mMixBuffer, count);
+#if defined(ATRACE_TAG) && (ATRACE_TAG != ATRACE_TAG_NEVER)
Tracer::traceEnd(ATRACE_TAG);
+#endif
if (framesWritten > 0) {
size_t bytesWritten = framesWritten << mBitShift;
mBytesWritten += bytesWritten;
diff --git a/services/audioflinger/FastMixer.cpp b/services/audioflinger/FastMixer.cpp
index e73257e..df9ec8e 100644
--- a/services/audioflinger/FastMixer.cpp
+++ b/services/audioflinger/FastMixer.cpp
@@ -17,8 +17,6 @@
#define LOG_TAG "FastMixer"
//#define LOG_NDEBUG 0
-//#define ATRACE_TAG ATRACE_TAG_AUDIO
-
#include <sys/atomics.h>
#include <time.h>
#include <utils/Log.h>
@@ -359,10 +357,17 @@
// up to 1 ms. If enough active tracks all blocked in sequence, this would result
// in the overall fast mix cycle being delayed. Should use a non-blocking FIFO.
size_t framesReady = fastTrack->mBufferProvider->framesReady();
+#if defined(ATRACE_TAG) && (ATRACE_TAG != ATRACE_TAG_NEVER)
+ // I wish we had formatted trace names
+ char traceName[16];
+ strcpy(traceName, "framesReady");
+ traceName[11] = i + (i < 10 ? '0' : 'A' - 10);
+ traceName[12] = '\0';
+ ATRACE_INT(traceName, framesReady);
+#endif
FastTrackDump *ftDump = &dumpState->mTracks[i];
FastTrackUnderruns underruns = ftDump->mUnderruns;
if (framesReady < frameCount) {
- ATRACE_INT("underrun", i);
if (framesReady == 0) {
underruns.mBitFields.mEmpty++;
underruns.mBitFields.mMostRecent = UNDERRUN_EMPTY;
@@ -396,9 +401,13 @@
// FIXME write() is non-blocking and lock-free for a properly implemented NBAIO sink,
// but this code should be modified to handle both non-blocking and blocking sinks
dumpState->mWriteSequence++;
+#if defined(ATRACE_TAG) && (ATRACE_TAG != ATRACE_TAG_NEVER)
Tracer::traceBegin(ATRACE_TAG, "write");
+#endif
ssize_t framesWritten = outputSink->write(mixBuffer, frameCount);
+#if defined(ATRACE_TAG) && (ATRACE_TAG != ATRACE_TAG_NEVER)
Tracer::traceEnd(ATRACE_TAG);
+#endif
dumpState->mWriteSequence++;
if (framesWritten >= 0) {
ALOG_ASSERT(framesWritten <= frameCount);
@@ -448,7 +457,9 @@
}
}
if (sec > 0 || nsec > underrunNs) {
+#if defined(ATRACE_TAG) && (ATRACE_TAG != ATRACE_TAG_NEVER)
ScopedTrace st(ATRACE_TAG, "underrun");
+#endif
// FIXME only log occasionally
ALOGV("underrun: time since last cycle %d.%03ld sec",
(int) sec, nsec / 1000000L);
@@ -518,6 +529,10 @@
// this store #4 is not atomic with respect to stores #1, #2, #3 above, but
// the newest open and oldest closed halves are atomic with respect to each other
dumpState->mBounds = bounds;
+#if defined(ATRACE_TAG) && (ATRACE_TAG != ATRACE_TAG_NEVER)
+ ATRACE_INT("cycle_ms", monotonicNs / 1000000);
+ ATRACE_INT("load_us", loadNs / 1000);
+#endif
#endif
} else {
// first time through the loop