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

Commit 316f1fd6 authored by Sanna Catherine de Treville Wager's avatar Sanna Catherine de Treville Wager
Browse files

Reports buffer period glitch timestamps and intervals

Test: dumpsys media.log

Change-Id: I3f386fdfc997f14cc825aa7f39e86488ccf0fcd2
parent d0dfe43a
Loading
Loading
Loading
Loading
+7 −3
Original line number Diff line number Diff line
@@ -941,6 +941,7 @@ void NBLog::Reader::dump(int fd, size_t indent, NBLog::Reader::Snapshot &snapsho
    mFd = fd;
    mIndent = indent;
    String8 timestamp, body;
    PerformanceAnalysis performanceAnalyzer; // used 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);
@@ -969,9 +970,11 @@ void NBLog::Reader::dump(int fd, size_t indent, NBLog::Reader::Snapshot &snapsho
            // 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,
            // compute its histogram, append this to mRecentHists and erase the time series
            // 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
@@ -1001,11 +1004,12 @@ void NBLog::Reader::dump(int fd, size_t indent, NBLog::Reader::Snapshot &snapsho
            break;
        }
    }
    PerformanceAnalysis performanceAnalyzer;
    performanceAnalyzer.reportPerformance(&body, mRecentHists);
    if (!body.isEmpty()) {
        dumpLine(timestamp, body);
    }
    // comment in for tests
    // performanceAnalyzer.testFunction();
}

void NBLog::Reader::dump(int fd, size_t indent)
+55 −50
Original line number Diff line number Diff line
@@ -22,7 +22,6 @@
#include <climits>
#include <deque>
#include <fstream>
// #include <inttypes.h>
#include <iostream>
#include <math.h>
#include <numeric>
@@ -47,7 +46,6 @@
namespace android {

PerformanceAnalysis::PerformanceAnalysis() : findGlitch(false) {
	ALOGE("this value should be 4: %d", kPeriodMs);
    kPeriodMsCPU = static_cast<int>(PerformanceAnalysis::kPeriodMs * kRatio);
}

@@ -60,49 +58,51 @@ static int widthOf(int x) {
    return width;
}

// WIP: uploading this half-written function to get code review on
// cleanup and new file creation.
/*
static std::vector<std::pair<int, int>> outlierIntervals(
        const std::deque<std::pair<int, short_histogram>> &shortHists) {
    // TODO: need the timestamps
    if (shortHists.size() < 1) {
// 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));
    }
}

// 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
// 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) {
    if (timestamps.size() < 1) {
        ALOGE("storeOutlierData called on empty vector");
        return;
    }
    // count number of outliers in histogram
    // TODO: need the alertIfGlitch analysis on the time series in NBLog::reader
    // to find all the glitches
    const std::vector<int> glitchCount = std::vector<int>(shortHists.size());
    // Total ms elapsed in each shortHist
    const std::vector<int> timeElapsedMs = std::vector<int>(shortHists.size());
    int i = 0;
    for (const auto &shortHist: shortHists) {
        for (const auto &bin: shortHist) {
            timeElapsedMs.at(i) += bin->first * bin->second;
            if (bin->first >= kGlitchThreshMs) {
                glitchCount.at(i) += bin->second;
            }
        }
        i++;
    }
    // seconds between glitches and corresponding timestamp
    const std::vector<std::pair<double, int>> glitchFreeIntervalsSec;
    // Sec since last glitch. nonzero if the duration spans many shortHists
    double glitchFreeSec = 0;
    for (int i = 0; i < kGlitchCount.size(); i++) {
      if (kGlitchCount.at(i) == 0) {
        glitchFreeSec += static_cast<double>timeElapsedMs.at(i) / kMsPerSec;
    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);
    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;
        }
      else {
        // average time between glitches in this interval
        const double kInterval = static_cast<double>(timeElapsedMs.at(i)) / kGlitchCount.at(i);
        for (int j = 0; j < kGlitchCount.at(i); j++) {
          kIntervals.emplace_front(kInterval);
        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));
    //}
}
    }
    return;
}*/

// TODO: implement peak detector
/*
@@ -189,6 +189,13 @@ void PerformanceAnalysis::reportPerformance(String8 *body,
    }
    body->appendFormat("%.*s%s", colWidth, 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));
    }

}


@@ -224,7 +231,5 @@ void PerformanceAnalysis::setFindGlitch(bool s)
{
    findGlitch = s;
}
//TODO: ask Andy where to keep '= 4'
const int PerformanceAnalysis::kPeriodMs; //  = 4;

}   // namespace android
+19 −13
Original line number Diff line number Diff line
@@ -39,12 +39,14 @@ PerformanceAnalysis();
// both in this header file and in NBLog.h?
using short_histogram = std::map<int, int>;

// returns a 2d array where the first values are ms time intervals between
// outliers and the second values are the timestamps at which the outliers
// occurred. The first values do not keep track of time spent *on* the outlier.
// 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
// static void outlierIntervals(const std::deque<std::pair
//                                    <int, short_histogram>> &shortHists);
void storeOutlierData(int author, const std::vector<int64_t> &timestamps);

// 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
@@ -60,7 +62,7 @@ using short_histogram = std::map<int, int>;
// 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
static void reportPerformance(String8 *body,
void reportPerformance(String8 *body,
                       const std::deque<std::pair
                       <int, short_histogram>> &shortHists,
                       int maxHeight = 10);
@@ -75,6 +77,9 @@ void setFindGlitch(bool s);

private:

// stores outlier analysis
std::vector<std::pair<uint64_t, uint64_t>> mOutlierData;

// stores long-term audio performance data
// TODO: Turn it into a circular buffer
std::deque<std::pair<int, int>> mPerformanceAnalysis;
@@ -82,10 +87,11 @@ std::deque<std::pair<int, int>> mPerformanceAnalysis;
// 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.
static const int kGlitchThreshMs = 7;
static const int kMsPerSec = 1000;
static const int kNumBuff = 3; // number of buffers considered in local history
static const int kPeriodMs = 4; // current period length is ideally 4 ms
//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
// 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