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

3 files changed, 27 insertions, 5 deletions

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 += -DSTATE_QUEUE_INSTANTIATIONS='"StateQueueInstantiations.cpp"'
 
 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 (mType == MIXER) {
             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 @@ void AudioFlinger::PlaybackThread::threadLoop_write()
 
 #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 @@ bool FastMixer::threadLoop()
                 // 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 @@ bool FastMixer::threadLoop()
             // 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 @@ bool FastMixer::threadLoop()
                     }
                 }
                 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 @@ bool FastMixer::threadLoop()
                 // 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