buildstats-diff 21 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521522523524525526527528529530531532533534535536537538539540541542543544545546547548549550551552553554555556557558559560561562563564
  1. #!/usr/bin/python3
  2. #
  3. # Script for comparing buildstats from two different builds
  4. #
  5. # Copyright (c) 2016, Intel Corporation.
  6. #
  7. # This program is free software; you can redistribute it and/or modify it
  8. # under the terms and conditions of the GNU General Public License,
  9. # version 2, as published by the Free Software Foundation.
  10. #
  11. # This program is distributed in the hope it will be useful, but WITHOUT
  12. # ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
  13. # FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for
  14. # more details.
  15. #
  16. import argparse
  17. import glob
  18. import json
  19. import logging
  20. import math
  21. import os
  22. import re
  23. import sys
  24. from collections import namedtuple
  25. from datetime import datetime, timedelta, tzinfo
  26. from operator import attrgetter
  27. # Setup logging
  28. logging.basicConfig(level=logging.INFO, format="%(levelname)s: %(message)s")
  29. log = logging.getLogger()
  30. class ScriptError(Exception):
  31. """Exception for internal error handling of this script"""
  32. pass
  33. class TimeZone(tzinfo):
  34. """Simple fixed-offset tzinfo"""
  35. def __init__(self, seconds, name):
  36. self._offset = timedelta(seconds=seconds)
  37. self._name = name
  38. def utcoffset(self, dt):
  39. return self._offset
  40. def tzname(self, dt):
  41. return self._name
  42. def dst(self, dt):
  43. return None
  44. TIMEZONES = {'UTC': TimeZone(0, 'UTC'),
  45. 'EET': TimeZone(7200, 'EET'),
  46. 'EEST': TimeZone(10800, 'EEST')}
  47. taskdiff_fields = ('pkg', 'pkg_op', 'task', 'task_op', 'value1', 'value2',
  48. 'absdiff', 'reldiff')
  49. TaskDiff = namedtuple('TaskDiff', ' '.join(taskdiff_fields))
  50. def to_datetime_obj(obj):
  51. """Helper for getting timestamps in datetime format"""
  52. if isinstance(obj, datetime):
  53. return obj
  54. else:
  55. return datetime.utcfromtimestamp(obj).replace(tzinfo=TIMEZONES['UTC'])
  56. class BSTask(dict):
  57. def __init__(self, *args, **kwargs):
  58. self['start_time'] = None
  59. self['elapsed_time'] = None
  60. self['status'] = None
  61. self['iostat'] = {}
  62. self['rusage'] = {}
  63. self['child_rusage'] = {}
  64. super(BSTask, self).__init__(*args, **kwargs)
  65. @property
  66. def cputime(self):
  67. """Sum of user and system time taken by the task"""
  68. return self['rusage']['ru_stime'] + self['rusage']['ru_utime'] + \
  69. self['child_rusage']['ru_stime'] + self['child_rusage']['ru_utime']
  70. @property
  71. def walltime(self):
  72. """Elapsed wall clock time"""
  73. return self['elapsed_time'].total_seconds()
  74. @property
  75. def read_bytes(self):
  76. """Bytes read from the block layer"""
  77. return self['iostat']['read_bytes']
  78. @property
  79. def write_bytes(self):
  80. """Bytes written to the block layer"""
  81. return self['iostat']['write_bytes']
  82. @property
  83. def read_ops(self):
  84. """Number of read operations on the block layer"""
  85. return self['rusage']['ru_inblock'] + self['child_rusage']['ru_inblock']
  86. @property
  87. def write_ops(self):
  88. """Number of write operations on the block layer"""
  89. return self['rusage']['ru_oublock'] + self['child_rusage']['ru_oublock']
  90. def read_buildstats_file(buildstat_file):
  91. """Convert buildstat text file into dict/json"""
  92. bs_task = BSTask()
  93. log.debug("Reading task buildstats from %s", buildstat_file)
  94. with open(buildstat_file) as fobj:
  95. for line in fobj.readlines():
  96. key, val = line.split(':', 1)
  97. val = val.strip()
  98. if key == 'Started':
  99. start_time = to_datetime_obj(float(val))
  100. bs_task['start_time'] = start_time
  101. elif key == 'Ended':
  102. end_time = to_datetime_obj(float(val))
  103. elif key.startswith('IO '):
  104. split = key.split()
  105. bs_task['iostat'][split[1]] = int(val)
  106. elif key.find('rusage') >= 0:
  107. split = key.split()
  108. ru_key = split[-1]
  109. if ru_key in ('ru_stime', 'ru_utime'):
  110. val = float(val)
  111. else:
  112. val = int(val)
  113. ru_type = 'rusage' if split[0] == 'rusage' else \
  114. 'child_rusage'
  115. bs_task[ru_type][ru_key] = val
  116. elif key == 'Status':
  117. bs_task['status'] = val
  118. bs_task['elapsed_time'] = end_time - start_time
  119. return bs_task
  120. def read_buildstats_dir(bs_dir):
  121. """Read buildstats directory"""
  122. def split_nevr(nevr):
  123. """Split name and version information from recipe "nevr" string"""
  124. n_e_v, revision = nevr.rsplit('-', 1)
  125. match = re.match(r'^(?P<name>\S+)-((?P<epoch>[0-9]{1,5})_)?(?P<version>[0-9]\S*)$',
  126. n_e_v)
  127. if not match:
  128. # If we're not able to parse a version starting with a number, just
  129. # take the part after last dash
  130. match = re.match(r'^(?P<name>\S+)-((?P<epoch>[0-9]{1,5})_)?(?P<version>[^-]+)$',
  131. n_e_v)
  132. name = match.group('name')
  133. version = match.group('version')
  134. epoch = match.group('epoch')
  135. return name, epoch, version, revision
  136. if not os.path.isfile(os.path.join(bs_dir, 'build_stats')):
  137. raise ScriptError("{} does not look like a buildstats directory".format(bs_dir))
  138. log.debug("Reading buildstats directory %s", bs_dir)
  139. buildstats = {}
  140. subdirs = os.listdir(bs_dir)
  141. for dirname in subdirs:
  142. recipe_dir = os.path.join(bs_dir, dirname)
  143. if not os.path.isdir(recipe_dir):
  144. continue
  145. name, epoch, version, revision = split_nevr(dirname)
  146. recipe_bs = {'nevr': dirname,
  147. 'name': name,
  148. 'epoch': epoch,
  149. 'version': version,
  150. 'revision': revision,
  151. 'tasks': {}}
  152. for task in os.listdir(recipe_dir):
  153. recipe_bs['tasks'][task] = [read_buildstats_file(
  154. os.path.join(recipe_dir, task))]
  155. if name in buildstats:
  156. raise ScriptError("Cannot handle multiple versions of the same "
  157. "package ({})".format(name))
  158. buildstats[name] = recipe_bs
  159. return buildstats
  160. def bs_append(dst, src):
  161. """Append data from another buildstats"""
  162. if set(dst.keys()) != set(src.keys()):
  163. raise ScriptError("Refusing to join buildstats, set of packages is "
  164. "different")
  165. for pkg, data in dst.items():
  166. if data['nevr'] != src[pkg]['nevr']:
  167. raise ScriptError("Refusing to join buildstats, package version "
  168. "differs: {} vs. {}".format(data['nevr'], src[pkg]['nevr']))
  169. if set(data['tasks'].keys()) != set(src[pkg]['tasks'].keys()):
  170. raise ScriptError("Refusing to join buildstats, set of tasks "
  171. "in {} differ".format(pkg))
  172. for taskname, taskdata in data['tasks'].items():
  173. taskdata.extend(src[pkg]['tasks'][taskname])
  174. def read_buildstats_json(path):
  175. """Read buildstats from JSON file"""
  176. buildstats = {}
  177. with open(path) as fobj:
  178. bs_json = json.load(fobj)
  179. for recipe_bs in bs_json:
  180. if recipe_bs['name'] in buildstats:
  181. raise ScriptError("Cannot handle multiple versions of the same "
  182. "package ({})".format(recipe_bs['name']))
  183. if recipe_bs['epoch'] is None:
  184. recipe_bs['nevr'] = "{}-{}-{}".format(recipe_bs['name'], recipe_bs['version'], recipe_bs['revision'])
  185. else:
  186. recipe_bs['nevr'] = "{}-{}_{}-{}".format(recipe_bs['name'], recipe_bs['epoch'], recipe_bs['version'], recipe_bs['revision'])
  187. for task, data in recipe_bs['tasks'].copy().items():
  188. recipe_bs['tasks'][task] = [BSTask(data)]
  189. buildstats[recipe_bs['name']] = recipe_bs
  190. return buildstats
  191. def read_buildstats(path, multi):
  192. """Read buildstats"""
  193. if not os.path.exists(path):
  194. raise ScriptError("No such file or directory: {}".format(path))
  195. if os.path.isfile(path):
  196. return read_buildstats_json(path)
  197. if os.path.isfile(os.path.join(path, 'build_stats')):
  198. return read_buildstats_dir(path)
  199. # Handle a non-buildstat directory
  200. subpaths = sorted(glob.glob(path + '/*'))
  201. if len(subpaths) > 1:
  202. if multi:
  203. log.info("Averaging over {} buildstats from {}".format(
  204. len(subpaths), path))
  205. else:
  206. raise ScriptError("Multiple buildstats found in '{}'. Please give "
  207. "a single buildstat directory of use the --multi "
  208. "option".format(path))
  209. bs = None
  210. for subpath in subpaths:
  211. if os.path.isfile(subpath):
  212. tmpbs = read_buildstats_json(subpath)
  213. else:
  214. tmpbs = read_buildstats_dir(subpath)
  215. if not bs:
  216. bs = tmpbs
  217. else:
  218. log.debug("Joining buildstats")
  219. bs_append(bs, tmpbs)
  220. if not bs:
  221. raise ScriptError("No buildstats found under {}".format(path))
  222. return bs
  223. def print_ver_diff(bs1, bs2):
  224. """Print package version differences"""
  225. pkgs1 = set(bs1.keys())
  226. pkgs2 = set(bs2.keys())
  227. new_pkgs = pkgs2 - pkgs1
  228. deleted_pkgs = pkgs1 - pkgs2
  229. echanged = []
  230. vchanged = []
  231. rchanged = []
  232. unchanged = []
  233. common_pkgs = pkgs2.intersection(pkgs1)
  234. if common_pkgs:
  235. for pkg in common_pkgs:
  236. if bs1[pkg]['epoch'] != bs2[pkg]['epoch']:
  237. echanged.append(pkg)
  238. elif bs1[pkg]['version'] != bs2[pkg]['version']:
  239. vchanged.append(pkg)
  240. elif bs1[pkg]['revision'] != bs2[pkg]['revision']:
  241. rchanged.append(pkg)
  242. else:
  243. unchanged.append(pkg)
  244. maxlen = max([len(pkg) for pkg in pkgs1.union(pkgs2)])
  245. fmt_str = " {:{maxlen}} ({})"
  246. # if unchanged:
  247. # print("\nUNCHANGED PACKAGES:")
  248. # print("-------------------")
  249. # maxlen = max([len(pkg) for pkg in unchanged])
  250. # for pkg in sorted(unchanged):
  251. # print(fmt_str.format(pkg, bs2[pkg]['nevr'], maxlen=maxlen))
  252. if new_pkgs:
  253. print("\nNEW PACKAGES:")
  254. print("-------------")
  255. for pkg in sorted(new_pkgs):
  256. print(fmt_str.format(pkg, bs2[pkg]['nevr'], maxlen=maxlen))
  257. if deleted_pkgs:
  258. print("\nDELETED PACKAGES:")
  259. print("-----------------")
  260. for pkg in sorted(deleted_pkgs):
  261. print(fmt_str.format(pkg, bs1[pkg]['nevr'], maxlen=maxlen))
  262. fmt_str = " {0:{maxlen}} {1:<20} ({2})"
  263. if rchanged:
  264. print("\nREVISION CHANGED:")
  265. print("-----------------")
  266. for pkg in sorted(rchanged):
  267. field1 = "{} -> {}".format(pkg, bs1[pkg]['revision'], bs2[pkg]['revision'])
  268. field2 = "{} -> {}".format(bs1[pkg]['nevr'], bs2[pkg]['nevr'])
  269. print(fmt_str.format(pkg, field1, field2, maxlen=maxlen))
  270. if vchanged:
  271. print("\nVERSION CHANGED:")
  272. print("----------------")
  273. for pkg in sorted(vchanged):
  274. field1 = "{} -> {}".format(bs1[pkg]['version'], bs2[pkg]['version'])
  275. field2 = "{} -> {}".format(bs1[pkg]['nevr'], bs2[pkg]['nevr'])
  276. print(fmt_str.format(pkg, field1, field2, maxlen=maxlen))
  277. if echanged:
  278. print("\nEPOCH CHANGED:")
  279. print("--------------")
  280. for pkg in sorted(echanged):
  281. field1 = "{} -> {}".format(pkg, bs1[pkg]['epoch'], bs2[pkg]['epoch'])
  282. field2 = "{} -> {}".format(bs1[pkg]['nevr'], bs2[pkg]['nevr'])
  283. print(fmt_str.format(pkg, field1, field2, maxlen=maxlen))
  284. def print_task_diff(bs1, bs2, val_type, min_val=0, min_absdiff=0, sort_by=('absdiff',)):
  285. """Diff task execution times"""
  286. def val_to_str(val, human_readable=False):
  287. """Convert raw value to printable string"""
  288. def hms_time(secs):
  289. """Get time in human-readable HH:MM:SS format"""
  290. h = int(secs / 3600)
  291. m = int((secs % 3600) / 60)
  292. s = secs % 60
  293. if h == 0:
  294. return "{:02d}:{:04.1f}".format(m, s)
  295. else:
  296. return "{:d}:{:02d}:{:04.1f}".format(h, m, s)
  297. if 'time' in val_type:
  298. if human_readable:
  299. return hms_time(val)
  300. else:
  301. return "{:.1f}s".format(val)
  302. elif 'bytes' in val_type and human_readable:
  303. prefix = ['', 'Ki', 'Mi', 'Gi', 'Ti', 'Pi']
  304. dec = int(math.log(val, 2) / 10)
  305. prec = 1 if dec > 0 else 0
  306. return "{:.{prec}f}{}B".format(val / (2 ** (10 * dec)),
  307. prefix[dec], prec=prec)
  308. elif 'ops' in val_type and human_readable:
  309. prefix = ['', 'k', 'M', 'G', 'T', 'P']
  310. dec = int(math.log(val, 1000))
  311. prec = 1 if dec > 0 else 0
  312. return "{:.{prec}f}{}ops".format(val / (1000 ** dec),
  313. prefix[dec], prec=prec)
  314. return str(int(val))
  315. def sum_vals(buildstats):
  316. """Get cumulative sum of all tasks"""
  317. total = 0.0
  318. for recipe_data in buildstats.values():
  319. for bs_task in recipe_data['tasks'].values():
  320. total += sum([getattr(b, val_type) for b in bs_task]) / len(bs_task)
  321. return total
  322. tasks_diff = []
  323. if min_val:
  324. print("Ignoring tasks less than {} ({})".format(
  325. val_to_str(min_val, True), val_to_str(min_val)))
  326. if min_absdiff:
  327. print("Ignoring differences less than {} ({})".format(
  328. val_to_str(min_absdiff, True), val_to_str(min_absdiff)))
  329. # Prepare the data
  330. pkgs = set(bs1.keys()).union(set(bs2.keys()))
  331. for pkg in pkgs:
  332. tasks1 = bs1[pkg]['tasks'] if pkg in bs1 else {}
  333. tasks2 = bs2[pkg]['tasks'] if pkg in bs2 else {}
  334. if not tasks1:
  335. pkg_op = '+ '
  336. elif not tasks2:
  337. pkg_op = '- '
  338. else:
  339. pkg_op = ' '
  340. for task in set(tasks1.keys()).union(set(tasks2.keys())):
  341. task_op = ' '
  342. if task in tasks1:
  343. # Average over all values
  344. val1 = [getattr(b, val_type) for b in bs1[pkg]['tasks'][task]]
  345. val1 = sum(val1) / len(val1)
  346. else:
  347. task_op = '+ '
  348. val1 = 0
  349. if task in tasks2:
  350. # Average over all values
  351. val2 = [getattr(b, val_type) for b in bs2[pkg]['tasks'][task]]
  352. val2 = sum(val2) / len(val2)
  353. else:
  354. val2 = 0
  355. task_op = '- '
  356. if val1 == 0:
  357. reldiff = float('inf')
  358. else:
  359. reldiff = 100 * (val2 - val1) / val1
  360. if max(val1, val2) < min_val:
  361. log.debug("Filtering out %s:%s (%s)", pkg, task,
  362. val_to_str(max(val1, val2)))
  363. continue
  364. if abs(val2 - val1) < min_absdiff:
  365. log.debug("Filtering out %s:%s (difference of %s)", pkg, task,
  366. val_to_str(val2-val1))
  367. continue
  368. tasks_diff.append(TaskDiff(pkg, pkg_op, task, task_op, val1, val2,
  369. val2-val1, reldiff))
  370. # Sort our list
  371. for field in reversed(sort_by):
  372. if field.startswith('-'):
  373. field = field[1:]
  374. reverse = True
  375. else:
  376. reverse = False
  377. tasks_diff = sorted(tasks_diff, key=attrgetter(field), reverse=reverse)
  378. linedata = [(' ', 'PKG', ' ', 'TASK', 'ABSDIFF', 'RELDIFF',
  379. val_type.upper() + '1', val_type.upper() + '2')]
  380. field_lens = dict([('len_{}'.format(i), len(f)) for i, f in enumerate(linedata[0])])
  381. # Prepare fields in string format and measure field lengths
  382. for diff in tasks_diff:
  383. task_prefix = diff.task_op if diff.pkg_op == ' ' else ' '
  384. linedata.append((diff.pkg_op, diff.pkg, task_prefix, diff.task,
  385. val_to_str(diff.absdiff),
  386. '{:+.1f}%'.format(diff.reldiff),
  387. val_to_str(diff.value1),
  388. val_to_str(diff.value2)))
  389. for i, field in enumerate(linedata[-1]):
  390. key = 'len_{}'.format(i)
  391. if len(field) > field_lens[key]:
  392. field_lens[key] = len(field)
  393. # Print data
  394. print()
  395. for fields in linedata:
  396. print("{:{len_0}}{:{len_1}} {:{len_2}}{:{len_3}} {:>{len_4}} {:>{len_5}} {:>{len_6}} -> {:{len_7}}".format(
  397. *fields, **field_lens))
  398. # Print summary of the diffs
  399. total1 = sum_vals(bs1)
  400. total2 = sum_vals(bs2)
  401. print("\nCumulative {}:".format(val_type))
  402. print (" {} {:+.1f}% {} ({}) -> {} ({})".format(
  403. val_to_str(total2 - total1), 100 * (total2-total1) / total1,
  404. val_to_str(total1, True), val_to_str(total1),
  405. val_to_str(total2, True), val_to_str(total2)))
  406. def parse_args(argv):
  407. """Parse cmdline arguments"""
  408. description="""
  409. Script for comparing buildstats of two separate builds."""
  410. parser = argparse.ArgumentParser(
  411. formatter_class=argparse.ArgumentDefaultsHelpFormatter,
  412. description=description)
  413. min_val_defaults = {'cputime': 3.0,
  414. 'read_bytes': 524288,
  415. 'write_bytes': 524288,
  416. 'read_ops': 500,
  417. 'write_ops': 500,
  418. 'walltime': 5}
  419. min_absdiff_defaults = {'cputime': 1.0,
  420. 'read_bytes': 131072,
  421. 'write_bytes': 131072,
  422. 'read_ops': 50,
  423. 'write_ops': 50,
  424. 'walltime': 2}
  425. parser.add_argument('--debug', '-d', action='store_true',
  426. help="Verbose logging")
  427. parser.add_argument('--ver-diff', action='store_true',
  428. help="Show package version differences and exit")
  429. parser.add_argument('--diff-attr', default='cputime',
  430. choices=min_val_defaults.keys(),
  431. help="Buildstat attribute which to compare")
  432. parser.add_argument('--min-val', default=min_val_defaults, type=float,
  433. help="Filter out tasks less than MIN_VAL. "
  434. "Default depends on --diff-attr.")
  435. parser.add_argument('--min-absdiff', default=min_absdiff_defaults, type=float,
  436. help="Filter out tasks whose difference is less than "
  437. "MIN_ABSDIFF, Default depends on --diff-attr.")
  438. parser.add_argument('--sort-by', default='absdiff',
  439. help="Comma-separated list of field sort order. "
  440. "Prepend the field name with '-' for reversed sort. "
  441. "Available fields are: {}".format(', '.join(taskdiff_fields)))
  442. parser.add_argument('--multi', action='store_true',
  443. help="Read all buildstats from the given paths and "
  444. "average over them")
  445. parser.add_argument('buildstats1', metavar='BUILDSTATS1', help="'Left' buildstat")
  446. parser.add_argument('buildstats2', metavar='BUILDSTATS2', help="'Right' buildstat")
  447. args = parser.parse_args(argv)
  448. # We do not nedd/want to read all buildstats if we just want to look at the
  449. # package versions
  450. if args.ver_diff:
  451. args.multi = False
  452. # Handle defaults for the filter arguments
  453. if args.min_val is min_val_defaults:
  454. args.min_val = min_val_defaults[args.diff_attr]
  455. if args.min_absdiff is min_absdiff_defaults:
  456. args.min_absdiff = min_absdiff_defaults[args.diff_attr]
  457. return args
  458. def main(argv=None):
  459. """Script entry point"""
  460. args = parse_args(argv)
  461. if args.debug:
  462. log.setLevel(logging.DEBUG)
  463. # Validate sort fields
  464. sort_by = []
  465. for field in args.sort_by.split(','):
  466. if field.lstrip('-') not in taskdiff_fields:
  467. log.error("Invalid sort field '%s' (must be one of: %s)" %
  468. (field, ', '.join(taskdiff_fields)))
  469. sys.exit(1)
  470. sort_by.append(field)
  471. try:
  472. bs1 = read_buildstats(args.buildstats1, args.multi)
  473. bs2 = read_buildstats(args.buildstats2, args.multi)
  474. if args.ver_diff:
  475. print_ver_diff(bs1, bs2)
  476. else:
  477. print_task_diff(bs1, bs2, args.diff_attr, args.min_val,
  478. args.min_absdiff, sort_by)
  479. except ScriptError as err:
  480. log.error(str(err))
  481. return 1
  482. return 0
  483. if __name__ == "__main__":
  484. sys.exit(main())