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