From 99c99d00beb43b939dedc9ffb07adb89f6a85ba5 Mon Sep 17 00:00:00 2001 From: Glenn Kasten Date: Mon, 14 May 2012 16:37:13 -0700 Subject: 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 --- services/audioflinger/Android.mk | 3 +++ services/audioflinger/AudioFlinger.cpp | 8 ++++++-- services/audioflinger/FastMixer.cpp | 21 ++++++++++++++++++--- 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 #include #include @@ -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 #include #include @@ -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 -- cgit v1.1