Merge "Moved analysis work from NBLog to PerformanceAnalysis"

        "MonoPipeReader.cpp",

        "NBAIO.cpp",

        "NBLog.cpp",

        "PerformanceAnalysis.cpp",

        "Pipe.cpp",

        "PipeReader.cpp",

        "SourceAudioBufferProvider.cpp",

#include <new>

#include <audio_utils/roundup.h>

#include <media/nbaio/NBLog.h>

#include <media/nbaio/PerformanceAnalysis.h>

// #include <utils/CallStack.h> // used to print callstack

#include <utils/Log.h>

#include <utils/String8.h>

      mFifo(mShared != NULL ?

        new audio_utils_fifo(size, sizeof(uint8_t),

            mShared->mBuffer, mShared->mRear, NULL /*throttlesFront*/) : NULL),

      mFifoReader(mFifo != NULL ? new audio_utils_fifo_reader(*mFifo) : NULL),

      findGlitch(false)

      mFifoReader(mFifo != NULL ? new audio_utils_fifo_reader(*mFifo) : NULL)

{

}

    delete mFifo;

}

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

    return (ns2 - ns1) / (1000 * 1000);

}

// Produces a log warning if the timing of recent buffer periods caused a glitch

// Computes sum of running window of three buffer periods

// Checks whether the buffer periods leave enough CPU time for the next one

// e.g. if a buffer period is expected to be 4 ms and a buffer requires 3 ms of CPU time,

// here are some glitch cases:

// 4 + 4 + 6 ; 5 + 4 + 5; 2 + 2 + 10

// TODO: develop this code to track changes in histogram distribution in addition

// to / instead of glitches

void NBLog::Reader::alertIfGlitch(const std::vector<int64_t> &samples) {

    //TODO: measure kPeriodLen and kRatio from the data as they may change.

    static const int kPeriodLen = 4; // current period length is ideally 4 ms

    static const double kRatio = 0.75; // estimate of CPU time as ratio of period length

    // DAC processing time for 4 ms buffer

    static const int kPeriodTime = static_cast<int>(round(kPeriodLen * kRatio));

    static const int kNumBuff = 3; // number of buffers considered in local history

    std::deque<int> periods(kNumBuff, kPeriodLen);

    for (size_t i = 2; i < samples.size(); ++i) { // skip first time entry

        periods.push_front(deltaMs(samples[i - 1], samples[i]));

        periods.pop_back();

        // TODO: check that all glitch cases are covered

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

            kPeriodLen - kPeriodTime) {

                ALOGW("A glitch occurred");

                periods.assign(kNumBuff, kPeriodLen);

        }

    }

    return;

}

const uint8_t *NBLog::Reader::findLastEntryOfTypes(const uint8_t *front, const uint8_t *back,

                                            const std::set<Event> &types) {

    while (back + Entry::kPreviousLengthOffset >= front) {

            ++entry;

            break;

        }

        // if (!body.isEmpty()) {

        //    dumpLine(timestamp, body);

        // }

    }

    reportPerformance(&body, mRecentHists);

    PerformanceAnalysis performanceAnalyzer;

    performanceAnalyzer.reportPerformance(&body, mRecentHists);

    if (!body.isEmpty()) {

        dumpLine(timestamp, body);

    }

    return iMemory != 0 && mIMemory != 0 && iMemory->pointer() == mIMemory->pointer();

}

void NBLog::Reader::setFindGlitch(bool s)

{

    findGlitch = s;

}

bool NBLog::Reader::isFindGlitch() const

{

    return findGlitch;

}

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

void NBLog::appendTimestamp(String8 *body, const void *data) {

    return arg;

}

static int widthOf(int x) {

    int width = 0;

    while (x > 0) {

        ++width;

        x /= 10;

    }

    return width;

}

static inline uint32_t log2(uint32_t x) {

    // This works for x > 0

    return 31 - __builtin_clz(x);

}

// TODO create a subclass of Reader for this and related work

void NBLog::Reader::reportPerformance(String8 *body,

                                  const std::deque<std::pair

                                         <int, short_histogram>> &shortHists,

                                         int maxHeight) {

    if (shortHists.size() < 1) {

        return;

    }

    // this is temporary code, which only prints out one histogram

    // of all data stored in buffer. The data is not erased, only overwritten.

    // TODO: more elaborate data analysis

    std::map<int, int> buckets;

    for (const auto &shortHist: shortHists) {

        for (const auto &countPair : shortHist.second) {

            buckets[countPair.first] += countPair.second;

        }

    }

    // underscores and spaces length corresponds to maximum width of histogram

    static const int kLen = 40;

    std::string underscores(kLen, '_');

    std::string spaces(kLen, ' ');

    auto it = buckets.begin();

    int 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 colWidth = std::max(std::max(widthOf(maxDelta) + 1, 3), leftPadding + 2);

    int scalingFactor = 1;

    // scale data if it exceeds maximum height

    if (height > maxHeight) {

        scalingFactor = (height + maxHeight) / maxHeight;

        height /= scalingFactor;

    }

    body->appendFormat("\n%*s", leftPadding + 11, "Occurrences");

    // write histogram label line with bucket values

    body->appendFormat("\n%s", " ");

    body->appendFormat("%*s", leftPadding, " ");

    for (auto const &x : buckets) {

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

          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) * colWidth, underscores.c_str());

    body->appendFormat("\n%s", " ");

    // write footer with bucket labels

    body->appendFormat("%*s", leftPadding, " ");

    for (auto const &x : buckets) {

        body->appendFormat("%*d", colWidth, x.first);

    }

    body->appendFormat("%.*s%s", colWidth, spaces.c_str(), "ms\n");

}

// TODO put this function in separate file. Make it return a std::string instead of modifying body

void NBLog::Reader::drawHistogram(String8 *body,

                                  const std::vector<int64_t> &samples,

                                  bool logScale,

                                  int indent,

                                  int maxHeight) {

    // this avoids some corner cases

    if (samples.size() <= 1) {

        return;

    }

    // temp code for debugging the outlier timestamp

    const int kMaxMs = 100;

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

        const int currDelta = deltaMs(samples[i - 1], samples[i]);

        if (currDelta > kMaxMs) {

            body->appendFormat("\nlocation: %zu, size: %zu, pos from end: %zu, %d\t", i,

                           samples.size(), samples.size() - i, currDelta);

        }

    }

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

    std::map<int, int> buckets = buildBuckets(samples);

    // TODO consider changing all ints to uint32_t or uint64_t

    // underscores and spaces length corresponds to maximum width of histogram

    static const int kLen = 40;

    std::string underscores(kLen, '_');

    std::string spaces(kLen, ' ');

    auto it = buckets.begin();

    int 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 = logScale ? log2(maxCount) + 1 : maxCount; // maxCount > 0, safe to call log2

    const int leftPadding = widthOf(logScale ? 1 << height : maxCount);

    const int colWidth = std::max(std::max(widthOf(maxDelta) + 1, 3), leftPadding + 2);

    int scalingFactor = 1;

    // scale data if it exceeds maximum height

    if (height > maxHeight) {

        scalingFactor = (height + maxHeight) / maxHeight;

        height /= scalingFactor;

    }

    body->appendFormat("\n%*s", leftPadding + 11, "Occurrences");

    // write histogram label line with bucket values

    body->appendFormat("\n%*s", indent, " ");

    body->appendFormat("%*s", leftPadding, " ");

    for (auto const &x : buckets) {

        body->appendFormat("%*d", colWidth, x.second);

    }

    // write histogram ascii art

    body->appendFormat("\n%*s", indent, " ");

    for (int row = height * scalingFactor; row >= 0; row -= scalingFactor) {

        const int value = logScale ? (1 << row) : row;

        body->appendFormat("%.*s", leftPadding, spaces.c_str());

        for (auto const &x : buckets) {

          body->appendFormat("%.*s%s", colWidth - 1, spaces.c_str(), x.second < value ? " " : "|");

        }

        body->appendFormat("\n%*s", indent, " ");

    }

    // print x-axis

    const int columns = static_cast<int>(buckets.size());

    body->appendFormat("%*c", leftPadding, ' ');

    body->appendFormat("%.*s", (columns + 1) * colWidth, underscores.c_str());

    body->appendFormat("\n%*s", indent, " ");

    // write footer with bucket labels

    body->appendFormat("%*s", leftPadding, " ");

    for (auto const &x : buckets) {

        body->appendFormat("%*d", colWidth, x.first);

    }

    body->appendFormat("%.*s%s", colWidth, spaces.c_str(), "ms\n");

}

NBLog::Merger::Merger(const void *shared, size_t size):

      mShared((Shared *) shared),

      mFifo(mShared != NULL ?

/*

 * 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 <fstream>

// #include <inttypes.h>

#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 <utils/CallStack.h> // used to print callstack

#include <utils/Log.h>

#include <utils/String8.h>

#include <queue>

#include <utility>

namespace android {

PerformanceAnalysis::PerformanceAnalysis() : findGlitch(false) {

	ALOGE("this value should be 4: %d", kPeriodMs);

	kPeriodMsCPU = static_cast<int>(PerformanceAnalysis::kPeriodMs * kRatio);

}

static int widthOf(int x) {

    int width = 0;

    while (x > 0) {

        ++width;

        x /= 10;

    }

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

        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;

      }

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

        }

      }

    }

    return;

}*/

// 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: 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) {

        return;

    }

    // this is temporary code, which only prints out one histogram

    // of all data stored in buffer. The data is not erased, only overwritten.

    // TODO: more elaborate data analysis

    std::map<int, int> buckets;

    for (const auto &shortHist: shortHists) {

        for (const auto &countPair : shortHist.second) {

            buckets[countPair.first] += countPair.second;

        }

    }

    // underscores and spaces length corresponds to maximum width of histogram

    static const int kLen = 40;

    std::string underscores(kLen, '_');

    std::string spaces(kLen, ' ');

    auto it = buckets.begin();

    int 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 colWidth = std::max(std::max(widthOf(maxDelta) + 1, 3), leftPadding + 2);

    int scalingFactor = 1;

    // scale data if it exceeds maximum height

    if (height > maxHeight) {

        scalingFactor = (height + maxHeight) / maxHeight;

        height /= scalingFactor;

    }

    body->appendFormat("\n%*s", leftPadding + 11, "Occurrences");

    // write histogram label line with bucket values

    body->appendFormat("\n%s", " ");

    body->appendFormat("%*s", leftPadding, " ");

    for (auto const &x : buckets) {

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

          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) * colWidth, underscores.c_str());

    body->appendFormat("\n%s", " ");

    // write footer with bucket labels

    body->appendFormat("%*s", leftPadding, " ");

    for (auto const &x : buckets) {

        body->appendFormat("%*d", colWidth, x.first);

    }

    body->appendFormat("%.*s%s", colWidth, spaces.c_str(), "ms\n");

}

// Produces a log warning if the timing of recent buffer periods caused a glitch

// Computes sum of running window of three buffer periods

// Checks whether the buffer periods leave enough CPU time for the next one

// e.g. if a buffer period is expected to be 4 ms and a buffer requires 3 ms of CPU time,

// here are some glitch cases:

// 4 + 4 + 6 ; 5 + 4 + 5; 2 + 2 + 10

// TODO: develop this code to track changes in histogram distribution in addition

// to / instead of glitches.

void PerformanceAnalysis::alertIfGlitch(const std::vector<int64_t> &samples) {

    std::deque<int> periods(kNumBuff, kPeriodMs);

    for (size_t i = 2; i < samples.size(); ++i) { // skip first time entry

        periods.push_front(deltaMs(samples[i - 1], samples[i]));

        periods.pop_back();

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

        }

    }

    return;

}

bool PerformanceAnalysis::isFindGlitch() const

{

    return findGlitch;

}

void PerformanceAnalysis::setFindGlitch(bool s)

{

    findGlitch = s;

}

//TODO: ask Andy where to keep '= 4'

const int PerformanceAnalysis::kPeriodMs; //  = 4;

}   // namespace android

/*

 * Copyright (C) 2013 The Android Open Source Project

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

    virtual ~Reader();

    void alertIfGlitch(const std::vector<int64_t> &samples);

    // get snapshot of readers fifo buffer, effectively consuming the buffer

    std::unique_ptr<Snapshot> getSnapshot();

    // dump a particular snapshot of the reader

    // dump the current content of the reader's buffer (call getSnapshot() and previous dump())

    void     dump(int fd, size_t indent = 0);

    bool     isIMemory(const sp<IMemory>& iMemory) const;

    // if findGlitch is true, log warning when buffer periods caused glitch

    void     setFindGlitch(bool s);

    bool     isFindGlitch() const;

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;

    // dummy method for handling absent author entry

    virtual void handleAuthor(const AbstractEntry& /*fmtEntry*/, String8* /*body*/) {}

    static void drawHistogram(String8 *body, const std::vector<int64_t> &samples,

                              bool logScale, int indent = 0, int maxHeight = 10);

    static void reportPerformance(String8 *body,

                                  const std::deque<std::pair

                                         <int, short_histogram>> &shortHists,

                                  int maxHeight = 10);

    // Searches for the last entry of type <type> in the range [front, back)

    // back has to be entry-aligned. Returns nullptr if none enconuntered.

    static const uint8_t *findLastEntryOfTypes(const uint8_t *front, const uint8_t *back,

                                         const std::set<Event> &types);

    static const size_t kSquashTimestamp = 5; // squash this many or more adjacent timestamps

    bool findGlitch; // alert if a local buffer period sequence caused an audio glitch

};

// Wrapper for a reader with a name. Contains a pointer to the reader and a pointer to the name

/*

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

 */

// Non-blocking event logger intended for safe communication between processes via shared memory

#ifndef ANDROID_MEDIA_PERFORMANCEANALYSIS_H

#define ANDROID_MEDIA_PERFORMANCEANALYSIS_H

#include <map>

#include <deque>

#include <vector>

namespace android {

class String8;

class PerformanceAnalysis {

public:

PerformanceAnalysis();

// stores a short-term histogram of size determined by kShortHistSize

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

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.

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

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

static 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);

~PerformanceAnalysis() {}

private:

// stores long-term audio performance data

// TODO: Turn it into a circular buffer

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

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

};

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

    return (ns2 - ns1) / (1000 * 1000);

}

static inline uint32_t log2(uint32_t x) {

    // This works for x > 0

    return 31 - __builtin_clz(x);

}