Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 41cad59d authored by Sanna Catherine de Treville Wager's avatar Sanna Catherine de Treville Wager
Browse files

Stores long-term histogram, outlier information

Moves analysis and storage from NBLog to
PerformanceAnalysis. Applies peak analysis to
outlier information to detect changes in the
distribution of outlier frequency.
Adds cleanup, documentation, FIXME comments for
upcoming changes.

Test: dumpsys media.log

Change-Id: Iea393dac62959aef754ae2a9b4afe2556c1f3ecb
parent 35d622f2
Loading
Loading
Loading
Loading
+4 −37
Original line number Diff line number Diff line
@@ -892,23 +892,14 @@ inline void writeHistToFile(const std::vector<int64_t> &samples, bool append) {
    ofs.close();
}

// converts a time series into a map. key: buffer period length. value: count
static std::map<int, int> buildBuckets(const std::vector<int64_t> &samples) {
    // TODO allow buckets of variable resolution
    std::map<int, int> buckets;
    for (size_t i = 1; i < samples.size(); ++i) {
        ++buckets[deltaMs(samples[i - 1], samples[i])];
    }
    return buckets;
}

void NBLog::Reader::dump(int fd, size_t indent, NBLog::Reader::Snapshot &snapshot)
{
    //  CallStack cs(LOG_TAG);
    mFd = fd;
    mIndent = indent;
    String8 timestamp, body;
    PerformanceAnalysis performanceAnalyzer; // used to call analysis functions
    // FIXME: this is not thread safe
    static PerformanceAnalysis performanceAnalysis; // used to store data and to call analysis functions
    size_t lost = snapshot.lost() + (snapshot.begin() - EntryIterator(snapshot.data()));
    if (lost > 0) {
        body.appendFormat("warning: lost %zu bytes worth of events", lost);
@@ -930,29 +921,7 @@ void NBLog::Reader::dump(int fd, size_t indent, NBLog::Reader::Snapshot &snapsho
            memcpy(&hash, &(data->hash), sizeof(hash));
            int64_t ts;
            memcpy(&ts, &data->ts, sizeof(ts));
            const std::pair<log_hash_t, int> key(hash, data->author);
            // TODO might want to filter excessively high outliers, which are usually caused
            // by the thread being inactive.
            mHists[key].push_back(ts);
            // store time series data for each reader in order to bucket it once there
            // is enough data. Then, it is written to recentHists as a histogram.
            mTimeStampSeries[data->author].push_back(ts);
            // if length of the time series has reached kShortHistSize samples, do 1) and 2):
            if (mTimeStampSeries[data->author].size() >= kShortHistSize) {
                // 1) analyze the series to store all outliers and their exact timestamps:
                performanceAnalyzer.storeOutlierData(data->author, mTimeStampSeries[data->author]);
                 // 2) compute its histogram, append this to mRecentHists and erase the time series
                mRecentHists.emplace_front(data->author,
                                           buildBuckets(mTimeStampSeries[data->author]));
                // do not let mRecentHists exceed capacity
                // TODO: turn the FIFO queue into a circular buffer
                if (mRecentHists.size() >= kRecentHistsCapacity) {
                    mRecentHists.pop_back();
                }
                mTimeStampSeries.erase(data->author);
            }
            // if an element in mHists has not grown for a long time, delete
            // TODO copy histogram data only to mRecentHistsBuffer and pop oldest
            performanceAnalysis.logTsEntry(data->author, ts);
            ++entry;
            break;
        }
@@ -967,12 +936,10 @@ void NBLog::Reader::dump(int fd, size_t indent, NBLog::Reader::Snapshot &snapsho
            break;
        }
    }
    performanceAnalyzer.reportPerformance(&body, mRecentHists);
    performanceAnalysis.reportPerformance(&body);
    if (!body.isEmpty()) {
        dumpLine(timestamp, body);
    }
    // comment in for tests
    // performanceAnalyzer.testFunction();
}

void NBLog::Reader::dump(int fd, size_t indent)
+151 −60
Original line number Diff line number Diff line
@@ -45,8 +45,21 @@

namespace android {

PerformanceAnalysis::PerformanceAnalysis() : findGlitch(false) {
    kPeriodMsCPU = static_cast<int>(PerformanceAnalysis::kPeriodMs * kRatio);
PerformanceAnalysis::PerformanceAnalysis() {
    // These variables will be (FIXME) learned from the data
    kPeriodMs = 4; // typical buffer period (mode)
    // average number of Ms spent processing buffer
    kPeriodMsCPU = static_cast<int>(kPeriodMs * kRatio);
}

// converts a time series into a map. key: buffer period length. value: count
static std::map<int, int> buildBuckets(const std::vector<int64_t> &samples) {
    // TODO allow buckets of variable resolution
    std::map<int, int> buckets;
    for (size_t i = 1; i < samples.size(); ++i) {
        ++buckets[deltaMs(samples[i - 1], samples[i])];
    }
    return buckets;
}

static int widthOf(int x) {
@@ -58,76 +71,164 @@ static int widthOf(int x) {
    return width;
}

// FIXME: delete this temporary test code, recycled for various new functions
void PerformanceAnalysis::testFunction() {
    // produces values (4: 5000000), (13: 18000000)
    // ns timestamps of buffer periods
    const std::vector<int64_t>kTempTestData = {1000000, 4000000, 5000000,
                                               16000000, 18000000, 28000000};
    const int kTestAuthor = 1;
    PerformanceAnalysis::storeOutlierData(kTestAuthor, kTempTestData);
    for (const auto &outlier: mOutlierData) {
        ALOGE("PerformanceAnalysis test %lld: %lld",
              static_cast<long long>(outlier.first), static_cast<long long>(outlier.second));
// Takes a single buffer period timestamp entry with author information and stores it
// in a temporary series of timestamps. Once the series is full, the data is analyzed,
// stored, and emptied.
// TODO: decide whether author or file location information is more important to store
// for now, only stores author (thread)
void PerformanceAnalysis::logTsEntry(int author, int64_t ts) {
    // TODO might want to filter excessively high outliers, which are usually caused
    // by the thread being inactive.
    // Store time series data for each reader in order to bucket it once there
    // is enough data. Then, write to recentHists as a histogram.
    mTimeStampSeries[author].push_back(ts);
    // if length of the time series has reached kShortHistSize samples, do 1) and 2):
    if (mTimeStampSeries[author].size() >= kShortHistSize) {
        // 1) analyze the series to store all outliers and their exact timestamps:
        storeOutlierData(mTimeStampSeries[author]);
        // 2) detect peaks in the outlier series
        detectPeaks();
        // 3) compute its histogram, append this to mRecentHists and erase the time series
        // FIXME: need to store the timestamp of the beginning of each histogram
        // FIXME: Restore LOG_HIST_FLUSH to separate histograms at every end-of-stream event
        // A histogram should not span data between audio off/on timespans
        mRecentHists.emplace_back(author,
                                   buildBuckets(mTimeStampSeries[author]));
        // do not let mRecentHists exceed capacity
        // ALOGD("mRecentHists size: %d", static_cast<int>(mRecentHists.size()));
        if (mRecentHists.size() >= kRecentHistsCapacity) {
            //  ALOGD("popped back mRecentHists");
            mRecentHists.pop_front();
        }
        mTimeStampSeries[author].clear();
    }
}

// Given a series of outlier intervals (mOutlier data),
// 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.
void PerformanceAnalysis::detectPeaks() {
    if (mOutlierData.empty()) {
        ALOGD("peak detector called on empty array");
        return;
    }

    // compute mean of the distribution. Used to check whether a value is large
    const double kTypicalDiff = std::accumulate(
        mOutlierData.begin(), mOutlierData.end(), 0,
        [](auto &a, auto &b){return a + b.first;}) / mOutlierData.size();
    // ALOGD("typicalDiff %f", kTypicalDiff);

    // iterator at the beginning of a sequence, or updated to the most recent peak
    std::deque<std::pair<uint64_t, uint64_t>>::iterator start = mOutlierData.begin();
    // the mean and standard deviation are updated every time a peak is detected
    // initialize first time. The mean from the previous sequence is stored
    // for the next sequence. Here, they are initialized for the first time.
    if (mPeakDetectorMean < 0) {
        mPeakDetectorMean = static_cast<double>(start->first);
        mPeakDetectorSd = 0;
    }
    auto sqr = [](auto x){ return x * x; };
    for (auto it = mOutlierData.begin(); it != mOutlierData.end(); ++it) {
        // no surprise occurred:
        // the new element is a small number of standard deviations from the mean
        if ((fabs(it->first - mPeakDetectorMean) < kStddevThreshold * mPeakDetectorSd) ||
             // or: right after peak has been detected, the delta is smaller than average
            (mPeakDetectorSd == 0 && fabs(it->first - mPeakDetectorMean) < kTypicalDiff)) {
            // update the mean and sd:
            // count number of elements (distance between start interator and current)
            const int kN = std::distance(start, it) + 1;
            // usual formulas for mean and sd
            mPeakDetectorMean = std::accumulate(start, it + 1, 0.0,
                                   [](auto &a, auto &b){return a + b.first;}) / kN;
            mPeakDetectorSd = sqrt(std::accumulate(start, it + 1, 0.0,
                      [=](auto &a, auto &b){ return a + sqr(b.first - mPeakDetectorMean);})) /
                      ((kN > 1)? kN - 1 : kN); // kN - 1: mean is correlated with variance
            // ALOGD("value, mean, sd: %f, %f, %f", static_cast<double>(it->first), mean, sd);
        }
        // surprising value: store peak timestamp and reset mean, sd, and start iterator
        else {
            mPeakTimestamps.emplace_back(it->second);
            // TODO: remove pop_front once a circular buffer is in place
            if (mPeakTimestamps.size() >= kShortHistSize) {
                ALOGD("popped back mPeakTimestamps");
                mPeakTimestamps.pop_front();
            }
            mPeakDetectorMean = static_cast<double>(it->first);
            mPeakDetectorSd = 0;
            start = it;
        }
    }
    //for (const auto &it : mPeakTimestamps) {
    //    ALOGE("mPeakTimestamps %f", static_cast<double>(it));
    //}
    return;
}

// Each pair consists of: <outlier timestamp, time elapsed since previous outlier>.
// The timestamp of the beginning of the outlier is recorded.
// The elapsed time is from the timestamp of the previous outlier
// Called by LogTsEntry. The input is a vector of timestamps.
// Finds outliers and writes to mOutlierdata.
// Each value in mOutlierdata consists of: <outlier timestamp, time elapsed since previous outlier>.
// e.g. timestamps (ms) 1, 4, 5, 16, 18, 28 will produce pairs (4, 5), (13, 18).
// This function is applied to the time series before it is converted into a histogram.
void PerformanceAnalysis::storeOutlierData(
    int author, const std::vector<int64_t> &timestamps) {
void PerformanceAnalysis::storeOutlierData(const std::vector<int64_t> &timestamps) {
    if (timestamps.size() < 1) {
        ALOGE("storeOutlierData called on empty vector");
        return;
    }
    author++; // temp to avoid unused error until this value is
    // either TODO: used or discarded from the arglist
    author--;
    uint64_t elapsed = 0;
    int64_t prev = timestamps.at(0);
    // first pass: need to initialize
    if (mElapsed == 0) {
        mPrevNs = timestamps[0];
    }
    for (const auto &ts: timestamps) {
        const uint64_t diff = static_cast<uint64_t>(deltaMs(prev, ts));
        if (diff >= static_cast<uint64_t>(kOutlierMs)) {
            mOutlierData.emplace_back(elapsed, static_cast<uint64_t>(prev));
            elapsed = 0;
        }
        elapsed += diff;
        prev = ts;
    }
    // ALOGE("storeOutlierData: result length %zu", outlierData.size());
    // for (const auto &outlier: OutlierData) {
    //    ALOGE("PerformanceAnalysis test %lld: %lld",
    //          static_cast<long long>(outlier.first), static_cast<long long>(outlier.second));
    //}
        const uint64_t diffMs = static_cast<uint64_t>(deltaMs(mPrevNs, ts));
        if (diffMs >= static_cast<uint64_t>(kOutlierMs)) {
            mOutlierData.emplace_back(mElapsed, static_cast<uint64_t>(mPrevNs));
            // Remove oldest value if the vector is full
            // TODO: remove pop_front once circular buffer is in place
            // FIXME: change kShortHistSize to some other constant. Make sure it is large
            // enough that data will never be lost before being written to a long-term FIFO
            if (mOutlierData.size() >= kShortHistSize) {
                ALOGD("popped back mOutlierData");
                mOutlierData.pop_front();
            }
            mElapsed = 0;
        }
        mElapsed += diffMs;
        mPrevNs = ts;
    }
}

// TODO: implement peak detector
/*
  static void peakDetector() {
  return;
  } */

// TODO put this function in separate file. Make it return a std::string instead of modifying body
// TODO create a subclass of Reader for this and related work
// FIXME: delete this temporary test code, recycled for various new functions
void PerformanceAnalysis::testFunction() {
    // produces values (4: 5000000), (13: 18000000)
    // ns timestamps of buffer periods
    const std::vector<int64_t>kTempTestData = {1000000, 4000000, 5000000,
                                               16000000, 18000000, 28000000};
    PerformanceAnalysis::storeOutlierData(kTempTestData);
    for (const auto &outlier: mOutlierData) {
        ALOGE("PerformanceAnalysis test %lld: %lld",
              static_cast<long long>(outlier.first), static_cast<long long>(outlier.second));
    }
    detectPeaks();
}

// TODO Make it return a std::string instead of modifying body --> is this still relevant?
// FIXME: as can be seen when printing the values, the outlier timestamps typically occur
// in the first histogram 35 to 38 indices from the end (most often 35).
// TODO: build histogram buckets earlier and discard timestamps to save memory
// TODO consider changing all ints to uint32_t or uint64_t
void PerformanceAnalysis::reportPerformance(String8 *body,
                                            const std::deque<std::pair
                                            <int, short_histogram>> &shortHists,
                                            int maxHeight) {
    if (shortHists.size() < 1) {
void PerformanceAnalysis::reportPerformance(String8 *body, int maxHeight) {
    if (mRecentHists.size() < 1) {
        ALOGD("reportPerformance: mRecentHists is empty");
        return;
    }
    // this is temporary code, which only prints out one histogram
    // of all data stored in buffer. The data is not erased, only overwritten.
    ALOGD("reportPerformance: hists size %d", static_cast<int>(mRecentHists.size()));
    // TODO: more elaborate data analysis
    std::map<int, int> buckets;
    for (const auto &shortHist: shortHists) {
    for (const auto &shortHist: mRecentHists) {
        for (const auto &countPair : shortHist.second) {
            buckets[countPair.first] += countPair.second;
        }
@@ -222,14 +323,4 @@ void PerformanceAnalysis::alertIfGlitch(const std::vector<int64_t> &samples) {
    return;
}

bool PerformanceAnalysis::isFindGlitch() const
{
    return findGlitch;
}

void PerformanceAnalysis::setFindGlitch(bool s)
{
    findGlitch = s;
}

}   // namespace android
+2 −20
Original line number Diff line number Diff line
@@ -406,6 +406,7 @@ class Reader : public RefBase {
public:

    // A snapshot of a readers buffer
    // This is raw data. No analysis has been done on it
    class Snapshot {
    public:
        Snapshot() : mData(NULL), mLost(0) {}
@@ -445,6 +446,7 @@ public:
    // get snapshot of readers fifo buffer, effectively consuming the buffer
    std::unique_ptr<Snapshot> getSnapshot();
    // dump a particular snapshot of the reader
    // TODO: move dump to PerformanceAnalysis. Model/view/controller design
    void     dump(int fd, size_t indent, Snapshot & snap);
    // dump the current content of the reader's buffer (call getSnapshot() and previous dump())
    void     dump(int fd, size_t indent = 0);
@@ -452,9 +454,6 @@ public:

private:

    // TODO: decide whether these belong in NBLog::Reader or in PerformanceAnalysis
    static const int kShortHistSize = 50; // number of samples in a short-term histogram
    static const int kRecentHistsCapacity = 100; // number of short-term histograms stored in memory
    static const std::set<Event> startingTypes;
    static const std::set<Event> endingTypes;
    /*const*/ Shared* const mShared;    // raw pointer to shared memory, actually const but not
@@ -467,23 +466,6 @@ private:
    audio_utils_fifo_reader * const mFifoReader;    // used to read from FIFO,
                                                    // non-NULL unless constructor fails

    // stores a short-term histogram of size determined by kShortHistSize
    // TODO: unsigned, unsigned
    using short_histogram = std::map<int, int>;

    // each pair contains a sequence of timestamps (one histogram's worth)
    // pair's log_hash_t is the hash of the source code location where the timestamp was taken
    // pair's int points to the Reader that originated the entry
    std::map<std::pair<log_hash_t, int>, std::vector<int64_t>> mHists;

    // mHistsCopy stores timestamp vectors whose key is the reader thread index.
    // TODO remove old mHists after changing the code
    std::map<int, std::vector<int64_t>> mTimeStampSeries;

    // stores fixed-size short buffer period histograms with hash and thread data
    // TODO: Turn it into a circular buffer for better data flow
    std::deque<std::pair<int, short_histogram>> mRecentHists;

    // TODO: it might be clearer, instead of a direct map from source location to vector of
    // timestamps, if we instead first mapped from source location to an object that
    // represented that location. And one_of its fields would be a vector of timestamps.
+102 −62
Original line number Diff line number Diff line
@@ -22,80 +22,120 @@
#include <map>
#include <deque>
#include <vector>
#include "NBLog.h"

namespace android {

class String8;

class PerformanceAnalysis {

    // This class stores and analyzes audio processing wakeup timestamps from NBLog
    // FIXME: currently, all performance data is stored in deques. Need to add a mutex.
    // FIXME: continue this way until analysis is done in a separate thread. Then, use
    // the fifo writer utilities.
public:

    PerformanceAnalysis();

    // FIXME: decide whether to use 64 or 32 bits
    typedef uint64_t log_hash_t;

    // stores a short-term histogram of size determined by kShortHistSize
    // key: observed buffer period. value: count
    // TODO: unsigned, unsigned
// CHECK: is there a better way to use short_histogram than to write 'using'
// both in this header file and in NBLog.h?
    // TODO: change this name to histogram
    using short_histogram = std::map<int, int>;

// returns a vector of pairs <outlier timestamp, time elapsed since previous outlier
// called by NBLog::Reader::dump before data is converted into histogram
// TODO: currently, the elapsed time
// The resolution is only as good as the ms duration of one shortHist
void storeOutlierData(int author, const std::vector<int64_t> &timestamps);
    using outlierInterval = uint64_t;
    // int64_t timestamps are converted to uint64_t in PerformanceAnalysis::storeOutlierData,
    // and all further analysis functions use uint64_t.
    using timestamp = uint64_t;
    using timestamp_raw = int64_t;

    // Writes wakeup timestamp entry to log and runs analysis
    // author is the thread ID
    // TODO: check. if the thread has multiple histograms, is author info correct
    // FIXME: remove author from arglist. Want to call these function separately on
    // each thread’s data.
    // FIXME: decide whether to store the hash (source file location) instead
    // FIXME: If thread has multiple histograms, check that code works and correct
    // author is stored (test with multiple threads). Need to check that the current
    // code is not receiving data from multiple threads. This could cause odd values.
    void logTsEntry(int author, timestamp_raw ts);

    // FIXME: make peakdetector and storeOutlierData a single function
    // Input: mOutlierData. Looks at time elapsed between outliers
    // finds significant changes in the distribution
    // writes timestamps of significant changes to mPeakTimestamps
    void detectPeaks();

    // runs analysis on timestamp series before it is converted to a histogram
    // finds outliers
    // writes to mOutlierData <time elapsed since previous outlier, outlier timestamp>
    void storeOutlierData(const std::vector<timestamp_raw> &timestamps);

    // input: series of short histograms. Generates a string of analysis of the buffer periods
    // TODO: WIP write more detailed analysis
    // FIXME: move this data visualization to a separate class. Model/view/controller
    void reportPerformance(String8 *body, int maxHeight = 10);

    // TODO: delete this. temp for testing
    void testFunction();

// Given a series, looks for changes in distribution (peaks)
// Returns a 'signal' array of the same length as the series, where each
// value is mapped to -1, 0, or 1 based on whether a negative or positive peak
// was detected, or no significant change occurred.
// 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.
// static void peakDetector();

// input: series of short histograms. output: prints an analysis of the
// data to the console
// TODO: change this so that it writes the analysis to the long-term
// circular buffer and prints an analyses both for the short and long-term
void reportPerformance(String8 *body,
                       const std::deque<std::pair
                       <int, short_histogram>> &shortHists,
                       int maxHeight = 10);

// if findGlitch is true, log warning when buffer periods caused glitch
// TODO adapt this to the analysis in reportPerformance instead of logging
void     alertIfGlitch(const std::vector<int64_t> &samples);
bool     isFindGlitch() const;
void     setFindGlitch(bool s);
    // This function used to detect glitches in a time series
    // TODO incorporate this into the analysis (currently unused)
    void     alertIfGlitch(const std::vector<timestamp_raw> &samples);

    ~PerformanceAnalysis() {}

private:

// stores outlier analysis
std::vector<std::pair<uint64_t, uint64_t>> mOutlierData;
    // stores outlier analysis: <elapsed time between outliers in ms, outlier timestamp>
    std::deque<std::pair<outlierInterval, timestamp>> mOutlierData;

    // stores each timestamp at which a peak was detected
    // a peak is a moment at which the average outlier interval changed significantly
    std::deque<timestamp> mPeakTimestamps;

    // FIFO of small histograms
    // stores fixed-size short buffer period histograms with hash and thread data
    // TODO: Turn it into a circular buffer for better data flow
    std::deque<std::pair<int, short_histogram>> mRecentHists;

// stores long-term audio performance data
// TODO: Turn it into a circular buffer
std::deque<std::pair<int, int>> mPerformanceAnalysis;
    // map from author to vector of timestamps, collected from NBLog
    // when a vector reaches its maximum size, analysis is run and the data is deleted
    std::map<int, std::vector<timestamp_raw>> mTimeStampSeries;

// alert if a local buffer period sequence caused an audio glitch
bool findGlitch;
    // TODO: measure these from the data (e.g., mode) as they may change.
    // const int kGlitchThreshMs = 7;
    // const int kMsPerSec = 1000;
const int kNumBuff = 3; // number of buffers considered in local history
const int kPeriodMs = 4; // current period length is ideally 4 ms
const int kOutlierMs = 7; // values greater or equal to this cause glitches every time

    // Parameters used when detecting outliers
    // TODO: learn some of these from the data, delete unused ones
    // FIXME: decide whether to make kPeriodMs static.
    // The non-const values are (TODO: will be) learned from the data
    static const int kNumBuff = 3; // number of buffers considered in local history
    int kPeriodMs; // current period length is ideally 4 ms
    static const int kOutlierMs = 7; // values greater or equal to this cause glitches
    // DAC processing time for 4 ms buffer
    static constexpr double kRatio = 0.75; // estimate of CPU time as ratio of period length
    int kPeriodMsCPU; // compute based on kPeriodLen and kRatio

    // Peak detection: number of standard deviations from mean considered a significant change
    static const int kStddevThreshold = 5;

    static const int kRecentHistsCapacity = 100; // number of short-term histograms stored in memory
    static const int kShortHistSize = 50; // number of samples in a short-term histogram

    // these variables are stored in-class to ensure continuity while analyzing the timestamp
    // series one short sequence at a time: the variables are not re-initialized every time.
    // FIXME: create inner class for these variables and decide which other ones to add to it
    double mPeakDetectorMean = -1;
    double mPeakDetectorSd = -1;
    // variables for storeOutlierData
    uint64_t mElapsed = 0;
    int64_t mPrevNs = -1;

};

static inline int deltaMs(int64_t ns1, int64_t ns2) {