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

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

Separate merge from dump and call merge periodically 

Every time merge is called by the thread loop,
the data is also processed and written to
PerformanceAnalysis. A call to dump retrieves
the FIFO of processed data in PerformanceAnalysis
instead of the unprocessed Reader FIFO, and prints
the result to the console.

Test: dumpsys media.log

Change-Id: Ic479f48e9e4fdf4523a8f15db514dbdd85b70434
parent 633adf69

include/media/nbaio/ReportPerformance.h

0 → 120000
+1 −0
Original line number Diff line number Diff line 
../../../media/libnbaio/include/media/nbaio/ReportPerformance.h
 
 No newline at end of file

media/libnbaio/NBLog.cpp

+56 −24
Original line number Diff line number Diff line
@@ -87,7 +87,6 @@ 
*/



#define LOG_TAG "NBLog"

// #define LOG_NDEBUG 0



#include <algorithm>

#include <climits>
@@ -109,7 +108,7 @@ 
#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/CallStack.h>

#include <utils/Log.h>

#include <utils/String8.h>
@@ -766,8 +765,8 @@ const std::set<NBLog::Event> NBLog::Reader::endingTypes {NBLog::Event::EVENT_E 
                                                           NBLog::Event::EVENT_AUDIO_STATE};



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

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

      mFd(-1), mIndent(0),

    : mFd(-1), mIndent(0), mLost(0),

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

      mFifo(mShared != NULL ?

        new audio_utils_fifo(size, sizeof(uint8_t),

            mShared->mBuffer, mShared->mRear, NULL /*throttlesFront*/) : NULL),
@@ -805,6 +804,9 @@ const uint8_t *NBLog::Reader::findLastEntryOfTypes(const uint8_t *front, const u 
    return nullptr; // no entry found

}



// Copies content of a Reader FIFO into its Snapshot

// The Snapshot has the same raw data, but represented as a sequence of entries

// and an EntryIterator making it possible to process the data.

std::unique_ptr<NBLog::Reader::Snapshot> NBLog::Reader::getSnapshot()

{

    if (mFifoReader == NULL) {
@@ -870,23 +872,19 @@ std::unique_ptr<NBLog::Reader::Snapshot> NBLog::Reader::getSnapshot() 


}



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

// Takes raw content of the local merger FIFO, processes log entries, and

// writes the data to a map of class PerformanceAnalysis, based on their thread ID.

void NBLog::MergeReader::getAndProcessSnapshot(NBLog::Reader::Snapshot &snapshot)

{

    mFd = fd;

    mIndent = indent;

    String8 timestamp, body;

    // TODO: check: is the FIXME below still a problem?

    // FIXME: this is not thread safe

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

    // used to store data and to call analysis functions

    static ReportPerformance::PerformanceAnalysis performanceAnalysis;

    // TODO: add lost data information and notification to ReportPerformance

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

    if (lost > 0) {

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

        // TODO timestamp empty here, only other choice to wait for the first timestamp event in the

        //      log to push it out.  Consider keeping the timestamp/body between calls to copyEntryDataAt().

        dumpLine(timestamp, body);

        // TODO: ultimately, this will be += and reset to 0. TODO: check that this is

        // obsolete now that Merger::merge is called periodically. No data should be lost

        mLost = lost;

    }



    for (auto entry = snapshot.begin(); entry != snapshot.end();) {
@@ -902,12 +900,20 @@ void NBLog::Reader::dump(int fd, size_t indent, NBLog::Reader::Snapshot &snapsho 
            memcpy(&hash, &(data->hash), sizeof(hash));

            int64_t ts;

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

            performanceAnalysis.logTsEntry(ts);

            mThreadPerformanceAnalysis[data->author].logTsEntry(ts);

            ++entry;

            break;

        }

        case EVENT_AUDIO_STATE: {

            performanceAnalysis.handleStateChange();

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

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

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

            // TODO: incorporate hash information in mThreadPerformanceAnalysis

            // log_hash_t hash;

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

            // int64_t ts;

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

            mThreadPerformanceAnalysis[data->author].handleStateChange();

            ++entry;

            break;

        }
@@ -922,19 +928,38 @@ void NBLog::Reader::dump(int fd, size_t indent, NBLog::Reader::Snapshot &snapsho 
            break;

        }

    }

    performanceAnalysis.reportPerformance(&body);

    // FIXME: decide whether to print the warnings here or elsewhere

    if (!body.isEmpty()) {

        dumpLine(timestamp, body);

    }

}



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

void NBLog::MergeReader::getAndProcessSnapshot()

{

    // get a snapshot, dump it

    // get a snapshot, process it

    std::unique_ptr<Snapshot> snap = getSnapshot();

    dump(fd, indent, *snap);

    getAndProcessSnapshot(*snap);

}



// TODO: move this function to a different class than NBLog::Reader

// writes summary of performance to the console

void NBLog::MergeReader::dump(int fd, size_t indent)

{

    mFd = fd;

    mIndent = indent;

    String8 body, timestamp;

    // TODO: check: is the FIXME below still a problem?

    // FIXME: this is not thread safe

    for (auto & threadReport : mThreadPerformanceAnalysis) {

        threadReport.second.reportPerformance(&body);

    }

    if (!body.isEmpty()) {

        ALOGD("body is not empty");

        dumpLine(timestamp, body);

    }

}



// Writes a string to the console

void NBLog::Reader::dumpLine(const String8 &timestamp, String8 &body)

{

    if (mFd >= 0) {
@@ -1093,6 +1118,7 @@ NBLog::Merger::Merger(const void *shared, size_t size): 
      {}



void NBLog::Merger::addReader(const NBLog::NamedReader &reader) {



    // FIXME This is called by binder thread in MediaLogService::registerWriter

    //       but the access to shared variable mNamedReaders is not yet protected by a lock.

    mNamedReaders.push_back(reader);
@@ -1116,7 +1142,7 @@ bool operator>(const struct MergeItem &i1, const struct MergeItem &i2) { 
    return i1.ts > i2.ts || (i1.ts == i2.ts && i1.index > i2.index);

}



// Merge registered readers, sorted by timestamp

// Merge registered readers, sorted by timestamp, and write data to a single FIFO in local memory

void NBLog::Merger::merge() {

    // FIXME This is called by merge thread

    //       but the access to shared variable mNamedReaders is not yet protected by a lock.
@@ -1173,8 +1199,9 @@ void NBLog::MergeReader::handleAuthor(const NBLog::AbstractEntry &entry, String8 


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



NBLog::MergeThread::MergeThread(NBLog::Merger &merger)

NBLog::MergeThread::MergeThread(NBLog::Merger &merger, NBLog::MergeReader &mergeReader)

    : mMerger(merger),

      mMergeReader(mergeReader),

      mTimeoutUs(0) {}



NBLog::MergeThread::~MergeThread() {
@@ -1196,7 +1223,12 @@ bool NBLog::MergeThread::threadLoop() { 
        mTimeoutUs -= kThreadSleepPeriodUs;

    }

    if (doMerge) {

        // Merge data from all the readers

        mMerger.merge();

        // Process the data collected by mMerger and write it to PerformanceAnalysis

        // FIXME: decide whether to call getAndProcessSnapshot every time

        // or whether to have a separate thread that calls it with a lower frequency

        mMergeReader.getAndProcessSnapshot();

    }

    return true;

}

media/libnbaio/PerformanceAnalysis.cpp

+1 −1
Original line number Diff line number Diff line
@@ -271,7 +271,6 @@ void PerformanceAnalysis::reportPerformance(String8 *body, int maxHeight) { 
        ALOGD("reportPerformance: mRecentHists is empty");

        return;

    }

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

    // TODO: more elaborate data analysis

    std::map<int, int> buckets;

    for (const auto &shortHist: mRecentHists) {
@@ -306,6 +305,7 @@ void PerformanceAnalysis::reportPerformance(String8 *body, int maxHeight) { 
        scalingFactor = (height + maxHeight) / maxHeight;

        height /= scalingFactor;

    }

    // TODO: print reader (author) ID

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

    // write histogram label line with bucket values

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

media/libnbaio/ReportPerformance.cpp

+3 −2
Original line number Diff line number Diff line
@@ -38,8 +38,8 @@ 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,

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

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

                                    const char * kName,

                                    bool append) {

    ALOGD("writing performance data to file");
@@ -65,6 +65,7 @@ void writeToFile(std::deque<std::pair<outlierInterval, timestamp>> &outlierData, 
        for (const auto &bucket : hist.second) {

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

        }

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

    }

    ofs.close();

}

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

+50 −29
Original line number Diff line number Diff line
@@ -19,16 +19,18 @@ 
#ifndef ANDROID_MEDIA_NBLOG_H

#define ANDROID_MEDIA_NBLOG_H



#include <binder/IMemory.h>

#include <audio_utils/fifo.h>

#include <utils/Mutex.h>

#include <utils/threads.h>



#include <map>

#include <deque>

#include <map>

#include <set>

#include <vector>



#include <audio_utils/fifo.h>

#include <binder/IMemory.h>

#include <media/nbaio/PerformanceAnalysis.h>

#include <media/nbaio/ReportPerformance.h>

#include <utils/Mutex.h>

#include <utils/threads.h>



namespace android {



class String8;
@@ -409,7 +411,6 @@ public: 


    class Reader : public RefBase {

    public:



        // A snapshot of a readers buffer

        // This is raw data. No analysis has been done on it

        class Snapshot {
@@ -434,6 +435,7 @@ public: 
            EntryIterator end() { return mEnd; }



        private:

            friend class MergeReader;

            friend class Reader;

            uint8_t              *mData;

            size_t                mLost;
@@ -450,22 +452,26 @@ public: 


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

        std::unique_ptr<Snapshot> getSnapshot();

        // dump a particular snapshot of the reader

        // TODO: move dump to PerformanceAnalysis. Model/view/controller design

        void     dump(int fd, size_t indent, Snapshot & snap);

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

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

        // print a summary of the performance to the console

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



    private:

    protected:

        void    dumpLine(const String8& timestamp, String8& body);

        EntryIterator   handleFormat(const FormatEntry &fmtEntry,

                                     String8 *timestamp,

                                     String8 *body);

        int mFd;                // file descriptor

        int mIndent;            // indentation level

        int mLost;              // bytes of data lost before buffer was read



    private:

        static const std::set<Event> startingTypes;

        static const std::set<Event> endingTypes;

        /*const*/ Shared* const mShared;    // raw pointer to shared memory, actually const but not



        // declared as const because audio_utils_fifo() constructor

        sp<IMemory> mIMemory;       // ref-counted version, assigned only in constructor

        int     mFd;                // file descriptor

        int     mIndent;            // indentation level



        /*const*/ Shared* const mShared;    // raw pointer to shared memory, actually const but not

        audio_utils_fifo * const mFifo;                 // FIFO itself,

        // non-NULL unless constructor fails

        audio_utils_fifo_reader * const mFifoReader;    // used to read from FIFO,
@@ -476,20 +482,14 @@ public: 
        // represented that location. And one_of its fields would be a vector of timestamps.

        // That would allow us to record other information about the source location beyond

        // timestamps.

        void    dumpLine(const String8& timestamp, String8& body);



        EntryIterator   handleFormat(const FormatEntry &fmtEntry,

                                     String8 *timestamp,

                                     String8 *body);

        // dummy method for handling absent author entry

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



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

        // dummy method for handling absent author entry

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

    };



    // Wrapper for a reader with a name. Contains a pointer to the reader and a pointer to the name
@@ -511,6 +511,8 @@ public: 


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



    // This class is used to read data from each thread's individual FIFO in shared memory

    // and write it to a single FIFO in local memory.

    class Merger : public RefBase {

    public:

        Merger(const void *shared, size_t size);
@@ -520,27 +522,43 @@ public: 
        void addReader(const NamedReader &reader);

        // TODO add removeReader

        void merge();



        // FIXME This is returning a reference to a shared variable that needs a lock

        const std::vector<NamedReader>& getNamedReaders() const;



    private:

        // vector of the readers the merger is supposed to merge from.

        // every reader reads from a writer's buffer

        // FIXME Needs to be protected by a lock

        std::vector<NamedReader> mNamedReaders;



        // TODO Need comments on all of these

        Shared * const mShared;

        std::unique_ptr<audio_utils_fifo> mFifo;

        std::unique_ptr<audio_utils_fifo_writer> mFifoWriter;

        Shared * const mShared; // raw pointer to shared memory

        std::unique_ptr<audio_utils_fifo> mFifo; // FIFO itself

        std::unique_ptr<audio_utils_fifo_writer> mFifoWriter; // used to write to FIFO

    };



    // This class has a pointer to the FIFO in local memory which stores the merged

    // data collected by NBLog::Merger from all NamedReaders. It is used to process

    // this data and write the result to PerformanceAnalysis.

    class MergeReader : public Reader {

    public:

        MergeReader(const void *shared, size_t size, Merger &merger);



        // TODO: consider moving dump to ReportPerformance

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

        // process a particular snapshot of the reader

        void getAndProcessSnapshot(Snapshot & snap);

        // call getSnapshot of the content of the reader's buffer and process the data

        void getAndProcessSnapshot();



    private:

        // FIXME Needs to be protected by a lock,

        //       because even though our use of it is read-only there may be asynchronous updates

        const std::vector<NamedReader>& mNamedReaders;



        // analyzes, compresses and stores the merged data

        std::map<int, ReportPerformance::PerformanceAnalysis> mThreadPerformanceAnalysis;



        // handle author entry by looking up the author's name and appending it to the body

        // returns number of bytes read from fmtEntry

        void handleAuthor(const AbstractEntry &fmtEntry, String8 *body);
@@ -552,7 +570,7 @@ public: 
    // The thread is triggered on AudioFlinger binder activity.

    class MergeThread : public Thread {

    public:

        MergeThread(Merger &merger);

        MergeThread(Merger &merger, MergeReader &mergeReader);

        virtual ~MergeThread() override;



        // Reset timeout and activate thread to merge periodically if it's idle
@@ -567,6 +585,9 @@ public: 
        // the merger who actually does the work of merging the logs

        Merger&     mMerger;



        // the mergereader used to process data merged by mMerger

        MergeReader& mMergeReader;



        // mutex for the condition variable

        Mutex       mMutex;