Patchwork [bitbake-devel] toaster: time data for tasks differ from buildstats

login
register
mail settings
Submitter Marius Avram
Date Feb. 19, 2014, 9:52 a.m.
Message ID <1392803554-27957-1-git-send-email-marius.avram@intel.com>
Download mbox | patch
Permalink /patch/66961/
State New
Headers show

Comments

Marius Avram - Feb. 19, 2014, 9:52 a.m.
The BuildInfoHelper class was measuring separately the time for a build.
This was causing many difference in the time measured by buildstats class and
the time measured here. The main problem is toaster does database operations
which delay the arrival of events.

The simplest solution, which is implemented in this fix, is to keep the time
of creation for every BaseTask and calculate the duration by making a
difference between the creation time of TaskSucceeded and TaskStarted.

[YOCTO #5727]

Signed-off-by: Marius Avram <marius.avram@intel.com>
---
 bitbake/lib/bb/build.py              |    2 ++
 bitbake/lib/bb/ui/buildinfohelper.py |   17 +++++++++++------
 bitbake/lib/bb/ui/toasterui.py       |    6 +++++-
 3 files changed, 18 insertions(+), 7 deletions(-)
Alex Damian - Feb. 19, 2014, 5:31 p.m.
Please hold merging this patch.

I have discovered a unrelated problem processing bb.build.Task* events
which will affect how this patch is structured.

Alex


On Wed, Feb 19, 2014 at 9:52 AM, Marius Avram <marius.avram@intel.com>wrote:

> The BuildInfoHelper class was measuring separately the time for a build.
> This was causing many difference in the time measured by buildstats class
> and
> the time measured here. The main problem is toaster does database
> operations
> which delay the arrival of events.
>
> The simplest solution, which is implemented in this fix, is to keep the
> time
> of creation for every BaseTask and calculate the duration by making a
> difference between the creation time of TaskSucceeded and TaskStarted.
>
> [YOCTO #5727]
>
> Signed-off-by: Marius Avram <marius.avram@intel.com>
> ---
>  bitbake/lib/bb/build.py              |    2 ++
>  bitbake/lib/bb/ui/buildinfohelper.py |   17 +++++++++++------
>  bitbake/lib/bb/ui/toasterui.py       |    6 +++++-
>  3 files changed, 18 insertions(+), 7 deletions(-)
>
> diff --git a/bitbake/lib/bb/build.py b/bitbake/lib/bb/build.py
> index 50a28dc..03e7996 100644
> --- a/bitbake/lib/bb/build.py
> +++ b/bitbake/lib/bb/build.py
> @@ -30,6 +30,7 @@ import sys
>  import logging
>  import shlex
>  import glob
> +import time
>  import bb
>  import bb.msg
>  import bb.process
> @@ -75,6 +76,7 @@ class TaskBase(event.Event):
>          self.taskfile = d.getVar("FILE", True)
>          self.taskname = self._task
>          self.logfile = logfile
> +        self.time = time.time()
>          event.Event.__init__(self)
>          self._message = "recipe %s: task %s: %s" % (d.getVar("PF", True),
> t, self.getDisplayName())
>
> diff --git a/bitbake/lib/bb/ui/buildinfohelper.py
> b/bitbake/lib/bb/ui/buildinfohelper.py
> index da777f1..093d685 100644
> --- a/bitbake/lib/bb/ui/buildinfohelper.py
> +++ b/bitbake/lib/bb/ui/buildinfohelper.py
> @@ -102,10 +102,9 @@ class ORMWrapper(object):
>              elif outcome_task_setscene == Task.OUTCOME_FAILED:
>                  task_object.sstate_result = Task.SSTATE_FAILED
>
> -        # mark down duration if we have a start time
> -        if 'start_time' in task_information.keys():
> -            duration = datetime.datetime.now() -
> task_information['start_time']
> -            task_object.elapsed_time = duration.total_seconds()
> +        # mark down duration if we have an end time
> +        if 'end_time' in task_information.keys():
> +            task_object.elapsed_time = task_information['end_time'] -
> task_information['start_time']
>
>          task_object.save()
>          return task_object
> @@ -448,6 +447,10 @@ class BuildInfoHelper(object):
>          task_information = self._get_task_information(event, recipe)
>          task_information['outcome'] = Task.OUTCOME_NA
>
> +        self.internal_state[identifier] = {}
> +        if isinstance(event, bb.build.TaskStarted):
> +            self.internal_state[identifier]['start_time'] = event.time
> +
>          if isinstance(event, bb.runqueue.runQueueTaskSkipped):
>              task_information['task_executed'] = False
>              if event.reason == "covered":
> @@ -468,8 +471,6 @@ class BuildInfoHelper(object):
>
>          task_obj =
> self.orm_wrapper.get_update_task_object(task_information)
>
> -        self.internal_state[identifier] = {'start_time':
> datetime.datetime.now()}
> -
>
>      def store_tasks_stats(self, event):
>          for (taskfile, taskname, taskstats) in event.data:
> @@ -507,6 +508,10 @@ class BuildInfoHelper(object):
>              else:
>                  task_information['script_type'] = Task.CODING_SHELL
>
> +        if isinstance(event, bb.build.TaskSucceeded):
> +            task_information['start_time'] =
> self.internal_state[identifier]['start_time']
> +            task_information['end_time'] = event.time
> +
>          if isinstance(event, (bb.runqueue.runQueueTaskCompleted,
> bb.runqueue.sceneQueueTaskCompleted)):
>              task_information['outcome'] = Task.OUTCOME_SUCCESS
>              del self.internal_state[identifier]
> diff --git a/bitbake/lib/bb/ui/toasterui.py
> b/bitbake/lib/bb/ui/toasterui.py
> index e469d93..58abfd3 100644
> --- a/bitbake/lib/bb/ui/toasterui.py
> +++ b/bitbake/lib/bb/ui/toasterui.py
> @@ -109,7 +109,11 @@ def main(server, eventHandler, params ):
>              if isinstance(event, bb.event.BuildStarted):
>                  buildinfohelper.store_started_build(event)
>
> -            if isinstance(event, (bb.build.TaskStarted,
> bb.build.TaskSucceeded, bb.build.TaskFailedSilent)):
> +            if isinstance(event, bb.build.TaskStarted):
> +                buildinfohelper.store_started_task(event)
> +                continue
> +
> +            if isinstance(event, (bb.build.TaskSucceeded,
> bb.build.TaskFailedSilent)):
>                  buildinfohelper.update_and_store_task(event)
>                  continue
>
> --
> 1.7.9.5
>
> _______________________________________________
> bitbake-devel mailing list
> bitbake-devel@lists.openembedded.org
> http://lists.openembedded.org/mailman/listinfo/bitbake-devel
>

Patch

diff --git a/bitbake/lib/bb/build.py b/bitbake/lib/bb/build.py
index 50a28dc..03e7996 100644
--- a/bitbake/lib/bb/build.py
+++ b/bitbake/lib/bb/build.py
@@ -30,6 +30,7 @@  import sys
 import logging
 import shlex
 import glob
+import time
 import bb
 import bb.msg
 import bb.process
@@ -75,6 +76,7 @@  class TaskBase(event.Event):
         self.taskfile = d.getVar("FILE", True)
         self.taskname = self._task
         self.logfile = logfile
+        self.time = time.time()
         event.Event.__init__(self)
         self._message = "recipe %s: task %s: %s" % (d.getVar("PF", True), t, self.getDisplayName())
 
diff --git a/bitbake/lib/bb/ui/buildinfohelper.py b/bitbake/lib/bb/ui/buildinfohelper.py
index da777f1..093d685 100644
--- a/bitbake/lib/bb/ui/buildinfohelper.py
+++ b/bitbake/lib/bb/ui/buildinfohelper.py
@@ -102,10 +102,9 @@  class ORMWrapper(object):
             elif outcome_task_setscene == Task.OUTCOME_FAILED:
                 task_object.sstate_result = Task.SSTATE_FAILED
 
-        # mark down duration if we have a start time
-        if 'start_time' in task_information.keys():
-            duration = datetime.datetime.now() - task_information['start_time']
-            task_object.elapsed_time = duration.total_seconds()
+        # mark down duration if we have an end time
+        if 'end_time' in task_information.keys():
+            task_object.elapsed_time = task_information['end_time'] - task_information['start_time']
 
         task_object.save()
         return task_object
@@ -448,6 +447,10 @@  class BuildInfoHelper(object):
         task_information = self._get_task_information(event, recipe)
         task_information['outcome'] = Task.OUTCOME_NA
 
+        self.internal_state[identifier] = {}
+        if isinstance(event, bb.build.TaskStarted):
+            self.internal_state[identifier]['start_time'] = event.time
+
         if isinstance(event, bb.runqueue.runQueueTaskSkipped):
             task_information['task_executed'] = False
             if event.reason == "covered":
@@ -468,8 +471,6 @@  class BuildInfoHelper(object):
 
         task_obj = self.orm_wrapper.get_update_task_object(task_information)
 
-        self.internal_state[identifier] = {'start_time': datetime.datetime.now()}
-
 
     def store_tasks_stats(self, event):
         for (taskfile, taskname, taskstats) in event.data:
@@ -507,6 +508,10 @@  class BuildInfoHelper(object):
             else:
                 task_information['script_type'] = Task.CODING_SHELL
 
+        if isinstance(event, bb.build.TaskSucceeded):
+            task_information['start_time'] = self.internal_state[identifier]['start_time']
+            task_information['end_time'] = event.time
+
         if isinstance(event, (bb.runqueue.runQueueTaskCompleted, bb.runqueue.sceneQueueTaskCompleted)):
             task_information['outcome'] = Task.OUTCOME_SUCCESS
             del self.internal_state[identifier]
diff --git a/bitbake/lib/bb/ui/toasterui.py b/bitbake/lib/bb/ui/toasterui.py
index e469d93..58abfd3 100644
--- a/bitbake/lib/bb/ui/toasterui.py
+++ b/bitbake/lib/bb/ui/toasterui.py
@@ -109,7 +109,11 @@  def main(server, eventHandler, params ):
             if isinstance(event, bb.event.BuildStarted):
                 buildinfohelper.store_started_build(event)
 
-            if isinstance(event, (bb.build.TaskStarted, bb.build.TaskSucceeded, bb.build.TaskFailedSilent)):
+            if isinstance(event, bb.build.TaskStarted):
+                buildinfohelper.store_started_task(event)
+                continue
+
+            if isinstance(event, (bb.build.TaskSucceeded, bb.build.TaskFailedSilent)):
                 buildinfohelper.update_and_store_task(event)
                 continue