1 /* 2 * Copyright (C) 2017 The Android Open Source Project 3 * 4 * Licensed under the Apache License, Version 2.0 (the "License"); 5 * you may not use this file except in compliance with the License. 6 * You may obtain a copy of the License at 7 * 8 * http://www.apache.org/licenses/LICENSE-2.0 9 * 10 * Unless required by applicable law or agreed to in writing, software 11 * distributed under the License is distributed on an "AS IS" BASIS, 12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 13 * See the License for the specific language governing permissions and 14 * limitations under the License. 15 */ 16 17 #define LOG_TAG "ReportPerformance" 18 //#define LOG_NDEBUG 0 19 20 #include <fstream> 21 #include <iostream> 22 #include <memory> 23 #include <queue> 24 #include <stdarg.h> 25 #include <stdint.h> 26 #include <stdio.h> 27 #include <string.h> 28 #include <sstream> 29 #include <sys/prctl.h> 30 #include <sys/time.h> 31 #include <utility> 32 #include <json/json.h> 33 #include <media/MediaAnalyticsItem.h> 34 #include <media/nblog/Events.h> 35 #include <media/nblog/PerformanceAnalysis.h> 36 #include <media/nblog/ReportPerformance.h> 37 #include <utils/Log.h> 38 #include <utils/String8.h> 39 40 namespace android { 41 namespace ReportPerformance { 42 43 static std::unique_ptr<Json::Value> dumpToJson(const PerformanceData& data) 44 { 45 std::unique_ptr<Json::Value> rootPtr = std::make_unique<Json::Value>(Json::objectValue); 46 Json::Value& root = *rootPtr; 47 root["ioHandle"] = data.threadInfo.id; 48 root["type"] = NBLog::threadTypeToString(data.threadInfo.type); 49 root["frameCount"] = (Json::Value::Int)data.threadParams.frameCount; 50 root["sampleRate"] = (Json::Value::Int)data.threadParams.sampleRate; 51 root["workMsHist"] = data.workHist.toString(); 52 root["latencyMsHist"] = data.latencyHist.toString(); 53 root["warmupMsHist"] = data.warmupHist.toString(); 54 root["underruns"] = (Json::Value::Int64)data.underruns; 55 root["overruns"] = (Json::Value::Int64)data.overruns; 56 root["activeMs"] = (Json::Value::Int64)ns2ms(data.active); 57 root["durationMs"] = (Json::Value::Int64)ns2ms(systemTime() - data.start); 58 return rootPtr; 59 } 60 61 static std::string dumpHistogramsToString(const PerformanceData& data) 62 { 63 std::stringstream ss; 64 ss << "==========================================\n"; 65 ss << "Thread type=" << NBLog::threadTypeToString(data.threadInfo.type) 66 << " handle=" << data.threadInfo.id 67 << " sampleRate=" << data.threadParams.sampleRate 68 << " frameCount=" << data.threadParams.frameCount << "\n"; 69 ss << " Thread work times in ms:\n" << data.workHist.asciiArtString(4 /*indent*/); 70 ss << " Thread latencies in ms:\n" << data.latencyHist.asciiArtString(4 /*indent*/); 71 ss << " Thread warmup times in ms:\n" << data.warmupHist.asciiArtString(4 /*indent*/); 72 return ss.str(); 73 } 74 75 void dumpJson(int fd, const std::map<int, PerformanceData>& threadDataMap) 76 { 77 if (fd < 0) { 78 return; 79 } 80 81 Json::Value root(Json::arrayValue); 82 for (const auto& item : threadDataMap) { 83 const ReportPerformance::PerformanceData& data = item.second; 84 // Skip threads that do not have performance data recorded yet. 85 if (data.empty()) { 86 continue; 87 } 88 std::unique_ptr<Json::Value> dataJson = ReportPerformance::dumpToJson(data); 89 if (dataJson == nullptr) { 90 continue; 91 } 92 (*dataJson)["threadNum"] = item.first; 93 root.append(*dataJson); 94 } 95 Json::StyledWriter writer; 96 std::string rootStr = writer.write(root); 97 write(fd, rootStr.c_str(), rootStr.size()); 98 } 99 100 void dumpPlots(int fd, const std::map<int, PerformanceData>& threadDataMap) 101 { 102 if (fd < 0) { 103 return; 104 } 105 106 for (const auto &item : threadDataMap) { 107 const ReportPerformance::PerformanceData& data = item.second; 108 if (data.empty()) { 109 continue; 110 } 111 std::string hists = ReportPerformance::dumpHistogramsToString(data); 112 write(fd, hists.c_str(), hists.size()); 113 } 114 } 115 116 static std::string dumpRetroString(const PerformanceData& data, int64_t now) 117 { 118 std::stringstream ss; 119 ss << NBLog::threadTypeToString(data.threadInfo.type) << "," << data.threadInfo.id << "\n"; 120 for (const auto &item : data.snapshots) { 121 // TODO use an enum to string conversion method. One good idea: 122 // https://stackoverflow.com/a/238157 123 if (item.first == NBLog::EVENT_UNDERRUN) { 124 ss << "EVENT_UNDERRUN,"; 125 } else if (item.first == NBLog::EVENT_OVERRUN) { 126 ss << "EVENT_OVERRUN,"; 127 } 128 ss << now - item.second << "\n"; 129 } 130 ss << "\n"; 131 return ss.str(); 132 } 133 134 void dumpRetro(int fd, const std::map<int, PerformanceData>& threadDataMap) 135 { 136 if (fd < 0) { 137 return; 138 } 139 140 const nsecs_t now = systemTime(); 141 for (const auto &item : threadDataMap) { 142 const ReportPerformance::PerformanceData& data = item.second; 143 if (data.snapshots.empty()) { 144 continue; 145 } 146 const std::string retroStr = dumpRetroString(data, now); 147 write(fd, retroStr.c_str(), retroStr.size()); 148 } 149 } 150 151 bool sendToMediaMetrics(const PerformanceData& data) 152 { 153 // See documentation for these metrics here: 154 // docs.google.com/document/d/11--6dyOXVOpacYQLZiaOY5QVtQjUyqNx2zT9cCzLKYE/edit?usp=sharing 155 static constexpr char kThreadType[] = "android.media.audiothread.type"; 156 static constexpr char kThreadFrameCount[] = "android.media.audiothread.framecount"; 157 static constexpr char kThreadSampleRate[] = "android.media.audiothread.samplerate"; 158 static constexpr char kThreadWorkHist[] = "android.media.audiothread.workMs.hist"; 159 static constexpr char kThreadLatencyHist[] = "android.media.audiothread.latencyMs.hist"; 160 static constexpr char kThreadWarmupHist[] = "android.media.audiothread.warmupMs.hist"; 161 static constexpr char kThreadUnderruns[] = "android.media.audiothread.underruns"; 162 static constexpr char kThreadOverruns[] = "android.media.audiothread.overruns"; 163 static constexpr char kThreadActive[] = "android.media.audiothread.activeMs"; 164 static constexpr char kThreadDuration[] = "android.media.audiothread.durationMs"; 165 166 // Currently, we only allow FastMixer thread data to be sent to Media Metrics. 167 if (data.threadInfo.type != NBLog::FASTMIXER) { 168 return false; 169 } 170 171 std::unique_ptr<MediaAnalyticsItem> item(MediaAnalyticsItem::create("audiothread")); 172 173 const Histogram &workHist = data.workHist; 174 if (workHist.totalCount() > 0) { 175 item->setCString(kThreadWorkHist, workHist.toString().c_str()); 176 } 177 178 const Histogram &latencyHist = data.latencyHist; 179 if (latencyHist.totalCount() > 0) { 180 item->setCString(kThreadLatencyHist, latencyHist.toString().c_str()); 181 } 182 183 const Histogram &warmupHist = data.warmupHist; 184 if (warmupHist.totalCount() > 0) { 185 item->setCString(kThreadWarmupHist, warmupHist.toString().c_str()); 186 } 187 188 if (data.underruns > 0) { 189 item->setInt64(kThreadUnderruns, data.underruns); 190 } 191 192 if (data.overruns > 0) { 193 item->setInt64(kThreadOverruns, data.overruns); 194 } 195 196 // Send to Media Metrics if the record is not empty. 197 // The thread and time info are added inside the if statement because 198 // we want to send them only if there are performance metrics to send. 199 if (item->count() > 0) { 200 // Add thread info fields. 201 const char * const typeString = NBLog::threadTypeToString(data.threadInfo.type); 202 item->setCString(kThreadType, typeString); 203 item->setInt32(kThreadFrameCount, data.threadParams.frameCount); 204 item->setInt32(kThreadSampleRate, data.threadParams.sampleRate); 205 // Add time info fields. 206 item->setInt64(kThreadActive, data.active / 1000000); 207 item->setInt64(kThreadDuration, (systemTime() - data.start) / 1000000); 208 return item->selfrecord(); 209 } 210 return false; 211 } 212 213 //------------------------------------------------------------------------------ 214 215 // TODO: use a function like this to extract logic from writeToFile 216 // https://stackoverflow.com/a/9279620 217 218 // Writes outlier intervals, timestamps, and histograms spanning long time intervals to file. 219 // TODO: write data in binary format 220 void writeToFile(const std::deque<std::pair<timestamp, Hist>> &hists, 221 const std::deque<std::pair<msInterval, timestamp>> &outlierData, 222 const std::deque<timestamp> &peakTimestamps, 223 const char * directory, bool append, int author, log_hash_t hash) { 224 225 // TODO: remove old files, implement rotating files as in AudioFlinger.cpp 226 227 if (outlierData.empty() && hists.empty() && peakTimestamps.empty()) { 228 ALOGW("No data, returning."); 229 return; 230 } 231 232 std::stringstream outlierName; 233 std::stringstream histogramName; 234 std::stringstream peakName; 235 236 // get current time 237 char currTime[16]; //YYYYMMDDHHMMSS + '\0' + one unused 238 struct timeval tv; 239 gettimeofday(&tv, NULL); 240 struct tm tm; 241 localtime_r(&tv.tv_sec, &tm); 242 strftime(currTime, sizeof(currTime), "%Y%m%d%H%M%S", &tm); 243 244 // generate file names 245 std::stringstream common; 246 common << author << "_" << hash << "_" << currTime << ".csv"; 247 248 histogramName << directory << "histograms_" << common.str(); 249 outlierName << directory << "outliers_" << common.str(); 250 peakName << directory << "peaks_" << common.str(); 251 252 std::ofstream hfs; 253 hfs.open(histogramName.str(), append ? std::ios::app : std::ios::trunc); 254 if (!hfs.is_open()) { 255 ALOGW("couldn't open file %s", histogramName.str().c_str()); 256 return; 257 } 258 // each histogram is written as a line where the first value is the timestamp and 259 // subsequent values are pairs of buckets and counts. Each value is separated 260 // by a comma, and each histogram is separated by a newline. 261 for (auto hist = hists.begin(); hist != hists.end(); ++hist) { 262 hfs << hist->first << ", "; 263 for (auto bucket = hist->second.begin(); bucket != hist->second.end(); ++bucket) { 264 hfs << bucket->first / static_cast<double>(kJiffyPerMs) 265 << ", " << bucket->second; 266 if (std::next(bucket) != end(hist->second)) { 267 hfs << ", "; 268 } 269 } 270 if (std::next(hist) != end(hists)) { 271 hfs << "\n"; 272 } 273 } 274 hfs.close(); 275 276 std::ofstream ofs; 277 ofs.open(outlierName.str(), append ? std::ios::app : std::ios::trunc); 278 if (!ofs.is_open()) { 279 ALOGW("couldn't open file %s", outlierName.str().c_str()); 280 return; 281 } 282 // outliers are written as pairs separated by newlines, where each 283 // pair's values are separated by a comma 284 for (const auto &outlier : outlierData) { 285 ofs << outlier.first << ", " << outlier.second << "\n"; 286 } 287 ofs.close(); 288 289 std::ofstream pfs; 290 pfs.open(peakName.str(), append ? std::ios::app : std::ios::trunc); 291 if (!pfs.is_open()) { 292 ALOGW("couldn't open file %s", peakName.str().c_str()); 293 return; 294 } 295 // peaks are simply timestamps separated by commas 296 for (auto peak = peakTimestamps.begin(); peak != peakTimestamps.end(); ++peak) { 297 pfs << *peak; 298 if (std::next(peak) != end(peakTimestamps)) { 299 pfs << ", "; 300 } 301 } 302 pfs.close(); 303 } 304 305 } // namespace ReportPerformance 306 } // namespace android 307
