1 # Copyright (c) 2013 The Chromium Authors. All rights reserved. 2 # Use of this source code is governed by a BSD-style license that can be 3 # found in the LICENSE file. 4 5 import errno 6 import hashlib 7 import logging 8 import os 9 import re 10 11 from autotest_lib.client.bin import utils 12 from autotest_lib.client.common_lib import error 13 from autotest_lib.client.common_lib import file_utils 14 from autotest_lib.client.cros import chrome_binary_test 15 from autotest_lib.client.cros.video import device_capability 16 from autotest_lib.client.cros.video import helper_logger 17 18 from contextlib import closing 19 from math import ceil, floor 20 21 KEY_DELIVERY_TIME = 'delivery_time' 22 KEY_DELIVERY_TIME_FIRST = 'delivery_time.first' 23 KEY_DELIVERY_TIME_75 = 'delivery_time.percentile_0.75' 24 KEY_DELIVERY_TIME_50 = 'delivery_time.percentile_0.50' 25 KEY_DELIVERY_TIME_25 = 'delivery_time.percentile_0.25' 26 KEY_FRAME_DROP_RATE = 'frame_drop_rate' 27 KEY_CPU_KERNEL_USAGE = 'cpu_usage.kernel' 28 KEY_CPU_USER_USAGE = 'cpu_usage.user' 29 KEY_DECODE_TIME_50 = 'decode_time.percentile_0.50' 30 31 DOWNLOAD_BASE = ('http://commondatastorage.googleapis.com' 32 '/chromiumos-test-assets-public/') 33 BINARY = 'video_decode_accelerator_unittest' 34 OUTPUT_LOG = 'test_output.log' 35 TIME_LOG = 'time.log' 36 37 TIME_BINARY = '/usr/local/bin/time' 38 MICROSECONDS_PER_SECOND = 1000000 39 40 UNIT_MILLISECOND = 'milliseconds' 41 UNIT_MICROSECOND = 'us' 42 UNIT_RATIO = 'ratio' 43 44 # The format used for 'time': <real time>, <kernel time>, <user time> 45 TIME_OUTPUT_FORMAT = '%e %S %U' 46 47 RE_FRAME_DELIVERY_TIME = re.compile('frame \d+: (\d+) us') 48 RE_DECODE_TIME_MEDIAN = re.compile('Decode time median: (\d+)') 49 50 51 def _percentile(values, k): 52 assert k >= 0 and k <= 1 53 i = k * (len(values) - 1) 54 c, f = int(ceil(i)), int(floor(i)) 55 56 if c == f: return values[c] 57 return (i - f) * values[c] + (c - i) * values[f] 58 59 60 def _remove_if_exists(filepath): 61 if filepath and os.path.exists(filepath): 62 try: 63 os.remove(filepath) 64 except OSError, e: 65 raise 66 67 68 class video_VDAPerf(chrome_binary_test.ChromeBinaryTest): 69 """ 70 This test monitors several performance metrics reported by Chrome test 71 binary, video_decode_accelerator_unittest. 72 """ 73 74 version = 1 75 76 77 def _logperf(self, name, key, value, units, higher_is_better=False): 78 description = '%s.%s' % (name, key) 79 self.output_perf_value( 80 description=description, value=value, units=units, 81 higher_is_better=higher_is_better) 82 83 84 def _analyze_frame_delivery_times(self, name, frame_delivery_times): 85 """ 86 Analyzes the frame delivery times and output the statistics to the 87 Chrome Performance dashboard. 88 89 @param name: The name of the test video. 90 @param frame_delivery_times: The delivery time of each frame in the 91 test video. 92 """ 93 # Log the delivery time of the first frame. 94 self._logperf(name, KEY_DELIVERY_TIME_FIRST, frame_delivery_times[0], 95 UNIT_MICROSECOND) 96 97 # Log all the delivery times, the Chrome performance dashboard will do 98 # the statistics. 99 self._logperf(name, KEY_DELIVERY_TIME, frame_delivery_times, 100 UNIT_MICROSECOND) 101 102 # Log the 25%, 50%, and 75% percentile of the frame delivery times. 103 t = sorted(frame_delivery_times) 104 self._logperf(name, KEY_DELIVERY_TIME_75, _percentile(t, 0.75), 105 UNIT_MICROSECOND) 106 self._logperf(name, KEY_DELIVERY_TIME_50, _percentile(t, 0.50), 107 UNIT_MICROSECOND) 108 self._logperf(name, KEY_DELIVERY_TIME_25, _percentile(t, 0.25), 109 UNIT_MICROSECOND) 110 111 112 def _analyze_frame_drop_rate( 113 self, name, frame_delivery_times, rendering_fps): 114 frame_duration = MICROSECONDS_PER_SECOND / rendering_fps 115 116 render_time = frame_duration; 117 delivery_time = 0; 118 drop_count = 0 119 120 # Ignore the delivery time of the first frame since we delay the 121 # rendering until we get the first frame. 122 # 123 # Note that we keep accumulating delivery times and don't use deltas 124 # between current and previous delivery time. If the decoder cannot 125 # catch up after falling behind, it will keep dropping frames. 126 for t in frame_delivery_times[1:]: 127 render_time += frame_duration 128 delivery_time += t 129 if delivery_time > render_time: 130 drop_count += 1 131 132 n = len(frame_delivery_times) 133 134 # Since we won't drop the first frame, don't add it to the number of 135 # frames. 136 drop_rate = float(drop_count) / (n - 1) if n > 1 else 0 137 self._logperf(name, KEY_FRAME_DROP_RATE, drop_rate, UNIT_RATIO) 138 139 # The performance keys would be used as names of python variables when 140 # evaluating the test constraints. So we cannot use '.' as we did in 141 # _logperf. 142 self._perf_keyvals['%s_%s' % (name, KEY_FRAME_DROP_RATE)] = drop_rate 143 144 145 def _analyze_cpu_usage(self, name, time_log_file): 146 with open(time_log_file) as f: 147 content = f.read() 148 r, s, u = (float(x) for x in content.split()) 149 150 self._logperf(name, KEY_CPU_USER_USAGE, u / r, UNIT_RATIO) 151 self._logperf(name, KEY_CPU_KERNEL_USAGE, s / r, UNIT_RATIO) 152 153 154 def _load_frame_delivery_times(self, test_log_file): 155 """ 156 Gets the frame delivery times from the |test_log_file|. 157 158 The |test_log_file| could contain frame delivery times for more than 159 one decoder. However, we use only one in this test. 160 161 The expected content in the |test_log_file|: 162 163 The first line is the frame number of the first decoder. For exmplae: 164 frame count: 250 165 It is followed by the delivery time of each frame. For example: 166 frame 0000: 16123 us 167 frame 0001: 16305 us 168 : 169 170 Then it is the frame number of the second decoder followed by the 171 delivery times, and so on so forth. 172 173 @param test_log_file: The test log file where we load the frame 174 delivery times from. 175 @returns a list of integers which are the delivery times of all frames 176 (in microsecond). 177 """ 178 result = [] 179 with open(test_log_file, 'r') as f: 180 while True: 181 line = f.readline() 182 if not line: break 183 _, count = line.split(':') 184 times = [] 185 for i in xrange(int(count)): 186 line = f.readline() 187 m = RE_FRAME_DELIVERY_TIME.match(line) 188 assert m, 'invalid format: %s' % line 189 times.append(int(m.group(1))) 190 result.append(times) 191 if len(result) != 1: 192 raise error.TestError('Frame delivery times load failed.') 193 return result[0] 194 195 196 def _get_test_case_name(self, path): 197 """Gets the test_case_name from the video's path. 198 199 For example: for the path 200 "/crowd/crowd1080-1edaaca36b67e549c51e5fea4ed545c3.vp8" 201 We will derive the test case's name as "crowd1080_vp8". 202 """ 203 s = path.split('/')[-1] # get the filename 204 return '%s_%s' % (s[:s.rfind('-')], s[s.rfind('.') + 1:]) 205 206 207 def _download_video(self, download_path, local_file): 208 url = '%s%s' % (DOWNLOAD_BASE, download_path) 209 logging.info('download "%s" to "%s"', url, local_file) 210 211 file_utils.download_file(url, local_file) 212 213 with open(local_file, 'r') as r: 214 md5sum = hashlib.md5(r.read()).hexdigest() 215 if md5sum not in download_path: 216 raise error.TestError('unmatched md5 sum: %s' % md5sum) 217 218 219 def _results_file(self, test_name, type_name, filename): 220 return os.path.join(self.resultsdir, 221 '%s_%s_%s' % (test_name, type_name, filename)) 222 223 224 def _append_freon_switch_if_needed(self, cmd_line): 225 return cmd_line + ' --ozone-platform=gbm' 226 227 228 def _run_test_case(self, name, test_video_data, frame_num, rendering_fps): 229 230 # Get frame delivery time, decode as fast as possible. 231 test_log_file = self._results_file(name, 'no_rendering', OUTPUT_LOG) 232 cmd_line_list = [ 233 '--test_video_data="%s"' % test_video_data, 234 '--gtest_filter=DecodeVariations/*/0', 235 '--rendering_fps=0', 236 '--output_log="%s"' % test_log_file, 237 '--ozone-platform=gbm', 238 helper_logger.chrome_vmodule_flag(), 239 ] 240 cmd_line = ' '.join(cmd_line_list) 241 self.run_chrome_test_binary(BINARY, cmd_line) 242 243 frame_delivery_times = self._load_frame_delivery_times(test_log_file) 244 if len(frame_delivery_times) != frame_num: 245 raise error.TestError( 246 "frames number mismatch - expected: %d, got: %d" % 247 (frame_num, len(frame_delivery_times))); 248 self._analyze_frame_delivery_times(name, frame_delivery_times) 249 250 # Get frame drop rate & CPU usage, decode at the specified fps 251 test_log_file = self._results_file(name, 'with_rendering', OUTPUT_LOG) 252 time_log_file = self._results_file(name, 'with_rendering', TIME_LOG) 253 cmd_line_list = [ 254 '--test_video_data="%s"' % test_video_data, 255 '--gtest_filter=DecodeVariations/*/0', 256 '--rendering_fps=%s' % rendering_fps, 257 '--output_log="%s"' % test_log_file, 258 '--ozone-platform=gbm', 259 helper_logger.chrome_vmodule_flag(), 260 ] 261 cmd_line = ' '.join(cmd_line_list) 262 time_cmd = ('%s -f "%s" -o "%s" ' % 263 (TIME_BINARY, TIME_OUTPUT_FORMAT, time_log_file)) 264 self.run_chrome_test_binary(BINARY, cmd_line, prefix=time_cmd) 265 266 frame_delivery_times = self._load_frame_delivery_times(test_log_file) 267 self._analyze_frame_drop_rate(name, frame_delivery_times, rendering_fps) 268 self._analyze_cpu_usage(name, time_log_file) 269 270 # Get decode time median. 271 test_log_file = self._results_file(name, 'decode_time', OUTPUT_LOG) 272 cmd_line_list = [ 273 '--test_video_data="%s"' % test_video_data, 274 '--gtest_filter=*TestDecodeTimeMedian', 275 '--output_log="%s"' % test_log_file, 276 '--ozone-platform=gbm', 277 helper_logger.chrome_vmodule_flag(), 278 ] 279 cmd_line = ' '.join(cmd_line_list) 280 self.run_chrome_test_binary(BINARY, cmd_line) 281 line = open(test_log_file, 'r').read() 282 m = RE_DECODE_TIME_MEDIAN.match(line) 283 assert m, 'invalid format: %s' % line 284 decode_time = int(m.group(1)) 285 self._logperf(name, KEY_DECODE_TIME_50, decode_time, UNIT_MICROSECOND) 286 287 @helper_logger.video_log_wrapper 288 @chrome_binary_test.nuke_chrome 289 def run_once(self, test_cases): 290 self._perf_keyvals = {} 291 video_path = None 292 last_error = None 293 dc = device_capability.DeviceCapability() 294 for (path, width, height, frame_num, frag_num, profile, 295 fps, required_cap) in test_cases: 296 try: 297 name = self._get_test_case_name(path) 298 if not dc.have_capability(required_cap): 299 logging.info("%s is unavailable. Skip %s", 300 required_cap, name) 301 continue 302 video_path = os.path.join(self.bindir, '%s.download' % name) 303 test_video_data = '%s:%s:%s:%s:%s:%s:%s:%s' % (video_path, 304 width, height, frame_num, frag_num, 0, 0, profile) 305 self._download_video(path, video_path) 306 self._run_test_case(name, test_video_data, frame_num, fps) 307 except Exception as last_error: 308 # log the error and continue to the next test case. 309 logging.exception(last_error) 310 finally: 311 _remove_if_exists(video_path) 312 313 self.write_perf_keyval(self._perf_keyvals) 314 315 if last_error: 316 raise # the last error 317
