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