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

Commit bc8281ab authored by Eric Tan's avatar Eric Tan
Browse files

NBLog: add retroactive dump and standard printing format 

The retroactive dump outputs historical snapshots of data that
correspond to important NBLog Events at the time they were read.

The standard printing format added is as follows: for each line, the
first column is the NBLog Event as a string, and the following columns
correspond to each field of the struct, or the type, that the NBLog
Event maps to. All columns are separated by commas.

Other changes:
Added option to Reader::getSnapshot() for flushing the buffer. This
makes it possible to always read the full buffer contents when doing a
dump of the raw log contents.

Test: dumpsys media.log with -r and --retro options
Bug: 68148948
Change-Id: I4bbbf6e2f9a3a86fae976986ac35a7eef79520de
parent ea055e6d

media/libnblog/Merger.cpp

+22 −5
Original line number Diff line number Diff line
@@ -167,12 +167,24 @@ void MergeReader::processSnapshot(Snapshot &snapshot, int author) 
            const double timeMs = it.payload<double>();

            data.warmupHist.add(timeMs);

        } break;

        case EVENT_UNDERRUN:

        case EVENT_UNDERRUN: {

            const int64_t ts = it.payload<int64_t>();

            data.underruns++;

            break;

        case EVENT_OVERRUN:

            data.snapshots.emplace_front(EVENT_UNDERRUN, ts);

            // TODO have a data structure to automatically handle resizing

            if (data.snapshots.size() > ReportPerformance::PerformanceData::kMaxSnapshotsToStore) {

                data.snapshots.pop_back();

            }

        } break;

        case EVENT_OVERRUN: {

            const int64_t ts = it.payload<int64_t>();

            data.overruns++;

            break;

            data.snapshots.emplace_front(EVENT_UNDERRUN, ts);

            // TODO have a data structure to automatically handle resizing

            if (data.snapshots.size() > ReportPerformance::PerformanceData::kMaxSnapshotsToStore) {

                data.snapshots.pop_back();

            }

        } break;

        case EVENT_RESERVED:

        case EVENT_UPPER_BOUND:

            ALOGW("warning: unexpected event %d", it->type);
@@ -216,7 +228,7 @@ void MergeReader::dump(int fd, const Vector<String16>& args) 
{

    // TODO: add a mutex around media.log dump

    // Options for dumpsys

    bool pa = false, json = false, plots = false;

    bool pa = false, json = false, plots = false, retro = false;

    for (const auto &arg : args) {

        if (arg == String16("--pa")) {

            pa = true;
@@ -224,6 +236,8 @@ void MergeReader::dump(int fd, const Vector<String16>& args) 
            json = true;

        } else if (arg == String16("--plots")) {

            plots = true;

        } else if (arg == String16("--retro")) {

            retro = true;

        }

    }

    if (pa) {
@@ -235,6 +249,9 @@ void MergeReader::dump(int fd, const Vector<String16>& args) 
    if (plots) {

        ReportPerformance::dumpPlots(fd, mThreadPerformanceData);

    }

    if (retro) {

        ReportPerformance::dumpRetro(fd, mThreadPerformanceData);

    }

}



void MergeReader::handleAuthor(const AbstractEntry &entry, String8 *body)

media/libnblog/Reader.cpp

+29 −15
Original line number Diff line number Diff line
@@ -59,7 +59,7 @@ Reader::~Reader() 
// 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<Snapshot> Reader::getSnapshot()

std::unique_ptr<Snapshot> Reader::getSnapshot(bool flush)

{

    if (mFifoReader == NULL) {

        return std::unique_ptr<Snapshot>(new Snapshot());
@@ -146,7 +146,9 @@ std::unique_ptr<Snapshot> Reader::getSnapshot() 
    }



    // advance fifo reader index to after last entry read.

    if (flush) {

        mFifoReader->release(snapshot->mEnd - front);

    }



    snapshot->mLost = lost;

    return snapshot;
@@ -221,36 +223,48 @@ const uint8_t *Reader::findLastValidEntry(const uint8_t *front, const uint8_t *b 
void DumpReader::dump(int fd, size_t indent)

{

    if (fd < 0) return;

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

    std::unique_ptr<Snapshot> snapshot = getSnapshot(false /*flush*/);

    if (snapshot == nullptr) {

        return;

    }

    String8 timestamp, body;



    // TODO all logged types should have a printable format.

    // TODO can we make the printing generic?

    for (EntryIterator it = snapshot->begin(); it != snapshot->end(); ++it) {

        switch (it->type) {

        case EVENT_FMT_START:

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

            break;

        case EVENT_WORK_TIME: {

            const int64_t monotonicNs = it.payload<int64_t>();

            body.appendFormat("Thread cycle: %ld ns", (long)monotonicNs);

        } break;

        case EVENT_LATENCY: {

            const double latencyMs = it.payload<double>();

            body.appendFormat("latency: %.3f ms", latencyMs);

            body.appendFormat("EVENT_LATENCY,%.3f", latencyMs);

        } break;

        case EVENT_OVERRUN: {

            const int64_t ts = it.payload<int64_t>();

            body.appendFormat("EVENT_OVERRUN,%lld", static_cast<long long>(ts));

        } break;

        case EVENT_THREAD_INFO: {

            const thread_info_t info = it.payload<thread_info_t>();

            body.appendFormat("EVENT_THREAD_INFO,%d,%s", static_cast<int>(info.id),

                    threadTypeToString(info.type));

        } break;

        case EVENT_UNDERRUN: {

            const int64_t ts = it.payload<int64_t>();

            body.appendFormat("EVENT_UNDERRUN,%lld", static_cast<long long>(ts));

        } break;

        case EVENT_WARMUP_TIME: {

            const double timeMs = it.payload<double>();

            body.appendFormat("warmup time: %.3f ms", timeMs);

            body.appendFormat("EVENT_WARMUP_TIME,%.3f", timeMs);

        } break;

        case EVENT_WORK_TIME: {

            const int64_t monotonicNs = it.payload<int64_t>();

            body.appendFormat("EVENT_WORK_TIME,%lld", static_cast<long long>(monotonicNs));

        } break;

        case EVENT_THREAD_PARAMS: {

            const thread_params_t params = it.payload<thread_params_t>();

            body.appendFormat("EVENT_THREAD_PARAMS,%zu,%u", params.frameCount, params.sampleRate);

        } break;

        case EVENT_UNDERRUN:

            body.appendFormat("underrun");

            break;

        case EVENT_OVERRUN:

            body.appendFormat("overrun");

            break;

        case EVENT_FMT_END:

        case EVENT_RESERVED:

        case EVENT_UPPER_BOUND:

media/libnblog/ReportPerformance.cpp

+35 −0
Original line number Diff line number Diff line
@@ -113,6 +113,41 @@ void dumpPlots(int fd, const std::map<int, PerformanceData>& threadDataMap) 
    }

}



static std::string dumpRetroString(const PerformanceData& data, int64_t now)

{

    std::stringstream ss;

    ss << NBLog::threadTypeToString(data.threadInfo.type) << "," << data.threadInfo.id << "\n";

    for (const auto &item : data.snapshots) {

        // TODO use an enum to string conversion method. One good idea:

        // https://stackoverflow.com/a/238157

        if (item.first == NBLog::EVENT_UNDERRUN) {

            ss << "EVENT_UNDERRUN,";

        } else if (item.first == NBLog::EVENT_OVERRUN) {

            ss << "EVENT_OVERRUN,";

        }

        ss << now - item.second << "\n";

    }

    ss << "\n";

    return ss.str();

}



void dumpRetro(int fd, const std::map<int, PerformanceData>& threadDataMap)

{

    if (fd < 0) {

        return;

    }



    const nsecs_t now = systemTime();

    for (const auto &item : threadDataMap) {

        const ReportPerformance::PerformanceData& data = item.second;

        if (data.snapshots.empty()) {

            continue;

        }

        const std::string retroStr = dumpRetroString(data, now);

        write(fd, retroStr.c_str(), retroStr.size());

    }

}



bool sendToMediaMetrics(const PerformanceData& data)

{

    // See documentation for these metrics here:

media/libnblog/include/media/nblog/PerformanceAnalysis.h

+3 −0
Original line number Diff line number Diff line
@@ -19,6 +19,7 @@ 


#include <deque>

#include <map>

#include <string>

#include <utility>

#include <vector>
@@ -159,6 +160,8 @@ struct PerformanceData { 
    Histogram latencyHist{kLatencyConfig};

    Histogram warmupHist{kWarmupConfig};

    int64_t underruns = 0;

    static constexpr size_t kMaxSnapshotsToStore = 256;

    std::deque<std::pair<NBLog::Event, int64_t /*timestamp*/>> snapshots;

    int64_t overruns = 0;

    nsecs_t active = 0;

    nsecs_t start{systemTime()};

media/libnblog/include/media/nblog/Reader.h

+2 −2
Original line number Diff line number Diff line
@@ -51,7 +51,7 @@ public: 
    ~Reader() override;



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

    std::unique_ptr<Snapshot> getSnapshot();

    std::unique_ptr<Snapshot> getSnapshot(bool flush = true);

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

    const std::string &name() const { return mName; }
@@ -99,7 +99,7 @@ public: 
private:

    Snapshot() = default;

    explicit Snapshot(size_t bufferSize) : mData(new uint8_t[bufferSize]) {}

    friend std::unique_ptr<Snapshot> Reader::getSnapshot();

    friend std::unique_ptr<Snapshot> Reader::getSnapshot(bool flush);



    uint8_t * const       mData = nullptr;

    size_t                mLost = 0;