[bitbake-devel] [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