Merge "Write audio performance data to file"

        "PerformanceAnalysis.cpp",

        "Pipe.cpp",

        "PipeReader.cpp",

        "ReportPerformance.cpp",

        "SourceAudioBufferProvider.cpp",

    ],

#include <audio_utils/roundup.h>

#include <media/nbaio/NBLog.h>

#include <media/nbaio/PerformanceAnalysis.h>

#include <media/nbaio/ReportPerformance.h>

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

#include <utils/Log.h>

#include <utils/String8.h>

}

// writes sample deltas to file, either truncating or appending

inline void writeHistToFile(const std::vector<int64_t> &samples, bool append) {

    // name of file on audioserver

    static const char* const kName = (char *)"/data/misc/audioserver/sample_results.txt";

    // stores deltas between the samples

    std::vector<int64_t> intervals;

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

        intervals.push_back(deltaMs(samples[i - 1], samples[i]));

    }

    if (intervals.empty()) return;

    // Deletes maximum value in a histogram. Temp quick fix.

    // FIXME: need to find root cause of approx. 35th element from the end

    // consistently being an outlier in the first histogram of a flush

    // ALOGW("%" PRId64 "before", (int64_t) *(std::max_element(intervals.begin(), intervals.end())));

    intervals.erase(std::max_element(intervals.begin(), intervals.end()));

    // ALOGW("%" PRId64 "after", (int64_t) *(std::max_element(intervals.begin(), intervals.end())));

    std::ofstream ofs;

    ofs.open(kName, append ? std::ios::app : std::ios::trunc);

    if (!ofs) {

        ALOGW("couldn't open file %s", kName);

        return;

    }

    for (size_t i = 0; i < intervals.size(); ++i) {

        ofs << intervals[i] << "\n";

    }

    ofs.close();

}

// TODO: move this to PerformanceAnalysis

// TODO: make call to dump periodic so that data in shared FIFO does not get overwritten

void NBLog::Reader::dump(int fd, size_t indent, NBLog::Reader::Snapshot &snapshot)

{

    //  CallStack cs(LOG_TAG);

    mFd = fd;

    mIndent = indent;

    String8 timestamp, body;

    // FIXME: this is not thread safe

    static PerformanceAnalysis performanceAnalysis; // used to store data and to call analysis functions

    // TODO: need a separate instance of performanceAnalysis for each thread

    // used to store data and to call analysis functions

    static ReportPerformance::PerformanceAnalysis performanceAnalysis;

    size_t lost = snapshot.lost() + (snapshot.begin() - EntryIterator(snapshot.data()));

    if (lost > 0) {

        body.appendFormat("warning: lost %zu bytes worth of events", lost);

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

            int64_t ts;

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

            performanceAnalysis.logTsEntry(data->author, ts);

            performanceAnalysis.logTsEntry(ts);

            ++entry;

            break;

        }

        case EVENT_AUDIO_STATE: {

            StateTsEntryWithAuthor *data = (StateTsEntryWithAuthor *) (entry->data);

            // TODO This memcpies are here to avoid unaligned memory access crash.

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

            performanceAnalysis.handleStateChange(data->author);

            performanceAnalysis.handleStateChange();

            ++entry;

            break;

        }

#include <algorithm>

#include <climits>

#include <deque>

#include <fstream>

#include <iostream>

#include <math.h>

#include <numeric>

#include <audio_utils/roundup.h>

#include <media/nbaio/NBLog.h>

#include <media/nbaio/PerformanceAnalysis.h>

#include <media/nbaio/ReportPerformance.h>

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

#include <utils/Log.h>

#include <utils/String8.h>

namespace android {

namespace ReportPerformance {

PerformanceAnalysis::PerformanceAnalysis() {

    // These variables will be (FIXME) learned from the data

    kPeriodMs = 4; // typical buffer period (mode)

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

void PerformanceAnalysis::processAndFlushTimeStampSeries() {

    // 1) analyze the series to store all outliers and their exact timestamps:

    storeOutlierData(mTimeStampSeries[author]);

    storeOutlierData(mTimeStampSeries);

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

    // 3) compute its histogram, append to mRecentHists and clear the time series

    mRecentHists.emplace_back(static_cast<timestamp>(mTimeStampSeries[0]),

                              buildBuckets(mTimeStampSeries));

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

    mTimeStampSeries.clear();

}

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

// to buffer period data

void PerformanceAnalysis::handleStateChange(int author) {

void PerformanceAnalysis::handleStateChange() {

    ALOGD("handleStateChange");

    processAndFlushTimeStampSeries(author);

    processAndFlushTimeStampSeries();

    return;

}

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

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

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

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[author].push_back(ts);

    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[author].size() >= kShortHistSize) {

        processAndFlushTimeStampSeries(author);

    if (mTimeStampSeries.size() >= kShortHistSize) {

        processAndFlushTimeStampSeries();

    }

}

// When the short-term histogram array mRecentHists has reached capacity,

// merge histograms for data compression and store them in mLongTermHists

// clears mRecentHists

// TODO: have logTsEntry write directly to mLongTermHists, discard mRecentHists,

// start a new histogram when a peak occurs

void PerformanceAnalysis::processAndFlushRecentHists() {

    // Buckets is used to aggregate short-term histograms.

    Histogram buckets;

    timestamp startingTs = mRecentHists[0].first;

    for (const auto &shortHist: mRecentHists) {

        // If the time between starting and ending timestamps has reached the maximum,

        // add the current histogram (buckets) to the long-term histogram buffer,

        // clear buckets, and start a new long-term histogram aggregation process.

        if (deltaMs(startingTs, shortHist.first) >= kMaxHistTimespanMs) {

            mLongTermHists.emplace_back(startingTs, std::move(buckets));

            buckets.clear();

            startingTs = shortHist.first;

            // When memory is full, delete oldest histogram

            // TODO use a circular buffer

            if (mLongTermHists.size() >= kLongTermHistsCapacity) {

                mLongTermHists.pop_front();

            }

        }

        // add current histogram to buckets

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

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

        }

    }

    mRecentHists.clear();

    // TODO: decide when/where to call writeToFile

    // TODO: add a thread-specific extension to the file name

    static const char* const kName = (const char *) "/data/misc/audioserver/sample_results.txt";

    writeToFile(mOutlierData, mLongTermHists, kName, false);

}

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

// are set to the peak value and 0.

void PerformanceAnalysis::detectPeaks() {

    if (mOutlierData.empty()) {

        ALOGD("peak detector called on empty array");

        return;

    }

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

            if (mPeakTimestamps.size() >= kPeakSeriesSize) {

                mPeakTimestamps.pop_front();

            }

            mPeakDetectorMean = static_cast<double>(it->first);

            start = it;

        }

    }

    //for (const auto &it : mPeakTimestamps) {

    //    ALOGE("mPeakTimestamps %f", static_cast<double>(it));

    //}

    return;

}

// This function is applied to the time series before it is converted into a histogram.

void PerformanceAnalysis::storeOutlierData(const std::vector<int64_t> &timestamps) {

    if (timestamps.size() < 1) {

        ALOGE("storeOutlierData called on empty vector");

        return;

    }

    // first pass: need to initialize

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

            // FIXME: make sure kShortHistSize is large enough that that data will never be lost

            // before being written to file or to a FIFO

            if (mOutlierData.size() >= kOutlierSeriesSize) {

                mOutlierData.pop_front();

            }

            mElapsed = 0;

}

// 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 consider changing all ints to uint32_t or uint64_t

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

void PerformanceAnalysis::reportPerformance(String8 *body, int maxHeight) {

    if (mRecentHists.size() < 1) {

        ALOGD("reportPerformance: mRecentHists is empty");

    return;

}

} // namespace ReportPerformance

}   // namespace android

/*

 * 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 "ReportPerformance"

#include <fstream>

#include <iostream>

#include <queue>

#include <stdarg.h>

#include <stdint.h>

#include <stdio.h>

#include <string.h>

#include <sys/prctl.h>

#include <utility>

#include <media/nbaio/NBLog.h>

#include <media/nbaio/PerformanceAnalysis.h>

#include <media/nbaio/ReportPerformance.h>

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

#include <utils/Log.h>

#include <utils/String8.h>

namespace android {

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

void writeToFile(std::deque<std::pair<outlierInterval, timestamp>> &outlierData,

                                    std::deque<std::pair<timestamp, Histogram>> &hists,

                                    const char * kName,

                                    bool append) {

    ALOGD("writing performance data to file");

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

        return;

    }

    std::ofstream ofs;

    ofs.open(kName, append ? std::ios::app : std::ios::trunc);

    if (!ofs.is_open()) {

        ALOGW("couldn't open file %s", kName);

        return;

    }

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

    for (const auto &outlier : outlierData) {

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

    }

    ofs << "Histogram data\n";

    for (const auto &hist : hists) {

        ofs << "\ttimestamp\n";

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

        ofs << "\tbuckets and counts\n";

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

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

        }

    }

    ofs.close();

}

} // namespace ReportPerformance

}   // namespace android

#include <deque>

#include <vector>

#include "NBLog.h"

#include "ReportPerformance.h"

namespace android {

class String8;

namespace ReportPerformance {

class PerformanceAnalysis {

    // This class stores and analyzes audio processing wakeup timestamps from NBLog

    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

    // TODO: change this name to histogram

    using short_histogram = std::map<int, int>;

    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;

    // Given a series of audio processing wakeup timestamps,

    // compresses and and analyzes the data, and flushes

    // the timestamp series from memory.

    void processAndFlushTimeStampSeries(int author);

    void processAndFlushTimeStampSeries();

    // Called when an audio on/off event is read from the buffer

    // Called when an audio on/off event is read from the buffer,

    // e.g. EVENT_AUDIO_STATE.

    // calls flushTimeStampSeries on the data up to the event,

    // effectively skipping over the idle audio time interval

    // when writing buffer period data to memory.

    void handleStateChange(int author);

    // effectively discarding the idle audio time interval

    void handleStateChange();

    // When the short-term histogram array mRecentHists has reached capacity,

    // merges histograms for data compression and stores them in mLongTermHists

    void processAndFlushRecentHists();

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

    // TODO: make this thread safe. Each thread should have its own instance

    // of PerformanceAnalysis.

    void logTsEntry(timestamp_raw ts);

    // FIXME: make peakdetector and storeOutlierData a single function

    // Input: mOutlierData. Looks at time elapsed between outliers

    // TODO incorporate this into the analysis (currently unused)

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

    ~PerformanceAnalysis() {}

private:

    // stores outlier analysis: <elapsed time between outliers in ms, outlier timestamp>

    // a peak is a moment at which the average outlier interval changed significantly

    std::deque<timestamp> mPeakTimestamps;

    // TODO: turn these into circular buffers for better data flow

    // FIFO of small histograms

    // stores fixed-size short buffer period histograms with timestamp of first sample

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

    // 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 fixed-size long-term buffer period histograms with timestamp of first sample

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

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

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

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

    std::vector<timestamp_raw> mTimeStampSeries;

    // TODO: measure these from the data (e.g., mode) as they may change.

    // const int kGlitchThreshMs = 7;

    // const int kMsPerSec = 1000;

    static const int kMsPerSec = 1000;

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

    // Peak detection: number of standard deviations from mean considered a significant change

    static const int kStddevThreshold = 5;

    // capacity allocated to data structures

    // TODO: adjust all of these values

    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

    static const int kOutlierSeriesSize = 100; // number of values stored in outlier array

    static const int kPeakSeriesSize = 100; // number of values stored in peak array

    static const int kLongTermHistsCapacity = 20; // number of long-term histogram stored in memory

    // maximum elapsed time between first and last timestamp of a long-term histogram

    static const int kMaxHistTimespanMs = 5 * kMsPerSec;

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

};

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

}

} // namespace ReportPerformance

}   // namespace android