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