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

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

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.

Cheers,

Richard