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

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

On Sat, 2024-02-10 at 20:42 +0000, Richard Purdie via
lists.openembedded.org wrote:
> On Sat, 2024-02-10 at 15:16 +0000, Richard Purdie via
> lists.openembedded.org wrote:
> > On Fri, 2024-02-09 at 23:59 +0000, Richard Purdie via
> > lists.openembedded.org wrote:
> > > On Fri, 2024-02-09 at 23:33 +0000, Richard Purdie via
> > > lists.openembedded.org wrote:
> > > > On Fri, 2024-02-09 at 21:44 +0100, Alexander Kanavin wrote:
> > > > > On Fri, 9 Feb 2024 at 18:02, Alexander Kanavin via
> > > > > lists.openembedded.org <alex.kanavin=gmail.com@lists.openembedded.org>
> > > > > wrote:
> > > > > > I worked around it by running 'bitbake world' without -P so it could
> > > > > > parse recipes successfully, then re-running with -P against pre-parsed
> > > > > > data. So profiles are being collected now.
> > > > > 
> > > > > Here it is: https://drive.google.com/file/d/1bM1MGJWU5uWRf6kE6AaENQLQKIbopnGW/view?usp=sharing
> > > > > 
> > > > > I pressed ctrl-c after some 20 minutes - I took a look into it then
> > > > > but somehow couldn't find anything related to execute(). The two
> > > > > collected profiles seemingly are just waiting on select().
> > > > 
> > > > This didn't make much sense to me so I ended up going digging.
> > > > 
> > > > The traceback you showed is reproducible if you trigger parsing while
> > > > using -P so a bug needs fixing there. You can avoid it with something
> > > > like:
> > > > 
> > > > bitbake -p
> > > > bitbake world -nP
> > > > 
> > > > However what I've then realised is that when we added the second thread
> > > > to cooker, we only dump the performance data for one of the threads,
> > > > not the other.
> > > > 
> > > > So I suspect we need to fix the profiling to dump the stats on the
> > > > second thread, then we'll see what the real issue is.
> > > > 
> > > > I can confirm that bitbake world -nP is running much slower than it
> > > > should, even just for oe-core.
> > > 
> > > I've sent a patch to add the profiling for the other thread. With that
> > > applied and a simple "bitbake bash -nP", profile-mainloop.log.processed
> > > contains:
> > > 
> > >    Ordered by: cumulative time
> > > 
> > >    ncalls  tottime  percall  cumtime  percall filename:lineno(function)
> > >         1    0.240    0.240  104.476  104.476 /media/build/poky/bitbake/lib/bb/server/process.py:421(idle_thread_internal)
> > >     12663   75.679    0.006   75.679    0.006 {built-in method select.select}
> > >     13842    0.036    0.000   26.361    0.002 /media/build/poky/bitbake/lib/bb/cooker.py:1474(buildTargetsIdle)
> > >     13842    0.017    0.000   26.324    0.002 /media/build/poky/bitbake/lib/bb/runqueue.py:1624(execute_runqueue)
> > >     13842    0.214    0.000   26.306    0.002 /media/build/poky/bitbake/lib/bb/runqueue.py:1523(_execute_runqueue)
> > >     13842    0.274    0.000   23.590    0.002 /media/build/poky/bitbake/lib/bb/runqueue.py:2147(execute)
> > >      1621    6.623    0.004   15.030    0.009 /media/build/poky/bitbake/lib/bb/runqueue.py:2418(build_taskdepdata)
> > >   1338979    3.250    0.000    5.513    0.000 /media/build/poky/bitbake/lib/bb/runqueue.py:2407(filtermcdeps)
> > >    211156    0.633    0.000    3.877    0.000 /media/build/poky/bitbake/lib/bb/runqueue.py:3217(read)
> > >     25898    0.058    0.000    3.213    0.000 /media/build/poky/bitbake/lib/bb/runqueue.py:1419(read_workers)
> > >     37063    0.252    0.000    2.876    0.000 /media/build/poky/bitbake/lib/bb/event.py:190(fire_ui_handlers)
> > >      1686    0.029    0.000    2.870    0.002 /media/build/poky/bitbake/lib/bb/runqueue.py:1328(send_pickled_data)
> > >   1411556    1.677    0.000    2.704    0.000 /media/build/poky/bitbake/lib/bb/runqueue.py:56(split_tid_mcfn)
> > > 8982/8940    0.016    0.000    1.936    0.000 /media/build/poky/bitbake/lib/bb/event.py:217(fire)
> > >   2284982    1.234    0.000    1.924    0.000 /media/build/poky/bitbake/lib/bb/runqueue.py:41(mc_from_tid)
> > >       979    0.002    0.000    1.906    0.002 /media/build/poky/bitbake/lib/bb/command.py:110(runAsyncCommand)
> > >      1686    1.852    0.001    1.852    0.001 {method 'write' of '_io.BufferedWriter' objects}
> > > 
> > > 
> > > which even without a world build, says some interesting things about
> > > the 1.3 million calls to filtermcdeps and the time spend in
> > > build_taskdepdata.
> > 
> > I was curious about the time spent in build_taskdepdata() since we can
> > fix that. I'll send a patch out shortly but with it applied, the above
> > becomes:
> > 
> >    ncalls  tottime  percall  cumtime  percall filename:lineno(function)
> >         1    0.268    0.268   93.061   93.061 /media/build/poky/bitbake/lib/bb/server/process.py:426(idle_thread_internal)
> >     16033   78.812    0.005   78.812    0.005 {built-in method select.select}
> >     16876    0.038    0.000   11.875    0.001 /media/build/poky/bitbake/lib/bb/cooker.py:1474(buildTargetsIdle)
> >     16876    0.019    0.000   11.835    0.001 /media/build/poky/bitbake/lib/bb/runqueue.py:1624(execute_runqueue)
> >     16876    0.084    0.000   11.816    0.001 /media/build/poky/bitbake/lib/bb/runqueue.py:1523(_execute_runqueue)
> >     16876    0.274    0.000    9.231    0.001 /media/build/poky/bitbake/lib/bb/runqueue.py:2149(execute)
> >    201858    0.615    0.000    3.589    0.000 /media/build/poky/bitbake/lib/bb/runqueue.py:3227(read)
> >     32302    0.062    0.000    2.924    0.000 /media/build/poky/bitbake/lib/bb/runqueue.py:1419(read_workers)
> >     37041    0.217    0.000    2.616    0.000 /media/build/poky/bitbake/lib/bb/event.py:190(fire_ui_handlers)
> >      1686    0.021    0.000    2.606    0.002 /media/build/poky/bitbake/lib/bb/runqueue.py:1328(send_pickled_data)
> >      1686    1.837    0.001    1.837    0.001 {method 'write' of '_io.BufferedWriter' objects}
> >       979    0.002    0.000    1.827    0.002 /media/build/poky/bitbake/lib/bb/command.py:110(runAsyncCommand)
> > 8960/8929    0.015    0.000    1.798    0.000 /media/build/poky/bitbake/lib/bb/event.py:217(fire)
> >      1621    1.355    0.001    1.491    0.001 /media/build/poky/bitbake/lib/bb/runqueue.py:2436(build_taskdepdata)
> >     17943    0.144    0.000    1.451    0.000 /media/build/poky/bitbake/lib/bb/cooker.py:113(send)
> >     28081    0.022    0.000    1.354    0.000 /media/build/poky/bitbake/lib/bb/event.py:237(fire_from_worker)
> > [...]
> >      3657    0.078    0.000    0.085    0.000 /media/build/poky/bitbake/lib/bb/runqueue.py:2409(filtermcdeps)
> > 
> > i.e. 1.3 million function calls to filtermcdeps becomes 3657, so
> > probably a valid speedup.
> > 
> > There is probably something different Alex is running into in his build
> > so I'll wait for the data for that case.
> > 
> > I'd note that whilst the performance logging patch does work, it can
> > mean the cooker is slow to shut down so if the mainloop file isn't
> > there, wait for the cooker to exit.
> 
> I did try a world build under dryrun and the profile for that is
> interesting:
> 
>    ncalls  tottime  percall  cumtime  percall filename:lineno(function)
>         1    1.965    1.965 2141.353 2141.353 /media/build/poky/bitbake/lib/bb/server/process.py:421(idle_thread_internal)
>     79527    0.362    0.000 2029.951    0.026 /media/build/poky/bitbake/lib/bb/cooker.py:1474(buildTargetsIdle)
>     79527    0.202    0.000 2029.579    0.026 /media/build/poky/bitbake/lib/bb/runqueue.py:1624(execute_runqueue)
>     79527    1.243    0.000 2029.377    0.026 /media/build/poky/bitbake/lib/bb/runqueue.py:1523(_execute_runqueue)
>     79527  820.305    0.010 2007.390    0.025 /media/build/poky/bitbake/lib/bb/runqueue.py:2149(execute)
>     64340    6.256    0.000  702.802    0.011 /media/build/poky/bitbake/lib/bb/runqueue.py:286(next)
>     34291  386.267    0.011  696.392    0.020 /media/build/poky/bitbake/lib/bb/runqueue.py:225(next_buildable_task)
>     32188  174.899    0.005  185.634    0.006 /media/build/poky/bitbake/lib/bb/runqueue.py:2436(build_taskdepdata)
> 147477450   90.392    0.000  156.644    0.000 /media/build/poky/bitbake/lib/bb/runqueue.py:38(taskname_from_tid)
>     32279    1.105    0.000  142.652    0.004 /media/build/poky/bitbake/lib/bb/runqueue.py:1328(send_pickled_data)
>     37605  100.098    0.003  100.098    0.003 {built-in method select.select}
>     32279   92.282    0.003   92.282    0.003 {method 'write' of '_io.BufferedWriter' objects}
>    703235    6.748    0.000   83.246    0.000 /media/build/poky/bitbake/lib/bb/event.py:190(fire_ui_handlers)
>     34309   77.040    0.002   77.040    0.002 {method 'difference' of 'set' objects}
>    117124    0.501    0.000   76.536    0.001 /media/build/poky/bitbake/lib/bb/runqueue.py:1419(read_workers)
>    197389    7.075    0.000   76.379    0.000 /media/build/poky/bitbake/lib/bb/runqueue.py:3228(read)
> 149286630   66.616    0.000   66.616    0.000 {method 'rsplit' of 'str' objects}
>    341878   52.515    0.000   52.515    0.000 {built-in method _pickle.dumps}
> 111790/109676    0.394    0.000   51.501    0.000 /media/build/poky/bitbake/lib/bb/event.py:217(fire)
>     68594   46.275    0.001   46.275    0.001 {method 'difference_update' of 'set' objects}
>    591445    0.700    0.000   43.421    0.000 /media/build/poky/bitbake/lib/bb/event.py:237(fire_from_worker)
>    309599    3.991    0.000   42.746    0.000 /media/build/poky/bitbake/lib/bb/cooker.py:113(send)
>     34308   25.668    0.001   25.668    0.001 {method 'intersection_update' of 'set' objects}
> 16970/15322   23.129    0.001   23.278    0.002 /media/build/poky/bitbake/lib/bb/runqueue.py:2683(scenequeue_updatecounters)
> 16739/15091    0.023    0.000   23.236    0.002 /media/build/poky/bitbake/lib/bb/runqueue.py:2748(sq_task_failoutright)
>     71163    0.436    0.000   20.433    0.000 /media/build/poky/bitbake/lib/bb/server/process.py:880(send)
>     71163    0.534    0.000   17.511    0.000 /media/build/poky/bitbake/lib/bb/server/process.py:874(_send)
>     71163    0.422    0.000   16.073    0.000 /usr/lib/python3.11/multiprocessing/connection.py:182(send_bytes)
> 
> in particular the 147 million calls to taskname_from_tid(). Definitely
> something to be done in there.

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.

Cheers,

Richard