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 5import errno 6import hashlib 7import logging 8import os 9import re 10 11from autotest_lib.client.bin import utils 12from autotest_lib.client.common_lib import error 13from autotest_lib.client.common_lib import file_utils 14from autotest_lib.client.cros import chrome_binary_test 15 16from contextlib import closing 17from math import ceil, floor 18 19KEY_DELIVERY_TIME = 'delivery_time' 20KEY_DELIVERY_TIME_FIRST = 'delivery_time.first' 21KEY_DELIVERY_TIME_75 = 'delivery_time.percentile_0.75' 22KEY_DELIVERY_TIME_50 = 'delivery_time.percentile_0.50' 23KEY_DELIVERY_TIME_25 = 'delivery_time.percentile_0.25' 24KEY_FRAME_DROP_RATE = 'frame_drop_rate' 25KEY_CPU_KERNEL_USAGE = 'cpu_usage.kernel' 26KEY_CPU_USER_USAGE = 'cpu_usage.user' 27KEY_DECODE_TIME_50 = 'decode_time.percentile_0.50' 28 29DOWNLOAD_BASE = ('http://commondatastorage.googleapis.com' 30 '/chromiumos-test-assets-public/') 31BINARY = 'video_decode_accelerator_unittest' 32OUTPUT_LOG = 'test_output.log' 33TIME_LOG = 'time.log' 34 35TIME_BINARY = '/usr/local/bin/time' 36MICROSECONDS_PER_SECOND = 1000000 37 38RENDERING_WARM_UP_ITERS = 30 39 40# These strings should match chromium/src/tools/perf/unit-info.json. 41UNIT_MILLISECOND = 'milliseconds' 42UNIT_MICROSECOND = 'us' 43UNIT_PERCENT = 'percent' 44 45# The format used for 'time': <real time>, <kernel time>, <user time> 46TIME_OUTPUT_FORMAT = '%e %S %U' 47 48RE_FRAME_DELIVERY_TIME = re.compile('frame \d+: (\d+) us') 49RE_DECODE_TIME_MEDIAN = re.compile('Decode time median: (\d+)') 50 51 52def _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 61def _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 69class 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_PERCENT) 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_PERCENT) 152 self._logperf(name, KEY_CPU_KERNEL_USAGE, s / r, UNIT_PERCENT) 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 if utils.is_freon(): 227 return cmd_line + ' --ozone-platform=gbm' 228 else: 229 return cmd_line 230 231 232 def _run_test_case(self, name, test_video_data, frame_num, rendering_fps): 233 234 # Get frame delivery time, decode as fast as possible. 235 test_log_file = self._results_file(name, 'no_rendering', OUTPUT_LOG) 236 cmd_line = self._append_freon_switch_if_needed( 237 '--test_video_data="%s" ' % test_video_data + 238 '--gtest_filter=DecodeVariations/*/0 ' + 239 '--disable_rendering ' + 240 '--output_log="%s"' % test_log_file) 241 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 = self._append_freon_switch_if_needed( 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 time_cmd = ('%s -f "%s" -o "%s" ' % 261 (TIME_BINARY, TIME_OUTPUT_FORMAT, time_log_file)) 262 self.run_chrome_test_binary(BINARY, cmd_line, prefix=time_cmd) 263 264 frame_delivery_times = self._load_frame_delivery_times(test_log_file) 265 self._analyze_frame_drop_rate(name, frame_delivery_times, rendering_fps) 266 self._analyze_cpu_usage(name, time_log_file) 267 268 # Get decode time median. 269 test_log_file = self._results_file(name, 'decode_time', OUTPUT_LOG) 270 cmd_line = self._append_freon_switch_if_needed( 271 '--test_video_data="%s" ' % test_video_data + 272 '--gtest_filter=*TestDecodeTimeMedian ' + 273 '--output_log="%s"' % test_log_file) 274 self.run_chrome_test_binary(BINARY, cmd_line) 275 line = open(test_log_file, 'r').read() 276 m = RE_DECODE_TIME_MEDIAN.match(line) 277 assert m, 'invalid format: %s' % line 278 decode_time = int(m.group(1)) 279 self._logperf(name, KEY_DECODE_TIME_50, decode_time, UNIT_MICROSECOND) 280 281 282 @chrome_binary_test.nuke_chrome 283 def run_once(self, test_cases): 284 self._perf_keyvals = {} 285 last_error = None 286 for (path, width, height, frame_num, frag_num, profile, 287 fps) in test_cases: 288 name = self._get_test_case_name(path) 289 video_path = os.path.join(self.bindir, '%s.download' % name) 290 test_video_data = '%s:%s:%s:%s:%s:%s:%s:%s' % ( 291 video_path, width, height, frame_num, frag_num, 0, 0, profile) 292 try: 293 self._download_video(path, video_path) 294 self._run_test_case(name, test_video_data, frame_num, fps) 295 except Exception as last_error: 296 # log the error and continue to the next test case. 297 logging.exception(last_error) 298 finally: 299 _remove_if_exists(video_path) 300 301 if last_error: 302 raise # the last error 303 304 self.write_perf_keyval(self._perf_keyvals) 305