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

[Rasmus Villemoes]

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
forever.

Signed-off-by: Rasmus Villemoes <rasmus.villemoes at prevas.dk>
---
v2:
- 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
         os.chdir(cwd)
 
+    start = _get_times()
     bb.debug(2, "Executing python function %s" % func)
 
     try:
@@ -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")
     finally:
-        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:
             try:
@@ -444,6 +465,7 @@ exit $ret
     if os.path.exists(fifopath):
         os.unlink(fifopath)
     os.mkfifo(fifopath)
+    start = _get_times()
     with open(fifopath, 'r+b', buffering=0) as fifo:
         try:
             bb.debug(2, "Executing shell function %s" % func)
@@ -452,7 +474,9 @@ exit $ret
         finally:
             os.unlink(fifopath)
 
-    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)
-- 
2.23.0