[OE-core] Long delays with latest bitbake (was: [PATCH 1/7] insane.bbclass: in file-rdeps do not look into RDEPENDS recursively)

[richard.purdie at linuxfoundation.org]

On Thu, 2019-08-15 at 14:56 +0200, Alexander Kanavin wrote:
> On Wed, 14 Aug 2019 at 23:25, <richard.purdie at linuxfoundation.org>
> wrote:
> > Right, it still definitely needs work. Its a balancing act between
> > sorting out the execution bugs in the code and figuring out the
> > performance problem.
> > 
> > If anyone wants to experiment, the way I'd debug this is to run the
> > before and after cases with the -P option to bitbake. If you want
> > to
> > exit early just make the code return where it prints "Executing
> > tasks"
> > or whatever makes sense as Ctrl+C won't write the profile data.
> > 
> > You want the profile.log.processed file.
> > 
> > So save that file with the "before" commit, then save it afterwards
> > and
> > look at those files and see where its spending more time.
> > 
> > If someone generates those two files I'll happily take a look, I'm
> > kind
> > of used to reading them. There are four sets of output in there,
> > same
> > data but different sorting/types, each has its uses.
> 
> And here they are (with task spinning included this time):
> http://sensi.org/~ak/tmp/profile.log.processed.before
> http://sensi.org/~ak/tmp/profile.log.processed.after
> 
> Hope you find it useful!

How many tasks are in that build?

What is really odd is this on both traces:

   524436  405.102    0.001  405.266    0.001 /home/alexander/development/poky/bitbake/lib/bb/cooker.py:264(notifications)

What that means is that cooker recieved notification of 524436 file
changes whilst it was parsing/preparing runqueue.

I would be very interested to understand which files its being notified
of changes to as I suspect there is something that shouldn't be there.

If we fixed that, it would take 406s off the 1800s for starters in both
cases. I don't see that locally in my trace, my build layout may be
different.

Other things of note:

Time in next_buildable_task went up 338 -> 440s
(probably through the set manipulation e.g. method 'difference' of
'set' objects)
New function update_holdofftasks() took 173s

build_taskdepdata is also eating lots of time suddenly.

So yes, useful, thanks. You may want to add some debug to that
nofitications() function in cooker and see which files are changing
though.

Cheers,

Richard