1# Copyright (c) 2016, Intel Corporation.
2#
3# SPDX-License-Identifier: GPL-2.0-only
4#
5"""Build performance test base classes and functionality"""
6import json
7import logging
8import os
9import re
10import resource
11import socket
12import shutil
13import time
14import unittest
15import xml.etree.ElementTree as ET
16from collections import OrderedDict
17from datetime import datetime, timedelta
18from functools import partial
19from multiprocessing import Process
20from multiprocessing import SimpleQueue
21from xml.dom import minidom
22
23import oe.path
24from oeqa.utils.commands import CommandError, runCmd, get_bb_vars
25from oeqa.utils.git import GitError, GitRepo
26
27# Get logger for this module
28log = logging.getLogger('build-perf')
29
30# Our own version of runCmd which does not raise AssertErrors which would cause
31# errors to interpreted as failures
32runCmd2 = partial(runCmd, assert_error=False, limit_exc_output=40)
33
34
35class KernelDropCaches(object):
36    """Container of the functions for dropping kernel caches"""
37    sudo_passwd = None
38
39    @classmethod
40    def check(cls):
41        """Check permssions for dropping kernel caches"""
42        from getpass import getpass
43        from locale import getdefaultlocale
44        cmd = ['sudo', '-k', '-n', 'tee', '/proc/sys/vm/drop_caches']
45        ret = runCmd2(cmd, ignore_status=True, data=b'0')
46        if ret.output.startswith('sudo:'):
47            pass_str = getpass(
48                "\nThe script requires sudo access to drop caches between "
49                "builds (echo 3 > /proc/sys/vm/drop_caches).\n"
50                "Please enter your sudo password: ")
51            cls.sudo_passwd = bytes(pass_str, getdefaultlocale()[1])
52
53    @classmethod
54    def drop(cls):
55        """Drop kernel caches"""
56        cmd = ['sudo', '-k']
57        if cls.sudo_passwd:
58            cmd.append('-S')
59            input_data = cls.sudo_passwd + b'\n'
60        else:
61            cmd.append('-n')
62            input_data = b''
63        cmd += ['tee', '/proc/sys/vm/drop_caches']
64        input_data += b'3'
65        runCmd2(cmd, data=input_data)
66
67
68def str_to_fn(string):
69    """Convert string to a sanitized filename"""
70    return re.sub(r'(\W+)', '-', string, flags=re.LOCALE)
71
72
73class ResultsJsonEncoder(json.JSONEncoder):
74    """Extended encoder for build perf test results"""
75    unix_epoch = datetime.utcfromtimestamp(0)
76
77    def default(self, obj):
78        """Encoder for our types"""
79        if isinstance(obj, datetime):
80            # NOTE: we assume that all timestamps are in UTC time
81            return (obj - self.unix_epoch).total_seconds()
82        if isinstance(obj, timedelta):
83            return obj.total_seconds()
84        return json.JSONEncoder.default(self, obj)
85
86
87class BuildPerfTestResult(unittest.TextTestResult):
88    """Runner class for executing the individual tests"""
89    # List of test cases to run
90    test_run_queue = []
91
92    def __init__(self, out_dir, *args, **kwargs):
93        super(BuildPerfTestResult, self).__init__(*args, **kwargs)
94
95        self.out_dir = out_dir
96        self.hostname = socket.gethostname()
97        self.product = os.getenv('OE_BUILDPERFTEST_PRODUCT', 'oe-core')
98        self.start_time = self.elapsed_time = None
99        self.successes = []
100
101    def addSuccess(self, test):
102        """Record results from successful tests"""
103        super(BuildPerfTestResult, self).addSuccess(test)
104        self.successes.append(test)
105
106    def addError(self, test, err):
107        """Record results from crashed test"""
108        test.err = err
109        super(BuildPerfTestResult, self).addError(test, err)
110
111    def addFailure(self, test, err):
112        """Record results from failed test"""
113        test.err = err
114        super(BuildPerfTestResult, self).addFailure(test, err)
115
116    def addExpectedFailure(self, test, err):
117        """Record results from expectedly failed test"""
118        test.err = err
119        super(BuildPerfTestResult, self).addExpectedFailure(test, err)
120
121    def startTest(self, test):
122        """Pre-test hook"""
123        test.base_dir = self.out_dir
124        log.info("Executing test %s: %s", test.name, test.shortDescription())
125        self.stream.write(datetime.now().strftime("[%Y-%m-%d %H:%M:%S] "))
126        super(BuildPerfTestResult, self).startTest(test)
127
128    def startTestRun(self):
129        """Pre-run hook"""
130        self.start_time = datetime.utcnow()
131
132    def stopTestRun(self):
133        """Pre-run hook"""
134        self.elapsed_time = datetime.utcnow() - self.start_time
135
136    def all_results(self):
137        compound = [('SUCCESS', t, None) for t in self.successes] + \
138                   [('FAILURE', t, m) for t, m in self.failures] + \
139                   [('ERROR', t, m) for t, m in self.errors] + \
140                   [('EXPECTED_FAILURE', t, m) for t, m in self.expectedFailures] + \
141                   [('UNEXPECTED_SUCCESS', t, None) for t in self.unexpectedSuccesses] + \
142                   [('SKIPPED', t, m) for t, m in self.skipped]
143        return sorted(compound, key=lambda info: info[1].start_time)
144
145
146    def write_buildstats_json(self):
147        """Write buildstats file"""
148        buildstats = OrderedDict()
149        for _, test, _ in self.all_results():
150            for key, val in test.buildstats.items():
151                buildstats[test.name + '.' + key] = val
152        with open(os.path.join(self.out_dir, 'buildstats.json'), 'w') as fobj:
153            json.dump(buildstats, fobj, cls=ResultsJsonEncoder)
154
155
156    def write_results_json(self):
157        """Write test results into a json-formatted file"""
158        results = OrderedDict([('tester_host', self.hostname),
159                               ('start_time', self.start_time),
160                               ('elapsed_time', self.elapsed_time),
161                               ('tests', OrderedDict())])
162
163        for status, test, reason in self.all_results():
164            test_result = OrderedDict([('name', test.name),
165                                       ('description', test.shortDescription()),
166                                       ('status', status),
167                                       ('start_time', test.start_time),
168                                       ('elapsed_time', test.elapsed_time),
169                                       ('measurements', test.measurements)])
170            if status in ('ERROR', 'FAILURE', 'EXPECTED_FAILURE'):
171                test_result['message'] = str(test.err[1])
172                test_result['err_type'] = test.err[0].__name__
173                test_result['err_output'] = reason
174            elif reason:
175                test_result['message'] = reason
176
177            results['tests'][test.name] = test_result
178
179        with open(os.path.join(self.out_dir, 'results.json'), 'w') as fobj:
180            json.dump(results, fobj, indent=4,
181                      cls=ResultsJsonEncoder)
182
183    def write_results_xml(self):
184        """Write test results into a JUnit XML file"""
185        top = ET.Element('testsuites')
186        suite = ET.SubElement(top, 'testsuite')
187        suite.set('name', 'oeqa.buildperf')
188        suite.set('timestamp', self.start_time.isoformat())
189        suite.set('time', str(self.elapsed_time.total_seconds()))
190        suite.set('hostname', self.hostname)
191        suite.set('failures', str(len(self.failures) + len(self.expectedFailures)))
192        suite.set('errors', str(len(self.errors)))
193        suite.set('skipped', str(len(self.skipped)))
194
195        test_cnt = 0
196        for status, test, reason in self.all_results():
197            test_cnt += 1
198            testcase = ET.SubElement(suite, 'testcase')
199            testcase.set('classname', test.__module__ + '.' + test.__class__.__name__)
200            testcase.set('name', test.name)
201            testcase.set('description', test.shortDescription())
202            testcase.set('timestamp', test.start_time.isoformat())
203            testcase.set('time', str(test.elapsed_time.total_seconds()))
204            if status in ('ERROR', 'FAILURE', 'EXP_FAILURE'):
205                if status in ('FAILURE', 'EXP_FAILURE'):
206                    result = ET.SubElement(testcase, 'failure')
207                else:
208                    result = ET.SubElement(testcase, 'error')
209                result.set('message', str(test.err[1]))
210                result.set('type', test.err[0].__name__)
211                result.text = reason
212            elif status == 'SKIPPED':
213                result = ET.SubElement(testcase, 'skipped')
214                result.text = reason
215            elif status not in ('SUCCESS', 'UNEXPECTED_SUCCESS'):
216                raise TypeError("BUG: invalid test status '%s'" % status)
217
218            for data in test.measurements.values():
219                measurement = ET.SubElement(testcase, data['type'])
220                measurement.set('name', data['name'])
221                measurement.set('legend', data['legend'])
222                vals = data['values']
223                if data['type'] == BuildPerfTestCase.SYSRES:
224                    ET.SubElement(measurement, 'time',
225                                  timestamp=vals['start_time'].isoformat()).text = \
226                        str(vals['elapsed_time'].total_seconds())
227                    attrib = dict((k, str(v)) for k, v in vals['iostat'].items())
228                    ET.SubElement(measurement, 'iostat', attrib=attrib)
229                    attrib = dict((k, str(v)) for k, v in vals['rusage'].items())
230                    ET.SubElement(measurement, 'rusage', attrib=attrib)
231                elif data['type'] == BuildPerfTestCase.DISKUSAGE:
232                    ET.SubElement(measurement, 'size').text = str(vals['size'])
233                else:
234                    raise TypeError('BUG: unsupported measurement type')
235
236        suite.set('tests', str(test_cnt))
237
238        # Use minidom for pretty-printing
239        dom_doc = minidom.parseString(ET.tostring(top, 'utf-8'))
240        with open(os.path.join(self.out_dir, 'results.xml'), 'w') as fobj:
241            dom_doc.writexml(fobj, addindent='  ', newl='\n', encoding='utf-8')
242
243
244class BuildPerfTestCase(unittest.TestCase):
245    """Base class for build performance tests"""
246    SYSRES = 'sysres'
247    DISKUSAGE = 'diskusage'
248    build_target = None
249
250    def __init__(self, *args, **kwargs):
251        super(BuildPerfTestCase, self).__init__(*args, **kwargs)
252        self.name = self._testMethodName
253        self.base_dir = None
254        self.start_time = None
255        self.elapsed_time = None
256        self.measurements = OrderedDict()
257        self.buildstats = OrderedDict()
258        # self.err is supposed to be a tuple from sys.exc_info()
259        self.err = None
260        self.bb_vars = get_bb_vars()
261        # TODO: remove 'times' and 'sizes' arrays when globalres support is
262        # removed
263        self.times = []
264        self.sizes = []
265
266    @property
267    def tmp_dir(self):
268        return os.path.join(self.base_dir, self.name + '.tmp')
269
270    def shortDescription(self):
271        return super(BuildPerfTestCase, self).shortDescription() or ""
272
273    def setUp(self):
274        """Set-up fixture for each test"""
275        if not os.path.isdir(self.tmp_dir):
276            os.mkdir(self.tmp_dir)
277        if self.build_target:
278            self.run_cmd(['bitbake', self.build_target, '--runall=fetch'])
279
280    def tearDown(self):
281        """Tear-down fixture for each test"""
282        if os.path.isdir(self.tmp_dir):
283            shutil.rmtree(self.tmp_dir)
284
285    def run(self, *args, **kwargs):
286        """Run test"""
287        self.start_time = datetime.now()
288        super(BuildPerfTestCase, self).run(*args, **kwargs)
289        self.elapsed_time = datetime.now() - self.start_time
290
291    def run_cmd(self, cmd):
292        """Convenience method for running a command"""
293        cmd_str = cmd if isinstance(cmd, str) else ' '.join(cmd)
294        log.info("Logging command: %s", cmd_str)
295        try:
296            runCmd2(cmd)
297        except CommandError as err:
298            log.error("Command failed: %s", err.retcode)
299            raise
300
301    def _append_measurement(self, measurement):
302        """Simple helper for adding measurements results"""
303        if measurement['name'] in self.measurements:
304            raise ValueError('BUG: two measurements with the same name in {}'.format(
305                self.__class__.__name__))
306        self.measurements[measurement['name']] = measurement
307
308    def measure_cmd_resources(self, cmd, name, legend, save_bs=False):
309        """Measure system resource usage of a command"""
310        def _worker(data_q, cmd, **kwargs):
311            """Worker process for measuring resources"""
312            try:
313                start_time = datetime.now()
314                ret = runCmd2(cmd, **kwargs)
315                etime = datetime.now() - start_time
316                rusage_struct = resource.getrusage(resource.RUSAGE_CHILDREN)
317                iostat = OrderedDict()
318                with open('/proc/{}/io'.format(os.getpid())) as fobj:
319                    for line in fobj.readlines():
320                        key, val = line.split(':')
321                        iostat[key] = int(val)
322                rusage = OrderedDict()
323                # Skip unused fields, (i.e. 'ru_ixrss', 'ru_idrss', 'ru_isrss',
324                # 'ru_nswap', 'ru_msgsnd', 'ru_msgrcv' and 'ru_nsignals')
325                for key in ['ru_utime', 'ru_stime', 'ru_maxrss', 'ru_minflt',
326                            'ru_majflt', 'ru_inblock', 'ru_oublock',
327                            'ru_nvcsw', 'ru_nivcsw']:
328                    rusage[key] = getattr(rusage_struct, key)
329                data_q.put({'ret': ret,
330                            'start_time': start_time,
331                            'elapsed_time': etime,
332                            'rusage': rusage,
333                            'iostat': iostat})
334            except Exception as err:
335                data_q.put(err)
336
337        cmd_str = cmd if isinstance(cmd, str) else ' '.join(cmd)
338        log.info("Timing command: %s", cmd_str)
339        data_q = SimpleQueue()
340        try:
341            proc = Process(target=_worker, args=(data_q, cmd,))
342            proc.start()
343            data = data_q.get()
344            proc.join()
345            if isinstance(data, Exception):
346                raise data
347        except CommandError:
348            log.error("Command '%s' failed", cmd_str)
349            raise
350        etime = data['elapsed_time']
351
352        measurement = OrderedDict([('type', self.SYSRES),
353                                   ('name', name),
354                                   ('legend', legend)])
355        measurement['values'] = OrderedDict([('start_time', data['start_time']),
356                                             ('elapsed_time', etime),
357                                             ('rusage', data['rusage']),
358                                             ('iostat', data['iostat'])])
359        if save_bs:
360            self.save_buildstats(name)
361
362        self._append_measurement(measurement)
363
364        # Append to 'times' array for globalres log
365        e_sec = etime.total_seconds()
366        self.times.append('{:d}:{:02d}:{:05.2f}'.format(int(e_sec / 3600),
367                                                      int((e_sec % 3600) / 60),
368                                                       e_sec % 60))
369
370    def measure_disk_usage(self, path, name, legend, apparent_size=False):
371        """Estimate disk usage of a file or directory"""
372        cmd = ['du', '-s', '--block-size', '1024']
373        if apparent_size:
374            cmd.append('--apparent-size')
375        cmd.append(path)
376
377        ret = runCmd2(cmd)
378        size = int(ret.output.split()[0])
379        log.debug("Size of %s path is %s", path, size)
380        measurement = OrderedDict([('type', self.DISKUSAGE),
381                                   ('name', name),
382                                   ('legend', legend)])
383        measurement['values'] = OrderedDict([('size', size)])
384        self._append_measurement(measurement)
385        # Append to 'sizes' array for globalres log
386        self.sizes.append(str(size))
387
388    def save_buildstats(self, measurement_name):
389        """Save buildstats"""
390        def split_nevr(nevr):
391            """Split name and version information from recipe "nevr" string"""
392            n_e_v, revision = nevr.rsplit('-', 1)
393            match = re.match(r'^(?P<name>\S+)-((?P<epoch>[0-9]{1,5})_)?(?P<version>[0-9]\S*)$',
394                             n_e_v)
395            if not match:
396                # If we're not able to parse a version starting with a number, just
397                # take the part after last dash
398                match = re.match(r'^(?P<name>\S+)-((?P<epoch>[0-9]{1,5})_)?(?P<version>[^-]+)$',
399                                 n_e_v)
400            name = match.group('name')
401            version = match.group('version')
402            epoch = match.group('epoch')
403            return name, epoch, version, revision
404
405        def bs_to_json(filename):
406            """Convert (task) buildstats file into json format"""
407            bs_json = OrderedDict()
408            iostat = OrderedDict()
409            rusage = OrderedDict()
410            with open(filename) as fobj:
411                for line in fobj.readlines():
412                    key, val = line.split(':', 1)
413                    val = val.strip()
414                    if key == 'Started':
415                        start_time = datetime.utcfromtimestamp(float(val))
416                        bs_json['start_time'] = start_time
417                    elif key == 'Ended':
418                        end_time = datetime.utcfromtimestamp(float(val))
419                    elif key.startswith('IO '):
420                        split = key.split()
421                        iostat[split[1]] = int(val)
422                    elif key.find('rusage') >= 0:
423                        split = key.split()
424                        ru_key = split[-1]
425                        if ru_key in ('ru_stime', 'ru_utime'):
426                            val = float(val)
427                        else:
428                            val = int(val)
429                        rusage[ru_key] = rusage.get(ru_key, 0) + val
430                    elif key == 'Status':
431                        bs_json['status'] = val
432            bs_json['elapsed_time'] = end_time - start_time
433            bs_json['rusage'] = rusage
434            bs_json['iostat'] = iostat
435            return bs_json
436
437        log.info('Saving buildstats in JSON format')
438        bs_dirs = sorted(os.listdir(self.bb_vars['BUILDSTATS_BASE']))
439        if len(bs_dirs) > 1:
440            log.warning("Multiple buildstats found for test %s, only "
441                        "archiving the last one", self.name)
442        bs_dir = os.path.join(self.bb_vars['BUILDSTATS_BASE'], bs_dirs[-1])
443
444        buildstats = []
445        for fname in os.listdir(bs_dir):
446            recipe_dir = os.path.join(bs_dir, fname)
447            if not os.path.isdir(recipe_dir) or fname == "reduced_proc_pressure":
448                continue
449            name, epoch, version, revision = split_nevr(fname)
450            recipe_bs = OrderedDict((('name', name),
451                                     ('epoch', epoch),
452                                     ('version', version),
453                                     ('revision', revision),
454                                     ('tasks', OrderedDict())))
455            for task in os.listdir(recipe_dir):
456                recipe_bs['tasks'][task] = bs_to_json(os.path.join(recipe_dir,
457                                                                   task))
458            buildstats.append(recipe_bs)
459
460        self.buildstats[measurement_name] = buildstats
461
462    def rm_tmp(self):
463        """Cleanup temporary/intermediate files and directories"""
464        log.debug("Removing temporary and cache files")
465        for name in ['bitbake.lock', 'cache/sanity_info',
466                     self.bb_vars['TMPDIR']]:
467            oe.path.remove(name, recurse=True)
468
469    def rm_sstate(self):
470        """Remove sstate directory"""
471        log.debug("Removing sstate-cache")
472        oe.path.remove(self.bb_vars['SSTATE_DIR'], recurse=True)
473
474    def rm_cache(self):
475        """Drop bitbake caches"""
476        oe.path.remove(self.bb_vars['PERSISTENT_DIR'], recurse=True)
477
478    @staticmethod
479    def sync():
480        """Sync and drop kernel caches"""
481        runCmd2('bitbake -m', ignore_status=True)
482        log.debug("Syncing and dropping kernel caches""")
483        KernelDropCaches.drop()
484        os.sync()
485        # Wait a bit for all the dirty blocks to be written onto disk
486        time.sleep(3)
487
488
489class BuildPerfTestLoader(unittest.TestLoader):
490    """Test loader for build performance tests"""
491    sortTestMethodsUsing = None
492
493
494class BuildPerfTestRunner(unittest.TextTestRunner):
495    """Test loader for build performance tests"""
496    sortTestMethodsUsing = None
497
498    def __init__(self, out_dir, *args, **kwargs):
499        super(BuildPerfTestRunner, self).__init__(*args, **kwargs)
500        self.out_dir = out_dir
501
502    def _makeResult(self):
503        return BuildPerfTestResult(self.out_dir, self.stream, self.descriptions,
504                                   self.verbosity)
505