[bitbake-devel] [PATCH v2] build.py: record time spent executing each function

Rasmus Villemoes rasmus.villemoes at prevas.dk
Tue Jan 21 09:05:27 UTC 2020

In order to have a quick way to see if optimizing some task function
actually has an effect, append a little information to each
"Python/Shell function foo finished" line listing the wallclock,
system and user time spent. That can also help figure out which parts
of a recipe is taking the longest and hence find places that might be
worth looking at.

bitbake already has the --profile/-P option, but that produces an
enourmous amount of output. If the above reveals that a certain python
function is slow, that detailed profiling can of course be useful, but
having the above more coarse-grained (and quite lightweight) info
available by default can help one know where to start looking. Also,
in some cases it is immediately obvious what one can do once one knows
that it's some specific postfunc that causes do_foobar to take

Signed-off-by: Rasmus Villemoes <rasmus.villemoes at prevas.dk>
- avoid "self" and "sys" as names of local variables.
- fold the info into the "function ... finished" line

 lib/bb/build.py | 28 ++++++++++++++++++++++++++--
 1 file changed, 26 insertions(+), 2 deletions(-)

diff --git a/lib/bb/build.py b/lib/bb/build.py
index 3d9cc10c..de51aebe 100644
--- a/lib/bb/build.py
+++ b/lib/bb/build.py
@@ -19,6 +19,7 @@ import shlex
 import glob
 import time
 import stat
+import resource
 import bb
 import bb.msg
 import bb.process
@@ -172,6 +173,23 @@ class StdoutNoopContextManager:
     def name(self):
         return sys.stdout.name
+def _get_times():
+    try:
+        walltime = time.monotonic()
+        res_self = resource.getrusage(resource.RUSAGE_SELF)
+        res_children = resource.getrusage(resource.RUSAGE_CHILDREN)
+        usertime = res_self.ru_utime + res_children.ru_utime
+        systime =  res_self.ru_stime + res_children.ru_stime
+        return (walltime, usertime, systime)
+    except:
+        return None
+def _delta_times(start):
+    stop = _get_times()
+    if start is None or stop is None:
+        return (-1, -1, -1)
+    return (stop[0]-start[0], stop[1]-start[1], stop[2]-start[2])
 def exec_func(func, d, dirs = None):
     """Execute a BB 'function'"""
@@ -281,6 +299,7 @@ def exec_func_python(func, d, runfile, cwd=None):
             olddir = None
+    start = _get_times()
     bb.debug(2, "Executing python function %s" % func)
@@ -292,7 +311,9 @@ def exec_func_python(func, d, runfile, cwd=None):
         comp = utils.better_compile(code, func, "exec_python_func() autogenerated")
         utils.better_exec(comp, {"d": d}, code, "exec_python_func() autogenerated")
-        bb.debug(2, "Python function %s finished" % func)
+        delta = _delta_times(start)
+        bb.debug(2, "Python function %s finished (wall %.3f; user %.3f; sys %.3f)" %
+                 ((func,) + delta))
         if cwd and olddir:
@@ -444,6 +465,7 @@ exit $ret
     if os.path.exists(fifopath):
+    start = _get_times()
     with open(fifopath, 'r+b', buffering=0) as fifo:
             bb.debug(2, "Executing shell function %s" % func)
@@ -452,7 +474,9 @@ exit $ret
-    bb.debug(2, "Shell function %s finished" % func)
+    delta = _delta_times(start)
+    bb.debug(2, "Shell function %s finished (wall %.3f; user %.3f; sys %.3f)" %
+             ((func,) + delta))
 def _task_data(fn, task, d):
     localdata = bb.data.createCopy(d)

More information about the bitbake-devel mailing list