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
dumpToJson(const PerformanceData & data)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
dumpHistogramsToString(const PerformanceData & data)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
dumpJson(int fd,const std::map<int,PerformanceData> & threadDataMap)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
dumpPlots(int fd,const std::map<int,PerformanceData> & threadDataMap)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
dumpRetroString(const PerformanceData & data,int64_t now)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
dumpRetro(int fd,const std::map<int,PerformanceData> & threadDataMap)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
sendToMediaMetrics(const PerformanceData & data)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
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)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