blob: 4c78b019df29cfff24d73f6138f7bf4173f0321b [file] [log] [blame]
/*
* Copyright (C) 2017 The Android Open Source Project
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/
#define LOG_TAG "ReportPerformance"
//#define LOG_NDEBUG 0
#include <fstream>
#include <iostream>
#include <memory>
#include <queue>
#include <stdarg.h>
#include <stdint.h>
#include <stdio.h>
#include <string.h>
#include <sstream>
#include <sys/prctl.h>
#include <sys/time.h>
#include <utility>
#include <json/json.h>
#include <media/MediaMetricsItem.h>
#include <media/nblog/Events.h>
#include <media/nblog/PerformanceAnalysis.h>
#include <media/nblog/ReportPerformance.h>
#include <utils/Log.h>
#include <utils/String8.h>
namespace android {
namespace ReportPerformance {
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["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();
root["underruns"] = (Json::Value::Int64)data.underruns;
root["overruns"] = (Json::Value::Int64)data.overruns;
root["activeMs"] = (Json::Value::Int64)ns2ms(data.active);
root["durationMs"] = (Json::Value::Int64)ns2ms(systemTime() - data.start);
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::StreamWriterBuilder factory;
std::string rootStr = Json::writeString(factory, 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());
}
}
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:
// docs.google.com/document/d/11--6dyOXVOpacYQLZiaOY5QVtQjUyqNx2zT9cCzLKYE/edit?usp=sharing
static constexpr char kThreadType[] = "android.media.audiothread.type";
static constexpr char kThreadFrameCount[] = "android.media.audiothread.framecount";
static constexpr char kThreadSampleRate[] = "android.media.audiothread.samplerate";
static constexpr char kThreadWorkHist[] = "android.media.audiothread.workMs.hist";
static constexpr char kThreadLatencyHist[] = "android.media.audiothread.latencyMs.hist";
static constexpr char kThreadWarmupHist[] = "android.media.audiothread.warmupMs.hist";
static constexpr char kThreadUnderruns[] = "android.media.audiothread.underruns";
static constexpr char kThreadOverruns[] = "android.media.audiothread.overruns";
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<mediametrics::Item> item(mediametrics::Item::create("audiothread"));
const Histogram &workHist = data.workHist;
if (workHist.totalCount() > 0) {
item->setCString(kThreadWorkHist, workHist.toString().c_str());
}
const Histogram &latencyHist = data.latencyHist;
if (latencyHist.totalCount() > 0) {
item->setCString(kThreadLatencyHist, latencyHist.toString().c_str());
}
const Histogram &warmupHist = data.warmupHist;
if (warmupHist.totalCount() > 0) {
item->setCString(kThreadWarmupHist, warmupHist.toString().c_str());
}
if (data.underruns > 0) {
item->setInt64(kThreadUnderruns, data.underruns);
}
if (data.overruns > 0) {
item->setInt64(kThreadOverruns, data.overruns);
}
// Send to Media Metrics if the record is not empty.
// The thread and time info are added inside the if statement because
// we want to send them only if there are performance metrics to send.
if (item->count() > 0) {
// Add thread info fields.
const char * const typeString = NBLog::threadTypeToString(data.threadInfo.type);
item->setCString(kThreadType, typeString);
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);
return item->selfrecord();
}
return false;
}
//------------------------------------------------------------------------------
// TODO: use a function like this to extract logic from writeToFile
// https://stackoverflow.com/a/9279620
// Writes outlier intervals, timestamps, and histograms spanning long time intervals to file.
// TODO: write data in binary format
void writeToFile(const std::deque<std::pair<timestamp, Hist>> &hists,
const std::deque<std::pair<msInterval, timestamp>> &outlierData,
const std::deque<timestamp> &peakTimestamps,
const char * directory, bool append, int author, log_hash_t hash) {
// TODO: remove old files, implement rotating files as in AudioFlinger.cpp
if (outlierData.empty() && hists.empty() && peakTimestamps.empty()) {
ALOGW("No data, returning.");
return;
}
std::stringstream outlierName;
std::stringstream histogramName;
std::stringstream peakName;
// get current time
char currTime[16]; //YYYYMMDDHHMMSS + '\0' + one unused
struct timeval tv;
gettimeofday(&tv, NULL);
struct tm tm;
localtime_r(&tv.tv_sec, &tm);
strftime(currTime, sizeof(currTime), "%Y%m%d%H%M%S", &tm);
// generate file names
std::stringstream common;
common << author << "_" << hash << "_" << currTime << ".csv";
histogramName << directory << "histograms_" << common.str();
outlierName << directory << "outliers_" << common.str();
peakName << directory << "peaks_" << common.str();
std::ofstream hfs;
hfs.open(histogramName.str(), append ? std::ios::app : std::ios::trunc);
if (!hfs.is_open()) {
ALOGW("couldn't open file %s", histogramName.str().c_str());
return;
}
// each histogram is written as a line where the first value is the timestamp and
// subsequent values are pairs of buckets and counts. Each value is separated
// by a comma, and each histogram is separated by a newline.
for (auto hist = hists.begin(); hist != hists.end(); ++hist) {
hfs << hist->first << ", ";
for (auto bucket = hist->second.begin(); bucket != hist->second.end(); ++bucket) {
hfs << bucket->first / static_cast<double>(kJiffyPerMs)
<< ", " << bucket->second;
if (std::next(bucket) != end(hist->second)) {
hfs << ", ";
}
}
if (std::next(hist) != end(hists)) {
hfs << "\n";
}
}
hfs.close();
std::ofstream ofs;
ofs.open(outlierName.str(), append ? std::ios::app : std::ios::trunc);
if (!ofs.is_open()) {
ALOGW("couldn't open file %s", outlierName.str().c_str());
return;
}
// outliers are written as pairs separated by newlines, where each
// pair's values are separated by a comma
for (const auto &outlier : outlierData) {
ofs << outlier.first << ", " << outlier.second << "\n";
}
ofs.close();
std::ofstream pfs;
pfs.open(peakName.str(), append ? std::ios::app : std::ios::trunc);
if (!pfs.is_open()) {
ALOGW("couldn't open file %s", peakName.str().c_str());
return;
}
// peaks are simply timestamps separated by commas
for (auto peak = peakTimestamps.begin(); peak != peakTimestamps.end(); ++peak) {
pfs << *peak;
if (std::next(peak) != end(peakTimestamps)) {
pfs << ", ";
}
}
pfs.close();
}
} // namespace ReportPerformance
} // namespace android