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

Comparing that build to a corresponding do-nothing build with Thud, the time difference matches those three minutes where I have no idea what bitbake is doing now that it didn’t need to do before…

Hopefully these time degradations can be solved, because the current state of bitbake is barely usable. We also need to look into possible ways to improve the cooker output when it is running the setscene tasks so it makes some kind of sense again.

We talked on irc and you pointed at the commit things started to go wrong. Just to summarise things for the benefit of the list, this is some quick testing I did:

"bitbake -p; time bitbake core-image-minimal -n"

30.0s 6c7c0cefd34067311144a1d4c01986fe0a4aef26
30.6s a0d941c787cf3ef030d190903279d311bc05d752
40.3s 7df31ff36892c2f9c65326b06b4c70
42.2s a0542ed3ff700eca35f9195f743c9e28bcd50f3e
45.4s 9983b07fffd19082abded7c3f15cc77d306dd69c
76.9s master-next

So basically the original changes showed a 25% hit but the performance of -next is dire.

Quoted 11 lines · Peter Kjellerstedt

Comparing that build to a corresponding do-nothing build with Thud, the time difference matches those three minutes where I have no idea
what bitbake is doing now that it didn’t need to do before…

Hopefully these time degradations can be solved, because the current
state of bitbake is barely usable. We also need to look into possible
ways to improve the cooker output when it is running the setscene tasks so it makes some kind of sense again.

We talked on irc and you pointed at the commit things started to go wrong. Just to summarise things for the benefit of the list, this is some quick testing I did:

"bitbake -p; time bitbake core-image-minimal -n"

30.0s 6c7c0cefd34067311144a1d4c01986fe0a4aef26
30.6s a0d941c787cf3ef030d190903279d311bc05d752
40.3s 7df31ff36892c2f9c65326b06b4c70
42.2s a0542ed3ff700eca35f9195f743c9e28bcd50f3e
45.4s 9983b07fffd19082abded7c3f15cc77d306dd69c
76.9s master-next

So basically the original changes showed a 25% hit but the performance
of -next is dire.

This is with no hash equiv server configured.

It will vary depending on the target used (numbers with -sato for the above would be interesting for comparision) and how much was or is in sstate, they type of sstate mirror configured and so on.

I really need to focus on getting the new code functioning correctly before we attempt to optimise but if nobody tests the new code due to performance problems we have a different issue. We also have a scaling
problem with the hash server itself I need to fix to stop the autobuilder throwing weird errors. I'm therefore a bit challenged on where to start with it all :/.

Quoted 36 lines · Richard Purdie

Quoted 11 lines · Peter Kjellerstedt

Comparing that build to a corresponding do-nothing build with Thud, the time difference matches those three minutes where I have no idea
what bitbake is doing now that it didn’t need to do before…

Hopefully these time degradations can be solved, because the current
state of bitbake is barely usable. We also need to look into possible
ways to improve the cooker output when it is running the setscene tasks so it makes some kind of sense again.

We talked on irc and you pointed at the commit things started to go wrong. Just to summarise things for the benefit of the list, this is some quick testing I did:

"bitbake -p; time bitbake core-image-minimal -n"

30.0s 6c7c0cefd34067311144a1d4c01986fe0a4aef26
30.6s a0d941c787cf3ef030d190903279d311bc05d752
40.3s 7df31ff36892c2f9c65326b06b4c70
42.2s a0542ed3ff700eca35f9195f743c9e28bcd50f3e
45.4s 9983b07fffd19082abded7c3f15cc77d306dd69c
76.9s master-next

So basically the original changes showed a 25% hit but the performance
of -next is dire.

This is with no hash equiv server configured.

It will vary depending on the target used (numbers with -sato for the above would be interesting for comparision) and how much was or is in sstate, they type of sstate mirror configured and so on.

Quoted 7 lines

I really need to focus on getting the new code functioning correctly before we attempt to optimise but if nobody tests the new code due to performance problems we have a different issue. We also have a scaling
problem with the hash server itself I need to fix to stop the autobuilder throwing weird errors. I'm therefore a bit challenged on where to start with it all :/.

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.

Cheers,

Richard

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.

Quoted 11 lines · Richard Purdie

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.

Quoted 2 lines

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.

Quoted 13 lines · Alexander Kanavin

Quoted 11 lines · Richard Purdie

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.

Quoted 7 lines

Quoted 2 lines

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))

?

This might sound slightly crazy but can you try commenting out this

Quoted 5 lines

line in runqueue.py:

logger.debug(2, "Holding off tasks %s" %
pprint.pformat(self.holdoff_tasks))

Quoted 2 lines

?

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.

Quoted 28 lines · On Wed, 14 Aug 2019 at 13:36, <[email protected]> wrote:

Quoted 13 lines · Alexander Kanavin

Quoted 11 lines · Richard Purdie

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.

Quoted 7 lines

Quoted 2 lines

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))

Quoted 2 lines

?

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.

Quoted 30 lines · On Wed, 14 Aug 2019 at 13:36, <[email protected]> wrote:

Quoted 5 lines · Alexander Kanavin

Quoted 3 lines · Richard Purdie

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.

Quoted 2 lines

Quoted 2 lines

That
is good as those classes are effectively independent of the

other

Quoted 3 lines

Quoted 3 lines

changes and hence are a separate fix.

I've put a patch in -next which takes the above test to 36s

which

Quoted 4 lines

Quoted 4 lines

is
close to the older bitbake.

Could be interesting to see how it looks for others and

different

Quoted 4 lines

Quoted 1 line

workloads.

I just tried the same test I did yesterday with ab56d466452148e5fce330d279d13e2495eceb1f. Unfortunately it

doesn't

Quoted 2 lines

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:

Quoted 4 lines

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.

-----Original Message-----
From: [email protected] <[email protected]>
Sent: den 14 augusti 2019 14:56
To: Alexander Kanavin <[email protected]>
Cc: Peter Kjellerstedt <[email protected]>; Khem Raj <[email protected]>; OE-core <openembedded- [email protected]>
Subject: Re: [OE-core] Long delays with latest bitbake (was: [PATCH 1/7] insane.bbclass: in file-rdeps do not look into RDEPENDS recursively)

Quoted 32 lines · Alexander Kanavin

Quoted 30 lines · On Wed, 14 Aug 2019 at 13:36, <[email protected]> wrote:

Quoted 5 lines · Alexander Kanavin

Quoted 3 lines · Richard Purdie

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.

Quoted 2 lines

Quoted 2 lines

That
is good as those classes are effectively independent of the

other

Quoted 3 lines

Quoted 3 lines

changes and hence are a separate fix.

I've put a patch in -next which takes the above test to 36s

which

Quoted 4 lines

Quoted 4 lines

is
close to the older bitbake.

Could be interesting to see how it looks for others and

different

Quoted 4 lines

Quoted 1 line

workloads.

I just tried the same test I did yesterday with ab56d466452148e5fce330d279d13e2495eceb1f. Unfortunately it

doesn't

Quoted 2 lines

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:

Quoted 6 lines

Quoted 4 lines

logger.debug(2, "Holding off tasks %s" %
pprint.pformat(self.holdoff_tasks))

?

Even crazier is the outcome: it helped!

Cool, I think I can explain it.

The holdoff_tasks list can contain a list of nearly all the tasks at some points in execution. Even though the debug messages aren't being printed on the console, they are being sent over the internal IPC bus between the cooker, UI and other event handlers. Obviously for small task lists its not a problem, for large ones its multiple 4k chunks over pipes which isn't going to be fast.

We have done a lot of optimisation in the past but its all too easy to trend on something like this and upset things :/.

Quoted 3 lines

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.

You followed up mentioning this wasn't with master-next. I think there is a patch in -next which will help with the empty task spin so both together might get us back to more normal numbers.

Cheers,

Richard

Quoted 69 lines

-----Original Message-----
From: [email protected] <[email protected]>
Sent: den 14 augusti 2019 14:56
To: Alexander Kanavin <[email protected]>
Cc: Peter Kjellerstedt <[email protected]>; Khem Raj <[email protected]>; OE-core <openembedded- [email protected]>
Subject: Re: [OE-core] Long delays with latest bitbake (was: [PATCH 1/7] insane.bbclass: in file-rdeps do not look into RDEPENDS recursively)

Quoted 32 lines · Alexander Kanavin

Quoted 30 lines · On Wed, 14 Aug 2019 at 13:36, <[email protected]> wrote:

Quoted 5 lines · Alexander Kanavin

Quoted 3 lines · Richard Purdie

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.

Quoted 2 lines

Quoted 2 lines

That
is good as those classes are effectively independent of the

other

Quoted 3 lines

Quoted 3 lines

changes and hence are a separate fix.

I've put a patch in -next which takes the above test to 36s

which

Quoted 4 lines

Quoted 4 lines

is
close to the older bitbake.

Could be interesting to see how it looks for others and

different

Quoted 4 lines

Quoted 1 line

workloads.

I just tried the same test I did yesterday with ab56d466452148e5fce330d279d13e2495eceb1f. Unfortunately it

doesn't

Quoted 2 lines

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:

Quoted 6 lines

Quoted 4 lines

logger.debug(2, "Holding off tasks %s" %
pprint.pformat(self.holdoff_tasks))

?

Even crazier is the outcome: it helped!

Cool, I think I can explain it.

The holdoff_tasks list can contain a list of nearly all the tasks at some points in execution. Even though the debug messages aren't being printed on the console, they are being sent over the internal IPC bus between the cooker, UI and other event handlers. Obviously for small task lists its not a problem, for large ones its multiple 4k chunks over pipes which isn't going to be fast.

We have done a lot of optimisation in the past but its all too easy to trend on something like this and upset things :/.

Quoted 3 lines

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.

Quoted 7 lines

You followed up mentioning this wasn't with master-next. I think there is a patch in -next which will help with the empty task spin so both together might get us back to more normal numbers.

Cheers,

Richard

I can just confirm that removing the debug line removes almost all of the delays I was seeing. Here are some time statistics from my builds:

6c7c0cef: 02:50
7df31ff3: 06:13 (first attempt)
a0542ed3: 06:32 (master)
19a88c68: 43:19* (~yesterday's master-next)
b0a0e4a6: 06:55 (master-next)
no debug: 03:04 (master-next + removal of "Holding off tasks" debug)

* I aborted this build after about half of the 12540 tasks were done...

One thing I have noticed while I was doing the timings is that I do not seem to be able to kill the bitbake server with bitbake -m after the builds have completed, but have to resort to using kill -9 most of the time...

//Peter

You followed up mentioning this wasn't with master-next. I think there is a patch in -next which will help with the empty task spin so both together might get us back to more normal numbers.

Quoted 6 lines · On Wed, 14 Aug 2019 at 14:55, <[email protected]> wrote:

You followed up mentioning this wasn't with master-next. I think there
is a patch in -next which will help with the empty task spin so both
together might get us back to more normal numbers.

As all of these patches are now in master, I re-ran the test with that (209f89ab8ed51ac2867ca8f749336af1ee24ab25), but without including the spinning task part, pressing ctrl-c just as it starts. The outcome is 9m42s, compared to 2m9s for the baseline (6c7c0cefd34067311144a1d4c01986fe0a4aef26). So the worst is fixed, but the slowdown is still noticeable.

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.

Quoted 17 lines · On Wed, 14 Aug 2019 at 23:25, <[email protected]> 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.

Quoted 5 lines

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!

On Thu, 2019-08-15 at 14:56 +0200, Alexander Kanavin wrote:
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(notific ations)

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.

Quoted 8 lines · Peter Kjellerstedt

Comparing that build to a corresponding do-nothing build with Thud, the time difference matches those three minutes where I have no idea what bitbake is doing now that it didn’t need to do before…

Hopefully these time degradations can be solved, because the current state of bitbake is barely usable. We also need to look into possible ways to improve the cooker output when it is running the setscene tasks so it makes some kind of sense again.

We talked on irc and you pointed at the commit things started to go wrong. Just to summarise things for the benefit of the list, this is some quick testing I did:

"bitbake -p; time bitbake core-image-minimal -n"

30.0s 6c7c0cefd34067311144a1d4c01986fe0a4aef26
30.6s a0d941c787cf3ef030d190903279d311bc05d752
40.3s 7df31ff36892c2f9c65326b06b4c70
42.2s a0542ed3ff700eca35f9195f743c9e28bcd50f3e
45.4s 9983b07fffd19082abded7c3f15cc77d306dd69c
76.9s master-next

So basically the original changes showed a 25% hit but the performance of -next is dire.

This is with no hash equiv server configured.

It will vary depending on the target used (numbers with -sato for the above would be interesting for comparision) and how much was or is in sstate, they type of sstate mirror configured and so on.

I really need to focus on getting the new code functioning correctly before we attempt to optimise but if nobody tests the new code due to performance problems we have a different issue. We also have a scaling problem with the hash server itself I need to fix to stop the autobuilder throwing weird errors. I'm therefore a bit challenged on where to start with it all :/.

Cheers,

Richard

Signature · 4 lines

_______________________________________________
Openembedded-core mailing list
[email protected]
http://lists.openembedded.org/mailman/listinfo/openembedded-core

Quoted 14 lines · Richard Purdie

Quoted 8 lines · Peter Kjellerstedt

Comparing that build to a corresponding do-nothing build with Thud, the time difference matches those three minutes where I have no idea what bitbake is doing now that it didn’t need to do before…

Hopefully these time degradations can be solved, because the current state of bitbake is barely usable. We also need to look into possible ways to improve the cooker output when it is running the setscene tasks so it makes some kind of sense again.

We talked on irc and you pointed at the commit things started to go wrong. Just to summarise things for the benefit of the list, this is some quick testing I did:

Quoted 8 lines

"bitbake -p; time bitbake core-image-minimal -n"

30.0s 6c7c0cefd34067311144a1d4c01986fe0a4aef26
30.6s a0d941c787cf3ef030d190903279d311bc05d752
40.3s 7df31ff36892c2f9c65326b06b4c70
42.2s a0542ed3ff700eca35f9195f743c9e28bcd50f3e
45.4s 9983b07fffd19082abded7c3f15cc77d306dd69c
76.9s master-next

I know I'm late to the party, but it took really long for the test to finish..

I'm not using poky, so reproduce this testing on our builds I've used bitbake revisions matching with poky revision RP was testing:

+ oe-core 18cdc087fd5da30e2b31f3d4e81b153cd36ca844 for older bitbake, because current master isn't compatible with old bitbake (bb.data_smart.ExpansionError: Failure expanding variable OE_IMPORTED[:=], expression was ${@oe_import(d)} which triggered exception AttributeError: module 'bb.siggen' has no attribute 'SignatureGeneratorUniHashMixIn') and oe-core 23db236a054ee7a989cdbbcb42ad5c6eefd4a6ae for newer bitbake (to possibly eliminate impact of metadata changes)

tested on 72core (Intel(R) Xeon(R) CPU E5-2699 v3 @ 2.30GHz) with 380GB RAM

nothing in TMPDIR/SSTATE_DIR, no SSTATE_MIRRO, no Hash Equivalence Server configured

on a build with few more layers:
Parsing of 3238 .bb files complete (0 cached, 3238 parsed). 7632 targets, 1927 skipped, 54 masked, 0 errors.

but first doing just core-image-minimal like RP did:

time poky bitbake oe-core
2m8.191s 6c7c0cefd34067311144a1d4c01986fe0a4aef26 18d4a31fdcec1f0e5d2199d6142f0ce833fca1a7 18cdc087fd5da30e2b31f3d4e81b153cd36ca844
N/A a0d941c787cf3ef030d190903279d311bc05d752 doesn't exist in poky/poky-contrib 18cdc087fd5da30e2b31f3d4e81b153cd36ca844
2m17.053s 7df31ff36892c2f9c65326b06b4c70 1f630fdf0260db08541d3ca9f25f852931c19905 18cdc087fd5da30e2b31f3d4e81b153cd36ca844
2m18.515s a0542ed3ff700eca35f9195f743c9e28bcd50f3e f43778c2d19e70d4befd483b06aaf247fc65c799 23db236a054ee7a989cdbbcb42ad5c6eefd4a6ae
2m22.220s 9983b07fffd19082abded7c3f15cc77d306dd69c 8c26b451f22193ef1c544e2017cc84515566c1b8
2m38.185s master-next fbcb89dc3dbabfc80310e9a4ebe72d919300a32e
cache.py:446: ResourceWarning: unclosed <socket.socket fd=10, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('127.0.0.1', 41117)>
value = pickled.load()
started showing with this revision
2m17.991s master-next + fixups f7cd14f90463957b3e4be6d3876def98b78f1424
2m9.651s master-next + "Holding off tasks %s" out

now world
253m36.637s 7df31ff36892c2f9c65326b06b4c70 1f630fdf0260db08541d3ca9f25f852931c19905 18cdc087fd5da30e2b31f3d4e81b153cd36ca844
174m13.324s a0542ed3ff700eca35f9195f743c9e28bcd50f3e f43778c2d19e70d4befd483b06aaf247fc65c799 23db236a054ee7a989cdbbcb42ad5c6eefd4a6ae
this is time when killed at "NOTE: Executing Tasks" without showing any progress on the tasks (unlike other tests) and only one bitbake process is running
633m27.475s master-next fbcb89dc3dbabfc80310e9a4ebe72d919300a32e
this is time when killed at (1417 from 71749) - running very slowly unlike other bitbake revisions where the task number changes relatively quickly - about 10 tasks per second
89m13.992s master-next + "Holding off tasks %s" out
89m59.201s master-next updated today 85fe627fdb6510f0942917964386fad9d8c479c8

Interestingly old 1f630fdf0260db08541d3ca9f25f852931c19905 is 3 times slower than recent master-next.

I'll send -P output next.

Quoted 29 lines

So basically the original changes showed a 25% hit but the performance of -next is dire.

This is with no hash equiv server configured.

It will vary depending on the target used (numbers with -sato for the above would be interesting for comparision) and how much was or is in sstate, they type of sstate mirror configured and so on.

I really need to focus on getting the new code functioning correctly before we attempt to optimise but if nobody tests the new code due to performance problems we have a different issue. We also have a scaling problem with the hash server itself I need to fix to stop the autobuilder throwing weird errors. I'm therefore a bit challenged on where to start with it all :/.

Cheers,

Richard

Signature · 4 lines

_______________________________________________
Openembedded-core mailing list
[email protected]
http://lists.openembedded.org/mailman/listinfo/openembedded-core

Signature · 1 line

Martin 'JaMa' Jansa     jabber: [email protected]

Will try to bump BB_NUMBER_THREADS from 8 to 72.

Quoted 17 lines · Martin Jansa

Quoted 16 lines · Richard Purdie

Quoted 8 lines · Peter Kjellerstedt

Comparing that build to a corresponding do-nothing build with Thud, the time difference matches those three minutes where I have no idea what bitbake is doing now that it didn’t need to do before…

Hopefully these time degradations can be solved, because the current state of bitbake is barely usable. We also need to look into possible ways to improve the cooker output when it is running the setscene tasks so it makes some kind of sense again.

We talked on irc and you pointed at the commit things started to go wrong. Just to summarise things for the benefit of the list, this is some quick testing I did:

"bitbake -p; time bitbake core-image-minimal -n"

Quoted 8 lines

Quoted 6 lines

30.0s 6c7c0cefd34067311144a1d4c01986fe0a4aef26
30.6s a0d941c787cf3ef030d190903279d311bc05d752
40.3s 7df31ff36892c2f9c65326b06b4c70
42.2s a0542ed3ff700eca35f9195f743c9e28bcd50f3e
45.4s 9983b07fffd19082abded7c3f15cc77d306dd69c
76.9s master-next

I know I'm late to the party, but it took really long for the test to

finish..

Quoted 5 lines

I'm not using poky, so reproduce this testing on our builds I've used bitbake revisions matching with poky revision RP was testing:

+ oe-core 18cdc087fd5da30e2b31f3d4e81b153cd36ca844 for older bitbake,

because current master isn't compatible with old bitbake (bb.data_smart.ExpansionError: Failure expanding variable OE_IMPORTED[:=], expression was ${@oe_import(d)} which triggered exception AttributeError:
module 'bb.siggen' has no attribute 'SignatureGeneratorUniHashMixIn')

Quoted 1 line

and oe-core 23db236a054ee7a989cdbbcb42ad5c6eefd4a6ae for newer bitbake

(to possibly eliminate impact of metadata changes)

Quoted 2 lines

tested on 72core (Intel(R) Xeon(R) CPU E5-2699 v3 @ 2.30GHz) with 380GB

RAM

Quoted 2 lines

nothing in TMPDIR/SSTATE_DIR, no SSTATE_MIRRO, no Hash Equivalence

Server configured

Quoted 3 lines

on a build with few more layers:
Parsing of 3238 .bb files complete (0 cached, 3238 parsed). 7632

targets, 1927 skipped, 54 masked, 0 errors.

Quoted 4 lines

but first doing just core-image-minimal like RP did:

time poky bitbake

oe-core

Quoted 1 line

2m8.191s 6c7c0cefd34067311144a1d4c01986fe0a4aef26

18d4a31fdcec1f0e5d2199d6142f0ce833fca1a7
18cdc087fd5da30e2b31f3d4e81b153cd36ca844

Quoted 1 line

N/A a0d941c787cf3ef030d190903279d311bc05d752 doesn't

exist in poky/poky-contrib
18cdc087fd5da30e2b31f3d4e81b153cd36ca844

Quoted 1 line

2m17.053s 7df31ff36892c2f9c65326b06b4c70

1f630fdf0260db08541d3ca9f25f852931c19905
18cdc087fd5da30e2b31f3d4e81b153cd36ca844

Quoted 1 line

2m18.515s a0542ed3ff700eca35f9195f743c9e28bcd50f3e

f43778c2d19e70d4befd483b06aaf247fc65c799
23db236a054ee7a989cdbbcb42ad5c6eefd4a6ae

Quoted 1 line

2m22.220s 9983b07fffd19082abded7c3f15cc77d306dd69c

8c26b451f22193ef1c544e2017cc84515566c1b8

Quoted 1 line

2m38.185s master-next

fbcb89dc3dbabfc80310e9a4ebe72d919300a32e

Quoted 1 line

cache.py:446: ResourceWarning: unclosed <socket.socket fd=10,

family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('127.0.0.1', 41117)>

Quoted 3 lines

value = pickled.load()
started showing with this revision
2m17.991s master-next + fixups

f7cd14f90463957b3e4be6d3876def98b78f1424

Quoted 4 lines

2m9.651s master-next + "Holding off tasks %s" out

now world
253m36.637s 7df31ff36892c2f9c65326b06b4c70

1f630fdf0260db08541d3ca9f25f852931c19905
18cdc087fd5da30e2b31f3d4e81b153cd36ca844

Quoted 1 line

174m13.324s a0542ed3ff700eca35f9195f743c9e28bcd50f3e

f43778c2d19e70d4befd483b06aaf247fc65c799
23db236a054ee7a989cdbbcb42ad5c6eefd4a6ae

Quoted 1 line

this is time when killed at "NOTE: Executing Tasks" without showing

any progress on the tasks (unlike other tests) and only one bitbake process is running

Quoted 1 line

633m27.475s master-next

fbcb89dc3dbabfc80310e9a4ebe72d919300a32e

Quoted 1 line

this is time when killed at (1417 from 71749) - running very slowly

unlike other bitbake revisions where the task number changes relatively quickly - about 10 tasks per second

Quoted 2 lines

89m13.992s master-next + "Holding off tasks %s" out
89m59.201s master-next updated today

85fe627fdb6510f0942917964386fad9d8c479c8

Quoted 5 lines

Interestingly old 1f630fdf0260db08541d3ca9f25f852931c19905 is 3 times slower than recent master-next.

I'll send -P output next.

So 1f630fdf0260db08541d3ca9f25f852931c19905 was already "bad", because this commit introduced that
logger.debug(2, "Holding off tasks %s" % pprint.pformat(self.holdoff_tasks))

Here is -P output from it:

5min (til "Executing Tasks" message):
profile.log.processed.1f630fdf0260db08541d3ca9f25f852931c19905.return.at .Executing.Tasks
http://paste.ubuntu.com/p/Nw6n5hTPmF/

5hours (whole dry run):

profile.log.processed.1f630fdf0260db08541d3ca9f25f852931c19905.whole.dry.run
http://paste.ubuntu.com/p/sydFGvYTxQ/

profile.log.processed.1f630fdf0260db08541d3ca9f25f852931c19905.worker.log.processed
http://paste.ubuntu.com/p/RMGbm9DyZz/

So for good old baseline I need to go few commits back, to e.g. 18d4a31f RP was testing before:

1f630fdf runqueue: Enable dynamic task adjustment to hash equivalency a0d941c7 siggen: Convert to use self.unitaskhashes
1f326f2c siggen: Add new unitaskhashes data variable which is cached b707d0cb runqueue: Improve scenequeue processing logic 19a6e356 cache: Add SimpleCache class
7bb79099 siggen: Import unihash code from OE-Core
7aec8632 hashserv: SQL Optimizations
18d4a31f fetch2/wget: avoid 'maximum recursion depth' RuntimeErrors when handling 403 codes

94m19.081s

profile.log.processed.18d4a31fdcec1f0e5d2199d6142f0ce833fca1a7.whole.dry.run
http://paste.ubuntu.com/p/Jnvv8GJNKB/

And here is profile with latest master from yesterday:
90mins:

profile.log.processed.a5e084a266f63c2fd370122327615e49beaeb94e.whole.dry.run
http://paste.ubuntu.com/p/YhMCHPmg56/

So good news is that current master is a bit faster than "good old" 18d4a31fdcec1f0e5d2199d6142f0ce833fca1a7.

But still significantly slower on my fast builder compared to world tests on poky + meta-oe,
not sure if it's all just because the size of metadata in my builds (with 71K tasks).

Even the dry running the tasks was about 10 tasks/second while RP was seeing around 200 tasks/second.

Will try to bump BB_NUMBER_THREADS from 8 to 72.

I've already disabled rm_work and PRserv, but that doesn't seem to have any significant impact on performance here. Other than resolving the PRserv terminating and then warnings about lost connection.

Cheers,

Quoted 24 lines

Quoted 24 lines

So basically the original changes showed a 25% hit but the performance of -next is dire.

This is with no hash equiv server configured.

It will vary depending on the target used (numbers with -sato for the above would be interesting for comparision) and how much was or is in sstate, they type of sstate mirror configured and so on.

I really need to focus on getting the new code functioning correctly before we attempt to optimise but if nobody tests the new code due to performance problems we have a different issue. We also have a scaling problem with the hash server itself I need to fix to stop the autobuilder throwing weird errors. I'm therefore a bit challenged on where to start with it all :/.

Cheers,

Richard

Quoted 8 lines

Quoted 5 lines

--
_______________________________________________
Openembedded-core mailing list
[email protected]
http://lists.openembedded.org/mailman/listinfo/openembedded-core

--
Martin 'JaMa' Jansa jabber: [email protected]

--
Martin 'JaMa' Jansa jabber: [email protected]

Quoted 1 line

Will try to bump BB_NUMBER_THREADS from 8 to 72.

I've tried to remove icecc.bbclass inherit (because it does things while parsing and RP probably doesn't have it inherited), but that didn't save much time.

All 3 tests were with bitbake
18d4a31fdcec1f0e5d2199d6142f0ce833fca1a7
94m19.081s 8 BB_NUMBER_THREADS and icecc
82m59.574s 8 BB_NUMBER_THREADS no icecc
68m3.556s 72 BB_NUMBER_THREADS no icecc

Still don't know how to get to sub 10min world runs RP was seeing, but at least it's as slow as it was before runqeueu changes (or even a bit faster in lastest master).

Quoted 12 lines · Martin Jansa

Quoted 1 line

Will try to bump BB_NUMBER_THREADS from 8 to 72.

I've tried to remove icecc.bbclass inherit (because it does things while parsing and RP probably doesn't have it inherited), but that didn't save much time.

All 3 tests were with bitbake
18d4a31fdcec1f0e5d2199d6142f0ce833fca1a7
94m19.081s 8 BB_NUMBER_THREADS and icecc
82m59.574s 8 BB_NUMBER_THREADS no icecc
68m3.556s 72 BB_NUMBER_THREADS no icecc

Quoted 3 lines

Still don't know how to get to sub 10min world runs RP was seeing, but at least it's as slow as it was before runqeueu changes (or even a bit faster in lastest master).

Just thinking out loud, other things which can influence timings:

Is SSTATE_DIR on NFS or local disk?

Are sstate mirrors configured?

Is there an existing build or not, if so, how much is valid?

Underlying filesystem of the build?

Your build seems especially slow at executing through the tasks which is effectively a test on how fast the system can fork() and return in some ways. It would be interesting to block dry-run on the server side, skip the fork and see how the numbers compare.

My build manages some parts of the tasklist faster than others, perhaps because there are more "free" tasks to execute at some points in the task graph than others.

Also, I have some patches which improve performance a bit which I'm still testing.

Quoted 13 lines · On Fri, Aug 16, 2019 at 04:54:48PM +0100, [email protected]…

Quoted 12 lines · Martin Jansa

Quoted 1 line

Will try to bump BB_NUMBER_THREADS from 8 to 72.

I've tried to remove icecc.bbclass inherit (because it does things while parsing and RP probably doesn't have it inherited), but that didn't save much time.

All 3 tests were with bitbake
18d4a31fdcec1f0e5d2199d6142f0ce833fca1a7
94m19.081s 8 BB_NUMBER_THREADS and icecc
82m59.574s 8 BB_NUMBER_THREADS no icecc
68m3.556s 72 BB_NUMBER_THREADS no icecc

Quoted 7 lines

Quoted 3 lines

Still don't know how to get to sub 10min world runs RP was seeing, but at least it's as slow as it was before runqeueu changes (or even a bit faster in lastest master).

Just thinking out loud, other things which can influence timings:

Is SSTATE_DIR on NFS or local disk?

SSTATE_DIR is empty directory on local disk
/dev/mapper/vg00-jenkins on /jenkins type ext4 (rw,noatime,nobarrier,commit=6000,stripe=128,data=ordered)

Quoted 1 line

Are sstate mirrors configured?

None, normally I have SSTATE_MIRRORS over sshfs in this case, but I've removed it before any performance testing.

Quoted 1 line

Is there an existing build or not, if so, how much is valid?

Nothing, I remove whole TMPDIR and cache before each run. Then let it recreate the cache before starting the profile:
bitbake -p; time bitbake world -P -n

Quoted 1 line

Underlying filesystem of the build?

ext4, everything is pretty much generic Ubuntu 18.04

There is plenty of ram, I'll try to test this from tmpfs as well.

Quoted 4 lines

Your build seems especially slow at executing through the tasks which is effectively a test on how fast the system can fork() and return in some ways. It would be interesting to block dry-run on the server side, skip the fork and see how the numbers compare.

As discussed on IRC, it's slower than yours (8 minutes from 68), but the most significant chunk of time is lost somewhere else.

Quoted 6 lines

My build manages some parts of the tasklist faster than others, perhaps because there are more "free" tasks to execute at some points in the task graph than others.

Also, I have some patches which improve performance a bit which I'm still testing.

Thanks for all the work on this!

Cheers,

Signature · 1 line

Martin 'JaMa' Jansa     jabber: [email protected]