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