From 3e9fc8d0916f1d51dd6b748fff966d8aafd7f438 Mon Sep 17 00:00:00 2001 From: Alexandru DAMIAN Date: Tue, 4 Nov 2014 16:47:36 +0000 Subject: [PATCH] bitbake: toasterui: performance improvements Improve the performance of data logging in toasterui. We modify the data queries used to: * cache searching in memory * insert in bulk (i.e. multiple values per insert, where possible) On development test rig (networked mysql), on no-op build, time for data recording is reduced from 4:10 to 1:30 (minutes). We also improve the logging, so it is easier to detect toasterui errors. (Bitbake rev: d42784432f927f58730caf80546c66772e0fec89) Signed-off-by: Alexandru DAMIAN Signed-off-by: Richard Purdie --- bitbake/lib/bb/ui/buildinfohelper.py | 207 +++++++++++++++++++-------- bitbake/lib/bb/ui/toasterui.py | 10 +- 2 files changed, 156 insertions(+), 61 deletions(-) diff --git a/bitbake/lib/bb/ui/buildinfohelper.py b/bitbake/lib/bb/ui/buildinfohelper.py index b5ae9e97b2..a907a0337b 100644 --- a/bitbake/lib/bb/ui/buildinfohelper.py +++ b/bitbake/lib/bb/ui/buildinfohelper.py @@ -32,6 +32,7 @@ from toaster.orm.models import Package, Package_File, Target_Installed_Package, from toaster.orm.models import Task_Dependency, Package_Dependency from toaster.orm.models import Recipe_Dependency from bb.msg import BBLogFormatter as format +from django.db import models class NotExisting(Exception): pass @@ -43,8 +44,57 @@ class ORMWrapper(object): """ def __init__(self): + self.layer_version_objects = [] + self.task_objects = {} + self.recipe_objects = {} pass + @staticmethod + def _build_key(**kwargs): + key = "0" + for k in sorted(kwargs.keys()): + if isinstance(kwargs[k], models.Model): + key += "-%d" % kwargs[k].id + else: + key += "-%s" % str(kwargs[k]) + return key + + + def _cached_get_or_create(self, clazz, **kwargs): + """ This is a memory-cached get_or_create. We assume that the objects will not be created in the + database through any other means. + """ + + assert issubclass(clazz, models.Model), "_cached_get_or_create needs to get the class as first argument" + + key = ORMWrapper._build_key(**kwargs) + dictname = "objects_%s" % clazz.__name__ + if not dictname in vars(self).keys(): + vars(self)[dictname] = {} + + created = False + if not key in vars(self)[dictname].keys(): + vars(self)[dictname][key] = clazz.objects.create(**kwargs) + created = True + + return (vars(self)[dictname][key], created) + + + def _cached_get(self, clazz, **kwargs): + """ This is a memory-cached get. We assume that the objects will not change in the database between gets. + """ + assert issubclass(clazz, models.Model), "_cached_get needs to get the class as first argument" + + key = ORMWrapper._build_key(**kwargs) + dictname = "objects_%s" % clazz.__name__ + + if not dictname in vars(self).keys(): + vars(self)[dictname] = {} + + if not key in vars(self)[dictname].keys(): + vars(self)[dictname][key] = clazz.objects.get(**kwargs) + + return vars(self)[dictname][key] def create_build_object(self, build_info, brbe): assert 'machine' in build_info @@ -87,7 +137,7 @@ class ORMWrapper(object): tgt_object = Target.objects.create( build = target_info['build'], target = tgt_name, is_image = False, - ); + ) targets.append(tgt_object) return targets @@ -117,41 +167,47 @@ class ORMWrapper(object): assert 'recipe' in task_information assert 'task_name' in task_information - task_object, created = Task.objects.get_or_create( - build=task_information['build'], - recipe=task_information['recipe'], - task_name=task_information['task_name'], - ) - - if must_exist and created: - task_information['debug'] = "build id %d, recipe id %d" % (task_information['build'].pk, task_information['recipe'].pk) - task_object.delete() - raise NotExisting("Task object created when expected to exist", task_information) + # we use must_exist info for database look-up optimization + task_object, created = self._cached_get_or_create(Task, + build=task_information['build'], + recipe=task_information['recipe'], + task_name=task_information['task_name'] + ) + if created and must_exist: + task_information['debug'] = "build id %d, recipe id %d" % (task_information['build'].pk, task_information['recipe'].pk) + raise NotExisting("Task object created when expected to exist", task_information) + object_changed = False for v in vars(task_object): if v in task_information.keys(): - vars(task_object)[v] = task_information[v] + if vars(task_object)[v] != task_information[v]: + vars(task_object)[v] = task_information[v] + object_changed = True - # update setscene-related information - if 1 == Task.objects.related_setscene(task_object).count(): - if task_object.outcome == Task.OUTCOME_COVERED: - task_object.outcome = Task.OUTCOME_CACHED + # update setscene-related information if the task was just created + if created and task_object.outcome == Task.OUTCOME_COVERED and 1 == Task.objects.related_setscene(task_object).count(): + task_object.outcome = Task.OUTCOME_CACHED + object_changed = True outcome_task_setscene = Task.objects.get(task_executed=True, build = task_object.build, recipe = task_object.recipe, task_name=task_object.task_name+"_setscene").outcome if outcome_task_setscene == Task.OUTCOME_SUCCESS: task_object.sstate_result = Task.SSTATE_RESTORED + object_changed = True elif outcome_task_setscene == Task.OUTCOME_FAILED: task_object.sstate_result = Task.SSTATE_FAILED + object_changed = True # mark down duration if we have a start time and a current time if 'start_time' in task_information.keys() and 'end_time' in task_information.keys(): duration = task_information['end_time'] - task_information['start_time'] task_object.elapsed_time = duration + object_changed = True del task_information['start_time'] del task_information['end_time'] - task_object.save() + if object_changed: + task_object.save() return task_object @@ -159,20 +215,19 @@ class ORMWrapper(object): assert 'layer_version' in recipe_information assert 'file_path' in recipe_information - - recipe_object, created = Recipe.objects.get_or_create( - layer_version=recipe_information['layer_version'], - file_path=recipe_information['file_path']) - - if must_exist and created: - recipe_object.delete() + recipe_object, created = self._cached_get_or_create(Recipe, layer_version=recipe_information['layer_version'], + file_path=recipe_information['file_path']) + if created and must_exist: raise NotExisting("Recipe object created when expected to exist", recipe_information) + object_changed = False for v in vars(recipe_object): if v in recipe_information.keys(): + object_changed = True vars(recipe_object)[v] = recipe_information[v] - recipe_object.save() + if object_changed: + recipe_object.save() return recipe_object @@ -191,6 +246,8 @@ class ORMWrapper(object): priority = layer_version_information['priority'] ) + self.layer_version_objects.append(layer_version_object) + return layer_version_object def get_update_layer_object(self, layer_information): @@ -235,7 +292,7 @@ class ORMWrapper(object): parent_path = "/".join(path.split("/")[:len(path.split("/")) - 1]) if len(parent_path) == 0: parent_path = "/" - parent_obj = Target_File.objects.get(target = target_obj, path = parent_path, inodetype = Target_File.ITYPE_DIRECTORY) + parent_obj = self._cached_get(Target_File, target = target_obj, path = parent_path, inodetype = Target_File.ITYPE_DIRECTORY) tf_obj = Target_File.objects.create( target = target_obj, path = path, @@ -269,7 +326,7 @@ class ORMWrapper(object): permission = permission, owner = user, group = group) - parent_obj = Target_File.objects.get(target = target_obj, path = parent_path, inodetype = Target_File.ITYPE_DIRECTORY) + parent_obj = self._cached_get(Target_File, target = target_obj, path = parent_path, inodetype = Target_File.ITYPE_DIRECTORY) tf_obj.directory = parent_obj tf_obj.save() @@ -324,7 +381,7 @@ class ORMWrapper(object): searchname = pkgpnmap[p]['OPKGN'] packagedict[p]['object'], created = Package.objects.get_or_create( build = build_obj, name = searchname ) - if True: # save the data anyway we can, not just if it was not created here; bug [YOCTO #6887] + if created or package[p]['object'].size == -1: # save the data anyway we can, not just if it was not created here; bug [YOCTO #6887] # fill in everything we can from the runtime-reverse package data try: packagedict[p]['object'].recipe = recipes[pkgpnmap[p]['PN']] @@ -338,11 +395,14 @@ class ORMWrapper(object): packagedict[p]['object'].size = int(pkgpnmap[p]['PKGSIZE']) # no files recorded for this package, so save files info + packagefile_objects = [] for targetpath in pkgpnmap[p]['FILES_INFO']: targetfilesize = pkgpnmap[p]['FILES_INFO'][targetpath] - Package_File.objects.create( package = packagedict[p]['object'], + packagefile_objects.append(Package_File( package = packagedict[p]['object'], path = targetpath, - size = targetfilesize) + size = targetfilesize)) + if len(packagefile_objects): + Package_File.objects.bulk_create(packagefile_objects) except KeyError as e: errormsg += " stpi: Key error, package %s key %s \n" % ( p, e ) @@ -352,6 +412,7 @@ class ORMWrapper(object): Target_Installed_Package.objects.create(target = target_obj, package = packagedict[p]['object']) + packagedeps_objs = [] for p in packagedict: for (px,deptype) in packagedict[p]['depends']: if deptype == 'depends': @@ -359,10 +420,13 @@ class ORMWrapper(object): elif deptype == 'recommends': tdeptype = Package_Dependency.TYPE_TRECOMMENDS - Package_Dependency.objects.create( package = packagedict[p]['object'], + packagedeps_objs.append(Package_Dependency( package = packagedict[p]['object'], depends_on = packagedict[px]['object'], dep_type = tdeptype, - target = target_obj); + target = target_obj)) + + if len(packagedeps_objs) > 0: + Package_Dependency.objects.bulk_create(packagedeps_objs) if (len(errormsg) > 0): raise Exception(errormsg) @@ -398,7 +462,7 @@ class ORMWrapper(object): if 'OPKGN' in package_info.keys(): pname = package_info['OPKGN'] - bp_object, created = Package.objects.get_or_create( build = build_obj, + bp_object = Package.objects.create( build = build_obj, name = pname ) bp_object.installed_name = package_info['PKG'] @@ -413,10 +477,13 @@ class ORMWrapper(object): bp_object.save() # save any attached file information + packagefile_objects = [] for path in package_info['FILES_INFO']: - fo = Package_File.objects.create( package = bp_object, + packagefile_objects.append(Package_File( package = bp_object, path = path, - size = package_info['FILES_INFO'][path] ) + size = package_info['FILES_INFO'][path] )) + if len(packagefile_objects): + Package_File.objects.bulk_create(packagefile_objects) def _po_byname(p): pkg, created = Package.objects.get_or_create(build = build_obj, name = p) @@ -425,39 +492,45 @@ class ORMWrapper(object): pkg.save() return pkg + packagedeps_objs = [] # save soft dependency information if 'RDEPENDS' in package_info and package_info['RDEPENDS']: for p in bb.utils.explode_deps(package_info['RDEPENDS']): - Package_Dependency.objects.get_or_create( package = bp_object, - depends_on = _po_byname(p), dep_type = Package_Dependency.TYPE_RDEPENDS) + packagedeps_objs.append(Package_Dependency( package = bp_object, + depends_on = _po_byname(p), dep_type = Package_Dependency.TYPE_RDEPENDS)) if 'RPROVIDES' in package_info and package_info['RPROVIDES']: for p in bb.utils.explode_deps(package_info['RPROVIDES']): - Package_Dependency.objects.get_or_create( package = bp_object, - depends_on = _po_byname(p), dep_type = Package_Dependency.TYPE_RPROVIDES) + packagedeps_objs.append(Package_Dependency( package = bp_object, + depends_on = _po_byname(p), dep_type = Package_Dependency.TYPE_RPROVIDES)) if 'RRECOMMENDS' in package_info and package_info['RRECOMMENDS']: for p in bb.utils.explode_deps(package_info['RRECOMMENDS']): - Package_Dependency.objects.get_or_create( package = bp_object, - depends_on = _po_byname(p), dep_type = Package_Dependency.TYPE_RRECOMMENDS) + packagedeps_objs.append(Package_Dependency( package = bp_object, + depends_on = _po_byname(p), dep_type = Package_Dependency.TYPE_RRECOMMENDS)) if 'RSUGGESTS' in package_info and package_info['RSUGGESTS']: for p in bb.utils.explode_deps(package_info['RSUGGESTS']): - Package_Dependency.objects.get_or_create( package = bp_object, - depends_on = _po_byname(p), dep_type = Package_Dependency.TYPE_RSUGGESTS) + packagedeps_objs.append(Package_Dependency( package = bp_object, + depends_on = _po_byname(p), dep_type = Package_Dependency.TYPE_RSUGGESTS)) if 'RREPLACES' in package_info and package_info['RREPLACES']: for p in bb.utils.explode_deps(package_info['RREPLACES']): - Package_Dependency.objects.get_or_create( package = bp_object, - depends_on = _po_byname(p), dep_type = Package_Dependency.TYPE_RREPLACES) + packagedeps_objs.append(Package_Dependency( package = bp_object, + depends_on = _po_byname(p), dep_type = Package_Dependency.TYPE_RREPLACES)) if 'RCONFLICTS' in package_info and package_info['RCONFLICTS']: for p in bb.utils.explode_deps(package_info['RCONFLICTS']): - Package_Dependency.objects.get_or_create( package = bp_object, - depends_on = _po_byname(p), dep_type = Package_Dependency.TYPE_RCONFLICTS) + packagedeps_objs.append(Package_Dependency( package = bp_object, + depends_on = _po_byname(p), dep_type = Package_Dependency.TYPE_RCONFLICTS)) + + if len(packagedeps_objs) > 0: + Package_Dependency.objects.bulk_create(packagedeps_objs) return bp_object def save_build_variables(self, build_obj, vardump): assert isinstance(build_obj, Build) + helptext_objects = [] + for k in vardump: - desc = vardump[k]['doc']; + desc = vardump[k]['doc'] if desc is None: var_words = [word for word in k.split('_')] root_var = "_".join([word for word in var_words if word.isupper()]) @@ -465,25 +538,31 @@ class ORMWrapper(object): desc = vardump[root_var]['doc'] if desc is None: desc = '' - if desc: - helptext_obj = HelpText.objects.create(build=build_obj, + if len(desc): + helptext_objects.append(HelpText(build=build_obj, area=HelpText.VARIABLE, key=k, - text=desc) + text=desc)) if not bool(vardump[k]['func']): - value = vardump[k]['v']; + value = vardump[k]['v'] if value is None: value = '' variable_obj = Variable.objects.create( build = build_obj, variable_name = k, variable_value = value, description = desc) + + varhist_objects = [] for vh in vardump[k]['history']: if not 'documentation.conf' in vh['file']: - VariableHistory.objects.create( variable = variable_obj, + varhist_objects.append(VariableHistory( variable = variable_obj, file_name = vh['file'], line_number = vh['line'], - operation = vh['op']) + operation = vh['op'])) + if len(varhist_objects): + VariableHistory.objects.bulk_create(varhist_objects) + + HelpText.objects.bulk_create(helptext_objects) class MockEvent: pass # sometimes we mock an event, declare it here @@ -555,7 +634,7 @@ class BuildInfoHelper(object): # Heuristics: we always match recipe to the deepest layer path that # we can match to the recipe file path - for bl in sorted(Layer_Version.objects.filter(build = self.internal_state['build']), reverse=True, key=_slkey): + for bl in sorted(self.orm_wrapper.layer_version_objects, reverse=True, key=_slkey): if (path.startswith(bl.layer.local_path)): return bl @@ -615,6 +694,7 @@ class BuildInfoHelper(object): def store_started_build(self, event): assert '_pkgs' in vars(event) + assert 'lvs' in self.internal_state, "Layer version information not found; Check if the bitbake server was configured to inherit toaster.bbclass." build_information = self._get_build_information() build_obj = self.orm_wrapper.create_build_object(build_information, self.brbe) @@ -885,20 +965,22 @@ class BuildInfoHelper(object): # save recipe dependency # buildtime + recipedeps_objects = [] for recipe in event._depgraph['depends']: try: target = self.internal_state['recipes'][recipe] for dep in event._depgraph['depends'][recipe]: dependency = self.internal_state['recipes'][dep] - Recipe_Dependency.objects.get_or_create( recipe = target, - depends_on = dependency, dep_type = Recipe_Dependency.TYPE_DEPENDS) + recipedeps_objects.append(Recipe_Dependency( recipe = target, + depends_on = dependency, dep_type = Recipe_Dependency.TYPE_DEPENDS)) except KeyError as e: if e not in assume_provided and not str(e).startswith("virtual/"): errormsg += " stpd: KeyError saving recipe dependency for %s, %s \n" % (recipe, e) + Recipe_Dependency.objects.bulk_create(recipedeps_objects) # save all task information def _save_a_task(taskdesc): - spec = re.split(r'\.', taskdesc); + spec = re.split(r'\.', taskdesc) pn = ".".join(spec[0:-1]) taskname = spec[-1] e = event @@ -915,6 +997,7 @@ class BuildInfoHelper(object): tasks[taskdesc] = _save_a_task(taskdesc) # create dependencies between tasks + taskdeps_objects = [] for taskdesc in event._depgraph['tdepends']: target = tasks[taskdesc] for taskdep in event._depgraph['tdepends'][taskdesc]: @@ -923,7 +1006,8 @@ class BuildInfoHelper(object): dep = _save_a_task(taskdep) else: dep = tasks[taskdep] - Task_Dependency.objects.get_or_create( task = target, depends_on = dep ) + taskdeps_objects.append(Task_Dependency( task = target, depends_on = dep )) + Task_Dependency.objects.bulk_create(taskdeps_objects) if (len(errormsg) > 0): raise Exception(errormsg) @@ -955,6 +1039,8 @@ class BuildInfoHelper(object): mockevent = MockEvent() mockevent.levelno = format.ERROR mockevent.msg = text + mockevent.pathname = '-- None' + mockevent.lineno = -1 self.store_log_event(mockevent) def store_log_event(self, event): @@ -980,9 +1066,10 @@ class BuildInfoHelper(object): if 'build' in self.internal_state and 'backlog' in self.internal_state: if len(self.internal_state['backlog']): tempevent = self.internal_state['backlog'].pop() - print " Saving stored event ", tempevent + print "DEBUG: Saving stored event ", tempevent self.store_log_event(tempevent) else: + print "ERROR: Events not saved: \n", self.internal_state['backlog'] del self.internal_state['backlog'] log_information = {} diff --git a/bitbake/lib/bb/ui/toasterui.py b/bitbake/lib/bb/ui/toasterui.py index 007c6b6114..b9e8029da1 100644 --- a/bitbake/lib/bb/ui/toasterui.py +++ b/bitbake/lib/bb/ui/toasterui.py @@ -295,9 +295,17 @@ def main(server, eventHandler, params ): main.shutdown = 1 pass except Exception as e: + # print errors to log logger.error(e) import traceback - traceback.print_exc() + exception_data = traceback.format_exc() + + # save them to database, if possible; if it fails, we already logged to console. + try: + buildinfohelper.store_log_error("%s\n%s" % (str(e), exception_data)) + except Exception: + pass + pass if interrupted: