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

Commit 0513b5df authored by Eric Tan's avatar Eric Tan
Browse files

Add options to dumpsys media.log and dump visualizations 

Other Changes:
- added thread_params_t type to NBLog
- rearranged ordering of macros in TypedLogger.h

Test: dumpsys media.log with --json, --pa, and --plots options
Bug: 68148948
Change-Id: If97714271a085a99bba0ab3ae0c268a9f407f053
parent cfa7c4b9

media/libnblog/Merger.cpp

+26 −19
Original line number Diff line number Diff line
@@ -34,9 +34,11 @@ 
#include <utils/Log.h>

#include <utils/Mutex.h>

#include <utils/RefBase.h>

#include <utils/String16.h>

#include <utils/String8.h>

#include <utils/Timers.h>

#include <utils/Thread.h>

#include <utils/Timers.h>

#include <utils/Vector.h>



namespace android {

namespace NBLog {
@@ -145,13 +147,12 @@ void MergeReader::processSnapshot(Snapshot &snapshot, int author) 
        } break;

        case EVENT_THREAD_INFO: {

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

            // TODO make PerformanceData hold a type of thread_info_t.

            // Currently, thread_info_t is defined in NBLog.h, which includes

            // PerformanceAnalysis.h. PerformanceData is defined in PerformanceAnalysis.h,

            // where including NBLog.h would result in circular includes. The organization

            // of files will need to change to avoid this problem.

            data.threadInfo = info;

        } break;

        case EVENT_THREAD_PARAMS: {

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

            data.threadParams = params;

        } break;

        case EVENT_LATENCY: {

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

            data.latencyHist.add(latencyMs);
@@ -211,23 +212,29 @@ void MergeReader::checkPushToMediaMetrics() 
    }

}



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

void MergeReader::dump(int fd, const Vector<String16>& args)

{

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

    ReportPerformance::dump(fd, indent, mThreadPerformanceAnalysis);

    Json::Value root(Json::arrayValue);

    for (const auto& item : mThreadPerformanceData) {

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

        std::unique_ptr<Json::Value> threadData = ReportPerformance::dumpToJson(data);

        if (threadData == nullptr) {

            continue;

    // Options for dumpsys

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

    for (const auto &arg : args) {

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

            pa = true;

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

            json = true;

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

            plots = true;

        }

    }

    if (pa) {

        ReportPerformance::dump(fd, 0 /*indent*/, mThreadPerformanceAnalysis);

    }

    if (json) {

        ReportPerformance::dumpJson(fd, mThreadPerformanceData);

    }

        (*threadData)["threadNum"] = item.first;

        root.append(*threadData);

    if (plots) {

        ReportPerformance::dumpPlots(fd, mThreadPerformanceData);

    }

    Json::StyledWriter writer;

    std::string rootStr = writer.write(root);

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

}



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

media/libnblog/ReportPerformance.cpp

+67 −6
Original line number Diff line number Diff line
@@ -40,13 +40,14 @@ 
namespace android {

namespace ReportPerformance {



std::unique_ptr<Json::Value> dumpToJson(const PerformanceData& data)

static std::unique_ptr<Json::Value> dumpToJson(const PerformanceData& data)

{

    std::unique_ptr<Json::Value> rootPtr = std::make_unique<Json::Value>(Json::objectValue);

    Json::Value& root = *rootPtr;

    root["type"] = (Json::Value::Int)data.threadInfo.type;

    root["frameCount"] = (Json::Value::Int)data.threadInfo.frameCount;

    root["sampleRate"] = (Json::Value::Int)data.threadInfo.sampleRate;

    root["ioHandle"] = data.threadInfo.id;

    root["type"] = NBLog::threadTypeToString(data.threadInfo.type);

    root["frameCount"] = (Json::Value::Int)data.threadParams.frameCount;

    root["sampleRate"] = (Json::Value::Int)data.threadParams.sampleRate;

    root["workMsHist"] = data.workHist.toString();

    root["latencyMsHist"] = data.latencyHist.toString();

    root["warmupMsHist"] = data.warmupHist.toString();
@@ -57,6 +58,61 @@ std::unique_ptr<Json::Value> dumpToJson(const PerformanceData& data) 
    return rootPtr;

}



static std::string dumpHistogramsToString(const PerformanceData& data)

{

    std::stringstream ss;

    ss << "==========================================\n";

    ss << "Thread type=" << NBLog::threadTypeToString(data.threadInfo.type)

            << " handle=" << data.threadInfo.id

            << " sampleRate=" << data.threadParams.sampleRate

            << " frameCount=" << data.threadParams.frameCount << "\n";

    ss << "  Thread work times in ms:\n" << data.workHist.asciiArtString(4 /*indent*/);

    ss << "  Thread latencies in ms:\n" << data.latencyHist.asciiArtString(4 /*indent*/);

    ss << "  Thread warmup times in ms:\n" << data.warmupHist.asciiArtString(4 /*indent*/);

    return ss.str();

}



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

{

    if (fd < 0) {

        return;

    }



    Json::Value root(Json::arrayValue);

    for (const auto& item : threadDataMap) {

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

        // Skip threads that do not have performance data recorded yet.

        if (data.empty()) {

            continue;

        }

        std::unique_ptr<Json::Value> dataJson = ReportPerformance::dumpToJson(data);

        if (dataJson == nullptr) {

            continue;

        }

        (*dataJson)["threadNum"] = item.first;

        root.append(*dataJson);

    }

    Json::StyledWriter writer;

    std::string rootStr = writer.write(root);

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

}



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

{

    if (fd < 0) {

        return;

    }



    for (const auto &item : threadDataMap) {

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

        if (data.empty()) {

            continue;

        }

        std::string hists = ReportPerformance::dumpHistogramsToString(data);

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

    }

}



bool sendToMediaMetrics(const PerformanceData& data)

{

    // See documentation for these metrics here:
@@ -72,6 +128,11 @@ bool sendToMediaMetrics(const PerformanceData& data) 
    static constexpr char kThreadActive[] = "android.media.audiothread.activeMs";

    static constexpr char kThreadDuration[] = "android.media.audiothread.durationMs";



    // Currently, we only allow FastMixer thread data to be sent to Media Metrics.

    if (data.threadInfo.type != NBLog::FASTMIXER) {

        return false;

    }



    std::unique_ptr<MediaAnalyticsItem> item(new MediaAnalyticsItem("audiothread"));



    const Histogram &workHist = data.workHist;
@@ -104,8 +165,8 @@ bool sendToMediaMetrics(const PerformanceData& data) 
        // Add thread info fields.

        const char * const typeString = NBLog::threadTypeToString(data.threadInfo.type);

        item->setCString(kThreadType, typeString);

        item->setInt32(kThreadFrameCount, data.threadInfo.frameCount);

        item->setInt32(kThreadSampleRate, data.threadInfo.sampleRate);

        item->setInt32(kThreadFrameCount, data.threadParams.frameCount);

        item->setInt32(kThreadSampleRate, data.threadParams.sampleRate);

        // Add time info fields.

        item->setInt64(kThreadActive, data.active / 1000000);

        item->setInt64(kThreadDuration, (systemTime() - data.start) / 1000000);

media/libnblog/include/media/nblog/Events.h

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


#include <stddef.h>

#include <stdint.h>

#include <system/audio.h>

#include <type_traits>



namespace android {
@@ -62,11 +63,11 @@ enum Event : uint8_t { 
    EVENT_LATENCY,              // difference between frames presented by HAL and frames

                                // written to HAL output sink, divided by sample rate.

    EVENT_OVERRUN,              // predicted thread overrun event timestamp

    EVENT_THREAD_INFO,          // thread type, frameCount and sampleRate, which give context

                                // for the metrics below.

    EVENT_THREAD_INFO,          // see thread_info_t below

    EVENT_UNDERRUN,             // predicted thread underrun event timestamp

    EVENT_WARMUP_TIME,          // thread warmup time

    EVENT_WORK_TIME,            // the time a thread takes to do work, e.g. read, write, etc.

    EVENT_THREAD_PARAMS,        // see thread_params_t below



    EVENT_UPPER_BOUND,          // to check for invalid events

};
@@ -113,10 +114,22 @@ inline const char *threadTypeToString(ThreadType type) { 
}



// mapped from EVENT_THREAD_INFO

// These fields always stay the same throughout a thread's lifetime and

// should only need to be logged once upon thread initialization.

// There is currently no recovery mechanism if the log event corresponding

// to this type is lost.

// TODO add this information when adding a reader to MediaLogService?

struct thread_info_t {

    ThreadType type;

    size_t frameCount;      // number of frames per read or write buffer

    unsigned sampleRate;    // in frames per second

    audio_io_handle_t id = -1;      // Thread I/O handle

    ThreadType type = UNKNOWN;      // See enum ThreadType above

};



// mapped from EVENT_THREAD_PARAMS

// These fields are not necessarily constant throughout a thread's lifetime and

// can be logged whenever a thread receives new configurations or parameters.

struct thread_params_t {

    size_t frameCount = 0;          // number of frames per read or write buffer

    unsigned sampleRate = 0;        // in frames per second

};



template <Event E> struct get_mapped;
@@ -135,6 +148,7 @@ MAP_EVENT_TO_TYPE(EVENT_THREAD_INFO, thread_info_t); 
MAP_EVENT_TO_TYPE(EVENT_UNDERRUN, int64_t);

MAP_EVENT_TO_TYPE(EVENT_WARMUP_TIME, double);

MAP_EVENT_TO_TYPE(EVENT_WORK_TIME, int64_t);

MAP_EVENT_TO_TYPE(EVENT_THREAD_PARAMS, thread_params_t);



}   // namespace NBLog

}   // namespace android

media/libnblog/include/media/nblog/Merger.h

+4 −1
Original line number Diff line number Diff line
@@ -29,9 +29,12 @@ 
#include <utils/Mutex.h>

#include <utils/RefBase.h>

#include <utils/Thread.h>

#include <utils/Timers.h>

#include <utils/Vector.h>



namespace android {



class String16;

class String8;



namespace NBLog {
@@ -83,7 +86,7 @@ public: 
    // the send if it is time to do so.

    void checkPushToMediaMetrics();



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

    void dump(int fd, const Vector<String16>& args);



private:

    // FIXME Needs to be protected by a lock,

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

+12 −4
Original line number Diff line number Diff line
@@ -136,6 +136,9 @@ private: 
// also does some additional analyzing of data, while the purpose of this struct is

// to hold data.

struct PerformanceData {

    // TODO the Histogram::Config numbers below are for FastMixer.

    // Specify different numbers for other thread types.



    // Values based on mUnderrunNs and mOverrunNs in FastMixer.cpp for frameCount = 192

    // and mSampleRate = 48000, which correspond to 2 and 7 seconds.

    static constexpr Histogram::Config kWorkConfig = { 0.25, 20, 2.};
@@ -148,10 +151,8 @@ struct PerformanceData { 
    // bin size and lower/upper limits.

    static constexpr Histogram::Config kWarmupConfig = { 5., 10, 10.};



    // Thread Info

    NBLog::thread_info_t threadInfo{

        NBLog::UNKNOWN /*threadType*/, 0 /*frameCount*/, 0 /*sampleRate*/

    };

    NBLog::thread_info_t threadInfo{};

    NBLog::thread_params_t threadParams{};



    // Performance Data

    Histogram workHist{kWorkConfig};
@@ -174,6 +175,13 @@ struct PerformanceData { 
        active = 0;

        start = systemTime();

    }



    // Return true if performance data has not been recorded yet, false otherwise.

    bool empty() const {

        return workHist.totalCount() == 0 && latencyHist.totalCount() == 0

                && warmupHist.totalCount() == 0 && underruns == 0 && overruns == 0

                && active == 0;

    }

};



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