[bitbake-devel] [PATCH] 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, add a single line to the log file for each
function executed 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, and AFAICT only concerns python code, so
won't help finding suboptimal shell functions.

Signed-off-by: Rasmus Villemoes <rasmus.villemoes at prevas.dk>
---
 lib/bb/build.py | 20 ++++++++++++++++++++
 1 file changed, 20 insertions(+)

diff --git a/lib/bb/build.py b/lib/bb/build.py
index 3d9cc10c..945efeae 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,14 @@ class StdoutNoopContextManager:
     def name(self):
         return sys.stdout.name
 
+def _get_times():
+    wall = time.monotonic()
+    self = resource.getrusage(resource.RUSAGE_SELF)
+    children = resource.getrusage(resource.RUSAGE_CHILDREN)
+    user = self.ru_utime + children.ru_utime
+    sys =  self.ru_stime + children.ru_stime
+
+    return (wall, user, sys)
 
 def exec_func(func, d, dirs = None):
     """Execute a BB 'function'"""
@@ -244,10 +253,21 @@ def exec_func(func, d, dirs = None):
                 pass
 
     with bb.utils.fileslocked(lockfiles):
+        try:
+            t0 = _get_times()
+        except:
+            t0 = None
         if ispython:
             exec_func_python(func, d, runfile, cwd=adir)
         else:
             exec_func_shell(func, d, runfile, cwd=adir)
+        if t0:
+            t1 = _get_times()
+            wtime = t1[0] - t0[0]
+            utime = t1[1] - t0[1]
+            stime = t1[2] - t0[2]
+            bb.debug(2, "Time spent executing %s: wall %.3f; user %.3f; system %.3f" %
+                     (func, wtime, utime, stime))
 
     try:
         curcwd = os.getcwd()
-- 
2.23.0