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

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

Restored audio onStateChange log 

Calls flushTsSeries when a state change was detected
to avoid logging idle audio time as a buffer period.

Test: dumpsys media.log
Change-Id: Ia33bec8829dcd5d2de5c40f904e5ea19c5a2b453
parent 41cad59d

media/libnbaio/NBLog.cpp

+18 −5
Original line number Diff line number Diff line
@@ -24,8 +24,8 @@ 
*     Calls LOG_HIST_TS

* LOG_HIST_TS

*     Hashes file name and line number, and writes single timestamp to buffer

*     calls NBLOG::Writer::logHistTS once

* NBLOG::Writer::logHistTS

*     calls NBLOG::Writer::logEventHistTS once

* NBLOG::Writer::logEventHistTS

*     calls NBLOG::Writer::log on hash and current timestamp

*     time is in CLOCK_MONOTONIC converted to ns

* NBLOG::Writer::log(Event, const void*, size_t)
@@ -44,6 +44,8 @@ 
* ssize_t audio_utils_fifo_reader::obtain

*     Determines readable buffer section via pointer arithmetic on reader

*     and writer pointers

* Similarly, LOG_AUDIO_STATE() is called by onStateChange whenever audio is

* turned on or off, and writes this notification to the FIFO.

*

* 2) reading the data from shared memory

* Thread::threadloop()
@@ -138,6 +140,7 @@ std::unique_ptr<NBLog::AbstractEntry> NBLog::AbstractEntry::buildEntry(const uin 
    switch (type) {

    case EVENT_START_FMT:

        return std::make_unique<FormatEntry>(FormatEntry(ptr));

    case EVENT_AUDIO_STATE:

    case EVENT_HISTOGRAM_ENTRY_TS:

        return std::make_unique<HistogramEntry>(HistogramEntry(ptr));

    default:
@@ -516,7 +519,7 @@ void NBLog::Writer::logHash(log_hash_t hash) 
    log(EVENT_HASH, &hash, sizeof(hash));

}



void NBLog::Writer::logHistTS(log_hash_t hash)

void NBLog::Writer::logEventHistTs(Event event, log_hash_t hash)

{

    if (!mEnabled) {

        return;
@@ -525,7 +528,7 @@ void NBLog::Writer::logHistTS(log_hash_t hash) 
    data.hash = hash;

    data.ts = get_monotonic_ns();

    if (data.ts > 0) {

        log(EVENT_HISTOGRAM_ENTRY_TS, &data, sizeof(data));

        log(event, &data, sizeof(data));

    } else {

        ALOGE("Failed to get timestamp");

    }
@@ -758,7 +761,9 @@ bool NBLog::LockedWriter::setEnabled(bool enabled) 
const std::set<NBLog::Event> NBLog::Reader::startingTypes {NBLog::Event::EVENT_START_FMT,

                                                           NBLog::Event::EVENT_HISTOGRAM_ENTRY_TS};

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

                                                           NBLog::Event::EVENT_HISTOGRAM_ENTRY_TS};

                                                           NBLog::Event::EVENT_HISTOGRAM_ENTRY_TS,

                                                           NBLog::Event::EVENT_AUDIO_STATE};



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

    : mShared((/*const*/ Shared *) shared), /*mIMemory*/

      mFd(-1), mIndent(0),
@@ -925,6 +930,14 @@ void NBLog::Reader::dump(int fd, size_t indent, NBLog::Reader::Snapshot &snapsho 
            ++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);

            ++entry;

            break;

        }

        case EVENT_END_FMT:

            body.appendFormat("warning: got to end format event");

            ++entry;

media/libnbaio/PerformanceAnalysis.cpp

+37 −18
Original line number Diff line number Diff line
@@ -71,29 +71,23 @@ static int widthOf(int x) { 
    return width;

}



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

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

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

    // if length of the time series has reached kShortHistSize samples, do 1) and 2):

    if (mTimeStampSeries[author].size() >= kShortHistSize) {

// Given a series of audio processing wakeup timestamps,

// buckets the time intervals 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(int author) {

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

    storeOutlierData(mTimeStampSeries[author]);



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

    mRecentHists.emplace_back(author, buildBuckets(mTimeStampSeries[author]));

    // do not let mRecentHists exceed capacity

    // ALOGD("mRecentHists size: %d", static_cast<int>(mRecentHists.size()));

    if (mRecentHists.size() >= kRecentHistsCapacity) {
@@ -102,6 +96,31 @@ void PerformanceAnalysis::logTsEntry(int author, int64_t ts) { 
    }

    mTimeStampSeries[author].clear();

}



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

// to buffer period data

void PerformanceAnalysis::handleStateChange(int author) {

    ALOGD("handleStateChange");

    processAndFlushTimeStampSeries(author);

    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,

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

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

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

    }

}



// Given a series of outlier intervals (mOutlier data),

media/libnbaio/include/media/nbaio/NBLog.h

+5 −3
Original line number Diff line number Diff line
@@ -44,8 +44,6 @@ typedef uint64_t log_hash_t; 
class Writer;

class Reader;



private:



enum Event : uint8_t {

    EVENT_RESERVED,

    EVENT_STRING,               // ASCII string, not NUL-terminated
@@ -60,11 +58,13 @@ enum Event : uint8_t { 
    EVENT_HASH,                 // unique HASH of log origin, originates from hash of file name

                                // and line number

    EVENT_HISTOGRAM_ENTRY_TS,   // single datum for timestamp histogram

    EVENT_AUDIO_STATE,          // audio on/off event: logged upon FastMixer::onStateChange() call

    EVENT_END_FMT,              // end of logFormat argument list



    EVENT_UPPER_BOUND,          // to check for invalid events

};



private:



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

// API for handling format entry operations
@@ -248,6 +248,8 @@ struct HistTsEntryWithAuthor { 
    int author;

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



using StateTsEntryWithAuthor = HistTsEntryWithAuthor;



struct HistIntEntry {

    log_hash_t hash;

    int value;
@@ -341,7 +343,7 @@ public: 
    virtual void    logStart(const char *fmt);

    virtual void    logEnd();

    virtual void    logHash(log_hash_t hash);

    virtual void    logHistTS(log_hash_t hash);

    virtual void    logEventHistTs(Event event, log_hash_t hash);



    virtual bool    isEnabled() const;

media/libnbaio/include/media/nbaio/PerformanceAnalysis.h

+11 −0
Original line number Diff line number Diff line
@@ -52,6 +52,17 @@ public: 
    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);



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

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



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

services/audioflinger/FastMixer.cpp

+2 −0
Original line number Diff line number Diff line
@@ -138,6 +138,8 @@ bool FastMixer::isSubClassCommand(FastThreadState::Command command) 


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;