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