Fixed timestamp outlier bug

*     class instances, where the wakeup() intervals are stored as histograms

*     and analyzed.

*

* 3) reading the data from private buffer

* MediaLogService::dump

*     calls NBLog::Reader::dump(CONSOLE)

*     The private buffer contains all logs for all readers in shared memory

* NBLog::Reader::dump(int)

*     calls getSnapshot on the current reader

*     calls dump(int, size_t, Snapshot)

* NBLog::Reader::dump(int, size, snapshot)

*     iterates through snapshot's events and switches based on their type

*     (string, timestamp, etc...)

*     In the case of EVENT_HISTOGRAM_ENTRY_TS, adds a list of timestamp sequences

*     (histogram entry) to NBLog::mHists

*     TODO: add every HISTOGRAM_ENTRY_TS to two

*     circular buffers: one short-term and one long-term (can add even longer-term

*     structures in the future). When dump is called, print everything currently

*     in the buffer.

* NBLog::drawHistogram

*     input: timestamp array

*     buckets this to a histogram and prints

*

* 3) Dumpsys media.log call to report the data

* MediaLogService::dump in MediaLogService.cpp

*     calls NBLog::Reader::dump, which calls ReportPerformance::dump

* ReportPerformance::dump

*     calls PerformanceAnalysis::ReportPerformance

*     and ReportPerformance::WriteToFile

* PerformanceAnalysis::ReportPerformance

*     for each thread/source file location instance of PerformanceAnalysis data,

*     combines all histograms into a single one and prints it to the console

*     along with outlier data

* ReportPerformance::WriteToFile

*     writes histogram, outlier, and peak information to file separately for each

*     instance of PerformanceAnalysis data.

*/

#define LOG_TAG "NBLog"

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

const std::set<NBLog::Event> NBLog::Reader::startingTypes {NBLog::Event::EVENT_START_FMT,

                                                           NBLog::Event::EVENT_HISTOGRAM_ENTRY_TS};

        NBLog::Event::EVENT_HISTOGRAM_ENTRY_TS,

        NBLog::Event::EVENT_AUDIO_STATE};

const std::set<NBLog::Event> NBLog::Reader::endingTypes   {NBLog::Event::EVENT_END_FMT,

        NBLog::Event::EVENT_HISTOGRAM_ENTRY_TS,

        NBLog::Event::EVENT_AUDIO_STATE};

            memcpy(&hash, &(data->hash), sizeof(hash));

            int64_t ts;

            memcpy(&ts, &data->ts, sizeof(ts));

            mThreadPerformanceAnalysis[data->author][hash].logTsEntry(ts);

            // TODO: hash for histogram ts and audio state need to match

            // and correspond to audio production source file location

            mThreadPerformanceAnalysis[data->author][0 /*hash*/].logTsEntry(ts);

            ++entry;

            break;

        }

            // There's probably a more efficient way to do it

            log_hash_t hash;

            memcpy(&hash, &(data->hash), sizeof(hash));

            mThreadPerformanceAnalysis[data->author][hash].handleStateChange();

            // TODO: remove ts if unused

            int64_t ts;

            memcpy(&ts, &data->ts, sizeof(ts));

            mThreadPerformanceAnalysis[data->author][0 /*hash*/].handleStateChange();

            ++entry;

            break;

        }

}

void NBLog::MergeReader::dump(int fd, int indent) {

    // TODO: add a mutex around media.log dump

    ReportPerformance::dump(fd, indent, mThreadPerformanceAnalysis);

}

    return width;

}

// Given a series of audio processing wakeup timestamps,

// buckets the time intervals into a histogram, searches for

// 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, and flushes

// the timestamp series from memory.

void PerformanceAnalysis::processAndFlushTimeStampSeries() {

    if (mTimeStampSeries.empty()) {

// small or large values and stores these as peaks

void PerformanceAnalysis::logTsEntry(int64_t ts) {

    // after a state change, start a new series and do not

    // record time intervals in-between

    if (mOutlierDistribution.mPrevTs == 0) {

        mOutlierDistribution.mPrevTs = ts;

        return;

    }

    // TODO: add mPrev ts depending on whether or not handleStateChange was called

    for (size_t i = 1; i < mTimeStampSeries.size(); i++) {

        // Check whether the current timestamp is an outlier

        const bool isOutlier = detectAndStoreOutlier(mTimeStampSeries[i]);

    // 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(ts);

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

        // Also insert a new empty histogram if a change in behavior (peak)

        // occurred at the current timestamp

        if (mHists.empty() || deltaMs(mHists[0].first, mTimeStampSeries[i]) >=

                kMaxLength.HistTimespanMs) {

            mHists.emplace_front(static_cast<uint64_t>(mTimeStampSeries[i]),

                                 std::map<int, int>());

    if (mHists.empty() ||

        deltaMs(mHists[0].first, ts) >= kMaxLength.HistTimespanMs) {

        mHists.emplace_front(static_cast<uint64_t>(ts), std::map<int, int>());

        // When memory is full, delete oldest histogram

        // TODO: use a circular buffer

        if (mHists.size() >= kMaxLength.Hists) {

        }

    }

    // add current time intervals to histogram

        ++mHists[0].second[deltaMs(mTimeStampSeries[i-1], mTimeStampSeries[i])];

    ++mHists[0].second[deltaMs(mOutlierDistribution.mPrevTs, ts)];

    // update previous timestamp

    mOutlierDistribution.mPrevTs = ts;

}

    // clear the timestamps

    mTimeStampSeries.clear();

    // reset outlier values

    mOutlierDistribution.mPrevNs = -1;

}

// forces short-term histogram storage to avoid adding idle audio time interval

// to buffer period data

void PerformanceAnalysis::handleStateChange() {

    ALOGD("handleStateChange");

    processAndFlushTimeStampSeries();

    mOutlierDistribution.mPrevTs = 0;

    return;

}

// Takes a single buffer period timestamp entry information and stores it in a

// temporary series of timestamps. Once the series is full, the data is analyzed,

// stored, and emptied.

void PerformanceAnalysis::logTsEntry(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.push_back(ts);

    // if length of the time series has reached kShortHistSize samples,

    // analyze the data and flush the timestamp series from memory

    if (mTimeStampSeries.size() >= kMaxLength.TimeStamps) {

        processAndFlushTimeStampSeries();

    }

}

// Checks whether the time interval between two outliers is far enough from

// a typical delta to be considered a peak.

bool PerformanceAnalysis::detectAndStorePeak(outlierInterval diff, timestamp ts) {

    bool isPeak = false;

    if (mOutlierData.empty()) {

        ALOGD("mOutlierData is empty");

        return false;

    }

    // Update mean of the distribution

        const double kDelta2 = diff - mOutlierDistribution.mMean;

        mOutlierDistribution.mM2 += kDelta * kDelta2;

        mOutlierDistribution.mSd = (mOutlierDistribution.mN < 2) ? 0 :

                mOutlierDistribution.mM2 / (mOutlierDistribution.mN - 1);

                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

    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).

bool PerformanceAnalysis::detectAndStoreOutlier(const int64_t ts) {

    // first pass: need to initialize

    if (mOutlierDistribution.mPrevNs == -1) {

        mOutlierDistribution.mPrevNs = ts;

    }

    bool isOutlier = false;

    const uint64_t diffMs = static_cast<uint64_t>(deltaMs(mOutlierDistribution.mPrevNs, ts));

    // ALOGD("%d\t", static_cast<int>(diffMs));

    if (diffMs >= static_cast<uint64_t>(kOutlierMs)) {

    const int64_t diffMs = static_cast<int64_t>(deltaMs(mOutlierDistribution.mPrevTs, ts));

    if (diffMs >= static_cast<int64_t>(kOutlierMs)) {

        isOutlier = true;

        //ALOGD("outlier outlier %d %d", static_cast<int>(diffMs),

        //      static_cast<int>(mOutlierDistribution.mElapsed));

        mOutlierData.emplace_front(mOutlierDistribution.mElapsed,

                                  static_cast<uint64_t>(mOutlierDistribution.mPrevNs));

                                  static_cast<uint64_t>(mOutlierDistribution.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

        mOutlierDistribution.mElapsed = 0;

    }

    mOutlierDistribution.mElapsed += diffMs;

    mOutlierDistribution.mPrevNs = ts;

    return isOutlier;

}

// TODO Make it return a std::string instead of modifying body --> is this still relevant?

// TODO consider changing all ints to uint32_t or uint64_t

// TODO: move this to ReportPerformance, probably make it a friend function of PerformanceAnalysis

        ALOGD("reportPerformance: mHists is empty");

        return;

    }

    ALOGD("reportPerformance: hists size %d", static_cast<int>(mHists.size()));

    std::map<int, int> buckets;

    for (const auto &shortHist: mHists) {

    }

}

// TODO: decide whether to use this or whether it is overkill, and it is enough

// to only treat as glitches single wakeup call intervals which are too long.

// Ultimately, glitch detection will be directly on the audio signal.

        // TODO: check that all glitch cases are covered

        if (std::accumulate(periods.begin(), periods.end(), 0) > kNumBuff * kPeriodMs +

            kPeriodMs - kPeriodMsCPU) {

                ALOGW("A glitch occurred");

                periods.assign(kNumBuff, kPeriodMs);

        }

    }

// writes summary of performance into specified file descriptor

void dump(int fd, int indent, PerformanceAnalysisMap &threadPerformanceAnalysis) {

    String8 body;

    int i = 0; // TODO: delete

    const char* const kDirectory = "/data/misc/audioserver/";

    for (auto & thread : threadPerformanceAnalysis) {

        for (auto & hash: thread.second) {

            ALOGD("hash number %d", i++);

            PerformanceAnalysis& curr = hash.second;

            // Add any new data

            curr.processAndFlushTimeStampSeries();

            // write performance data to console

            curr.reportPerformance(&body);

            if (!body.isEmpty()) {

    }

}

// Writes a string into specified file descriptor

void dumpLine(int fd, int indent, const String8 &body) {

    dprintf(fd, "%.*s%s \n", indent, "", body.string());

        int author;

    }; //TODO __attribute__((packed));

    using StateTsEntryWithAuthor = HistTsEntryWithAuthor;

    struct HistIntEntry {

        log_hash_t hash;

        int value;

    // stores buffer period histograms with timestamp of first sample

    std::deque<std::pair<timestamp, Histogram>> mHists;

    // vector of timestamps, collected from NBLog for a specific thread

    // when a vector reaches its maximum size, the data is processed and flushed

    std::vector<timestamp_raw> mTimeStampSeries;

    // Parameters used when detecting outliers

    // TODO: learn some of these from the data, delete unused ones

    // TODO: put used variables in a struct

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

    // TODO: use m prefix

    // TODO: change this to a running variance/mean class

    struct OutlierDistribution {

        double mMean = 0; // sample mean since previous peak

        double mSd = 0; // sample sd since previous peak

        outlierInterval mElapsed = 0; // time since previous detected outlier

        int64_t mPrevNs = -1; // previous timestamp

        int64_t mPrevTs = -1; // previous timestamp

        // number of standard deviations from mean considered a significant change

        const int kMaxDeviation = 5;

        double mTypicalDiff = 0; // global mean of outliers

void FastMixer::onStateChange()

{

    // log that audio was turned on/off

    LOG_AUDIO_STATE();

    const FastMixerState * const current = (const FastMixerState *) mCurrent;

    const FastMixerState * const previous = (const FastMixerState *) mPrevious;

    FastMixerDumpState * const dumpState = (FastMixerDumpState *) mDumpState;

void FastMixer::onWork()

{

    // TODO: pass an ID parameter to indicate which time series we want to write to in NBLog.cpp

    // Or: pass both of these into a single call with a boolean

    if (mIsWarm) {

        LOG_HIST_TS();

    } else {

        LOG_AUDIO_STATE();

    }

    const FastMixerState * const current = (const FastMixerState *) mCurrent;

    FastMixerDumpState * const dumpState = (FastMixerDumpState *) mDumpState;

    const FastMixerState::Command command = mCommand;