base.py 20 KB

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