/* * 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 #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include namespace android { namespace ReportPerformance { static std::unique_ptr dumpToJson(const PerformanceData& data) { std::unique_ptr rootPtr = std::make_unique(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& 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 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& 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& 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 item(MediaAnalyticsItem::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> &hists, const std::deque> &outlierData, const std::deque &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(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