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

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

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.

Cheers,

Richard