[PATCH] build.py: record time spent executing each function

[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@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

Re: [PATCH] build.py: record time spent executing each function

[chris.laplante]

> 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@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)

Not sure why you sent this to me, to be honest. But while I'm here... I don't think using variable names like "self" and "sys" is a good idea in Python. May lead to confusion.

Chris

Re: [PATCH] build.py: record time spent executing each function

[Richard Purdie]

On Sat, 2020-01-18 at 22:37 +0000, Rasmus Villemoes wrote:
> 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.

Shell code is executed by exec_func_shell() so it shows up on the
profiles as executed there. The main shell code is in end task
execution.

I'm torn on the patch, its clearly useful for debugging but I'm not
sure we'd want it for general use. This patch will generate a large
amount of data too, its just spread over a lot of places.

As Chris mentions, using self as a variable name is bad practise too.

Cheers,

Richard

Re: [PATCH] build.py: record time spent executing each function

[Rasmus Villemoes]

On 19/01/2020 03.14, chris.laplante@agilent.com wrote:

> Not sure why you sent this to me, to be honest. 

Lacking something like scripts/get_maintainer, I resorted to cc'ing the
last few people to touch that file.

> But while I'm here... I don't think using variable names like "self" and "sys" is a good idea in Python. May lead to confusion.

Yeah, agreed. I'll find something better. Naming in CS and all that...

Thanks,
Rasmus

Re: [PATCH] build.py: record time spent executing each function

[Rasmus Villemoes]

On 19/01/2020 14.17, Richard Purdie wrote:
> On Sat, 2020-01-18 at 22:37 +0000, Rasmus Villemoes wrote:
>> 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.
> 
> Shell code is executed by exec_func_shell() so it shows up on the
> profiles as executed there. The main shell code is in end task
> execution.

Hm, ok, but that doesn't help with the problem that --profile produces
way too much output to be quickly useful.

> I'm torn on the patch, its clearly useful for debugging but I'm not
> sure we'd want it for general use.

IME, having this kind of low-overhead and very simple profiling info
available even when not explicitly asked for is very valuable, and may
have more people actually look for bottlenecks. It allows one to say
"hmm, foo:do_install seemed to take a long time, I wonder what part is
taking so long", and then once it finishes immediately see "ahh, that
postfunc is where it was stuck, and it seems be O(n^2) in number of
files installed...". If the timing information is not there by itself,
it's much harder to get oneself to spend the time doing all the "-c
clean", "-c cleansstate" etc. and then redo the recipe build (knowing
that it takes a long time....) just to figure out where to start looking.

> This patch will generate a large
> amount of data too, its just spread over a lot of places.

Not sure about the huge amount of data, it adds one extra line besides
the two "Executing x function y", "X function y finished" which are
already emitted for each function. I can fold the info into the latter
line if the line count is a problem.

> As Chris mentions, using self as a variable name is bad practise too.

Yes, I'll definitely fix that.

Rasmus

[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@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

Re: [PATCH] build.py: record time spent executing each function

[chris.laplante]

> > Not sure why you sent this to me, to be honest.
> 
> Lacking something like scripts/get_maintainer, I resorted to cc'ing the
> last few people to touch that file.

Ah, gotcha :)

Re: [PATCH v2] build.py: record time spent executing each function

[Rasmus Villemoes]

On 21/01/2020 10.05, Rasmus Villemoes wrote:
> 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. 

Can I ask for a ack/nak on this, and if nak, is there some way this
could happen on opt-in basis (bitbake cmdline or some setting in
local.conf)?

Rasmus