/* * Copyright (C) 2014 The Android Open Source Project * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at * * http://www.apache.org/licenses/LICENSE-2.0 * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. * See the License for the specific language governing permissions and * limitations under the License. */ #define LOG_TAG "FastMixerDumpState" //#define LOG_NDEBUG 0 #include "Configuration.h" #ifdef FAST_THREAD_STATISTICS #include #ifdef CPU_FREQUENCY_STATISTICS #include #endif #endif #include #include #include "FastMixerDumpState.h" namespace android { FastMixerDumpState::FastMixerDumpState() : FastThreadDumpState(), mWriteSequence(0), mFramesWritten(0), mNumTracks(0), mWriteErrors(0), mSampleRate(0), mFrameCount(0), mTrackMask(0) { } FastMixerDumpState::~FastMixerDumpState() { } // helper function called by qsort() static int compare_uint32_t(const void *pa, const void *pb) { uint32_t a = *(const uint32_t *)pa; uint32_t b = *(const uint32_t *)pb; if (a < b) { return -1; } else if (a > b) { return 1; } else { return 0; } } void FastMixerDumpState::dump(int fd) const { if (mCommand == FastMixerState::INITIAL) { dprintf(fd, " FastMixer not initialized\n"); return; } double measuredWarmupMs = (mMeasuredWarmupTs.tv_sec * 1000.0) + (mMeasuredWarmupTs.tv_nsec / 1000000.0); double mixPeriodSec = (double) mFrameCount / mSampleRate; dprintf(fd, " FastMixer command=%s writeSequence=%u framesWritten=%u\n" " numTracks=%u writeErrors=%u underruns=%u overruns=%u\n" " sampleRate=%u frameCount=%zu measuredWarmup=%.3g ms, warmupCycles=%u\n" " mixPeriod=%.2f ms latency=%.2f ms\n", FastMixerState::commandToString(mCommand), mWriteSequence, mFramesWritten, mNumTracks, mWriteErrors, mUnderruns, mOverruns, mSampleRate, mFrameCount, measuredWarmupMs, mWarmupCycles, mixPeriodSec * 1e3, mLatencyMs); dprintf(fd, " FastMixer Timestamp stats: %s\n", mTimestampVerifier.toString().c_str()); #ifdef FAST_THREAD_STATISTICS // find the interval of valid samples const uint32_t bounds = mBounds; const uint32_t newestOpen = bounds & 0xFFFF; uint32_t oldestClosed = bounds >> 16; //uint32_t n = (newestOpen - oldestClosed) & 0xFFFF; uint32_t n; __builtin_sub_overflow(newestOpen, oldestClosed, &n); n &= 0xFFFF; if (n > mSamplingN) { ALOGE("too many samples %u", n); n = mSamplingN; } // statistics for monotonic (wall clock) time, thread raw CPU load in time, CPU clock frequency, // and adjusted CPU load in MHz normalized for CPU clock frequency audio_utils::Statistics wall, loadNs; #ifdef CPU_FREQUENCY_STATISTICS audio_utils::Statistics kHz, loadMHz; uint32_t previousCpukHz = 0; #endif // Assuming a normal distribution for cycle times, three standard deviations on either side of // the mean account for 99.73% of the population. So if we take each tail to be 1/1000 of the // sample set, we get 99.8% combined, or close to three standard deviations. static const uint32_t kTailDenominator = 1000; uint32_t *tail = n >= kTailDenominator ? new uint32_t[n] : NULL; // loop over all the samples for (uint32_t j = 0; j < n; ++j) { size_t i = oldestClosed++ & (mSamplingN - 1); uint32_t wallNs = mMonotonicNs[i]; if (tail != NULL) { tail[j] = wallNs; } wall.add(wallNs); uint32_t sampleLoadNs = mLoadNs[i]; loadNs.add(sampleLoadNs); #ifdef CPU_FREQUENCY_STATISTICS uint32_t sampleCpukHz = mCpukHz[i]; // skip bad kHz samples if ((sampleCpukHz & ~0xF) != 0) { kHz.add(sampleCpukHz >> 4); if (sampleCpukHz == previousCpukHz) { double megacycles = (double) sampleLoadNs * (double) (sampleCpukHz >> 4) * 1e-12; double adjMHz = megacycles / mixPeriodSec; // _not_ wallNs * 1e9 loadMHz.add(adjMHz); } } previousCpukHz = sampleCpukHz; #endif } if (n) { dprintf(fd, " Simple moving statistics over last %.1f seconds:\n", wall.getN() * mixPeriodSec); dprintf(fd, " wall clock time in ms per mix cycle:\n" " mean=%.2f min=%.2f max=%.2f stddev=%.2f\n", wall.getMean()*1e-6, wall.getMin()*1e-6, wall.getMax()*1e-6, wall.getStdDev()*1e-6); dprintf(fd, " raw CPU load in us per mix cycle:\n" " mean=%.0f min=%.0f max=%.0f stddev=%.0f\n", loadNs.getMean()*1e-3, loadNs.getMin()*1e-3, loadNs.getMax()*1e-3, loadNs.getStdDev()*1e-3); } else { dprintf(fd, " No FastMixer statistics available currently\n"); } #ifdef CPU_FREQUENCY_STATISTICS dprintf(fd, " CPU clock frequency in MHz:\n" " mean=%.0f min=%.0f max=%.0f stddev=%.0f\n", kHz.getMean()*1e-3, kHz.getMin()*1e-3, kHz.getMax()*1e-3, kHz.getStdDev()*1e-3); dprintf(fd, " adjusted CPU load in MHz (i.e. normalized for CPU clock frequency):\n" " mean=%.1f min=%.1f max=%.1f stddev=%.1f\n", loadMHz.getMean(), loadMHz.getMin(), loadMHz.getMax(), loadMHz.getStdDev()); #endif if (tail != NULL) { qsort(tail, n, sizeof(uint32_t), compare_uint32_t); // assume same number of tail samples on each side, left and right uint32_t count = n / kTailDenominator; audio_utils::Statistics left, right; for (uint32_t i = 0; i < count; ++i) { left.add(tail[i]); right.add(tail[n - (i + 1)]); } dprintf(fd, " Distribution of mix cycle times in ms for the tails " "(> ~3 stddev outliers):\n" " left tail: mean=%.2f min=%.2f max=%.2f stddev=%.2f\n" " right tail: mean=%.2f min=%.2f max=%.2f stddev=%.2f\n", left.getMean()*1e-6, left.getMin()*1e-6, left.getMax()*1e-6, left.getStdDev()*1e-6, right.getMean()*1e-6, right.getMin()*1e-6, right.getMax()*1e-6, right.getStdDev()*1e-6); delete[] tail; } #endif // The active track mask and track states are updated non-atomically. // So if we relied on isActive to decide whether to display, // then we might display an obsolete track or omit an active track. // Instead we always display all tracks, with an indication // of whether we think the track is active. uint32_t trackMask = mTrackMask; dprintf(fd, " Fast tracks: sMaxFastTracks=%u activeMask=%#x\n", FastMixerState::sMaxFastTracks, trackMask); dprintf(fd, " Index Active Full Partial Empty Recent Ready Written\n"); for (uint32_t i = 0; i < FastMixerState::sMaxFastTracks; ++i, trackMask >>= 1) { bool isActive = trackMask & 1; const FastTrackDump *ftDump = &mTracks[i]; const FastTrackUnderruns& underruns = ftDump->mUnderruns; const char *mostRecent; switch (underruns.mBitFields.mMostRecent) { case UNDERRUN_FULL: mostRecent = "full"; break; case UNDERRUN_PARTIAL: mostRecent = "partial"; break; case UNDERRUN_EMPTY: mostRecent = "empty"; break; default: mostRecent = "?"; break; } dprintf(fd, " %5u %6s %4u %7u %5u %7s %5zu %10lld\n", i, isActive ? "yes" : "no", (underruns.mBitFields.mFull) & UNDERRUN_MASK, (underruns.mBitFields.mPartial) & UNDERRUN_MASK, (underruns.mBitFields.mEmpty) & UNDERRUN_MASK, mostRecent, ftDump->mFramesReady, (long long)ftDump->mFramesWritten); } } } // android