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