From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: by yocto-www.yoctoproject.org (Postfix, from userid 118) id C6ED7E00833; Mon, 7 Mar 2016 11:06:06 -0800 (PST) X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on yocto-www.yoctoproject.org X-Spam-Level: X-Spam-Status: No, score=-6.9 required=5.0 tests=BAYES_00,RCVD_IN_DNSWL_HI autolearn=ham version=3.3.1 X-Spam-HAM-Report: * -5.0 RCVD_IN_DNSWL_HI RBL: Sender listed at http://www.dnswl.org/, high * trust * [134.134.136.65 listed in list.dnswl.org] * -1.9 BAYES_00 BODY: Bayes spam probability is 0 to 1% * [score: 0.0000] Received: from mga03.intel.com (mga03.intel.com [134.134.136.65]) by yocto-www.yoctoproject.org (Postfix) with ESMTP id DE362E0077F for ; Mon, 7 Mar 2016 11:06:04 -0800 (PST) Received: from orsmga002.jf.intel.com ([10.7.209.21]) by orsmga103.jf.intel.com with ESMTP; 07 Mar 2016 11:06:02 -0800 X-ExtLoop1: 1 X-IronPort-AV: E=Sophos;i="5.22,552,1449561600"; d="scan'208";a="928733286" Received: from gmorga1x-mobl.ger.corp.intel.com (HELO [10.252.19.21]) ([10.252.19.21]) by orsmga002.jf.intel.com with ESMTP; 07 Mar 2016 11:06:02 -0800 To: toaster@yoctoproject.org References: <1457353301-698-1-git-send-email-elliot.smith@intel.com> <1457353301-698-3-git-send-email-elliot.smith@intel.com> From: Michael Wood Message-ID: <56DDD118.1020303@intel.com> Date: Mon, 7 Mar 2016 19:06:00 +0000 User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:38.0) Gecko/20100101 Thunderbird/38.5.1 MIME-Version: 1.0 In-Reply-To: <1457353301-698-3-git-send-email-elliot.smith@intel.com> Subject: Re: [PATCH 2/3] toaster: rework task buildstats storage and display X-BeenThere: toaster@yoctoproject.org X-Mailman-Version: 2.1.13 Precedence: list List-Id: Web based interface for BitBake List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Mon, 07 Mar 2016 19:06:06 -0000 Content-Type: text/plain; charset="windows-1252"; format="flowed" Content-Transfer-Encoding: quoted-printable On 07/03/16 12:21, Elliot Smith wrote: > The data available from buildstats is now more fine grained than > previously, so take advantage of that to enrich the data we save > against tasks: > > * Store the CPU usage for user and system separately, and display > them separately. > * Disk IO is now measured in bytes, not ms. Also store the > read/write bytes separately. > * Store started and ended times, as well as elapsed_time. This > will enable future features such as showing which tasks were > running at a particular point in the build. > > There was also a problem with how we were looking up the Task > object, which meant that the buildstats were being added to > new tasks which weren't correctly associated with the build. Fix > how we look up the Task (only looking for tasks which match the > build, and the task and recipe names in the build stats data) so > the build stats are associated with the correct task. > > [YOCTO #8842] > > Signed-off-by: Elliot Smith > --- > bitbake/lib/bb/ui/buildinfohelper.py | 72 ++++++++++-----= ------- > .../orm/migrations/0005_task_field_separation.py | 48 +++++++++++++++ > bitbake/lib/toaster/orm/models.py | 18 +++++- > .../toastergui/templates/basebuildpage.html | 4 +- > bitbake/lib/toaster/toastergui/templates/task.html | 23 ++++--- > .../lib/toaster/toastergui/templates/tasks.html | 20 +++--- > bitbake/lib/toaster/toastergui/urls.py | 2 +- > bitbake/lib/toaster/toastergui/views.py | 55 +++++++++++----= -- > 8 files changed, 163 insertions(+), 79 deletions(-) > create mode 100644 bitbake/lib/toaster/orm/migrations/0005_task_field_s= eparation.py > > diff --git a/bitbake/lib/bb/ui/buildinfohelper.py b/bitbake/lib/bb/ui/bui= ldinfohelper.py > index 81abede..7fedb76 100644 > --- a/bitbake/lib/bb/ui/buildinfohelper.py > +++ b/bitbake/lib/bb/ui/buildinfohelper.py > @@ -50,6 +50,7 @@ from bb.msg import BBLogFormatter as formatter > from django.db import models > from pprint import pformat > import logging > +from datetime import datetime, timedelta > = > from django.db import transaction, connection > = > @@ -120,6 +121,12 @@ class ORMWrapper(object): > = > return vars(self)[dictname][key] > = > + def _timestamp_to_datetime(self, secs): > + """ > + Convert timestamp in seconds to Python datetime > + """ > + return datetime(1970, 1, 1) + timedelta(seconds=3Dsecs) Would it be possible to just use the inbuilt method from timestamp? e.g. datetime.fromtimestamp(sec) > + > # pylint: disable=3Dno-self-use > # we disable detection of no self use in functions because the meth= ods actually work on the object > # even if they don't touch self anywhere > @@ -223,6 +230,28 @@ class ORMWrapper(object): > target.license_manifest_path =3D license_manifest_path > target.save() > = > + def update_task_object(self, build, task_name, recipe_name, task_sta= ts): > + """ > + Find the task for build which matches the recipe and task name > + to be stored > + """ > + task_to_update =3D Task.objects.get( > + build =3D build, > + task_name =3D task_name, > + recipe__name =3D recipe_name > + ) > + > + task_to_update.started =3D self._timestamp_to_datetime(task_stat= s['started']) > + task_to_update.ended =3D self._timestamp_to_datetime(task_stats[= 'ended']) > + task_to_update.elapsed_time =3D (task_stats['ended'] - task_stat= s['started']) > + task_to_update.cpu_time_user =3D task_stats['cpu_time_user'] > + task_to_update.cpu_time_system =3D task_stats['cpu_time_system'] > + task_to_update.disk_io_read =3D task_stats['disk_io_read'] > + task_to_update.disk_io_write =3D task_stats['disk_io_write'] > + task_to_update.disk_io =3D task_stats['disk_io_read'] + task_sta= ts['disk_io_write'] > + > + task_to_update.save() > + > def get_update_task_object(self, task_information, must_exist =3D F= alse): > assert 'build' in task_information > assert 'recipe' in task_information > @@ -259,14 +288,6 @@ class ORMWrapper(object): > task_object.sstate_result =3D Task.SSTATE_FAILED > object_changed =3D 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 tas= k_information.keys(): > - duration =3D task_information['end_time'] - task_information= ['start_time'] > - task_object.elapsed_time =3D duration > - object_changed =3D True > - del task_information['start_time'] > - del task_information['end_time'] > - > if object_changed: > task_object.save() > return task_object > @@ -1091,31 +1112,11 @@ class BuildInfoHelper(object): > = > = > def store_tasks_stats(self, event): > - for (taskfile, taskname, taskstats, recipename) in BuildInfoHelp= er._get_data_from_event(event): > - localfilepath =3D taskfile.split(":")[-1] > - assert localfilepath.startswith("/") > + task_data =3D BuildInfoHelper._get_data_from_event(event) > = > - recipe_information =3D self._get_recipe_information_from_tas= kfile(taskfile) > - try: > - if recipe_information['file_path'].startswith(recipe_inf= ormation['layer_version'].local_path): > - recipe_information['file_path'] =3D recipe_informati= on['file_path'][len(recipe_information['layer_version'].local_path):].lstri= p("/") > - > - recipe_object =3D Recipe.objects.get(layer_version =3D r= ecipe_information['layer_version'], > - file_path__endswith =3D recipe_information['= file_path'], > - name =3D recipename) > - except Recipe.DoesNotExist: > - logger.error("Could not find recipe for recipe_informati= on %s name %s" , pformat(recipe_information), recipename) > - raise > - > - task_information =3D {} > - task_information['build'] =3D self.internal_state['build'] > - task_information['recipe'] =3D recipe_object > - task_information['task_name'] =3D taskname > - task_information['cpu_usage'] =3D taskstats['cpu_usage'] > - task_information['disk_io'] =3D taskstats['disk_io'] > - if 'elapsed_time' in taskstats: > - task_information['elapsed_time'] =3D taskstats['elapsed_= time'] > - self.orm_wrapper.get_update_task_object(task_information) > + for (task_file, task_name, task_stats, recipe_name) in task_data: > + build =3D self.internal_state['build'] > + self.orm_wrapper.update_task_object(build, task_name, recipe= _name, task_stats) > = > def update_and_store_task(self, event): > assert 'taskfile' in vars(event) > @@ -1137,13 +1138,6 @@ class BuildInfoHelper(object): > recipe =3D self.orm_wrapper.get_update_recipe_object(recipe_inf= ormation, True) > task_information =3D self._get_task_information(event,recipe) > = > - if 'time' in vars(event): > - if not 'start_time' in self.internal_state['taskdata'][ident= ifier]: > - self.internal_state['taskdata'][identifier]['start_time'= ] =3D event.time > - else: > - task_information['end_time'] =3D event.time > - task_information['start_time'] =3D self.internal_state['= taskdata'][identifier]['start_time'] > - > task_information['outcome'] =3D self.internal_state['taskdata']= [identifier]['outcome'] > = > if 'logfile' in vars(event): > diff --git a/bitbake/lib/toaster/orm/migrations/0005_task_field_separatio= n.py b/bitbake/lib/toaster/orm/migrations/0005_task_field_separation.py > new file mode 100644 > index 0000000..fb1196b > --- /dev/null > +++ b/bitbake/lib/toaster/orm/migrations/0005_task_field_separation.py > @@ -0,0 +1,48 @@ > +# -*- coding: utf-8 -*- > +from __future__ import unicode_literals > + > +from django.db import migrations, models > + > + > +class Migration(migrations.Migration): > + > + dependencies =3D [ > + ('orm', '0004_provides'), > + ] > + > + operations =3D [ > + migrations.RemoveField( > + model_name=3D'task', > + name=3D'cpu_usage', > + ), > + migrations.AddField( > + model_name=3D'task', > + name=3D'cpu_time_system', > + field=3Dmodels.DecimalField(null=3DTrue, max_digits=3D8, dec= imal_places=3D2), > + ), > + migrations.AddField( > + model_name=3D'task', > + name=3D'cpu_time_user', > + field=3Dmodels.DecimalField(null=3DTrue, max_digits=3D8, dec= imal_places=3D2), > + ), > + migrations.AddField( > + model_name=3D'task', > + name=3D'disk_io_read', > + field=3Dmodels.IntegerField(null=3DTrue), > + ), > + migrations.AddField( > + model_name=3D'task', > + name=3D'disk_io_write', > + field=3Dmodels.IntegerField(null=3DTrue), > + ), > + migrations.AddField( > + model_name=3D'task', > + name=3D'ended', > + field=3Dmodels.DateTimeField(null=3DTrue), > + ), > + migrations.AddField( > + model_name=3D'task', > + name=3D'started', > + field=3Dmodels.DateTimeField(null=3DTrue), > + ), > + ] > diff --git a/bitbake/lib/toaster/orm/models.py b/bitbake/lib/toaster/orm/= models.py > index 93b5df3..182d355 100644 > --- a/bitbake/lib/toaster/orm/models.py > +++ b/bitbake/lib/toaster/orm/models.py > @@ -720,9 +720,23 @@ class Task(models.Model): > work_directory =3D models.FilePathField(max_length=3D255, blank=3DT= rue) > script_type =3D models.IntegerField(choices=3DTASK_CODING, default= =3DCODING_NA) > line_number =3D models.IntegerField(default=3D0) > - disk_io =3D models.IntegerField(null=3DTrue) > - cpu_usage =3D models.DecimalField(max_digits=3D8, decimal_places=3D2= , null=3DTrue) > + > + # start/end times > + started =3D models.DateTimeField(null=3DTrue) > + ended =3D models.DateTimeField(null=3DTrue) > + > + # in seconds; this is stored to enable sorting > elapsed_time =3D models.DecimalField(max_digits=3D8, decimal_places= =3D2, null=3DTrue) > + > + # in bytes; note that disk_io is stored to enable sorting > + disk_io =3D models.IntegerField(null=3DTrue) > + disk_io_read =3D models.IntegerField(null=3DTrue) > + disk_io_write =3D models.IntegerField(null=3DTrue) > + > + # in seconds > + cpu_time_user =3D models.DecimalField(max_digits=3D8, decimal_places= =3D2, null=3DTrue) > + cpu_time_system =3D models.DecimalField(max_digits=3D8, decimal_plac= es=3D2, null=3DTrue) > + > sstate_result =3D models.IntegerField(choices=3DSSTATE_RESULT, defa= ult=3DSSTATE_NA) > message =3D models.CharField(max_length=3D240) > logfile =3D models.FilePathField(max_length=3D255, blank=3DTrue) > diff --git a/bitbake/lib/toaster/toastergui/templates/basebuildpage.html = b/bitbake/lib/toaster/toastergui/templates/basebuildpage.html > index 0dc71f5..ff9433e 100644 > --- a/bitbake/lib/toaster/toastergui/templates/basebuildpage.html > +++ b/bitbake/lib/toaster/toastergui/templates/basebuildpage.html > @@ -67,8 +67,8 @@ > {% block nav-buildtime %} >
  • Time
    • > {% endblock %} > - {% block nav-cpuusage %} > -
  • CPU usag= e
    • > + {% block nav-cputime %} > +
  • CPU time<= /a>
    • > {% endblock %} > {% block nav-diskio %} >
  • Disk I/O<= /a>
    • > diff --git a/bitbake/lib/toaster/toastergui/templates/task.html b/bitbake= /lib/toaster/toastergui/templates/task.html > index ef628d9..5768262 100644 > --- a/bitbake/lib/toaster/toastergui/templates/task.html > +++ b/bitbake/lib/toaster/toastergui/templates/task.html > @@ -238,7 +238,7 @@ > > = > {# Performance section - shown only for executed tasks #} > -{%if task.elapsed_time or task.cpu_usage or task.disk_io %} > +{%if task.elapsed_time or task.cpu_time_user or task.cpu_time_system or = task.disk_io %} >

    Performance

    > {% endif %} >
    > @@ -249,19 +249,26 @@ > >
    {{task.elapsed_time|format_none_and_zero|floatformat:2}} > {% endif %} > - {% if task.cpu_usage > 0 %} > + {% if task.cpu_time_user > 0 %} >
    > - > - CPU usage > + > + User CPU time (secs) >
    > -
    {{task.cpu_usage|format_none_and_zero|floatformat:2}}%
    > +
    {{task.cpu_time_user|format_none_and_zero|floatformat:2}} > + {% endif %} > + {% if task.cpu_time_system > 0 %} > +
    > + > + System CPU time (secs) > +
    > +
    {{task.cpu_time_system|format_none_and_zero|floatformat:2}}<= /dd> > {% endif %} > {% if task.disk_io > 0 %} >
    > - > - Disk I/O (ms) > + > + Disk I/O (bytes) >
    > -
    {{task.disk_io|format_none_and_zero}}
    > +
    {{task.disk_io|format_none_and_zero|intcomma}}
    > {% endif %} >
    > = > diff --git a/bitbake/lib/toaster/toastergui/templates/tasks.html b/bitbak= e/lib/toaster/toastergui/templates/tasks.html > index 353410f..23eb957 100644 > --- a/bitbake/lib/toaster/toastergui/templates/tasks.html > +++ b/bitbake/lib/toaster/toastergui/templates/tasks.html > @@ -1,4 +1,5 @@ > {% extends "basebuildpage.html" %} > +{% load humanize %} > {% load projecttags %} > = > {% block title %} {{mainheading}} - {{build.target_set.all|dictsort:"ta= rget"|join:", "}} {{build.machine}} - {{build.project.name}} - Toaster{% en= dblock %} > @@ -20,13 +21,15 @@ >
  • Time
    • > {% endif %} > {% endblock %} > -{% block nav-cpuusage %} > - {% if 'CPU usage' =3D=3D mainheading %} > -
  • CPU u= sage
    • > + > +{% block nav-cputime %} > + {% if 'CPU time' =3D=3D mainheading %} > +
  • CPU ti= me
    • > {% else %} > -
  • CPU usage
    • > +
  • CPU time
    • > {% endif %} > {% endblock %} > + > {% block nav-diskio %} > {% if 'Disk I/O' =3D=3D mainheading %} >
  • Disk I= /O
    • > @@ -107,11 +110,14 @@ > > {{task.elapsed_time|format_none_and_zero|floatformat:2}} > > - > - {{task.cpu_usage|format_none_and_zero|floatformat:2}}{% = if task.cpu_usage %}%{% endif %} > + > + {{task.cpu_time_system|format_none_and_zero|floatformat:= 2}} > + > + > + {{task.cpu_time_user|format_none_and_zero|floatformat:2}} > > > - {{task.disk_io|format_none_and_zero}} > + {{task.disk_io|format_none_and_zero|intcomma}} > > = > > diff --git a/bitbake/lib/toaster/toastergui/urls.py b/bitbake/lib/toaster= /toastergui/urls.py > index 4aa6488..400580a 100644 > --- a/bitbake/lib/toaster/toastergui/urls.py > +++ b/bitbake/lib/toaster/toastergui/urls.py > @@ -64,7 +64,7 @@ urlpatterns =3D patterns('toastergui.views', > url(r'^build/(?P\d+)/configuration$', 'configuration'= , name=3D'configuration'), > url(r'^build/(?P\d+)/configvars$', 'configvars', name= =3D'configvars'), > url(r'^build/(?P\d+)/buildtime$', 'buildtime', name= =3D'buildtime'), > - url(r'^build/(?P\d+)/cpuusage$', 'cpuusage', name=3D'c= puusage'), > + url(r'^build/(?P\d+)/cputime$', 'cputime', name=3D'cpu= time'), > url(r'^build/(?P\d+)/diskio$', 'diskio', name=3D'disk= io'), > = > # image information dir > diff --git a/bitbake/lib/toaster/toastergui/views.py b/bitbake/lib/toaste= r/toastergui/views.py > index bd11892..85ca9be 100755 > --- a/bitbake/lib/toaster/toastergui/views.py > +++ b/bitbake/lib/toaster/toastergui/views.py > @@ -1005,11 +1005,11 @@ def tasks_common(request, build_id, variant, task= _anchor): > object_search_display=3D"disk I/O data" > filter_search_display=3D"tasks" > (pagesize, orderby) =3D _get_parameters_values(request, 25, 'di= sk_io:-') > - elif 'cpuusage' =3D=3D variant: > - title_variant=3D'CPU usage' > - object_search_display=3D"CPU usage data" > + elif 'cputime' =3D=3D variant: > + title_variant=3D'CPU time' > + object_search_display=3D"CPU time data" > filter_search_display=3D"tasks" > - (pagesize, orderby) =3D _get_parameters_values(request, 25, 'cpu= _usage:-') > + (pagesize, orderby) =3D _get_parameters_values(request, 25, 'cpu= _time_system:-') > else : > title_variant=3D'Tasks' > object_search_display=3D"tasks" > @@ -1161,23 +1161,38 @@ def tasks_common(request, build_id, variant, task= _anchor): > del tc_time['clclass'] > tc_cache['hidden']=3D'1' > = > - tc_cpu=3D{ > - 'name':'CPU usage', > - 'qhelp':'The percentage of task CPU utilization', > - 'orderfield': _get_toggle_order(request, "cpu_usage", True), > - 'ordericon':_get_toggle_order_icon(request, "cpu_usage"), > - 'orderkey' : 'cpu_usage', > - 'clclass': 'cpu_used', 'hidden' : 1, > + tc_cpu_time_system=3D{ > + 'name':'System CPU time (secs)', > + 'qhelp':'Total amount of time spent executing in kernel mode, in= ' + > + 'seconds. Note that this time can be greater than the ta= sk ' + > + 'time due to parallel execution.', > + 'orderfield': _get_toggle_order(request, "cpu_time_system", True= ), > + 'ordericon':_get_toggle_order_icon(request, "cpu_time_system"), > + 'orderkey' : 'cpu_time_system', > + 'clclass': 'cpu_time_system', 'hidden' : 1, > } > = > - if 'cpuusage' =3D=3D variant: > - tc_cpu['hidden']=3D'0' > - del tc_cpu['clclass'] > + tc_cpu_time_user=3D{ > + 'name':'User CPU time (secs)', > + 'qhelp':'Total amount of time spent executing in user mode, in s= econds. ' + > + 'Note that this time can be greater than the task time d= ue to ' + > + 'parallel execution.', > + 'orderfield': _get_toggle_order(request, "cpu_time_user", True), > + 'ordericon':_get_toggle_order_icon(request, "cpu_time_user"), > + 'orderkey' : 'cpu_time_user', > + 'clclass': 'cpu_time_user', 'hidden' : 1, > + } > + > + if 'cputime' =3D=3D variant: > + tc_cpu_time_system['hidden']=3D'0' > + tc_cpu_time_user['hidden']=3D'0' > + del tc_cpu_time_system['clclass'] > + del tc_cpu_time_user['clclass'] > tc_cache['hidden']=3D'1' > = > tc_diskio=3D{ > - 'name':'Disk I/O (ms)', > - 'qhelp':'Number of miliseconds the task spent doing disk input a= nd output', > + 'name':'Disk I/O (bytes)', > + 'qhelp':'Number of bytes written to and read from the disk durin= g the task', > 'orderfield': _get_toggle_order(request, "disk_io", True), > 'ordericon':_get_toggle_order_icon(request, "disk_io"), > 'orderkey' : 'disk_io', > @@ -1208,7 +1223,8 @@ def tasks_common(request, build_id, variant, task_a= nchor): > tc_outcome, > tc_cache, > tc_time, > - tc_cpu, > + tc_cpu_time_system, > + tc_cpu_time_user, > tc_diskio, > ]} > = > @@ -1229,9 +1245,8 @@ def buildtime(request, build_id): > def diskio(request, build_id): > return tasks_common(request, build_id, 'diskio', '') > = > -def cpuusage(request, build_id): > - return tasks_common(request, build_id, 'cpuusage', '') > - > +def cputime(request, build_id): > + return tasks_common(request, build_id, 'cputime', '') > = > def recipes(request, build_id): > template =3D 'recipes.html' --------------------------------------------------------------------- Intel Corporation (UK) Limited Registered No. 1134945 (England) Registered Office: Pipers Way, Swindon SN3 1RJ VAT No: 860 2173 47 This e-mail and any attachments may contain confidential material for the sole use of the intended recipient(s). Any review or distribution by others is strictly prohibited. If you are not the intended recipient, please contact the sender and delete all copies.