1 /* 2 * Copyright (C) 2014 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 package com.android.media.tests; 18 19 import com.android.ddmlib.testrunner.TestIdentifier; 20 import com.android.tradefed.config.Option; 21 import com.android.tradefed.config.Option.Importance; 22 import com.android.tradefed.device.CollectingOutputReceiver; 23 import com.android.tradefed.device.DeviceNotAvailableException; 24 import com.android.tradefed.device.ITestDevice; 25 import com.android.tradefed.log.LogUtil.CLog; 26 import com.android.tradefed.result.ByteArrayInputStreamSource; 27 import com.android.tradefed.result.ITestInvocationListener; 28 import com.android.tradefed.result.LogDataType; 29 import com.android.tradefed.testtype.IDeviceTest; 30 import com.android.tradefed.testtype.IRemoteTest; 31 import com.android.tradefed.util.CommandResult; 32 import com.android.tradefed.util.IRunUtil; 33 import com.android.tradefed.util.RunUtil; 34 35 import org.junit.Assert; 36 37 import java.util.ArrayList; 38 import java.util.Collection; 39 import java.util.Collections; 40 import java.util.Date; 41 import java.util.HashMap; 42 import java.util.Map; 43 import java.util.concurrent.TimeUnit; 44 import java.util.regex.Matcher; 45 import java.util.regex.Pattern; 46 47 /** 48 * A harness that test video playback and reports result. 49 */ 50 public class VideoMultimeterTest implements IDeviceTest, IRemoteTest { 51 52 static final String RUN_KEY = "video_multimeter"; 53 54 @Option(name = "multimeter-util-path", description = "path for multimeter control util", 55 importance = Importance.ALWAYS) 56 String mMeterUtilPath = "/tmp/util.sh"; 57 58 @Option(name = "start-video-cmd", description = "adb shell command to start video playback; " + 59 "use '%s' as placeholder for media source filename", importance = Importance.ALWAYS) 60 String mCmdStartVideo = "am instrument -w -r -e media-file" 61 + " \"%s\" -e class com.android.mediaframeworktest.stress.MediaPlayerStressTest" 62 + " com.android.mediaframeworktest/.MediaPlayerStressTestRunner"; 63 64 @Option(name = "stop-video-cmd", description = "adb shell command to stop video playback", 65 importance = Importance.ALWAYS) 66 String mCmdStopVideo = "am force-stop com.android.mediaframeworktest"; 67 68 @Option(name="video-spec", description= 69 "Comma deliminated information for test video files with the following format: " + 70 "video_filename, reporting_key_prefix, fps, duration(in sec) " + 71 "May be repeated for test with multiple files.") 72 private Collection<String> mVideoSpecs = new ArrayList<>(); 73 74 @Option(name="wait-time-between-runs", description= 75 "wait time between two test video measurements, in millisecond") 76 private long mWaitTimeBetweenRuns = 3 * 60 * 1000; 77 78 @Option(name="calibration-video", description= 79 "filename of calibration video") 80 private String mCaliVideoDevicePath = "video_cali.mp4"; 81 82 @Option( 83 name = "debug-without-hardware", 84 description = "Use option to debug test without having specialized hardware", 85 importance = Importance.NEVER, 86 mandatory = false 87 ) 88 protected boolean mDebugWithoutHardware = false; 89 90 static final String ROTATE_LANDSCAPE = "content insert --uri content://settings/system" 91 + " --bind name:s:user_rotation --bind value:i:1"; 92 93 // Max number of trailing frames to trim 94 static final int TRAILING_FRAMES_MAX = 3; 95 // Min threshold for duration of trailing frames 96 static final long FRAME_DURATION_THRESHOLD_US = 500 * 1000; // 0.5s 97 98 static final String CMD_GET_FRAMERATE_STATE = "GETF"; 99 static final String CMD_START_CALIBRATION = "STAC"; 100 static final String CMD_SET_CALIBRATION_VALS = "SETCAL"; 101 static final String CMD_STOP_CALIBRATION = "STOC"; 102 static final String CMD_START_MEASUREMENT = "STAM"; 103 static final String CMD_STOP_MEASUREMENT = "STOM"; 104 static final String CMD_GET_NUM_FRAMES = "GETN"; 105 static final String CMD_GET_ALL_DATA = "GETD"; 106 107 static final long DEVICE_SYNC_TIME_MS = 30 * 1000; 108 static final long CALIBRATION_TIMEOUT_MS = 30 * 1000; 109 static final long COMMAND_TIMEOUT_MS = 5 * 1000; 110 static final long GETDATA_TIMEOUT_MS = 10 * 60 * 1000; 111 112 // Regex for: "OK (time); (frame duration); (marker color); (total dropped frames)" 113 static final String VIDEO_FRAME_DATA_PATTERN = "OK\\s+\\d+;\\s*(-?\\d+);\\s*[a-z]+;\\s*(\\d+)"; 114 115 // Regex for: "OK (time); (frame duration); (marker color); (total dropped frames); (lipsync)" 116 // results in: $1 == ts, $2 == lipsync 117 static final String LIPSYNC_DATA_PATTERN = 118 "OK\\s+(\\d+);\\s*\\d+;\\s*[a-z]+;\\s*\\d+;\\s*(-?\\d+)"; 119 // ts dur color missed latency 120 static final int LIPSYNC_SIGNAL = 2000000; // every 2 seconds 121 static final int LIPSYNC_SIGNAL_MIN = 1500000; // must be at least 1.5 seconds after prev 122 123 ITestDevice mDevice; 124 125 /** 126 * {@inheritDoc} 127 */ 128 @Override 129 public void setDevice(ITestDevice device) { 130 mDevice = device; 131 } 132 133 /** 134 * {@inheritDoc} 135 */ 136 @Override 137 public ITestDevice getDevice() { 138 return mDevice; 139 } 140 141 private void rotateScreen() throws DeviceNotAvailableException { 142 // rotate to landscape mode, except for manta 143 if (!getDevice().getProductType().contains("manta")) { 144 getDevice().executeShellCommand(ROTATE_LANDSCAPE); 145 } 146 } 147 148 protected boolean setupTestEnv() throws DeviceNotAvailableException { 149 return setupTestEnv(null); 150 } 151 152 protected void startPlayback(final String videoPath) { 153 new Thread() { 154 @Override 155 public void run() { 156 try { 157 CollectingOutputReceiver receiver = new CollectingOutputReceiver(); 158 getDevice().executeShellCommand(String.format( 159 mCmdStartVideo, videoPath), 160 receiver, 1L, TimeUnit.SECONDS, 0); 161 } catch (DeviceNotAvailableException e) { 162 CLog.e(e.getMessage()); 163 } 164 } 165 }.start(); 166 } 167 168 /** 169 * Perform calibration process for video multimeter 170 * 171 * @return boolean whether calibration succeeds 172 * @throws DeviceNotAvailableException 173 */ 174 protected boolean doCalibration() throws DeviceNotAvailableException { 175 // play calibration video 176 startPlayback(mCaliVideoDevicePath); 177 getRunUtil().sleep(3 * 1000); 178 rotateScreen(); 179 getRunUtil().sleep(1 * 1000); 180 CommandResult cr = getRunUtil().runTimedCmd( 181 COMMAND_TIMEOUT_MS, mMeterUtilPath, CMD_START_CALIBRATION); 182 CLog.i("Starting calibration: " + cr.getStdout()); 183 // check whether multimeter is calibrated 184 boolean isCalibrated = false; 185 long calibrationStartTime = System.currentTimeMillis(); 186 while (!isCalibrated && 187 System.currentTimeMillis() - calibrationStartTime <= CALIBRATION_TIMEOUT_MS) { 188 getRunUtil().sleep(1 * 1000); 189 cr = getRunUtil().runTimedCmd(2 * 1000, mMeterUtilPath, CMD_GET_FRAMERATE_STATE); 190 if (cr.getStdout().contains("calib0")) { 191 isCalibrated = true; 192 } 193 } 194 if (!isCalibrated) { 195 // stop calibration if time out 196 cr = getRunUtil().runTimedCmd( 197 COMMAND_TIMEOUT_MS, mMeterUtilPath, CMD_STOP_CALIBRATION); 198 CLog.e("Calibration timed out."); 199 } else { 200 CLog.i("Calibration succeeds."); 201 } 202 getDevice().executeShellCommand(mCmdStopVideo); 203 return isCalibrated; 204 } 205 206 protected boolean setupTestEnv(String caliValues) throws DeviceNotAvailableException { 207 getRunUtil().sleep(DEVICE_SYNC_TIME_MS); 208 CommandResult cr = getRunUtil().runTimedCmd( 209 COMMAND_TIMEOUT_MS, mMeterUtilPath, CMD_STOP_MEASUREMENT); 210 211 getDevice().setDate(new Date()); 212 CLog.i("syncing device time to host time"); 213 getRunUtil().sleep(3 * 1000); 214 215 // TODO: need a better way to clear old data 216 // start and stop to clear old data 217 cr = getRunUtil().runTimedCmd(COMMAND_TIMEOUT_MS, mMeterUtilPath, CMD_START_MEASUREMENT); 218 getRunUtil().sleep(3 * 1000); 219 cr = getRunUtil().runTimedCmd(COMMAND_TIMEOUT_MS, mMeterUtilPath, CMD_STOP_MEASUREMENT); 220 getRunUtil().sleep(3 * 1000); 221 CLog.i("Stopping measurement: " + cr.getStdout()); 222 223 if (caliValues == null) { 224 return doCalibration(); 225 } else { 226 CLog.i("Setting calibration values: " + caliValues); 227 final String calibrationValues = CMD_SET_CALIBRATION_VALS + " " + caliValues; 228 cr = getRunUtil().runTimedCmd(COMMAND_TIMEOUT_MS, mMeterUtilPath, calibrationValues); 229 final String response = mDebugWithoutHardware ? "OK" : cr.getStdout(); 230 if (response != null && response.startsWith("OK")) { 231 CLog.i("Calibration values are set to: " + caliValues); 232 return true; 233 } else { 234 CLog.e("Failed to set calibration values: " + cr.getStdout()); 235 return false; 236 } 237 } 238 } 239 240 private void doMeasurement(final String testVideoPath, long durationSecond) 241 throws DeviceNotAvailableException { 242 CommandResult cr; 243 getDevice().clearErrorDialogs(); 244 getRunUtil().sleep(mWaitTimeBetweenRuns); 245 246 // play test video 247 startPlayback(testVideoPath); 248 249 getRunUtil().sleep(3 * 1000); 250 251 rotateScreen(); 252 getRunUtil().sleep(1 * 1000); 253 cr = getRunUtil().runTimedCmd(COMMAND_TIMEOUT_MS, mMeterUtilPath, CMD_START_MEASUREMENT); 254 CLog.i("Starting measurement: " + cr.getStdout()); 255 256 // end measurement 257 getRunUtil().sleep(durationSecond * 1000); 258 259 cr = getRunUtil().runTimedCmd(COMMAND_TIMEOUT_MS, mMeterUtilPath, CMD_STOP_MEASUREMENT); 260 CLog.i("Stopping measurement: " + cr.getStdout()); 261 if (cr == null || !cr.getStdout().contains("OK")) { 262 cr = getRunUtil().runTimedCmd( 263 COMMAND_TIMEOUT_MS, mMeterUtilPath, CMD_STOP_MEASUREMENT); 264 CLog.i("Retry - Stopping measurement: " + cr.getStdout()); 265 } 266 267 getDevice().executeShellCommand(mCmdStopVideo); 268 getDevice().clearErrorDialogs(); 269 } 270 271 private Map<String, String> getResult(ITestInvocationListener listener, 272 Map<String, String> metrics, String keyprefix, float fps, boolean lipsync) { 273 CommandResult cr; 274 275 // get number of results 276 getRunUtil().sleep(5 * 1000); 277 cr = getRunUtil().runTimedCmd(COMMAND_TIMEOUT_MS, mMeterUtilPath, CMD_GET_NUM_FRAMES); 278 String frameNum = cr.getStdout(); 279 280 CLog.i("== Video Multimeter Result '%s' ==", keyprefix); 281 CLog.i("Number of results: " + frameNum); 282 283 String nrOfDataPointsStr = extractNumberOfCollectedDataPoints(frameNum); 284 metrics.put(keyprefix + "frame_captured", nrOfDataPointsStr); 285 286 long nrOfDataPoints = Long.parseLong(nrOfDataPointsStr); 287 288 Assert.assertTrue("Multimeter did not collect any data for " + keyprefix, 289 nrOfDataPoints > 0); 290 291 CLog.i("Captured frames: " + nrOfDataPointsStr); 292 293 // get all results from multimeter and write to output file 294 cr = getRunUtil().runTimedCmd(GETDATA_TIMEOUT_MS, mMeterUtilPath, CMD_GET_ALL_DATA); 295 String allData = cr.getStdout(); 296 listener.testLog( 297 keyprefix, LogDataType.TEXT, new ByteArrayInputStreamSource(allData.getBytes())); 298 299 // parse results 300 return parseResult(metrics, nrOfDataPoints, allData, keyprefix, fps, lipsync); 301 } 302 303 private String extractNumberOfCollectedDataPoints(String numFrames) { 304 // Create pattern that matches string like "OK 14132" capturing the 305 // number of data points. 306 Pattern p = Pattern.compile("OK\\s+(\\d+)$"); 307 Matcher m = p.matcher(numFrames.trim()); 308 309 String frameCapturedStr = "0"; 310 if (m.matches()) { 311 frameCapturedStr = m.group(1); 312 } 313 314 return frameCapturedStr; 315 } 316 317 protected void runMultimeterTest(ITestInvocationListener listener, 318 Map<String,String> metrics) throws DeviceNotAvailableException { 319 for (String videoSpec : mVideoSpecs) { 320 String[] videoInfo = videoSpec.split(","); 321 String filename = videoInfo[0].trim(); 322 String keyPrefix = videoInfo[1].trim(); 323 float fps = Float.parseFloat(videoInfo[2].trim()); 324 long duration = Long.parseLong(videoInfo[3].trim()); 325 doMeasurement(filename, duration); 326 metrics = getResult(listener, metrics, keyPrefix, fps, true); 327 } 328 } 329 330 /** 331 * {@inheritDoc} 332 */ 333 @Override 334 public void run(ITestInvocationListener listener) 335 throws DeviceNotAvailableException { 336 TestIdentifier testId = new TestIdentifier(getClass() 337 .getCanonicalName(), RUN_KEY); 338 339 listener.testRunStarted(RUN_KEY, 0); 340 listener.testStarted(testId); 341 342 long testStartTime = System.currentTimeMillis(); 343 Map<String, String> metrics = new HashMap<>(); 344 345 if (setupTestEnv()) { 346 runMultimeterTest(listener, metrics); 347 } 348 349 long durationMs = System.currentTimeMillis() - testStartTime; 350 listener.testEnded(testId, metrics); 351 listener.testRunEnded(durationMs, metrics); 352 } 353 354 /** 355 * Parse Multimeter result. 356 * 357 * @param result 358 * @return a {@link HashMap} that contains metrics keys and results 359 */ 360 private Map<String, String> parseResult(Map<String, String> metrics, 361 long frameCaptured, String result, String keyprefix, float fps, 362 boolean lipsync) { 363 final int MISSING_FRAME_CEILING = 5; //5+ frames missing count the same 364 final double[] MISSING_FRAME_WEIGHT = {0.0, 1.0, 2.5, 5.0, 6.25, 8.0}; 365 366 // Get total captured frames and calculate smoothness and freezing score 367 // format: "OK (time); (frame duration); (marker color); (total dropped frames)" 368 Pattern p = Pattern.compile(VIDEO_FRAME_DATA_PATTERN); 369 Matcher m = null; 370 String[] lines = result.split(System.getProperty("line.separator")); 371 String totalDropFrame = "-1"; 372 String lastDropFrame = "0"; 373 long frameCount = 0; 374 long consecutiveDropFrame = 0; 375 double freezingPenalty = 0.0; 376 long frameDuration = 0; 377 double offByOne = 0; 378 double offByMultiple = 0; 379 double expectedFrameDurationInUs = 1000000.0 / fps; 380 for (int i = 0; i < lines.length; i++) { 381 m = p.matcher(lines[i].trim()); 382 if (m.matches()) { 383 frameDuration = Long.parseLong(m.group(1)); 384 // frameDuration = -1 indicates dropped frame 385 if (frameDuration > 0) { 386 frameCount++; 387 } 388 totalDropFrame = m.group(2); 389 // trim the last few data points if needed 390 if (frameCount >= frameCaptured - TRAILING_FRAMES_MAX - 1 && 391 frameDuration > FRAME_DURATION_THRESHOLD_US) { 392 metrics.put(keyprefix + "frame_captured", String.valueOf(frameCount)); 393 break; 394 } 395 if (lastDropFrame.equals(totalDropFrame)) { 396 if (consecutiveDropFrame > 0) { 397 freezingPenalty += MISSING_FRAME_WEIGHT[(int) (Math.min(consecutiveDropFrame, 398 MISSING_FRAME_CEILING))] * consecutiveDropFrame; 399 consecutiveDropFrame = 0; 400 } 401 } else { 402 consecutiveDropFrame++; 403 } 404 lastDropFrame = totalDropFrame; 405 406 if (frameDuration < expectedFrameDurationInUs * 0.5) { 407 offByOne++; 408 } else if (frameDuration > expectedFrameDurationInUs * 1.5) { 409 if (frameDuration < expectedFrameDurationInUs * 2.5) { 410 offByOne++; 411 } else { 412 offByMultiple++; 413 } 414 } 415 } 416 } 417 if (totalDropFrame.equals("-1")) { 418 // no matching result found 419 CLog.w("No result found for " + keyprefix); 420 return metrics; 421 } else { 422 metrics.put(keyprefix + "frame_drop", totalDropFrame); 423 CLog.i("Dropped frames: " + totalDropFrame); 424 } 425 double smoothnessScore = 100.0 - (offByOne / frameCaptured) * 100.0 - 426 (offByMultiple / frameCaptured) * 300.0; 427 metrics.put(keyprefix + "smoothness", String.valueOf(smoothnessScore)); 428 CLog.i("Off by one frame: " + offByOne); 429 CLog.i("Off by multiple frames: " + offByMultiple); 430 CLog.i("Smoothness score: " + smoothnessScore); 431 432 double freezingScore = 100.0 - 100.0 * freezingPenalty / frameCaptured; 433 metrics.put(keyprefix + "freezing", String.valueOf(freezingScore)); 434 CLog.i("Freezing score: " + freezingScore); 435 436 // parse lipsync results (the audio and video synchronization offset) 437 // format: "OK (time); (frame duration); (marker color); (total dropped frames); (lipsync)" 438 if (lipsync) { 439 ArrayList<Integer> lipsyncVals = new ArrayList<>(); 440 StringBuilder lipsyncValsStr = new StringBuilder("["); 441 long lipsyncSum = 0; 442 int lipSyncLastTime = -1; 443 444 Pattern pLip = Pattern.compile(LIPSYNC_DATA_PATTERN); 445 for (int i = 0; i < lines.length; i++) { 446 m = pLip.matcher(lines[i].trim()); 447 if (m.matches()) { 448 int lipSyncTime = Integer.parseInt(m.group(1)); 449 int lipSyncVal = Integer.parseInt(m.group(2)); 450 if (lipSyncLastTime != -1) { 451 if ((lipSyncTime - lipSyncLastTime) < LIPSYNC_SIGNAL_MIN) { 452 continue; // ignore the early/spurious one 453 } 454 } 455 lipSyncLastTime = lipSyncTime; 456 457 lipsyncVals.add(lipSyncVal); 458 lipsyncValsStr.append(lipSyncVal); 459 lipsyncValsStr.append(", "); 460 lipsyncSum += lipSyncVal; 461 } 462 } 463 if (lipsyncVals.size() > 0) { 464 lipsyncValsStr.append("]"); 465 CLog.i("Lipsync values: " + lipsyncValsStr); 466 Collections.sort(lipsyncVals); 467 int lipsyncCount = lipsyncVals.size(); 468 int minLipsync = lipsyncVals.get(0); 469 int maxLipsync = lipsyncVals.get(lipsyncCount - 1); 470 metrics.put(keyprefix + "lipsync_count", String.valueOf(lipsyncCount)); 471 CLog.i("Lipsync Count: " + lipsyncCount); 472 metrics.put(keyprefix + "lipsync_min", String.valueOf(lipsyncVals.get(0))); 473 CLog.i("Lipsync Min: " + minLipsync); 474 metrics.put(keyprefix + "lipsync_max", String.valueOf(maxLipsync)); 475 CLog.i("Lipsync Max: " + maxLipsync); 476 double meanLipSync = (double) lipsyncSum / lipsyncCount; 477 metrics.put(keyprefix + "lipsync_mean", String.valueOf(meanLipSync)); 478 CLog.i("Lipsync Mean: " + meanLipSync); 479 } else { 480 CLog.w("Lipsync value not found in result."); 481 } 482 } 483 CLog.i("== End ==", keyprefix); 484 return metrics; 485 } 486 487 protected IRunUtil getRunUtil() { 488 return RunUtil.getDefault(); 489 } 490 } 491
