| /* |
| * Copyright (C) 2017 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 "PerformanceAnalysis" |
| // #define LOG_NDEBUG 0 |
| |
| #include <algorithm> |
| #include <climits> |
| #include <deque> |
| #include <iostream> |
| #include <math.h> |
| #include <numeric> |
| #include <vector> |
| #include <stdarg.h> |
| #include <stdint.h> |
| #include <stdio.h> |
| #include <string.h> |
| #include <sys/prctl.h> |
| #include <time.h> |
| #include <new> |
| #include <audio_utils/roundup.h> |
| #include <media/nbaio/NBLog.h> |
| #include <media/nbaio/PerformanceAnalysis.h> |
| #include <media/nbaio/ReportPerformance.h> |
| #include <utils/Log.h> |
| #include <utils/String8.h> |
| |
| #include <queue> |
| #include <utility> |
| |
| namespace android { |
| |
| namespace ReportPerformance { |
| |
| // Given a the most recent timestamp of a series of audio processing |
| // wakeup timestamps, |
| // buckets the time interval into a histogram, searches for |
| // outliers, analyzes the outlier series for unexpectedly |
| // small or large values and stores these as peaks |
| void PerformanceAnalysis::logTsEntry(timestamp ts) { |
| // after a state change, start a new series and do not |
| // record time intervals in-between |
| if (mBufferPeriod.mPrevTs == 0) { |
| mBufferPeriod.mPrevTs = ts; |
| return; |
| } |
| |
| // calculate time interval between current and previous timestamp |
| const msInterval diffMs = static_cast<msInterval>( |
| deltaMs(mBufferPeriod.mPrevTs, ts)); |
| |
| const int diffJiffy = deltaJiffy(mBufferPeriod.mPrevTs, ts); |
| |
| // old versus new weight ratio when updating the buffer period mean |
| static constexpr double exponentialWeight = 0.999; |
| // update buffer period mean with exponential weighting |
| mBufferPeriod.mMean = (mBufferPeriod.mMean < 0) ? diffMs : |
| exponentialWeight * mBufferPeriod.mMean + (1.0 - exponentialWeight) * diffMs; |
| // set mOutlierFactor to a smaller value for the fastmixer thread |
| const int kFastMixerMax = 10; |
| // NormalMixer times vary much more than FastMixer times. |
| // TODO: mOutlierFactor values are set empirically based on what appears to be |
| // an outlier. Learn these values from the data. |
| // TODO: the current settings are too high, change after next data collection is over |
| mBufferPeriod.mOutlierFactor = mBufferPeriod.mMean < kFastMixerMax ? 1.8 : 2.0; |
| // set outlier threshold |
| mBufferPeriod.mOutlier = mBufferPeriod.mMean * mBufferPeriod.mOutlierFactor; |
| |
| // Check whether the time interval between the current timestamp |
| // and the previous one is long enough to count as an outlier |
| const bool isOutlier = detectAndStoreOutlier(diffMs); |
| // If an outlier was found, check whether it was a peak |
| if (isOutlier) { |
| /*bool isPeak =*/ detectAndStorePeak( |
| mOutlierData[0].first, mOutlierData[0].second); |
| // TODO: decide whether to insert a new empty histogram if a peak |
| // TODO: remove isPeak if unused to avoid "unused variable" error |
| // occurred at the current timestamp |
| } |
| |
| // Insert a histogram to mHists if it is empty, or |
| // close the current histogram and insert a new empty one if |
| // if the current histogram has spanned its maximum time interval. |
| if (mHists.empty() || |
| deltaMs(mHists[0].first, ts) >= kMaxLength.HistTimespanMs) { |
| mHists.emplace_front(ts, std::map<int, int>()); |
| // When memory is full, delete oldest histogram |
| // TODO: use a circular buffer |
| if (mHists.size() >= kMaxLength.Hists) { |
| mHists.resize(kMaxLength.Hists); |
| } |
| } |
| // add current time intervals to histogram |
| ++mHists[0].second[diffJiffy]; |
| // update previous timestamp |
| mBufferPeriod.mPrevTs = ts; |
| } |
| |
| |
| // forces short-term histogram storage to avoid adding idle audio time interval |
| // to buffer period data |
| void PerformanceAnalysis::handleStateChange() { |
| mBufferPeriod.mPrevTs = 0; |
| return; |
| } |
| |
| |
| // Checks whether the time interval between two outliers is far enough from |
| // a typical delta to be considered a peak. |
| // looks for changes in distribution (peaks), which can be either positive or negative. |
| // The function sets the mean to the starting value and sigma to 0, and updates |
| // them as long as no peak is detected. When a value is more than 'threshold' |
| // standard deviations from the mean, a peak is detected and the mean and sigma |
| // are set to the peak value and 0. |
| bool PerformanceAnalysis::detectAndStorePeak(msInterval diff, timestamp ts) { |
| bool isPeak = false; |
| if (mOutlierData.empty()) { |
| return false; |
| } |
| // Update mean of the distribution |
| // TypicalDiff is used to check whether a value is unusually large |
| // when we cannot use standard deviations from the mean because the sd is set to 0. |
| mOutlierDistribution.mTypicalDiff = (mOutlierDistribution.mTypicalDiff * |
| (mOutlierData.size() - 1) + diff) / mOutlierData.size(); |
| |
| // Initialize short-term mean at start of program |
| if (mOutlierDistribution.mMean == 0) { |
| mOutlierDistribution.mMean = diff; |
| } |
| // Update length of current sequence of outliers |
| mOutlierDistribution.mN++; |
| |
| // Check whether a large deviation from the mean occurred. |
| // If the standard deviation has been reset to zero, the comparison is |
| // instead to the mean of the full mOutlierInterval sequence. |
| if ((fabs(diff - mOutlierDistribution.mMean) < |
| mOutlierDistribution.kMaxDeviation * mOutlierDistribution.mSd) || |
| (mOutlierDistribution.mSd == 0 && |
| fabs(diff - mOutlierDistribution.mMean) < |
| mOutlierDistribution.mTypicalDiff)) { |
| // update the mean and sd using online algorithm |
| // https://en.wikipedia.org/wiki/ |
| // Algorithms_for_calculating_variance#Online_algorithm |
| mOutlierDistribution.mN++; |
| const double kDelta = diff - mOutlierDistribution.mMean; |
| mOutlierDistribution.mMean += kDelta / mOutlierDistribution.mN; |
| const double kDelta2 = diff - mOutlierDistribution.mMean; |
| mOutlierDistribution.mM2 += kDelta * kDelta2; |
| mOutlierDistribution.mSd = (mOutlierDistribution.mN < 2) ? 0 : |
| sqrt(mOutlierDistribution.mM2 / (mOutlierDistribution.mN - 1)); |
| } else { |
| // new value is far from the mean: |
| // store peak timestamp and reset mean, sd, and short-term sequence |
| isPeak = true; |
| mPeakTimestamps.emplace_front(ts); |
| // if mPeaks has reached capacity, delete oldest data |
| // Note: this means that mOutlierDistribution values do not exactly |
| // match the data we have in mPeakTimestamps, but this is not an issue |
| // in practice for estimating future peaks. |
| // TODO: turn this into a circular buffer |
| if (mPeakTimestamps.size() >= kMaxLength.Peaks) { |
| mPeakTimestamps.resize(kMaxLength.Peaks); |
| } |
| mOutlierDistribution.mMean = 0; |
| mOutlierDistribution.mSd = 0; |
| mOutlierDistribution.mN = 0; |
| mOutlierDistribution.mM2 = 0; |
| } |
| return isPeak; |
| } |
| |
| |
| // Determines whether the difference between a timestamp and the previous |
| // one is beyond a threshold. If yes, stores the timestamp as an outlier |
| // and writes to mOutlierdata in the following format: |
| // Time elapsed since previous outlier: Timestamp of start of outlier |
| // e.g. timestamps (ms) 1, 4, 5, 16, 18, 28 will produce pairs (4, 5), (13, 18). |
| // TODO: learn what timestamp sequences correlate with glitches instead of |
| // manually designing a heuristic. |
| bool PerformanceAnalysis::detectAndStoreOutlier(const msInterval diffMs) { |
| bool isOutlier = false; |
| if (diffMs >= mBufferPeriod.mOutlier) { |
| isOutlier = true; |
| mOutlierData.emplace_front( |
| mOutlierDistribution.mElapsed, mBufferPeriod.mPrevTs); |
| // Remove oldest value if the vector is full |
| // TODO: turn this into a circular buffer |
| // TODO: make sure kShortHistSize is large enough that that data will never be lost |
| // before being written to file or to a FIFO |
| if (mOutlierData.size() >= kMaxLength.Outliers) { |
| mOutlierData.resize(kMaxLength.Outliers); |
| } |
| mOutlierDistribution.mElapsed = 0; |
| } |
| mOutlierDistribution.mElapsed += diffMs; |
| return isOutlier; |
| } |
| |
| static int widthOf(int x) { |
| int width = 0; |
| if (x < 0) { |
| width++; |
| x = x == INT_MIN ? INT_MAX : -x; |
| } |
| // assert (x >= 0) |
| do { |
| ++width; |
| x /= 10; |
| } while (x > 0); |
| return width; |
| } |
| |
| // computes the column width required for a specific histogram value |
| inline int numberWidth(double number, int leftPadding) { |
| // Added values account for whitespaces needed around numbers, and for the |
| // dot and decimal digit not accounted for by widthOf |
| return std::max(std::max(widthOf(static_cast<int>(number)) + 3, 2), leftPadding + 1); |
| } |
| |
| // rounds value to precision based on log-distance from mean |
| inline double logRound(double x, double mean) { |
| // Larger values decrease range of high resolution and prevent overflow |
| // of a histogram on the console. |
| // The following formula adjusts kBase based on the buffer period length. |
| // Different threads have buffer periods ranging from 2 to 40. The |
| // formula below maps buffer period 2 to kBase = ~1, 4 to ~2, 20 to ~3, 40 to ~4. |
| // TODO: tighten this for higher means, the data still overflows |
| const double kBase = log(mean) / log(2.2); |
| const double power = floor( |
| log(abs(x - mean) / mean) / log(kBase)) + 2; |
| // do not round values close to the mean |
| if (power < 1) { |
| return x; |
| } |
| const int factor = static_cast<int>(pow(10, power)); |
| return (static_cast<int>(x) * factor) / factor; |
| } |
| |
| // TODO Make it return a std::string instead of modifying body |
| // TODO: move this to ReportPerformance, probably make it a friend function |
| // of PerformanceAnalysis |
| void PerformanceAnalysis::reportPerformance(String8 *body, int author, log_hash_t hash, |
| int maxHeight) { |
| if (mHists.empty()) { |
| return; |
| } |
| |
| // ms of active audio in displayed histogram |
| double elapsedMs = 0; |
| // starting timestamp of histogram |
| timestamp startingTs = mHists[0].first; |
| |
| // histogram which stores .1 precision ms counts instead of Jiffy multiple counts |
| // TODO: when there is more data, print many histograms, possibly separated at peaks |
| std::map<double, int> buckets; |
| for (const auto &shortHist: mHists) { |
| for (const auto &countPair : shortHist.second) { |
| const double ms = static_cast<double>(countPair.first) / kJiffyPerMs; |
| buckets[logRound(ms, mBufferPeriod.mMean)] += countPair.second; |
| elapsedMs += ms * countPair.second; |
| } |
| } |
| |
| // underscores and spaces length corresponds to maximum width of histogram |
| static const int kLen = 200; |
| std::string underscores(kLen, '_'); |
| std::string spaces(kLen, ' '); |
| |
| auto it = buckets.begin(); |
| double maxDelta = it->first; |
| int maxCount = it->second; |
| // Compute maximum values |
| while (++it != buckets.end()) { |
| if (it->first > maxDelta) { |
| maxDelta = it->first; |
| } |
| if (it->second > maxCount) { |
| maxCount = it->second; |
| } |
| } |
| int height = log2(maxCount) + 1; // maxCount > 0, safe to call log2 |
| const int leftPadding = widthOf(1 << height); |
| const int bucketWidth = numberWidth(maxDelta, leftPadding); |
| int scalingFactor = 1; |
| // scale data if it exceeds maximum height |
| if (height > maxHeight) { |
| scalingFactor = (height + maxHeight) / maxHeight; |
| height /= scalingFactor; |
| } |
| body->appendFormat("\n%*s %3.2f %s", leftPadding + 11, |
| "Occurrences in", (elapsedMs / kMsPerSec), "seconds of audio:"); |
| body->appendFormat("\n%*s%d, %lld, %lld\n", leftPadding + 11, |
| "Thread, hash, starting timestamp: ", author, |
| static_cast<long long int>(hash), static_cast<long long int>(startingTs)); |
| // write histogram label line with bucket values |
| body->appendFormat("\n%s", " "); |
| body->appendFormat("%*s", leftPadding, " "); |
| for (auto const &x : buckets) { |
| const int colWidth = numberWidth(x.first, leftPadding); |
| body->appendFormat("%*d", colWidth, x.second); |
| } |
| // write histogram ascii art |
| body->appendFormat("\n%s", " "); |
| for (int row = height * scalingFactor; row >= 0; row -= scalingFactor) { |
| const int value = 1 << row; |
| body->appendFormat("%.*s", leftPadding, spaces.c_str()); |
| for (auto const &x : buckets) { |
| const int colWidth = numberWidth(x.first, leftPadding); |
| body->appendFormat("%.*s%s", colWidth - 1, |
| spaces.c_str(), x.second < value ? " " : "|"); |
| } |
| body->appendFormat("\n%s", " "); |
| } |
| // print x-axis |
| const int columns = static_cast<int>(buckets.size()); |
| body->appendFormat("%*c", leftPadding, ' '); |
| body->appendFormat("%.*s", (columns + 1) * bucketWidth, underscores.c_str()); |
| body->appendFormat("\n%s", " "); |
| |
| // write footer with bucket labels |
| body->appendFormat("%*s", leftPadding, " "); |
| for (auto const &x : buckets) { |
| const int colWidth = numberWidth(x.first, leftPadding); |
| body->appendFormat("%*.*f", colWidth, 1, x.first); |
| } |
| body->appendFormat("%.*s%s", bucketWidth, spaces.c_str(), "ms\n"); |
| |
| // Now report glitches |
| body->appendFormat("\ntime elapsed between glitches and glitch timestamps:\n"); |
| for (const auto &outlier: mOutlierData) { |
| body->appendFormat("%lld: %lld\n", static_cast<long long>(outlier.first), |
| static_cast<long long>(outlier.second)); |
| } |
| } |
| |
| //------------------------------------------------------------------------------ |
| |
| // writes summary of performance into specified file descriptor |
| void dump(int fd, int indent, PerformanceAnalysisMap &threadPerformanceAnalysis) { |
| String8 body; |
| const char* const kDirectory = "/data/misc/audioserver/"; |
| for (auto & thread : threadPerformanceAnalysis) { |
| for (auto & hash: thread.second) { |
| PerformanceAnalysis& curr = hash.second; |
| // write performance data to console |
| curr.reportPerformance(&body, thread.first, hash.first); |
| if (!body.isEmpty()) { |
| dumpLine(fd, indent, body); |
| body.clear(); |
| } |
| // write to file |
| writeToFile(curr.mHists, curr.mOutlierData, curr.mPeakTimestamps, |
| kDirectory, false, thread.first, hash.first); |
| } |
| } |
| } |
| |
| |
| // Writes a string into specified file descriptor |
| void dumpLine(int fd, int indent, const String8 &body) { |
| dprintf(fd, "%.*s%s \n", indent, "", body.string()); |
| } |
| |
| } // namespace ReportPerformance |
| |
| } // namespace android |