Merge "NBLog: add latency logging and histogram serialization"

gugelfrei
Eric Tan 6 years ago committed by Android (Google) Code Review
commit 10caf0e237

@ -478,12 +478,20 @@ void NBLog::Writer::logEventHistTs(Event event, log_hash_t hash)
}
}
void NBLog::Writer::logLatency(double latencyMs)
{
if (!mEnabled) {
return;
}
log(EVENT_LATENCY, &latencyMs, sizeof(latencyMs));
}
void NBLog::Writer::logMonotonicCycleTime(uint32_t monotonicNs)
{
if (!mEnabled) {
return;
}
log(EVENT_MONOTONIC_CYCLE_TIME, &monotonicNs, sizeof(&monotonicNs));
log(EVENT_MONOTONIC_CYCLE_TIME, &monotonicNs, sizeof(monotonicNs));
}
void NBLog::Writer::logFormat(const char *fmt, log_hash_t hash, ...)
@ -713,12 +721,14 @@ const std::unordered_set<NBLog::Event> NBLog::Reader::startingTypes {
NBLog::Event::EVENT_START_FMT,
NBLog::Event::EVENT_HISTOGRAM_ENTRY_TS,
NBLog::Event::EVENT_AUDIO_STATE,
NBLog::Event::EVENT_LATENCY,
NBLog::Event::EVENT_MONOTONIC_CYCLE_TIME
};
const std::unordered_set<NBLog::Event> NBLog::Reader::endingTypes {
NBLog::Event::EVENT_END_FMT,
NBLog::Event::EVENT_HISTOGRAM_ENTRY_TS,
NBLog::Event::EVENT_AUDIO_STATE,
NBLog::Event::EVENT_LATENCY,
NBLog::Event::EVENT_MONOTONIC_CYCLE_TIME
};
@ -873,6 +883,17 @@ void NBLog::MergeReader::getAndProcessSnapshot(NBLog::Snapshot &snapshot, int au
memcpy(&hash, &(data->hash), sizeof(hash));
mThreadPerformanceAnalysis[author][0 /*hash*/].handleStateChange();
} break;
case EVENT_LATENCY: {
double latencyMs;
memcpy(&latencyMs, etr.data, sizeof(latencyMs));
mPerformanceData.addLatencyEntry(author, latencyMs);
} break;
case EVENT_MONOTONIC_CYCLE_TIME: {
uint32_t monotonicNs;
memcpy(&monotonicNs, etr.data, sizeof(monotonicNs));
const double monotonicMs = monotonicNs * 1e-6;
mPerformanceData.addCycleTimeEntry(author, monotonicMs);
} break;
case EVENT_END_FMT:
case EVENT_RESERVED:
case EVENT_UPPER_BOUND:
@ -904,6 +925,7 @@ void NBLog::MergeReader::dump(int fd, int indent)
{
// TODO: add a mutex around media.log dump
ReportPerformance::dump(fd, indent, mThreadPerformanceAnalysis);
mPerformanceData.dump(fd);
}
// TODO for future compatibility, would prefer to have a dump() go to string, and then go
@ -926,7 +948,12 @@ void NBLog::DumpReader::dump(int fd, size_t indent)
case EVENT_MONOTONIC_CYCLE_TIME: {
uint32_t monotonicNs;
memcpy(&monotonicNs, it->data, sizeof(monotonicNs));
body.appendFormat("Thread cycle took %u ns", monotonicNs);
body.appendFormat("Thread cycle: %u ns", monotonicNs);
} break;
case EVENT_LATENCY: {
double latencyMs;
memcpy(&latencyMs, it->data, sizeof(latencyMs));
body.appendFormat("latency: %.3f ms", latencyMs);
} break;
case EVENT_END_FMT:
case EVENT_RESERVED:

@ -17,13 +17,15 @@
#define LOG_TAG "PerformanceAnalysis"
// #define LOG_NDEBUG 0
// #define WRITE_TO_FILE
#include <algorithm>
#include <climits>
#include <deque>
#include <iostream>
#include <math.h>
#include <numeric>
#include <sstream>
#include <string>
#include <vector>
#include <stdarg.h>
#include <stdint.h>
@ -45,6 +47,97 @@
namespace android {
void Histogram::add(double value)
{
// TODO Handle domain and range error exceptions?
const int binIndex = lround((value - mLow) / mBinSize);
if (binIndex < 0) {
mLowCount++;
} else if (binIndex >= mNumBins) {
mHighCount++;
} else {
mBins[binIndex]++;
}
mTotalCount++;
}
void Histogram::clear()
{
std::fill(mBins.begin(), mBins.end(), 0);
mLowCount = 0;
mHighCount = 0;
mTotalCount = 0;
}
uint64_t Histogram::totalCount() const
{
return mTotalCount;
}
std::string Histogram::serializeToString() const {
std::stringstream ss;
static constexpr char kDivider = '|';
ss << mBinSize << "," << mNumBins << "," << mLow << ",{";
bool first = true;
if (mLowCount != 0) {
ss << "-1" << kDivider << mLowCount;
first = false;
}
for (size_t i = 0; i < mNumBins; i++) {
if (mBins[i] != 0) {
if (!first) {
ss << ",";
}
ss << i << kDivider << mBins[i];
first = false;
}
}
if (mHighCount != 0) {
if (!first) {
ss << ",";
}
ss << mNumBins << kDivider << mHighCount;
first = false;
}
ss << "}";
return ss.str();
}
// TODO make a hash map from Event type to std::pair<HistConfig, unordered_map<int, Histogram>>
// so that we don't have to create a "add histogram entry" method for every different metric.
void PerformanceData::addCycleTimeEntry(int author, double cycleTimeMs)
{
if (mCycleTimeMsHists.count(author) == 0) {
mCycleTimeMsHists.emplace(author, Histogram(kCycleTimeConfig));
}
mCycleTimeMsHists.at(author).add(cycleTimeMs);
}
void PerformanceData::addLatencyEntry(int author, double latencyMs)
{
if (mLatencyMsHists.count(author) == 0) {
mLatencyMsHists.emplace(author, Histogram(kLatencyConfig));
}
mLatencyMsHists.at(author).add(latencyMs);
}
void PerformanceData::dump(int fd, int indent __unused)
{
// TODO add thread metadata for better context.
// Also output in a more machine-readable friendly format.
dprintf(fd, "Thread cycle time histograms:\n");
for (const auto &item : mCycleTimeMsHists) {
dprintf(fd, " Thread %d: %s\n", item.first, item.second.serializeToString().c_str());
}
dprintf(fd, "Latency histograms:\n");
for (const auto &item : mLatencyMsHists) {
dprintf(fd, " Thread %d: %s\n", item.first, item.second.serializeToString().c_str());
}
}
//------------------------------------------------------------------------------
namespace ReportPerformance {
// Given an audio processing wakeup timestamp, buckets the time interval
@ -277,7 +370,9 @@ void PerformanceAnalysis::reportPerformance(String8 *body, int author, log_hash_
// writes summary of performance into specified file descriptor
void dump(int fd, int indent, PerformanceAnalysisMap &threadPerformanceAnalysis) {
String8 body;
#ifdef WRITE_TO_FILE
const char* const kDirectory = "/data/misc/audioserver/";
#endif
for (auto & thread : threadPerformanceAnalysis) {
for (auto & hash: thread.second) {
PerformanceAnalysis& curr = hash.second;
@ -287,9 +382,11 @@ void dump(int fd, int indent, PerformanceAnalysisMap &threadPerformanceAnalysis)
dumpLine(fd, indent, body);
body.clear();
}
// write to file
#ifdef WRITE_TO_FILE
// write to file. Enable by uncommenting macro at top of file.
writeToFile(curr.mHists, curr.mOutlierData, curr.mPeakTimestamps,
kDirectory, false, thread.first, hash.first);
#endif
}
}
}

@ -350,6 +350,7 @@ public:
virtual void logFormat(const char *fmt, log_hash_t hash, ...);
virtual void logVFormat(const char *fmt, log_hash_t hash, va_list ap);
virtual void logEventHistTs(Event event, log_hash_t hash);
virtual void logLatency(double latencyMs);
virtual void logMonotonicCycleTime(uint32_t monotonicNs);
// End of functions that are not in LockedWriter yet.
@ -547,6 +548,8 @@ public:
// location within each author
ReportPerformance::PerformanceAnalysisMap mThreadPerformanceAnalysis;
PerformanceData mPerformanceData;
// 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);

@ -19,6 +19,7 @@
#include <deque>
#include <map>
#include <unordered_map>
#include <vector>
#include <media/nblog/ReportPerformance.h>
@ -27,6 +28,127 @@ namespace android {
class String8;
// TODO make this a templated class and put it in a separate file.
// The templated parameters would be bin size and low limit.
/*
* Histogram provides a way to store numeric data in histogram format and read it as a serialized
* string. The terms "bin" and "bucket" are used interchangeably.
*
* This class is not thread-safe.
*/
class Histogram {
public:
struct Config {
const double binSize; // TODO template type
const size_t numBins;
const double low; // TODO template type
};
// Histograms are constructed with fixed configuration numbers. Dynamic configuration based
// the data is possible but complex because
// - data points are added one by one, not processed as a batch.
// - Histograms with different configuration parameters are tricky to aggregate, and they
// will need to be aggregated at the Media Metrics cloud side.
// - not providing limits theoretically allows for infinite number of buckets.
/**
* \brief Creates a Histogram object.
*
* \param binSize the width of each bin of the histogram.
* Units are whatever data the caller decides to store.
* \param numBins the number of bins desired in the histogram range.
* \param low the lower bound of the histogram bucket values.
* Units are whatever data the caller decides to store.
* Note that the upper bound can be calculated by the following:
* upper = lower + binSize * numBins.
*/
Histogram(double binSize, size_t numBins, double low = 0.)
: mBinSize(binSize), mNumBins(numBins), mLow(low), mBins(mNumBins) {}
Histogram(const Config &c)
: Histogram(c.binSize, c.numBins, c.low) {}
/**
* \brief Add a data point to the histogram. The value of the data point
* is rounded to the nearest multiple of the bin size (before accounting
* for the lower bound offset, which may not be a multiple of the bin size).
*
* \param value the value of the data point to add.
*/
void add(double value);
/**
* \brief Removes all data points from the histogram.
*/
void clear();
/**
* \brief Returns the total number of data points added to the histogram.
*
* \return the total number of data points in the histogram.
*/
uint64_t totalCount() const;
/**
* \brief Serializes the histogram into a string. The format is chosen to be compatible with
* the histogram representation to send to the Media Metrics service.
*
* The string is as follows:
* binSize,numBins,low,{-1|lowCount,...,binIndex|count,...,numBins|highCount}
*
* - binIndex is an integer with 0 <= binIndex < numBins.
* - count is the number of occurrences of the (rounded) value
* low + binSize * bucketIndex.
* - lowCount is the number of (rounded) values less than low.
* - highCount is the number of (rounded) values greater than or equal to
* low + binSize * numBins.
* - a binIndex may be skipped if its count is 0.
*
* \return the histogram serialized as a string.
*/
std::string serializeToString() const;
private:
const double mBinSize; // Size of each bucket
const size_t mNumBins; // Number of buckets in histogram range
const double mLow; // Lower bound of values
std::vector<int> mBins; // Data structure to store the actual histogram
int mLowCount = 0; // Number of values less than mLow
int mHighCount = 0; // Number of values >= mLow + mBinSize * mNumBins
uint64_t mTotalCount = 0; // Total number of values recorded
};
// TODO For now this is a holder of audio performance metrics. The idea is essentially the same
// as PerformanceAnalysis, but the design structure is different. There is a PerformanceAnalysis
// instance for each thread writer (see PerformanceAnalysisMap later in this file), while a
// PerformanceData instance already takes into account each thread writer in its calculations.
// Eventually, this class should be merged with PerformanceAnalysis into some single entity.
/*
* PerformanceData stores audio performance data from audioflinger threads as histograms,
* time series, or counts, and outputs them in a machine-readable format.
*/
class PerformanceData {
public:
void addCycleTimeEntry(int author, double cycleTimeMs);
void addLatencyEntry(int author, double latencyMs);
void addWarmupTimeEntry(int author, double warmupTimeMs);
void addWarmupCyclesEntry(int author, double warmupCycles);
void dump(int fd, int indent = 0);
private:
// 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 kCycleTimeConfig = { 0.25, 20, 2.};
std::unordered_map<int /*author, i.e. thread number*/, Histogram> mCycleTimeMsHists;
// Values based on trial and error logging. Need a better way to determine
// bin size and lower/upper limits.
static constexpr Histogram::Config kLatencyConfig = { 2., 10, 10.};
std::unordered_map<int, Histogram> mLatencyMsHists;
};
//------------------------------------------------------------------------------
namespace ReportPerformance {
class PerformanceAnalysis;

@ -340,10 +340,19 @@ void FastMixer::onWork()
FastMixerDumpState * const dumpState = (FastMixerDumpState *) mDumpState;
if (mIsWarm) {
// Logging timestamps for FastMixer is currently disabled to make memory room for logging
// other statistics in FastMixer.
// To re-enable, delete the #ifdef FASTMIXER_LOG_HIST_TS lines (and the #endif lines).
#ifdef FASTMIXER_LOG_HIST_TS
LOG_HIST_TS();
#endif
//ALOGD("Eric FastMixer::onWork() mIsWarm");
} else {
dumpState->mTimestampVerifier.discontinuity();
// See comment in if block.
#ifdef FASTMIXER_LOG_HIST_TS
LOG_AUDIO_STATE();
#endif
}
const FastMixerState::Command command = mCommand;
const size_t frameCount = current->mFrameCount;
@ -498,8 +507,10 @@ void FastMixer::onWork()
timestamp.mTimeNs[ExtendedTimestamp::LOCATION_KERNEL];
// We don't compensate for server - kernel time difference and
// only update latency if we have valid info.
dumpState->mLatencyMs =
const double latencyMs =
(double)mNativeFramesWrittenButNotPresented * 1000 / mSampleRate;
dumpState->mLatencyMs = latencyMs;
LOG_LATENCY(latencyMs);
} else {
// HAL reported that more frames were presented than were written
mNativeFramesWrittenButNotPresented = 0;

@ -102,6 +102,9 @@ constexpr uint64_t hash(const char (&file)[n], uint32_t line) {
#define LOG_MONOTONIC_CYCLE_TIME(ns) do { NBLog::Writer *x = tlNBLogWriter; if (x != nullptr) \
x->logMonotonicCycleTime(ns); } while (0)
#define LOG_LATENCY(ms) do { NBLog::Writer *x = tlNBLogWriter; if (x != nullptr) \
x->logLatency(ms); } while (0)
namespace android {
extern "C" {
extern thread_local NBLog::Writer *tlNBLogWriter;

Loading…
Cancel
Save