Re: [bitbake-devel] regression of 'world' performance?

[Richard Purdie <richard.purdie@linuxfoundation.org>]

On Mon, 2024-02-12 at 13:58 +0100, Alexander Kanavin wrote:
> On Sat, 10 Feb 2024 at 21:53, Richard Purdie
> <richard.purdie@linuxfoundation.org> wrote:
> 
> > Looking at the code, people have altered next_buildable_task() to add
> > per task thread limits and pressure regulation and they don't realise
> > how often that function can be called or how fast it really needs to
> > be. Note that the profile above doesn't include pressure regulation but
> > if it did, it would be much worse.
> > 
> > It can be reworked but it isn't trivial.
> 
> Thanks for working on this, over the weekend. I just re-run profiling
> with the fix for the mainloop, and here's what I see:
> 
> 1. There are three performance fixes in master-next. Without any of
> them, profile shows this (pressed ctrl-c while it was still not
> running any tasks):
> 
> Mon Feb 12 12:32:56 2024    profile-mainloop.log
> 
>          71983446 function calls (71606940 primitive calls) in 1546.118 seconds
> 
>    Ordered by: internal time
> 
>    ncalls  tottime  percall  cumtime  percall filename:lineno(function)
>      9448 1461.507    0.155 1491.991    0.158
> /srv/work/alex/poky/bitbake/lib/bb/runqueue.py:2147(execute)
> 9510/9448   14.437    0.002   14.530    0.002
> /srv/work/alex/poky/bitbake/lib/bb/runqueue.py:2672(scenequeue_updatecounters)
>   5250612    7.414    0.000    7.414    0.000
> /srv/work/alex/poky/bitbake/lib/bb/__init__.py:63(bbdebug)
>   5219489    6.090    0.000   13.472    0.000
> /srv/work/alex/poky/bitbake/lib/bb/__init__.py:57(debug2)
>         1    5.906    5.906   18.979   18.979
> /srv/work/alex/poky/bitbake/lib/bb/runqueue.py:644(prepare)
> 43827/23463    1.662    0.000    4.198    0.000
> /usr/lib/python3.11/re/_parser.py:507(_parse)
> 
> So it is indeed the execute() loop itself which is slow. It's only
> logical then that with the first two performance fixes applied,
> nothing changes:
> 
> Mon Feb 12 13:03:42 2024    profile-mainloop.log
> 
>          67576990 function calls (67201484 primitive calls) in 1226.143 seconds
> 
>    Ordered by: internal time
> 
>    ncalls  tottime  percall  cumtime  percall filename:lineno(function)
>      8711 1147.496    0.132 1173.321    0.135
> /srv/work/alex/poky/bitbake/lib/bb/runqueue.py:2149(execute)
> 8773/8711   12.261    0.001   12.347    0.001
> /srv/work/alex/poky/bitbake/lib/bb/runqueue.py:2683(scenequeue_updatecounters)
>   4498537    6.303    0.000    6.303    0.000
> /srv/work/alex/poky/bitbake/lib/bb/__init__.py:63(bbdebug)
>         1    6.238    6.238   16.135   16.135
> /srv/work/alex/poky/bitbake/lib/bb/runqueue.py:644(prepare)
>   4467414    5.149    0.000   11.418    0.000
> /srv/work/alex/poky/bitbake/lib/bb/__init__.py:57(debug2)
> 43827/23463    1.662    0.000    4.239    0.000
> /usr/lib/python3.11/re/_parser.py:507(_parse)
> 
> Do note the quadratic growth in tottime though: 9448/8711 = 1.08, but
> 1461/1148 = 1.27
> 
> 2. With the third fix (allow the loop to work through all items), I
> finally didn't have to press ctrl-c, and the dry world run completed,
> with the following picture:
> 
> Mon Feb 12 13:21:51 2024    profile-mainloop.log
> 
>          158073071 function calls (157658186 primitive calls) in 972.810 seconds
> 
>    Ordered by: internal time
> 
>    ncalls  tottime  percall  cumtime  percall filename:lineno(function)
>     35784  307.013    0.009  513.933    0.014
> /srv/work/alex/poky/bitbake/lib/bb/runqueue.py:225(next_buildable_task)
>     34092  160.895    0.005  168.126    0.005
> /srv/work/alex/poky/bitbake/lib/bb/runqueue.py:2438(build_taskdepdata)
>     35807  118.265    0.003  118.265    0.003 {method 'difference' of
> 'set' objects}
>     71592   54.910    0.001   54.910    0.001 {method
> 'difference_update' of 'set' objects}
>     34096   50.010    0.001   50.010    0.001 {method 'write' of
> '_io.BufferedWriter' objects}
> 17639/15964   48.203    0.003   48.480    0.003
> /srv/work/alex/poky/bitbake/lib/bb/runqueue.py:2685(scenequeue_updatecounters)
>    298834   45.690    0.000   45.691    0.000 {built-in method _pickle.dumps}
>     35827   22.092    0.001   22.092    0.001 {method
> 'intersection_update' of 'set' objects}
>     35783   10.610    0.000   10.610    0.000 {method 'index' of 'list' objects}
>     35957    9.649    0.000  916.610    0.025
> /srv/work/alex/poky/bitbake/lib/bb/runqueue.py:2149(execute)
> 
> execute() moves to the 10th place, and the time starts to be dominated
> by other items
> 
> 3. I'm not seeing anything obviously inefficient in the execute() loop
> itself: it's mostly doing standard data structure lookups.
> So I'd say execute() should be allowed to handle all the items in a
> batch or otherwise make its own decisions about when to return. This
> results in fails elsewhere as you've commented, I didn't yet look into
> that.

I worked out a way to make it work with "continue" however there was
more that was bugging me about the behaviour of this. You can see it in
this profile:

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    15223  807.225    0.053  838.759    0.055 /media/build/poky/bitbake/lib/bb/runqueue.py:2149(execute)
16970/15322   23.029    0.001   23.177    0.002 /media/build/poky/bitbake/lib/bb/runqueue.py:2683(scenequeue_updatecounters)
  5239701    3.361    0.000    3.361    0.000 /media/build/poky/bitbake/lib/bb/__init__.py:63(bbdebug)
        1    3.072    3.072    7.529    7.529 /media/build/poky/bitbake/lib/bb/runqueue.py:644(prepare)
  5208322    2.964    0.000    6.313    0.000 /media/build/poky/bitbake/lib/bb/__init__.py:57(debug2)
       43    1.236    0.029    1.236    0.029 {built-in method select.select}
 10707192    0.913    0.000    0.913    0.000 {method 'issubset' of 'set' objects}
24335/13567    0.669    0.000    1.264    0.000 /usr/lib/python3.11/re/_parser.py:509(_parse)
   996792    0.652    0.000    0.742    0.000 /usr/lib/python3.11/glob.py:141(_iterdir)
    41296    0.583    0.000    0.583    0.000 {built-in method posix.write}

Note that whilst they didn't take too long a time, there are 5 million
calls to debug2 (each is a line of log information) and 10 million
calls to issubset().

execute() should only be processing task entries when that entry has
some kind of "progress" that can be made and there is "space" to
execute a new task. The millions of log lines suggest something is
being "processed" multiple times over with no progress. The issubset()
gives a pointer to which code block.

As you've already identified, that points back to the code block:

if nexttask in self.sqdata.sq_harddeps_rev and not self.sqdata.sq_harddeps_rev[nexttask].issubset(self.scenequeue_covered | self.scenequeue_notcovered):
    logger.debug2("Deferring %s due to hard dependencies" % nexttask)

but I mainly mention this to show how it shows up in the profile.

The key question is why does that block keep getting triggered and how
can we make it only run when it needs to.

The answer is perhaps the patch I sent to the bitbake list a few hours
ago, which runs it once, then skips it until it has progress than can
be made (the harddep dependencies have run).

That change in behaviour is able to change the profile to:

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.069    0.069   62.756   62.756 /media/build/poky/bitbake/lib/bb/server/process.py:421(idle_thread_internal)
    15222    0.013    0.000   57.848    0.004 /media/build/poky/bitbake/lib/bb/cooker.py:1474(buildTargetsIdle)
    15222    0.012    0.000   57.834    0.004 /media/build/poky/bitbake/lib/bb/runqueue.py:1624(execute_runqueue)
    15222    0.057    0.000   57.822    0.004 /media/build/poky/bitbake/lib/bb/runqueue.py:1523(_execute_runqueue)
    15222   15.182    0.001   39.881    0.003 /media/build/poky/bitbake/lib/bb/runqueue.py:2150(execute)
16970/15322   23.639    0.001   23.775    0.002 /media/build/poky/bitbake/lib/bb/runqueue.py:2686(scenequeue_updatecounters)
16739/15091    0.017    0.000   23.723    0.002 /media/build/poky/bitbake/lib/bb/runqueue.py:2756(sq_task_failoutright)
        1    0.022    0.022    8.504    8.504 /media/build/poky/bitbake/lib/bb/runqueue.py:1814(__init__)
        1    2.842    2.842    7.013    7.013 /media/build/poky/bitbake/lib/bb/runqueue.py:644(prepare)
    16970    0.044    0.000    4.550    0.000 /media/build/poky/bitbake/lib/bb/build.py:855(find_stale_stamps)
    33948    0.032    0.000    4.197    0.000 /usr/lib/python3.11/glob.py:13(glob)

so without profiling enabled, "bitbake world -n --setscene-only" takes
around 30s (60s with profiling) for the workload which previously was
taking 12 minutes.

execute() is 40s of that and of the 40s, 23s is spent in the
scenequeue_updatecounters() accounting function.

The other "performance" changes I sent help the task execution phase
which happens after setscene() so they improve "bitbake world -n" but
not the setscene piece specifically.

The patches fix low hanging issues but I suspect there is more we
could/should do in this code.

Cheers,

Richard