Merge "Develop histogram logging"

namespace ReportPerformance {

static int widthOf(int x) {

    int width = 0;

    while (x > 0) {

        ++width;

        x /= 10;

    }

    return width;

}

// Given a the most recent timestamp of a series of audio processing

// wakeup timestamps,

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

    const int diffJiffy = deltaJiffy(mBufferPeriod.mPrevTs, ts);

    // update buffer period distribution

    // old versus new weight ratio when updating the buffer period mean

    static constexpr double exponentialWeight = 0.999;

    // update buffer period mean with exponential weighting

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

    return isOutlier;

}

static int widthOf(int x) {

    int width = 0;

    if (x < 0) {

        width++;

        x = x == INT_MIN ? INT_MAX : -x;

    }

    // assert (x >= 0)

    do {

        ++width;

        x /= 10;

    } while (x > 0);

    return width;

}

// computes the column width required for a specific histogram value

inline int numberWidth(int number, int leftPadding) {

    return std::max(std::max(widthOf(number) + 4, 3), leftPadding + 2);

inline int numberWidth(double number, int leftPadding) {

    // Added values account for whitespaces needed around numbers, and for the

    // dot and decimal digit not accounted for by widthOf

    return std::max(std::max(widthOf(static_cast<int>(number)) + 3, 2), leftPadding + 1);

}

// rounds value to precision based on log-distance from mean

inline double logRound(double x, double mean) {

    // Larger values increase range of high resolution

    constexpr double kBase = 2;

    const double power = floor(

        log(abs(x - mean) / mean) / log(kBase)) + 1;

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

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

        return;

    }

    std::map<int, int> buckets;

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

    // TODO: when there is more data, print many histograms, possibly separated at peaks

    std::map<double, int> buckets;

    for (const auto &shortHist: mHists) {

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

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

            const double ms = static_cast<double>(countPair.first) / kJiffyPerMs;

            buckets[logRound(ms, mBufferPeriod.mMean)] += countPair.second;

            elapsedMs += ms;

        }

    }

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

    static const int kLen = 100;

    static const int kLen = 200;

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

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

    auto it = buckets.begin();

    int maxDelta = it->first;

    double maxDelta = it->first;

    int maxCount = it->second;

    // Compute maximum values

    while (++it != buckets.end()) {

        scalingFactor = (height + maxHeight) / maxHeight;

        height /= scalingFactor;

    }

    // TODO: print reader (author) ID

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

    body->appendFormat("\n%*s %3.2f %s", leftPadding + 11,

            "Occurrences in", (elapsedMs / kMsPerSec), "seconds of audio:");

    body->appendFormat("\n%*s%d, %lld, %lld\n", leftPadding + 11,

            "Thread, hash, starting timestamp: ", author,

            static_cast<long long int>(hash), static_cast<long long int>(startingTs));

    // write histogram label line with bucket values

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

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

    for (auto const &x : buckets) {

        const int colWidth = numberWidth(x.first / kJiffyPerMs, leftPadding);

        const int colWidth = numberWidth(x.first, leftPadding);

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

    }

    // write histogram ascii art

        const int value = 1 << row;

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

        for (auto const &x : buckets) {

            const int colWidth = numberWidth(x.first / kJiffyPerMs, leftPadding);

            const int colWidth = numberWidth(x.first, leftPadding);

            body->appendFormat("%.*s%s", colWidth - 1,

                               spaces.c_str(), x.second < value ? " " : "|");

        }

    // write footer with bucket labels

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

    for (auto const &x : buckets) {

        const int colWidth = numberWidth(x.first / kJiffyPerMs, leftPadding);

        body->appendFormat("%*.*f", colWidth, 1,

                           static_cast<double>(x.first) / kJiffyPerMs);

        const int colWidth = numberWidth(x.first, leftPadding);

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

    }

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

    // Now report glitches

    body->appendFormat("\ntime elapsed between glitches and glitch timestamps\n");

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

    }

}

// TODO: learn what timestamp sequences correlate with glitches instead of

// manually designing a heuristic. Ultimately, detect glitches directly from audio.

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

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

//              periods.assign(kNumBuff, kPeriodMs);

//      }

//  }

//  return;

//}

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

// writes summary of performance into specified file descriptor

        for (auto & hash: thread.second) {

            PerformanceAnalysis& curr = hash.second;

            // write performance data to console

            curr.reportPerformance(&body);

            curr.reportPerformance(&body, thread.first, hash.first);

            if (!body.isEmpty()) {

                dumpLine(fd, indent, body);

                body.clear();

#include <string.h>

#include <sstream>

#include <sys/prctl.h>

#include <sys/time.h>

#include <utility>

#include <media/nbaio/NBLog.h>

#include <media/nbaio/PerformanceAnalysis.h>

namespace ReportPerformance {

// Writes outlier intervals, timestamps, and histograms spanning long time intervals to a file.

// TODO: format the data efficiently and write different types of data to different files

// Writes outlier intervals, timestamps, and histograms spanning long time intervals to file.

// TODO: write data in binary format

void writeToFile(const std::deque<std::pair<timestamp, Histogram>> &hists,

                 const std::deque<std::pair<msInterval, timestamp>> &outlierData,

                 const std::deque<timestamp> &peakTimestamps,

                 const char * directory, bool append, int author, log_hash_t hash) {

    if (outlierData.empty() || hists.empty()) {

    // TODO: remove old files, implement rotating files as in AudioFlinger.cpp

    if (outlierData.empty() && hists.empty() && peakTimestamps.empty()) {

        ALOGW("No data, returning.");

        return;

    }

    std::stringstream histogramName;

    std::stringstream peakName;

    histogramName << directory << "histograms_" << author << "_" << hash;

    outlierName << directory << "outliers_" << author << "_" << hash;

    peakName << directory << "peaks_" << author << "_" << hash;

    // get current time

    char currTime[16]; //YYYYMMDDHHMMSS + '\0' + one unused

    struct timeval tv;

    gettimeofday(&tv, NULL);

    struct tm tm;

    localtime_r(&tv.tv_sec, &tm);

    strftime(currTime, sizeof(currTime), "%Y%m%d%H%M%S", &tm);

    // generate file names

    std::stringstream common;

    common << author << "_" << hash << "_" << currTime << ".csv";

    histogramName << directory << "histograms_" << common.str();

    outlierName << directory << "outliers_" << common.str();

    peakName << directory << "peaks_" << common.str();

    std::ofstream hfs;

    hfs.open(histogramName.str(), append ? std::ios::app : std::ios::trunc);

        ALOGW("couldn't open file %s", histogramName.str().c_str());

        return;

    }

    hfs << "Histogram data\n";

    // each histogram is written as a line where the first value is the timestamp and

    // subsequent values are pairs of buckets and counts. Each value is separated

    // by a comma, and each histogram is separated by a newline.

    for (const auto &hist : hists) {

        hfs << "\ttimestamp\n";

        hfs << hist.first << "\n";

        hfs << "\tbuckets (in ms) and counts\n";

        hfs << hist.first << ", ";

        for (const auto &bucket : hist.second) {

            hfs << bucket.first / static_cast<double>(kJiffyPerMs)

                    << ": " << bucket.second << "\n";

                    << ", " << bucket.second << ", ";

        }

        hfs << "\n"; // separate histograms with a newline

        hfs << "\n";

    }

    hfs.close();

        ALOGW("couldn't open file %s", outlierName.str().c_str());

        return;

    }

    ofs << "Outlier data: interval and timestamp\n";

    // outliers are written as pairs separated by newlines, where each

    // pair's values are separated by a comma

    for (const auto &outlier : outlierData) {

        ofs << outlier.first << ": " << outlier.second << "\n";

        ofs << outlier.first << ", " << outlier.second << "\n";

    }

    ofs.close();

        ALOGW("couldn't open file %s", peakName.str().c_str());

        return;

    }

    pfs << "Peak data: timestamp\n";

    // peaks are simply timestamps separated by commas

    for (const auto &peak : peakTimestamps) {

        pfs << peak << "\n";

        pfs << peak << ", ";

    }

    pfs.close();

}

 * 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

    // Generates a string of analysis of the buffer periods and prints to console

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

    // This function detects glitches in a time series.

    // TODO: learn what timestamp sequences correlate with glitches instead of

    // manually designing a heuristic. Ultimately, detect glitches directly from audio.

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

    void reportPerformance(String8 *body, int author, log_hash_t hash,

                           int maxHeight = 10);

private:

        timestamp mPrevTs = -1;        // previous timestamp

    } mBufferPeriod;

    // TODO: delete values below if unused or add them to the BufferPeriod struct

    // FIXME: decide whether to make kPeriodMs static.

    // 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 CPU time as ratio of period

    // int kPeriodMsCPU; // compute based on kPeriodLen and kRatio

    // capacity allocated to data structures

    // TODO: make these values longer when testing is finished

    struct MaxLength {

// shared by MIXER and DIRECT, overridden by DUPLICATING

ssize_t AudioFlinger::PlaybackThread::threadLoop_write()

{

    LOG_HIST_TS();

    mInWrite = true;

    ssize_t bytesWritten;

    const size_t offset = mCurrentWriteLength - mBytesRemaining;

                    threadLoop_standby();

                    // This is where we go into standby

                    if (!mStandby) {

                        LOG_AUDIO_STATE();

                    }

                    mStandby = true;

                }

        mPausedWriteLength(0), mPausedBytesRemaining(0), mKeepWakeLock(true),

        mOffloadUnderrunPosition(~0LL)

{

    //FIXME: mStandby should be set to true by ThreadBase constructor

    //FIXME: mStandby should be set to true by ThreadBase constructo

    mStandby = true;

    mKeepWakeLock = property_get_bool("ro.audio.offload_wakelock", true /* default_value */);

}

                // Updated by updateSuspendedSessions_l() only.

                KeyedVector< audio_session_t, KeyedVector< int, sp<SuspendedSessionDesc> > >

                                        mSuspendedSessions;

                // TODO: add comment and adjust size as needed

                static const size_t     kLogSize = 4 * 1024;

                sp<NBLog::Writer>       mNBLogWriter;

                bool                    mSystemReady;

    sp<NBAIO_Source>        mTeeSource;

#endif

    uint32_t                mScreenState;   // cached copy of gScreenState

    // TODO: add comment and adjust size as needed

    static const size_t     kFastMixerLogSize = 8 * 1024;

    sp<NBLog::Writer>       mFastMixerNBLogWriter;

            // If a fast capture is present, the Pipe as IMemory, otherwise clear

            sp<IMemory>                         mPipeMemory;

            // TODO: add comment and adjust size as needed

            static const size_t                 kFastCaptureLogSize = 4 * 1024;

            sp<NBLog::Writer>                   mFastCaptureNBLogWriter;