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

[Mikko.Rapeli at bmw.de]

On Wed, Aug 14, 2019 at 02:08:01PM +0200, Alexander Kanavin wrote:
> On Wed, 14 Aug 2019 at 13:36, <richard.purdie at linuxfoundation.org> wrote:
> 
> > On Wed, 2019-08-14 at 13:25 +0200, Alexander Kanavin wrote:
> > > On Tue, 13 Aug 2019 at 21:18, Richard Purdie <
> > > richard.purdie at linuxfoundation.org> wrote:
> > > > I had a glance at the profile output from master-next and the
> > > > problem
> > > > wasn't where I thought it would be, it was in the scheduler code.
> > > > That
> > > > is good as those classes are effectively independent of the other
> > > > changes and hence are a separate fix.
> > > >
> > > > I've put a patch in -next which takes the above test to 36s which
> > > > is
> > > > close to the older bitbake.
> > > >
> > > > Could be interesting to see how it looks for others and different
> > > > workloads.
> > >
> > > I just tried the same test I did yesterday with
> > > ab56d466452148e5fce330d279d13e2495eceb1f. Unfortunately it doesn't
> > > seem to improve things much: bitbake is stuck at "NOTE: Executing
> > > Tasks" for 15 minutes now.
> >
> > This might sound slightly crazy but can you try commenting out this
> > line in runqueue.py:
> >
> > logger.debug(2, "Holding off tasks %s" %
> > pprint.pformat(self.holdoff_tasks))
> >
> > ?
> >
> 
> Even crazier is the outcome: it helped! The whole thing completed after
> 15m49secons (with much of the time going to the empty task spin), that's
> some 3 minutes slower, but certainly it's usable again.
> 
> I have not enabled the hash server at any point.

Indeed, commenting that debug statement out removes few minutes of the
bitbake preparation times.

Here is a time stamped output from master branch:

2019-08-14_14:29:24  
2019-08-14_14:29:35  Initialising tasks...done.
2019-08-14_14:32:41  Checking sstate mirror object availability...done.
2019-08-14_14:32:41  Sstate summary: Wanted 436 Found 426 Missed 10 Current 2407 (97% match, 99% complete)
2019-08-14_14:32:41  NOTE: Executing Tasks
2019-08-14_14:32:52  NOTE: Setscene tasks completed

And with the comment removed:

2019-08-14_14:35:10  
2019-08-14_14:35:21  Initialising tasks...done.
2019-08-14_14:35:30  Checking sstate mirror object availability...done.
2019-08-14_14:35:30  Sstate summary: Wanted 436 Found 426 Missed 10 Current 2407 (97% match, 99% complete)
2019-08-14_14:35:30  NOTE: Executing Tasks

And just in case back to master branch state:

2019-08-14_14:41:32  
2019-08-14_14:41:43  Initialising tasks...done.
2019-08-14_14:45:02  Checking sstate mirror object availability...done.
2019-08-14_14:45:02  Sstate summary: Wanted 436 Found 426 Missed 10 Current 2407 (97% match, 99% complete)
2019-08-14_14:45:02  NOTE: Executing Tasks

I did not flush caches in between and I stopped the builds once bitbake started doing stuff, so I think sstate cache was completely buffered in memory
from file system and IO delays did not affect the timings.

Change to poky was exactly:

--- a/bitbake/lib/bb/runqueue.py
+++ b/bitbake/lib/bb/runqueue.py
@@ -2216,7 +2216,7 @@ class RunQueueExecute:
             for dep in self.sqdata.sq_covered_tasks[tid]:
                 if dep not in self.runq_complete:
                     self.holdoff_tasks.add(dep)
-        logger.debug(2, "Holding off tasks %s" % pprint.pformat(self.holdoff_tasks))
+        # logger.debug(2, "Holding off tasks %s" % pprint.pformat(self.holdoff_tasks))
 
     def process_possible_migrations(self):
         changes = False

-Mikko