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

Commit 201079a8 authored by Sanna Catherine de Treville Wager's avatar Sanna Catherine de Treville Wager
Browse files

Produce log warning when a glitch occurred. 

A glitch is assumed to occur when the sum of the three
latest buffer periods cause CPU time to be unavailable
for the next buffer. For example, if a buffer period
is 4 ms, requires 3 ms of CPU time, and a running sum of
3 consecutive buffer periods is examined, this sum cannot
exceed 13 = 3*4 + (4-3), where 3*4 is the expected total
time and (4-3) is the CPU time left available by one 4 ms
period. Glitch examples:
4 + 4 + 6; 5 + 4 + 5; 2 + 2 + 10

See NBLog::Reader::alertIfGlitch.
Boolean NBLog::Reader::findGlitch should be set to true
for the notification to occur.

Note: this function needs to be developed to track glitch
occurrences over time and notify when a difference in
trend occurs.

Test: dumpsys media.log
      logcat | grep NBLog

Change-Id: Ibf120afd990a71eb40863157a28c3a5a4a610c64
parent cced674a

media/libnbaio/NBLog.cpp

+56 −6
Original line number Diff line number Diff line
@@ -18,7 +18,9 @@ 
//#define LOG_NDEBUG 0



#include <climits>

#include <deque>

#include <math.h>

#include <numeric>

#include <stdarg.h>

#include <stdint.h>

#include <stdio.h>
@@ -701,7 +703,8 @@ NBLog::Reader::Reader(const void *shared, size_t size) 
      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)

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

      findGlitch(false)

{

}
@@ -717,6 +720,39 @@ NBLog::Reader::~Reader() 
    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) {
@@ -800,10 +836,6 @@ std::unique_ptr<NBLog::Reader::Snapshot> NBLog::Reader::getSnapshot() 


}



inline static int deltaMs(int64_t t1, int64_t t2) {

    return (t2 - t1) / (1000 * 1000);

}



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

{

#if 0
@@ -917,7 +949,6 @@ void NBLog::Reader::dump(int fd, size_t indent, NBLog::Reader::Snapshot &snapsho 
            break;

#endif

        case EVENT_START_FMT:

            // right now, this is the only supported case

            entry = handleFormat(FormatEntry(entry), &timestamp, &body);

            break;

        case EVENT_HISTOGRAM_ENTRY_TS: {
@@ -938,16 +969,24 @@ void NBLog::Reader::dump(int fd, size_t indent, NBLog::Reader::Snapshot &snapsho 
        case EVENT_HISTOGRAM_FLUSH: {

            HistogramEntry histEntry(entry);

            // Log timestamp

            // Timestamp of call to drawHistogram, not when audio was generated

            const int64_t ts = histEntry.timestamp();

            timestamp.clear();

            timestamp.appendFormat("[%d.%03d]", (int) (ts / (1000 * 1000 * 1000)),

                            (int) ((ts / (1000 * 1000)) % 1000));

            // Log histograms

            setFindGlitch(true);

            body.appendFormat("Histogram flush - ");

            handleAuthor(histEntry, &body);

            int debug = 0;

            for (auto hist = mHists.begin(); hist != mHists.end();) {

                // TODO: "debug" is always 0. Is a for loop necessary here?

                ALOGW("EVENT_HISTOGRAM_FLUSH case hist: %d", debug++);

                if (hist->first.second == histEntry.author()) {

                    body.appendFormat("%X", (int)hist->first.first);

                    if (findGlitch) {

                        alertIfGlitch(hist->second);

                    }

                    drawHistogram(&body, hist->second, true, indent);

                    hist = mHists.erase(hist);

                } else {
@@ -1000,6 +1039,16 @@ bool NBLog::Reader::isIMemory(const sp<IMemory>& iMemory) const 
    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) {
@@ -1147,6 +1196,7 @@ static std::map<int, int> buildBuckets(const std::vector<int64_t> &samples) { 
    // TODO allow buckets of variable resolution

    std::map<int, int> buckets;

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

        // ALOGW("sample %d ", deltaMs(samples[i - 1], samples[i]));

        ++buckets[deltaMs(samples[i - 1], samples[i])];

    }

    return buckets;

media/libnbaio/include/NBLog.h

+7 −1
Original line number Diff line number Diff line
@@ -424,7 +424,6 @@ public: 
        // iterator to end of readable segment of snapshot

        EntryIterator end() { return mEnd; }





    private:

        friend class Reader;

        uint8_t              *mData;
@@ -440,6 +439,8 @@ public: 


    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
@@ -447,6 +448,9 @@ public: 
    // dump the current content of the reader's buffer

    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:

    static const std::set<Event> startingTypes;
@@ -480,6 +484,8 @@ private: 
                                         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