1 /*
2  * Copyright (C) 2018 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 package com.android.game.qualification.metric;
17 
18 import static com.android.game.qualification.metric.MetricSummary.TimeType.PRESENT;
19 import static com.android.game.qualification.metric.MetricSummary.TimeType.READY;
20 
21 import com.android.annotations.VisibleForTesting;
22 import com.android.game.qualification.proto.ResultDataProto;
23 import com.android.tradefed.device.DeviceNotAvailableException;
24 import com.android.tradefed.device.metric.DeviceMetricData;
25 import com.android.tradefed.log.LogUtil.CLog;
26 import com.android.tradefed.result.ByteArrayInputStreamSource;
27 import com.android.tradefed.result.FileInputStreamSource;
28 import com.android.tradefed.result.InputStreamSource;
29 import com.android.tradefed.result.LogDataType;
30 
31 import com.google.common.base.Preconditions;
32 
33 import java.io.BufferedWriter;
34 import java.io.ByteArrayOutputStream;
35 import java.io.File;
36 import java.io.FileWriter;
37 import java.io.IOException;
38 import java.util.ArrayList;
39 import java.util.Collection;
40 import java.util.List;
41 import java.util.regex.Matcher;
42 import java.util.regex.Pattern;
43 import java.util.regex.PatternSyntaxException;
44 
45 /**
46  * A {@link com.android.tradefed.device.metric.IMetricCollector} to collect FPS data.
47  */
48 public class GameQualificationFpsCollector extends GameQualificationScheduledMetricCollector {
49     private long mLatestSeen = 0;
50     private long mVSyncPeriod = 0;
51     private List<GameQualificationMetric> mElapsedTimes = new ArrayList<>();
52     private File mRawFile;
53     private Pattern mLayerPattern;
54     private String mTestLayer;
55     private boolean mAppStarted;
56 
GameQualificationFpsCollector()57     public GameQualificationFpsCollector() {
58         mIntervalMs = 1000L;
59     }
60 
61     @VisibleForTesting
getElapsedTimes()62     List<GameQualificationMetric> getElapsedTimes() {
63         return mElapsedTimes;
64     }
65 
66     @Override
doStart(DeviceMetricData runData)67     protected void doStart(DeviceMetricData runData) {
68         if (!isEnabled()) {
69             return;
70         }
71         Preconditions.checkState(getApkInfo() != null);
72         CLog.v("Test run started on device %s.", mDevice);
73 
74         try {
75             mRawFile = File.createTempFile("GameQualification_RAW_TIMES", ".txt");
76         } catch (IOException e) {
77             setErrorMessage("Failed creating file to store raw FPS data.");
78             throw new RuntimeException(e);
79         }
80 
81         mElapsedTimes.clear();
82         mLatestSeen = 0;
83         mAppStarted = false;
84         setErrorMessage(
85                 "Unable to retrieve any metrics.  App might not have started or the target "
86                         + "layer name did not exists.");
87         setHasError(true);
88 
89         try {
90             mLayerPattern = Pattern.compile(getApkInfo().getLayerName());
91         } catch (PatternSyntaxException e) {
92             throw new RuntimeException(e);
93         }
94     }
95 
96     /**
97      * Task periodically & asynchronously run during the test running.
98      */
collect()99     protected void collect() {
100         try {
101             String[] raw = getRawData();
102             processRawData(raw);
103         } catch (DeviceNotAvailableException e) {
104             setErrorMessage(
105                     "Device not available during FPS data collection: " + e.getMessage());
106             throw new RuntimeException(e);
107         }
108     }
109 
getRawData()110     private String[] getRawData() throws DeviceNotAvailableException {
111         if (!mAppStarted) {
112             String listCmd = "dumpsys SurfaceFlinger --list";
113             String[] layerList = mDevice.executeShellCommand(listCmd).split("\n");
114 
115             for (String layer : layerList) {
116                 Matcher m = mLayerPattern.matcher(layer);
117                 if (m.matches()) {
118                     mTestLayer = layer;
119                     break;
120                 }
121             }
122         }
123         CLog.d("Collecting benchmark stats for layer: %s", mTestLayer);
124 
125 
126         String cmd = "dumpsys SurfaceFlinger --latency \"" + mTestLayer+ "\"";
127         return mDevice.executeShellCommand(cmd).split("\n");
128     }
129 
130     @VisibleForTesting
processRawData(String[] raw)131     void processRawData(String[] raw) {
132         if (raw.length == 1) {
133             if (mAppStarted) {
134                 throw new RuntimeException("App was terminated");
135             } else {
136                 return;
137             }
138         }
139 
140         if (!mAppStarted) {
141             mVSyncPeriod = Long.parseLong(raw[0]);
142             mAppStarted = true;
143             setHasError(false);
144             setErrorMessage("");
145         }
146 
147         try (BufferedWriter outputFile = new BufferedWriter(new FileWriter(mRawFile, true))) {
148             outputFile.write("Vsync: " + raw[0] + "\n");
149             outputFile.write("Latest Seen: " + mLatestSeen + "\n");
150 
151             outputFile.write(String.format("%20s", "Desired Present Time") + "\t");
152             outputFile.write(String.format("%20s", "Actual Present Time") + "\t");
153             outputFile.write(String.format("%20s", "Frame Ready Time") + "\n");
154 
155             boolean overlap = false;
156             for (int i = 1; i < raw.length; i++) {
157                 String[] parts = raw[i].split("\t");
158 
159                 if (parts.length == 3) {
160                     if (sample(Long.parseLong(parts[2]), Long.parseLong(parts[1]))) {
161                         overlap = true;
162                     }
163                 }
164 
165                 outputFile.write(String.format("%20d", Long.parseLong(parts[0])) + "\t");
166                 outputFile.write(String.format("%20d", Long.parseLong(parts[1])) + "\t");
167                 outputFile.write(String.format("%20d", Long.parseLong(parts[2])) + "\n");
168             }
169 
170             if (!overlap) {
171                 CLog.e("No overlap with previous poll, we missed some frames!"); // FIND SOMETHING BETTER
172             }
173 
174             outputFile.write("\n\n");
175         } catch (IOException e) {
176             throw new RuntimeException(e);
177         }
178     }
179 
180 
sample(long readyTimeStamp, long presentTimeStamp)181     private boolean sample(long readyTimeStamp, long presentTimeStamp) {
182         if (presentTimeStamp == Long.MAX_VALUE || readyTimeStamp == Long.MAX_VALUE) {
183             return false;
184         }
185         else if (presentTimeStamp < mLatestSeen) {
186             return false;
187         }
188         else if (presentTimeStamp == mLatestSeen) {
189             return true;
190         }
191         else {
192             mElapsedTimes.add(new GameQualificationMetric(presentTimeStamp, readyTimeStamp));
193             mLatestSeen = presentTimeStamp;
194             return false;
195         }
196     }
197 
198 
processTimestampsSlice( MetricSummary.Builder summary, int runIndex, long startTimestamp, long endTimestamp, BufferedWriter outputFile)199     private void processTimestampsSlice(
200             MetricSummary.Builder summary,
201             int runIndex,
202             long startTimestamp,
203             long endTimestamp,
204             BufferedWriter outputFile) throws IOException {
205         outputFile.write("Loop " + runIndex + " timestamp: " + startTimestamp + " ns\n");
206         outputFile.write("Present Time (ms)\tFrame Ready Time (ms)\n");
207 
208         long prevPresentTime = 0, prevReadyTime = 0;
209 
210         List<Long> frameTimes = new ArrayList<>();
211 
212         summary.beginLoop();
213         for(GameQualificationMetric metric : mElapsedTimes)
214         {
215             long presentTime = metric.getActualPresentTime();
216             long readyTime = metric.getFrameReadyTime();
217 
218             if (presentTime < startTimestamp) {
219                 continue;
220             }
221             if (presentTime > endTimestamp) {
222                 break;
223             }
224 
225             if (prevPresentTime == 0) {
226                 prevPresentTime = presentTime;
227                 prevReadyTime = readyTime;
228                 continue;
229             }
230 
231             long presentTimeDiff = presentTime - prevPresentTime;
232             prevPresentTime = presentTime;
233             summary.addFrameTime(PRESENT, presentTimeDiff);
234 
235             long readyTimeDiff = readyTime - prevReadyTime;
236             prevReadyTime = readyTime;
237             summary.addFrameTime(READY, readyTimeDiff);
238 
239             outputFile.write(
240                     String.format(
241                             "%d.%06d\t\t%d.%06d\n",
242                             presentTimeDiff / 1000000,
243                             presentTimeDiff % 1000000,
244                             readyTimeDiff / 1000000,
245                             readyTimeDiff % 1000000));
246             frameTimes.add(presentTimeDiff);
247         }
248         summary.endLoop();
249         printHistogram(frameTimes, runIndex);
250     }
251 
252     @Override
doEnd(DeviceMetricData runData)253     protected void doEnd(DeviceMetricData runData) {
254         if (mElapsedTimes.isEmpty()) {
255             return;
256         }
257         try {
258             try(InputStreamSource rawData = new FileInputStreamSource(mRawFile, true)) {
259                 testLog("RAW-" + getApkInfo().getName(), LogDataType.TEXT, rawData);
260             }
261 
262             mRawFile.delete();
263 
264             File tmpFile = File.createTempFile("GameQualification-frametimes", ".txt");
265             try (BufferedWriter outputFile = new BufferedWriter(new FileWriter(tmpFile))) {
266                 MetricSummary.Builder summaryBuilder =
267                         new MetricSummary.Builder(mCertificationRequirements, mVSyncPeriod);
268 
269                 long startTime = 0L;
270                 int runIndex = 0;
271 
272                 // Calculate load time.
273                 long appLaunchedTime = 0;
274                 for (ResultDataProto.Event e : mDeviceResultData.getEventsList()) {
275                     if (e.getType() == ResultDataProto.Event.Type.APP_LAUNCH) {
276                         appLaunchedTime = e.getTimestamp();
277                         continue;
278                     }
279                     // Get the first START_LOOP.  Assume START_LOOP is in chronological order
280                     // and comes after APP_LAUNCH.
281                     if (e.getType() == ResultDataProto.Event.Type.START_LOOP) {
282                         summaryBuilder.setLoadTimeMs(e.getTimestamp() - appLaunchedTime);
283                         break;
284                     }
285                 }
286                 for (ResultDataProto.Event e : mDeviceResultData.getEventsList()) {
287                     if (e.getType() != ResultDataProto.Event.Type.START_LOOP) {
288                         continue;
289                     }
290 
291                     long endTime = e.getTimestamp() * 1000000;  /* ms to ns */
292 
293                     if (startTime != 0) {
294                         processTimestampsSlice(summaryBuilder, runIndex++, startTime, endTime, outputFile);
295                     }
296                     startTime = endTime;
297                 }
298 
299                 processTimestampsSlice(
300                         summaryBuilder,
301                         runIndex,
302                         startTime,
303                         mElapsedTimes.get(mElapsedTimes.size() - 1).getActualPresentTime(),
304                         outputFile);
305 
306                 MetricSummary summary = summaryBuilder.build();
307                 summary.addToMetricData(runData);
308                 outputFile.flush();
309                 try(InputStreamSource source = new FileInputStreamSource(tmpFile, true)) {
310                     testLog("GameQualification-frametimes-" + getApkInfo().getName(), LogDataType.TEXT, source);
311                 }
312             }
313             tmpFile.delete();
314         } catch (IOException e) {
315             throw new RuntimeException(e);
316         }
317     }
318 
printHistogram(Collection<Long> frameTimes, int runIndex)319     void printHistogram(Collection<Long> frameTimes, int runIndex) {
320         try(ByteArrayOutputStream output = new ByteArrayOutputStream()) {
321             Histogram histogram =
322                     new Histogram(frameTimes, mVSyncPeriod / 30L, null, 5 * mVSyncPeriod);
323             histogram.plotAscii(output, 100);
324             try(InputStreamSource source = new ByteArrayInputStreamSource(output.toByteArray())) {
325                 testLog(
326                         "GameQualification-histogram-" + getApkInfo().getName() + "-run" + runIndex,
327                         LogDataType.TEXT,
328                         source);
329             }
330         } catch (IOException e) {
331             throw new RuntimeException(e);
332         }
333     }
334 }
335