media/libnblog/PerformanceAnalysis.cpp

/*
 * 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
// #define WRITE_TO_FILE

#include <algorithm>
#include <climits>
#include <deque>
#include <math.h>
#include <numeric>
#include <sstream>
#include <string>
#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/LogPlot.h>
#include <audio_utils/roundup.h>
#include <media/nblog/NBLog.h>
#include <media/nblog/PerformanceAnalysis.h>
#include <media/nblog/ReportPerformance.h>
#include <utils/Log.h>
#include <utils/String8.h>

#include <queue>
#include <utility>

namespace android {

void Histogram::add(double value)
{
    // TODO Handle domain and range error exceptions?
    const int binIndex = lround((value - mLow) / mBinSize);
    if (binIndex < 0) {
        mLowCount++;
    } else if (binIndex >= mNumBins) {
        mHighCount++;
    } else {
        mBins[binIndex]++;
    }
    mTotalCount++;
}

void Histogram::clear()
{
    std::fill(mBins.begin(), mBins.end(), 0);
    mLowCount = 0;
    mHighCount = 0;
    mTotalCount = 0;
}

uint64_t Histogram::totalCount() const
{
    return mTotalCount;
}

std::string Histogram::serializeToString() const {
    std::stringstream ss;
    static constexpr char kDivider = '|';
    ss << mBinSize << "," << mNumBins << "," << mLow << ",{";
    bool first = true;
    if (mLowCount != 0) {
        ss << "-1" << kDivider << mLowCount;
        first = false;
    }
    for (size_t i = 0; i < mNumBins; i++) {
        if (mBins[i] != 0) {
            if (!first) {
                ss << ",";
            }
            ss << i << kDivider << mBins[i];
            first = false;
        }
    }
    if (mHighCount != 0) {
        if (!first) {
            ss << ",";
        }
        ss << mNumBins << kDivider << mHighCount;
        first = false;
    }
    ss << "}";

    return ss.str();
}

// TODO make a hash map from Event type to std::pair<HistConfig, unordered_map<int, Histogram>>
// so that we don't have to create a "add histogram entry" method for every different metric.
void PerformanceData::addCycleTimeEntry(int author, double cycleTimeMs)
{
    if (mCycleTimeMsHists.count(author) == 0) {
        mCycleTimeMsHists.emplace(author, Histogram(kCycleTimeConfig));
    }
    mCycleTimeMsHists.at(author).add(cycleTimeMs);
}

void PerformanceData::addLatencyEntry(int author, double latencyMs)
{
    if (mLatencyMsHists.count(author) == 0) {
        mLatencyMsHists.emplace(author, Histogram(kLatencyConfig));
    }
    mLatencyMsHists.at(author).add(latencyMs);
}

void PerformanceData::dump(int fd, int indent __unused)
{
    // TODO add thread metadata for better context.
    // Also output in a more machine-readable friendly format.
    dprintf(fd, "Thread cycle time histograms:\n");
    for (const auto &item : mCycleTimeMsHists) {
        dprintf(fd, "  Thread %d: %s\n", item.first, item.second.serializeToString().c_str());
    }
    dprintf(fd, "Latency histograms:\n");
    for (const auto &item : mLatencyMsHists) {
        dprintf(fd, "  Thread %d: %s\n", item.first, item.second.serializeToString().c_str());
    }
}

//------------------------------------------------------------------------------

namespace ReportPerformance {

// Given an audio processing wakeup timestamp, buckets the time interval
// since the previous timestamp 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.
    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;
}

// rounds value to precision based on log-distance from mean
__attribute__((no_sanitize("signed-integer-overflow")))
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() || body == nullptr) {
        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
    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;
        }
    }

    static const int SIZE = 128;
    char title[SIZE];
    snprintf(title, sizeof(title), "\n%s %3.2f %s\n%s%d, %lld, %lld\n",
            "Occurrences in", (elapsedMs / kMsPerSec), "seconds of audio:",
            "Thread, hash, starting timestamp: ", author,
            static_cast<long long>(hash), static_cast<long long>(startingTs));
    static const char * const kLabel = "ms";

    body->appendFormat("%s",
            audio_utils_plot_histogram(buckets, title, kLabel, maxHeight).c_str());

    // 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;
#ifdef WRITE_TO_FILE
    const char* const kDirectory = "/data/misc/audioserver/";
#endif
    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();
            }
#ifdef WRITE_TO_FILE
            // write to file. Enable by uncommenting macro at top of file.
            writeToFile(curr.mHists, curr.mOutlierData, curr.mPeakTimestamps,
                        kDirectory, false, thread.first, hash.first);
#endif
        }
    }
}


// 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