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

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

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.

Cheers,

Richard