[bitbake-devel] [PATCH 1/2] toaster: time data for tasks differ from buildstats
Marius Avram
marius.avram at intel.com
Tue Mar 11 14:23:27 UTC 2014
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 event and calculate the duration by making a
difference between the creation time of TaskSucceeded and TaskStarted.
[YOCTO #5485]
Signed-off-by: Marius Avram <marius.avram at intel.com>
---
bitbake/lib/bb/build.py | 2 +
bitbake/lib/bb/ui/buildinfohelper.py | 73 ++++++++++++++++++++--------------
bitbake/lib/bb/ui/toasterui.py | 6 ++-
3 files changed, 51 insertions(+), 30 deletions(-)
diff --git a/bitbake/lib/bb/build.py b/bitbake/lib/bb/build.py
index 52e4149..5cb4c06 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 d7b526a..df67d70 100644
--- a/bitbake/lib/bb/ui/buildinfohelper.py
+++ b/bitbake/lib/bb/ui/buildinfohelper.py
@@ -125,9 +125,9 @@ class ORMWrapper(object):
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()
+ if 'end_time' in task_information.keys():
+ duration = task_information['end_time'] - task_information['start_time']
+ task_object.elapsed_time = duration
task_object.save()
return task_object
@@ -455,7 +455,32 @@ class BuildInfoHelper(object):
if i not in ret:
ret.append(i)
return " ".join(sorted(ret))
+
+
+ def _get_real_recipe(self, event):
+ # Will be used by events derived from TaskBase. Some of this
+ # events have a missing namespace in front of their taskfile name,
+ # which is called virtual:native:. To avoid duplication of entries
+ # in the database it will append the namespace where it is needed
+ # and get the correct recipe and identifier
+ identifier = event.taskfile + ":" + event.taskname
+ if not identifier in self.internal_state['taskdata']:
+ if isinstance(event, bb.build.TaskBase):
+ # we do a bit of guessing
+ candidates = [x for x in self.internal_state['taskdata'].keys() if x.endswith(identifier)]
+ if len(candidates) == 1:
+ identifier = candidates[0]
+
+ if isinstance(event, bb.build.TaskBase):
+ assert identifier in self.internal_state['taskdata']
+ identifierlist = identifier.split(":")
+ realtaskfile = ":".join(identifierlist[0:len(identifierlist)-1])
+ recipe_information = self._get_recipe_information_from_taskfile(realtaskfile)
+ recipe = self.orm_wrapper.get_update_recipe_object(recipe_information, True)
+
+ return (recipe, identifier)
+
################################
## external available methods to store information
@@ -497,15 +522,13 @@ class BuildInfoHelper(object):
self.orm_wrapper.update_build_object(self.internal_state['build'], errors, warnings, taskfailures)
def store_started_task(self, event):
- assert isinstance(event, (bb.runqueue.sceneQueueTaskStarted, bb.runqueue.runQueueTaskStarted, bb.runqueue.runQueueTaskSkipped))
+ assert isinstance(event, (bb.runqueue.sceneQueueTaskStarted, bb.runqueue.runQueueTaskStarted,
+ bb.build.TaskStarted, bb.runqueue.runQueueTaskSkipped))
assert 'taskfile' in vars(event)
localfilepath = event.taskfile.split(":")[-1]
assert localfilepath.startswith("/")
- identifier = event.taskfile + ":" + event.taskname
-
- recipe_information = self._get_recipe_information_from_taskfile(event.taskfile)
- recipe = self.orm_wrapper.get_update_recipe_object(recipe_information)
+ (recipe, identifier) = self._get_real_recipe(event)
task_information = self._get_task_information(event, recipe)
task_information['outcome'] = Task.OUTCOME_NA
@@ -528,15 +551,16 @@ class BuildInfoHelper(object):
if not isinstance(event, bb.runqueue.sceneQueueTaskStarted):
self.task_order += 1
task_information['order'] = self.task_order
-
+
+ self.internal_state['taskdata'][identifier] = {}
+ self.internal_state['taskdata'][identifier]['outcome'] = task_information['outcome']
+ # This would apply only in the case of TaskStarted
+ if 'time' in vars(event):
+ self.internal_state['taskdata'][identifier]['start_time'] = event.time
+
+ # If task object already exists it will only update the start_time field
task_obj = self.orm_wrapper.get_update_task_object(task_information)
- self.internal_state['taskdata'][identifier] = {
- 'start_time': datetime.datetime.now(),
- 'outcome': task_information['outcome'],
- }
-
-
def store_tasks_stats(self, event):
for (taskfile, taskname, taskstats) in event.data:
localfilepath = taskfile.split(":")[-1]
@@ -562,24 +586,15 @@ class BuildInfoHelper(object):
localfilepath = event.taskfile.split(":")[-1]
assert localfilepath.startswith("/")
- identifier = event.taskfile + ":" + event.taskname
- if not identifier in self.internal_state['taskdata']:
- if isinstance(event, bb.build.TaskBase):
- # we do a bit of guessing
- candidates = [x for x in self.internal_state['taskdata'].keys() if x.endswith(identifier)]
- if len(candidates) == 1:
- identifier = candidates[0]
+ (recipe, identifier) = self._get_real_recipe(event)
- assert identifier in self.internal_state['taskdata']
- identifierlist = identifier.split(":")
- realtaskfile = ":".join(identifierlist[0:len(identifierlist)-1])
- recipe_information = self._get_recipe_information_from_taskfile(realtaskfile)
- recipe = self.orm_wrapper.get_update_recipe_object(recipe_information, True)
task_information = self._get_task_information(event,recipe)
-
- task_information['start_time'] = self.internal_state['taskdata'][identifier]['start_time']
task_information['outcome'] = self.internal_state['taskdata'][identifier]['outcome']
+ if 'time' in vars(event):
+ task_information['start_time'] = self.internal_state['taskdata'][identifier]['start_time']
+ task_information['end_time'] = event.time
+
if 'logfile' in vars(event):
task_information['logfile'] = event.logfile
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
>From 1da35df930cb6b700bd80f792ba1ac928f81044c Mon Sep 17 00:00:00 2001
From: Marius Avram <marius.avram at intel.com>
Date: Tue, 11 Mar 2014 15:53:30 +0200
Subject: [PATCH 2/2] buildstats: use TaskBase time for elapsed time
To avoid any further inconsistencies between buildstats and buildinfohelper
from toaster, buildstats will measure task duration using the time field
from within the TaskBase events: TaskStarted and TaskSucceeded/TaskFailed.
Signed-off-by: Marius Avram <marius.avram at intel.com>
---
meta/classes/buildstats.bbclass | 23 +++++++++++++++--------
1 file changed, 15 insertions(+), 8 deletions(-)
diff --git a/meta/classes/buildstats.bbclass b/meta/classes/buildstats.bbclass
index 72fff11..89ae72c 100644
--- a/meta/classes/buildstats.bbclass
+++ b/meta/classes/buildstats.bbclass
@@ -109,14 +109,17 @@ def get_diskdata(var, dev, data):
diskdata["End"+key] = str(int(newdiskdata[key]))
return diskdata
-def set_timedata(var, data):
+def set_timedata(var, data, server_time=None):
import time
- time = time.time()
+ if server_time:
+ time = server_time
+ else:
+ time = time.time()
cputime = get_cputime()
proctime = get_process_cputime(os.getpid())
data.setVar(var, (time, cputime, proctime))
-def get_timedata(var, data):
+def get_timedata(var, data, server_time=None):
import time
timedata = data.getVar(var, False)
if timedata is None:
@@ -124,7 +127,11 @@ def get_timedata(var, data):
oldtime, oldcpu, oldproc = timedata
procdiff = get_process_cputime(os.getpid()) - oldproc
cpudiff = get_cputime() - oldcpu
- timediff = time.time() - oldtime
+ if server_time:
+ end_time = server_time
+ else:
+ end_time = time.time()
+ timediff = end_time - oldtime
if cpudiff > 0:
cpuperc = float(procdiff) * 100 / cpudiff
else:
@@ -136,7 +143,7 @@ def write_task_data(status, logfile, dev, e):
bsdir = os.path.join(e.data.getVar('BUILDSTATS_BASE', True), bn)
taskdir = os.path.join(bsdir, e.data.expand("${PF}"))
file = open(os.path.join(logfile), "a")
- timedata = get_timedata("__timedata_task", e.data)
+ timedata = get_timedata("__timedata_task", e.data, e.time)
if timedata:
elapsedtime, cpu = timedata
file.write(bb.data.expand("${PF}: %s: Elapsed time: %0.2f seconds \n" %
@@ -160,7 +167,7 @@ def write_task_data(status, logfile, dev, e):
file.write("Status: PASSED \n")
else:
file.write("Status: FAILED \n")
- file.write("Ended: %0.2f \n" % time.time())
+ file.write("Ended: %0.2f \n" % e.time)
file.close()
python run_buildstats () {
@@ -234,7 +241,7 @@ python run_buildstats () {
taskdir = os.path.join(bsdir, e.data.expand("${PF}"))
if device != "NoLogicalDevice":
set_diskdata("__diskdata_task", device, e.data)
- set_timedata("__timedata_task", e.data)
+ set_timedata("__timedata_task", e.data, e.time)
try:
bb.utils.mkdirhier(taskdir)
except:
@@ -242,7 +249,7 @@ python run_buildstats () {
# write into the task event file the name and start time
file = open(os.path.join(taskdir, e.task), "a")
file.write("Event: %s \n" % bb.event.getName(e))
- file.write("Started: %0.2f \n" % time.time())
+ file.write("Started: %0.2f \n" % e.time)
file.close()
elif isinstance(e, bb.build.TaskSucceeded):
--
1.7.9.5
More information about the bitbake-devel
mailing list