regression of 'world' performance?

regression of 'world' performance?

[Alexander Kanavin]

Hello all,

there seems to be a noticeable slowdown in bitbake doing world builds,
particularly when layers in meta-oe are added to it. I've locally
observed Cooker process spinning at 100% while no or few tasks get
executed, apparently deciding what to do next, and it is noticeable in
autobuilder too, e.g. right now:
https://autobuilder.yoctoproject.org/typhoon/#/builders/88/builds/3515

I'd like to profile what is happening, but not sure where to start. Suggestions?

Alex

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

[Richard Purdie]

On Fri, 2024-01-12 at 11:57 +0100, Alexander Kanavin wrote:
> there seems to be a noticeable slowdown in bitbake doing world builds,
> particularly when layers in meta-oe are added to it. I've locally
> observed Cooker process spinning at 100% while no or few tasks get
> executed, apparently deciding what to do next, and it is noticeable in
> autobuilder too, e.g. right now:
> https://autobuilder.yoctoproject.org/typhoon/#/builders/88/builds/3515
> 
> I'd like to profile what is happening, but not sure where to start. Suggestions?

I've noticed a few slow builds too but I'm not convinced it is bitbake.

We observed a qemuarm-oecore build take 19 hours and of that,
nativesdk-gcc (for i686) took 6 hours.

It is likely that something else on the machine (maybe in another
build) is probably taking up much of the CPU capacity, e.g. rust
building or something.

The reason I mention the nativesdk-gcc above is that at the point that
is executed, bitbake is pretty much out the equation, it is just
processing logs. Whilst it is possible bitbake is slowing it down, I
find that unlikely and there is probably some other factor at play.

It is worth noting that there is only one build currently running on
alma9-ty-1 where the above build is and there are quite often multiple
tasks completing each second when it updates.

So nothing specific I can suggest but just my observations/thoughts.

You could pull the event log json file from the build and "replay" it
with some new viewer tool to see if there is any specific delay
involved between task executions. The events should be in there to
allow that.

Cheers,

Richard

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

[Alexander Kanavin]

On Fri, 12 Jan 2024 at 13:13, Richard Purdie
<richard.purdie@linuxfoundation.org> wrote:
> So nothing specific I can suggest but just my observations/thoughts.
>
> You could pull the event log json file from the build and "replay" it
> with some new viewer tool to see if there is any specific delay
> involved between task executions. The events should be in there to
> allow that.

The troubling part is, I've seen cooker at 100% cpu and not
progressing for minutes locally, on an unloaded machine. Then it
spawns some tasks, which quickly complete, then it does nothing again
for some time. So these might be several different sources of slowness
we're observing. The meta-oe build I've pointed to had just about 6000
tasks completed after some 6 hours, which is surely much slower than
the machine is capable of (and there were no competing builds in that
time).

Alex

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

[Khem Raj]

On Fri, Jan 12, 2024 at 4:27 AM Alexander Kanavin
<alex.kanavin@gmail.com> wrote:
>
> On Fri, 12 Jan 2024 at 13:13, Richard Purdie
> <richard.purdie@linuxfoundation.org> wrote:
> > So nothing specific I can suggest but just my observations/thoughts.
> >
> > You could pull the event log json file from the build and "replay" it
> > with some new viewer tool to see if there is any specific delay
> > involved between task executions. The events should be in there to
> > allow that.
>
> The troubling part is, I've seen cooker at 100% cpu and not
> progressing for minutes locally, on an unloaded machine. Then it
> spawns some tasks, which quickly complete, then it does nothing again
> for some time. So these might be several different sources of slowness
> we're observing. The meta-oe build I've pointed to had just about 6000
> tasks completed after some 6 hours, which is surely much slower than
> the machine is capable of (and there were no competing builds in that
> time).

I have observed something similar and brought it up in last dev call as well
one suggestion was to disable hash equivalence, which I did, it does not change
a lot which could be attributed to hash equivalence or otherwise, I have also
tried different python versions on the host but that did not change
anything either.
I am still looking for more ways to narrow it down.

>
> Alex
>
> -=-=-=-=-=-=-=-=-=-=-=-
> Links: You receive all messages sent to this group.
> View/Reply Online (#15787): https://lists.openembedded.org/g/bitbake-devel/message/15787
> Mute This Topic: https://lists.openembedded.org/mt/103680528/1997914
> Group Owner: bitbake-devel+owner@lists.openembedded.org
> Unsubscribe: https://lists.openembedded.org/g/bitbake-devel/unsub [raj.khem@gmail.com]
> -=-=-=-=-=-=-=-=-=-=-=-
>

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

[Alexander Kanavin]

On Fri, 12 Jan 2024 at 23:20, Khem Raj <raj.khem@gmail.com> wrote:
> > > You could pull the event log json file from the build and "replay" it
> > > with some new viewer tool to see if there is any specific delay
> > > involved between task executions. The events should be in there to
> > > allow that.
> >
> > The troubling part is, I've seen cooker at 100% cpu and not
> > progressing for minutes locally, on an unloaded machine. Then it
> > spawns some tasks, which quickly complete, then it does nothing again
> > for some time. So these might be several different sources of slowness
> > we're observing. The meta-oe build I've pointed to had just about 6000
> > tasks completed after some 6 hours, which is surely much slower than
> > the machine is capable of (and there were no competing builds in that
> > time).
>
> I have observed something similar and brought it up in last dev call as well
> one suggestion was to disable hash equivalence, which I did, it does not change
> a lot which could be attributed to hash equivalence or otherwise, I have also
> tried different python versions on the host but that did not change
> anything either.
> I am still looking for more ways to narrow it down.

I finally got to look at this, and yes I think there is a nasty
quadratic growth in bitbake. Details:

1. How to reproduce: set up a plain build with empty sstate and
default config, enabling meta-oe layers:

BBLAYERS ?= " \
  /srv/work/alex/poky/meta \
  /srv/work/alex/poky/meta-poky \
  /srv/work/alex/poky/meta-yocto-bsp \
  /srv/work/alex/meta-openembedded/meta-oe \
  /srv/work/alex/meta-openembedded/meta-python \
  /srv/work/alex/meta-openembedded/meta-networking \
  /srv/work/alex/meta-openembedded/meta-filesystems \
  /srv/work/alex/meta-openembedded/meta-gnome \
  /srv/work/alex/meta-openembedded/meta-xfce \
  /srv/work/alex/meta-openembedded/meta-multimedia \
  "

Then run 'bitbake world'. No tasks are going to start for minutes and
minutes and minutes: it will seemingly remain stuck at
NOTE: Executing Tasks

2. What is happening? After adding some debugging to
bitbake/lib/bb/runqueue.py, I found:

RunQueueExecute's execute() is being called over and over and over,
thousands of times. Each new call into it is slower than the next. No
tasks are actually run.

execute() contains this loop:

            for nexttask in self.sorted_setscene_tids:

self.sorted_setscene_tids contains about 28000 entries in each
execution of the loop.

Every time the loop is executed, it iterates over those 28000 entries,
stopping one item further along in that list, in this block of code:

                    if nexttask in self.sqdata.outrightfail:
                        logger.debug2('No package found, so skipping
setscene task %s', nexttask)
                        self.sq_task_failoutright(nexttask)
                        return True

Then the loop restarts from the beginning, etc. Until it reaches the
end of self.sorted_setscene_tids. In the process, items in the list
are checked 28000^2-ish times (1+2+...+28000), before anything even
starts.

3. What to do?

Of course I have no idea what I'm doing; this code is extremely
delicate :) Nevertheless, I replaced 'return True' in that block with
'continue', with massive improvement to when tasks actually start
running (after printing 'NOTE: Executing Tasks') and no obvious
immediate fails.

Before the change it was still stuck in that loop after 60 minutes
(!), and after the change it proceeded to the tasks after just two
minutes (!).

There are other 'return True's inside that loop that could also be
contributing to quadratic behaviour, I didn't check those.

Hopefully this helps.

Alex

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

[Richard Purdie]

On Fri, 2024-02-09 at 16:23 +0100, Alexander Kanavin wrote:
> > I have observed something similar and brought it up in last dev call as well
> > one suggestion was to disable hash equivalence, which I did, it does not change
> > a lot which could be attributed to hash equivalence or otherwise, I have also
> > tried different python versions on the host but that did not change
> > anything either.
> > I am still looking for more ways to narrow it down.
> 
> I finally got to look at this, and yes I think there is a nasty
> quadratic growth in bitbake. Details:
> 
> 1. How to reproduce: set up a plain build with empty sstate and
> default config, enabling meta-oe layers:
> 
> BBLAYERS ?= " \
>   /srv/work/alex/poky/meta \
>   /srv/work/alex/poky/meta-poky \
>   /srv/work/alex/poky/meta-yocto-bsp \
>   /srv/work/alex/meta-openembedded/meta-oe \
>   /srv/work/alex/meta-openembedded/meta-python \
>   /srv/work/alex/meta-openembedded/meta-networking \
>   /srv/work/alex/meta-openembedded/meta-filesystems \
>   /srv/work/alex/meta-openembedded/meta-gnome \
>   /srv/work/alex/meta-openembedded/meta-xfce \
>   /srv/work/alex/meta-openembedded/meta-multimedia \
>   "
> 
> Then run 'bitbake world'. No tasks are going to start for minutes and
> minutes and minutes: it will seemingly remain stuck at
> NOTE: Executing Tasks
> 
> 2. What is happening? After adding some debugging to
> bitbake/lib/bb/runqueue.py, I found:
> 
> RunQueueExecute's execute() is being called over and over and over,
> thousands of times. Each new call into it is slower than the next. No
> tasks are actually run.
> 
> execute() contains this loop:
> 
>             for nexttask in self.sorted_setscene_tids:
> 
> self.sorted_setscene_tids contains about 28000 entries in each
> execution of the loop.
> 
> Every time the loop is executed, it iterates over those 28000 entries,
> stopping one item further along in that list, in this block of code:
> 
>                     if nexttask in self.sqdata.outrightfail:
>                         logger.debug2('No package found, so skipping
> setscene task %s', nexttask)
>                         self.sq_task_failoutright(nexttask)
>                         return True
> 
> Then the loop restarts from the beginning, etc. Until it reaches the
> end of self.sorted_setscene_tids. In the process, items in the list
> are checked 28000^2-ish times (1+2+...+28000), before anything even
> starts.
> 
> 3. What to do?
> 
> Of course I have no idea what I'm doing; this code is extremely
> delicate :) Nevertheless, I replaced 'return True' in that block with
> 'continue', with massive improvement to when tasks actually start
> running (after printing 'NOTE: Executing Tasks') and no obvious
> immediate fails.
> 
> Before the change it was still stuck in that loop after 60 minutes
> (!), and after the change it proceeded to the tasks after just two
> minutes (!).
> 
> There are other 'return True's inside that loop that could also be
> contributing to quadratic behaviour, I didn't check those.
> 
> Hopefully this helps.

There is effectively a "main loop" within bitbake, so execute() is
meant to do one thing, then return, on the assumption it will get
called straight back.

Since the "continue" makes it faster, it suggests something else
somewhere is being slow and as you mention, there are a load of other
code paths which could also have a similar issue.

Could you find out where the actual delay is, since it should just hget
a call straight back. Or is it the loop iteration itself which is slow?
Even with 20k entries, you'd think python would handle that.

Finally, I'd also mention the -P option to bitbake, then having a look
at the various profile*.log files. One of them should be for cooker and
should clearly show where it is spending the time.

Cheers,

Richard

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

[Alexander Kanavin]

On Fri, 9 Feb 2024 at 16:43, Richard Purdie
<richard.purdie@linuxfoundation.org> wrote:

> There is effectively a "main loop" within bitbake, so execute() is
> meant to do one thing, then return, on the assumption it will get
> called straight back.
>
> Since the "continue" makes it faster, it suggests something else
> somewhere is being slow and as you mention, there are a load of other
> code paths which could also have a similar issue.
>
> Could you find out where the actual delay is, since it should just hget
> a call straight back. Or is it the loop iteration itself which is slow?
> Even with 20k entries, you'd think python would handle that.

It's a combination of having 20k entries, and that the loop stops at
each of those entries, and returns from execute(), then execute()
starts again and the loop is restarted from the beginning. So the
result is processing 20000 entries to the power of two. I inserted the
timings, iteration counters and additional debug calls into execute()
specifically to confirm this, and they did.

Alex

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

[Richard Purdie]

On Fri, 2024-02-09 at 16:59 +0100, Alexander Kanavin wrote:
> On Fri, 9 Feb 2024 at 16:43, Richard Purdie
> <richard.purdie@linuxfoundation.org> wrote:
> 
> > There is effectively a "main loop" within bitbake, so execute() is
> > meant to do one thing, then return, on the assumption it will get
> > called straight back.
> > 
> > Since the "continue" makes it faster, it suggests something else
> > somewhere is being slow and as you mention, there are a load of other
> > code paths which could also have a similar issue.
> > 
> > Could you find out where the actual delay is, since it should just hget
> > a call straight back. Or is it the loop iteration itself which is slow?
> > Even with 20k entries, you'd think python would handle that.
> 
> It's a combination of having 20k entries, and that the loop stops at
> each of those entries, and returns from execute(), then execute()
> starts again and the loop is restarted from the beginning. So the
> result is processing 20000 entries to the power of two. I inserted the
> timings, iteration counters and additional debug calls into execute()
> specifically to confirm this, and they did.

Iterating 28k entries isn't an issue for python. Yes, it will be "slow"
when you put logging around it but I doubt it is the real problem.

What is more likely is one of the calls like:

self.check_dependencies(xxx)

getting called once per entry and that call being slow.

Can you try the profile -P data please. If it doesn't make sense, share
it somewhere and I'll take a look.

Cheers,

Richard

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

[Alexander Kanavin]

On Fri, 9 Feb 2024 at 17:06, Richard Purdie
<richard.purdie@linuxfoundation.org> wrote:
> Iterating 28k entries isn't an issue for python. Yes, it will be "slow"
> when you put logging around it but I doubt it is the real problem.
>
> What is more likely is one of the calls like:
>
> self.check_dependencies(xxx)
>
> getting called once per entry and that call being slow.
>
> Can you try the profile -P data please. If it doesn't make sense, share
> it somewhere and I'll take a look.

I get:

Parsing of 2966 .bb files complete (0 cached, 2966 parsed). 4758
targets, 129 skipped, 0 masked, 0 errors.
ERROR: Command execution failed: Traceback (most recent call last):
  File "/srv/work/alex/poky/bitbake/lib/bb/cooker.py", line 2284, in parse_next
    parsed, mc, result = next(self.results)
                         ^^^^^^^^^^^^^^^^^^
StopIteration

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/srv/work/alex/poky/bitbake/lib/bb/command.py", line 122, in
runAsyncCommand
    self.cooker.updateCache()
  File "/srv/work/alex/poky/bitbake/lib/bb/cooker.py", line 1635, in updateCache
    if not self.parser.parse_next():
           ^^^^^^^^^^^^^^^^^^^^^^^^
  File "/srv/work/alex/poky/bitbake/lib/bb/cooker.py", line 2293, in parse_next
    self.shutdown()
  File "/srv/work/alex/poky/bitbake/lib/bb/cooker.py", line 2244, in shutdown
    bb.utils.process_profilelog(profiles, pout = pout)
  File "/srv/work/alex/poky/bitbake/lib/bb/utils.py", line 1159, in
process_profilelog
    p = pstats.Stats(*fn, stream=pout)
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/pstats.py", line 116, in __init__
    self.add(*args)
  File "/usr/lib/python3.11/pstats.py", line 174, in add
    item = Stats(item)
           ^^^^^^^^^^^
  File "/usr/lib/python3.11/pstats.py", line 115, in __init__
    self.init(arg)
  File "/usr/lib/python3.11/pstats.py", line 129, in init
    self.load_stats(arg)
  File "/usr/lib/python3.11/pstats.py", line 143, in load_stats
    self.stats = marshal.load(f)
                 ^^^^^^^^^^^^^^^
EOFError: EOF read where object expected


Alex

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

[Richard Purdie]

On Fri, 2024-02-09 at 17:16 +0100, Alexander Kanavin wrote:
> On Fri, 9 Feb 2024 at 17:06, Richard Purdie
> <richard.purdie@linuxfoundation.org> wrote:
> > Iterating 28k entries isn't an issue for python. Yes, it will be "slow"
> > when you put logging around it but I doubt it is the real problem.
> > 
> > What is more likely is one of the calls like:
> > 
> > self.check_dependencies(xxx)
> > 
> > getting called once per entry and that call being slow.
> > 
> > Can you try the profile -P data please. If it doesn't make sense, share
> > it somewhere and I'll take a look.
> 
> I get:
> 
> Parsing of 2966 .bb files complete (0 cached, 2966 parsed). 4758
> targets, 129 skipped, 0 masked, 0 errors.
> ERROR: Command execution failed: Traceback (most recent call last):
>   File "/srv/work/alex/poky/bitbake/lib/bb/cooker.py", line 2284, in parse_next
>     parsed, mc, result = next(self.results)
>                          ^^^^^^^^^^^^^^^^^^
> StopIteration
> 
> During handling of the above exception, another exception occurred:
> 
> Traceback (most recent call last):
>   File "/srv/work/alex/poky/bitbake/lib/bb/command.py", line 122, in
> runAsyncCommand
>     self.cooker.updateCache()
>   File "/srv/work/alex/poky/bitbake/lib/bb/cooker.py", line 1635, in updateCache
>     if not self.parser.parse_next():
>            ^^^^^^^^^^^^^^^^^^^^^^^^
>   File "/srv/work/alex/poky/bitbake/lib/bb/cooker.py", line 2293, in parse_next
>     self.shutdown()
>   File "/srv/work/alex/poky/bitbake/lib/bb/cooker.py", line 2244, in shutdown
>     bb.utils.process_profilelog(profiles, pout = pout)
>   File "/srv/work/alex/poky/bitbake/lib/bb/utils.py", line 1159, in
> process_profilelog
>     p = pstats.Stats(*fn, stream=pout)
>         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
>   File "/usr/lib/python3.11/pstats.py", line 116, in __init__
>     self.add(*args)
>   File "/usr/lib/python3.11/pstats.py", line 174, in add
>     item = Stats(item)
>            ^^^^^^^^^^^
>   File "/usr/lib/python3.11/pstats.py", line 115, in __init__
>     self.init(arg)
>   File "/usr/lib/python3.11/pstats.py", line 129, in init
>     self.load_stats(arg)
>   File "/usr/lib/python3.11/pstats.py", line 143, in load_stats
>     self.stats = marshal.load(f)
>                  ^^^^^^^^^^^^^^^
> EOFError: EOF read where object expected


That is very unexpected. I just tested "bitbake bash -P" myself and it
did work out ok. The stack trace doesn't really make sense to me so no
sure what is going on or why this is failing :(

That does look like it might be the post processing code failing (it
saves the results in binary, then loads and processes the logs to be
human readable as it exits).

Cheers,

Richard

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

[Alexander Kanavin]

On Fri, 9 Feb 2024 at 17:22, Richard Purdie
<richard.purdie@linuxfoundation.org> wrote:

> That is very unexpected. I just tested "bitbake bash -P" myself and it
> did work out ok. The stack trace doesn't really make sense to me so no
> sure what is going on or why this is failing :(
>
> That does look like it might be the post processing code failing (it
> saves the results in binary, then loads and processes the logs to be
> human readable as it exits).

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.

Alex

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

[Alexander Kanavin]

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

Alex

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

[chris.laplante]

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

Has anyone tried just using strace? I'm trying it now and will post if I get any interesting results. 

For tracing the forks:
strace -f bitbake world

Thanks,
Chris

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

[chris.laplante]

> > 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().
> 
> Has anyone tried just using strace? I'm trying it now and will post if I get any
> interesting results.
> 
> For tracing the forks:
> strace -f bitbake world

Actually I didn't have a chance to run it today. Will revisit next week.

Thanks,
Chris

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

[Richard Purdie]

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.

Cheers,

Richard

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

[Richard Purdie]

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

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

[Richard Purdie]

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

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

[Richard Purdie]

On Sat, 2024-02-10 at 15:16 +0000, Richard Purdie via
lists.openembedded.org wrote:
> 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.

I did try a world build under dryrun and the profile for that is
interesting:

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    1.965    1.965 2141.353 2141.353 /media/build/poky/bitbake/lib/bb/server/process.py:421(idle_thread_internal)
    79527    0.362    0.000 2029.951    0.026 /media/build/poky/bitbake/lib/bb/cooker.py:1474(buildTargetsIdle)
    79527    0.202    0.000 2029.579    0.026 /media/build/poky/bitbake/lib/bb/runqueue.py:1624(execute_runqueue)
    79527    1.243    0.000 2029.377    0.026 /media/build/poky/bitbake/lib/bb/runqueue.py:1523(_execute_runqueue)
    79527  820.305    0.010 2007.390    0.025 /media/build/poky/bitbake/lib/bb/runqueue.py:2149(execute)
    64340    6.256    0.000  702.802    0.011 /media/build/poky/bitbake/lib/bb/runqueue.py:286(next)
    34291  386.267    0.011  696.392    0.020 /media/build/poky/bitbake/lib/bb/runqueue.py:225(next_buildable_task)
    32188  174.899    0.005  185.634    0.006 /media/build/poky/bitbake/lib/bb/runqueue.py:2436(build_taskdepdata)
147477450   90.392    0.000  156.644    0.000 /media/build/poky/bitbake/lib/bb/runqueue.py:38(taskname_from_tid)
    32279    1.105    0.000  142.652    0.004 /media/build/poky/bitbake/lib/bb/runqueue.py:1328(send_pickled_data)
    37605  100.098    0.003  100.098    0.003 {built-in method select.select}
    32279   92.282    0.003   92.282    0.003 {method 'write' of '_io.BufferedWriter' objects}
   703235    6.748    0.000   83.246    0.000 /media/build/poky/bitbake/lib/bb/event.py:190(fire_ui_handlers)
    34309   77.040    0.002   77.040    0.002 {method 'difference' of 'set' objects}
   117124    0.501    0.000   76.536    0.001 /media/build/poky/bitbake/lib/bb/runqueue.py:1419(read_workers)
   197389    7.075    0.000   76.379    0.000 /media/build/poky/bitbake/lib/bb/runqueue.py:3228(read)
149286630   66.616    0.000   66.616    0.000 {method 'rsplit' of 'str' objects}
   341878   52.515    0.000   52.515    0.000 {built-in method _pickle.dumps}
111790/109676    0.394    0.000   51.501    0.000 /media/build/poky/bitbake/lib/bb/event.py:217(fire)
    68594   46.275    0.001   46.275    0.001 {method 'difference_update' of 'set' objects}
   591445    0.700    0.000   43.421    0.000 /media/build/poky/bitbake/lib/bb/event.py:237(fire_from_worker)
   309599    3.991    0.000   42.746    0.000 /media/build/poky/bitbake/lib/bb/cooker.py:113(send)
    34308   25.668    0.001   25.668    0.001 {method 'intersection_update' of 'set' objects}
16970/15322   23.129    0.001   23.278    0.002 /media/build/poky/bitbake/lib/bb/runqueue.py:2683(scenequeue_updatecounters)
16739/15091    0.023    0.000   23.236    0.002 /media/build/poky/bitbake/lib/bb/runqueue.py:2748(sq_task_failoutright)
    71163    0.436    0.000   20.433    0.000 /media/build/poky/bitbake/lib/bb/server/process.py:880(send)
    71163    0.534    0.000   17.511    0.000 /media/build/poky/bitbake/lib/bb/server/process.py:874(_send)
    71163    0.422    0.000   16.073    0.000 /usr/lib/python3.11/multiprocessing/connection.py:182(send_bytes)

in particular the 147 million calls to taskname_from_tid(). Definitely
something to be done in there.

Cheers,

Richard

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

[Richard Purdie]

On Sat, 2024-02-10 at 20:42 +0000, Richard Purdie via
lists.openembedded.org wrote:
> On Sat, 2024-02-10 at 15:16 +0000, Richard Purdie via
> lists.openembedded.org wrote:
> > 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.
> 
> I did try a world build under dryrun and the profile for that is
> interesting:
> 
>    ncalls  tottime  percall  cumtime  percall filename:lineno(function)
>         1    1.965    1.965 2141.353 2141.353 /media/build/poky/bitbake/lib/bb/server/process.py:421(idle_thread_internal)
>     79527    0.362    0.000 2029.951    0.026 /media/build/poky/bitbake/lib/bb/cooker.py:1474(buildTargetsIdle)
>     79527    0.202    0.000 2029.579    0.026 /media/build/poky/bitbake/lib/bb/runqueue.py:1624(execute_runqueue)
>     79527    1.243    0.000 2029.377    0.026 /media/build/poky/bitbake/lib/bb/runqueue.py:1523(_execute_runqueue)
>     79527  820.305    0.010 2007.390    0.025 /media/build/poky/bitbake/lib/bb/runqueue.py:2149(execute)
>     64340    6.256    0.000  702.802    0.011 /media/build/poky/bitbake/lib/bb/runqueue.py:286(next)
>     34291  386.267    0.011  696.392    0.020 /media/build/poky/bitbake/lib/bb/runqueue.py:225(next_buildable_task)
>     32188  174.899    0.005  185.634    0.006 /media/build/poky/bitbake/lib/bb/runqueue.py:2436(build_taskdepdata)
> 147477450   90.392    0.000  156.644    0.000 /media/build/poky/bitbake/lib/bb/runqueue.py:38(taskname_from_tid)
>     32279    1.105    0.000  142.652    0.004 /media/build/poky/bitbake/lib/bb/runqueue.py:1328(send_pickled_data)
>     37605  100.098    0.003  100.098    0.003 {built-in method select.select}
>     32279   92.282    0.003   92.282    0.003 {method 'write' of '_io.BufferedWriter' objects}
>    703235    6.748    0.000   83.246    0.000 /media/build/poky/bitbake/lib/bb/event.py:190(fire_ui_handlers)
>     34309   77.040    0.002   77.040    0.002 {method 'difference' of 'set' objects}
>    117124    0.501    0.000   76.536    0.001 /media/build/poky/bitbake/lib/bb/runqueue.py:1419(read_workers)
>    197389    7.075    0.000   76.379    0.000 /media/build/poky/bitbake/lib/bb/runqueue.py:3228(read)
> 149286630   66.616    0.000   66.616    0.000 {method 'rsplit' of 'str' objects}
>    341878   52.515    0.000   52.515    0.000 {built-in method _pickle.dumps}
> 111790/109676    0.394    0.000   51.501    0.000 /media/build/poky/bitbake/lib/bb/event.py:217(fire)
>     68594   46.275    0.001   46.275    0.001 {method 'difference_update' of 'set' objects}
>    591445    0.700    0.000   43.421    0.000 /media/build/poky/bitbake/lib/bb/event.py:237(fire_from_worker)
>    309599    3.991    0.000   42.746    0.000 /media/build/poky/bitbake/lib/bb/cooker.py:113(send)
>     34308   25.668    0.001   25.668    0.001 {method 'intersection_update' of 'set' objects}
> 16970/15322   23.129    0.001   23.278    0.002 /media/build/poky/bitbake/lib/bb/runqueue.py:2683(scenequeue_updatecounters)
> 16739/15091    0.023    0.000   23.236    0.002 /media/build/poky/bitbake/lib/bb/runqueue.py:2748(sq_task_failoutright)
>     71163    0.436    0.000   20.433    0.000 /media/build/poky/bitbake/lib/bb/server/process.py:880(send)
>     71163    0.534    0.000   17.511    0.000 /media/build/poky/bitbake/lib/bb/server/process.py:874(_send)
>     71163    0.422    0.000   16.073    0.000 /usr/lib/python3.11/multiprocessing/connection.py:182(send_bytes)
> 
> in particular the 147 million calls to taskname_from_tid(). Definitely
> something to be done in there.

Looking at the code, people have altered next_buildable_task() to add
per task thread limits and pressure regulation and they don't realise
how often that function can be called or how fast it really needs to
be. Note that the profile above doesn't include pressure regulation but
if it did, it would be much worse.

It can be reworked but it isn't trivial.

Cheers,

Richard

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

[Alexander Kanavin]

On Sat, 10 Feb 2024 at 21:53, Richard Purdie
<richard.purdie@linuxfoundation.org> wrote:

> Looking at the code, people have altered next_buildable_task() to add
> per task thread limits and pressure regulation and they don't realise
> how often that function can be called or how fast it really needs to
> be. Note that the profile above doesn't include pressure regulation but
> if it did, it would be much worse.
>
> It can be reworked but it isn't trivial.

Thanks for working on this, over the weekend. I just re-run profiling
with the fix for the mainloop, and here's what I see:

1. There are three performance fixes in master-next. Without any of
them, profile shows this (pressed ctrl-c while it was still not
running any tasks):

Mon Feb 12 12:32:56 2024    profile-mainloop.log

         71983446 function calls (71606940 primitive calls) in 1546.118 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     9448 1461.507    0.155 1491.991    0.158
/srv/work/alex/poky/bitbake/lib/bb/runqueue.py:2147(execute)
9510/9448   14.437    0.002   14.530    0.002
/srv/work/alex/poky/bitbake/lib/bb/runqueue.py:2672(scenequeue_updatecounters)
  5250612    7.414    0.000    7.414    0.000
/srv/work/alex/poky/bitbake/lib/bb/__init__.py:63(bbdebug)
  5219489    6.090    0.000   13.472    0.000
/srv/work/alex/poky/bitbake/lib/bb/__init__.py:57(debug2)
        1    5.906    5.906   18.979   18.979
/srv/work/alex/poky/bitbake/lib/bb/runqueue.py:644(prepare)
43827/23463    1.662    0.000    4.198    0.000
/usr/lib/python3.11/re/_parser.py:507(_parse)

So it is indeed the execute() loop itself which is slow. It's only
logical then that with the first two performance fixes applied,
nothing changes:

Mon Feb 12 13:03:42 2024    profile-mainloop.log

         67576990 function calls (67201484 primitive calls) in 1226.143 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     8711 1147.496    0.132 1173.321    0.135
/srv/work/alex/poky/bitbake/lib/bb/runqueue.py:2149(execute)
8773/8711   12.261    0.001   12.347    0.001
/srv/work/alex/poky/bitbake/lib/bb/runqueue.py:2683(scenequeue_updatecounters)
  4498537    6.303    0.000    6.303    0.000
/srv/work/alex/poky/bitbake/lib/bb/__init__.py:63(bbdebug)
        1    6.238    6.238   16.135   16.135
/srv/work/alex/poky/bitbake/lib/bb/runqueue.py:644(prepare)
  4467414    5.149    0.000   11.418    0.000
/srv/work/alex/poky/bitbake/lib/bb/__init__.py:57(debug2)
43827/23463    1.662    0.000    4.239    0.000
/usr/lib/python3.11/re/_parser.py:507(_parse)

Do note the quadratic growth in tottime though: 9448/8711 = 1.08, but
1461/1148 = 1.27

2. With the third fix (allow the loop to work through all items), I
finally didn't have to press ctrl-c, and the dry world run completed,
with the following picture:

Mon Feb 12 13:21:51 2024    profile-mainloop.log

         158073071 function calls (157658186 primitive calls) in 972.810 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    35784  307.013    0.009  513.933    0.014
/srv/work/alex/poky/bitbake/lib/bb/runqueue.py:225(next_buildable_task)
    34092  160.895    0.005  168.126    0.005
/srv/work/alex/poky/bitbake/lib/bb/runqueue.py:2438(build_taskdepdata)
    35807  118.265    0.003  118.265    0.003 {method 'difference' of
'set' objects}
    71592   54.910    0.001   54.910    0.001 {method
'difference_update' of 'set' objects}
    34096   50.010    0.001   50.010    0.001 {method 'write' of
'_io.BufferedWriter' objects}
17639/15964   48.203    0.003   48.480    0.003
/srv/work/alex/poky/bitbake/lib/bb/runqueue.py:2685(scenequeue_updatecounters)
   298834   45.690    0.000   45.691    0.000 {built-in method _pickle.dumps}
    35827   22.092    0.001   22.092    0.001 {method
'intersection_update' of 'set' objects}
    35783   10.610    0.000   10.610    0.000 {method 'index' of 'list' objects}
    35957    9.649    0.000  916.610    0.025
/srv/work/alex/poky/bitbake/lib/bb/runqueue.py:2149(execute)

execute() moves to the 10th place, and the time starts to be dominated
by other items

3. I'm not seeing anything obviously inefficient in the execute() loop
itself: it's mostly doing standard data structure lookups.
So I'd say execute() should be allowed to handle all the items in a
batch or otherwise make its own decisions about when to return. This
results in fails elsewhere as you've commented, I didn't yet look into
that.

Alex

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

[Richard Purdie]

On Mon, 2024-02-12 at 13:58 +0100, Alexander Kanavin wrote:
> On Sat, 10 Feb 2024 at 21:53, Richard Purdie
> <richard.purdie@linuxfoundation.org> wrote:
> 
> > Looking at the code, people have altered next_buildable_task() to add
> > per task thread limits and pressure regulation and they don't realise
> > how often that function can be called or how fast it really needs to
> > be. Note that the profile above doesn't include pressure regulation but
> > if it did, it would be much worse.
> > 
> > It can be reworked but it isn't trivial.
> 
> Thanks for working on this, over the weekend. I just re-run profiling
> with the fix for the mainloop, and here's what I see:
> 
> 1. There are three performance fixes in master-next. Without any of
> them, profile shows this (pressed ctrl-c while it was still not
> running any tasks):
> 
> Mon Feb 12 12:32:56 2024    profile-mainloop.log
> 
>          71983446 function calls (71606940 primitive calls) in 1546.118 seconds
> 
>    Ordered by: internal time
> 
>    ncalls  tottime  percall  cumtime  percall filename:lineno(function)
>      9448 1461.507    0.155 1491.991    0.158
> /srv/work/alex/poky/bitbake/lib/bb/runqueue.py:2147(execute)
> 9510/9448   14.437    0.002   14.530    0.002
> /srv/work/alex/poky/bitbake/lib/bb/runqueue.py:2672(scenequeue_updatecounters)
>   5250612    7.414    0.000    7.414    0.000
> /srv/work/alex/poky/bitbake/lib/bb/__init__.py:63(bbdebug)
>   5219489    6.090    0.000   13.472    0.000
> /srv/work/alex/poky/bitbake/lib/bb/__init__.py:57(debug2)
>         1    5.906    5.906   18.979   18.979
> /srv/work/alex/poky/bitbake/lib/bb/runqueue.py:644(prepare)
> 43827/23463    1.662    0.000    4.198    0.000
> /usr/lib/python3.11/re/_parser.py:507(_parse)
> 
> So it is indeed the execute() loop itself which is slow. It's only
> logical then that with the first two performance fixes applied,
> nothing changes:
> 
> Mon Feb 12 13:03:42 2024    profile-mainloop.log
> 
>          67576990 function calls (67201484 primitive calls) in 1226.143 seconds
> 
>    Ordered by: internal time
> 
>    ncalls  tottime  percall  cumtime  percall filename:lineno(function)
>      8711 1147.496    0.132 1173.321    0.135
> /srv/work/alex/poky/bitbake/lib/bb/runqueue.py:2149(execute)
> 8773/8711   12.261    0.001   12.347    0.001
> /srv/work/alex/poky/bitbake/lib/bb/runqueue.py:2683(scenequeue_updatecounters)
>   4498537    6.303    0.000    6.303    0.000
> /srv/work/alex/poky/bitbake/lib/bb/__init__.py:63(bbdebug)
>         1    6.238    6.238   16.135   16.135
> /srv/work/alex/poky/bitbake/lib/bb/runqueue.py:644(prepare)
>   4467414    5.149    0.000   11.418    0.000
> /srv/work/alex/poky/bitbake/lib/bb/__init__.py:57(debug2)
> 43827/23463    1.662    0.000    4.239    0.000
> /usr/lib/python3.11/re/_parser.py:507(_parse)
> 
> Do note the quadratic growth in tottime though: 9448/8711 = 1.08, but
> 1461/1148 = 1.27
> 
> 2. With the third fix (allow the loop to work through all items), I
> finally didn't have to press ctrl-c, and the dry world run completed,
> with the following picture:
> 
> Mon Feb 12 13:21:51 2024    profile-mainloop.log
> 
>          158073071 function calls (157658186 primitive calls) in 972.810 seconds
> 
>    Ordered by: internal time
> 
>    ncalls  tottime  percall  cumtime  percall filename:lineno(function)
>     35784  307.013    0.009  513.933    0.014
> /srv/work/alex/poky/bitbake/lib/bb/runqueue.py:225(next_buildable_task)
>     34092  160.895    0.005  168.126    0.005
> /srv/work/alex/poky/bitbake/lib/bb/runqueue.py:2438(build_taskdepdata)
>     35807  118.265    0.003  118.265    0.003 {method 'difference' of
> 'set' objects}
>     71592   54.910    0.001   54.910    0.001 {method
> 'difference_update' of 'set' objects}
>     34096   50.010    0.001   50.010    0.001 {method 'write' of
> '_io.BufferedWriter' objects}
> 17639/15964   48.203    0.003   48.480    0.003
> /srv/work/alex/poky/bitbake/lib/bb/runqueue.py:2685(scenequeue_updatecounters)
>    298834   45.690    0.000   45.691    0.000 {built-in method _pickle.dumps}
>     35827   22.092    0.001   22.092    0.001 {method
> 'intersection_update' of 'set' objects}
>     35783   10.610    0.000   10.610    0.000 {method 'index' of 'list' objects}
>     35957    9.649    0.000  916.610    0.025
> /srv/work/alex/poky/bitbake/lib/bb/runqueue.py:2149(execute)
> 
> execute() moves to the 10th place, and the time starts to be dominated
> by other items
> 
> 3. I'm not seeing anything obviously inefficient in the execute() loop
> itself: it's mostly doing standard data structure lookups.
> So I'd say execute() should be allowed to handle all the items in a
> batch or otherwise make its own decisions about when to return. This
> results in fails elsewhere as you've commented, I didn't yet look into
> that.

I worked out a way to make it work with "continue" however there was
more that was bugging me about the behaviour of this. You can see it in
this profile:

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    15223  807.225    0.053  838.759    0.055 /media/build/poky/bitbake/lib/bb/runqueue.py:2149(execute)
16970/15322   23.029    0.001   23.177    0.002 /media/build/poky/bitbake/lib/bb/runqueue.py:2683(scenequeue_updatecounters)
  5239701    3.361    0.000    3.361    0.000 /media/build/poky/bitbake/lib/bb/__init__.py:63(bbdebug)
        1    3.072    3.072    7.529    7.529 /media/build/poky/bitbake/lib/bb/runqueue.py:644(prepare)
  5208322    2.964    0.000    6.313    0.000 /media/build/poky/bitbake/lib/bb/__init__.py:57(debug2)
       43    1.236    0.029    1.236    0.029 {built-in method select.select}
 10707192    0.913    0.000    0.913    0.000 {method 'issubset' of 'set' objects}
24335/13567    0.669    0.000    1.264    0.000 /usr/lib/python3.11/re/_parser.py:509(_parse)
   996792    0.652    0.000    0.742    0.000 /usr/lib/python3.11/glob.py:141(_iterdir)
    41296    0.583    0.000    0.583    0.000 {built-in method posix.write}

Note that whilst they didn't take too long a time, there are 5 million
calls to debug2 (each is a line of log information) and 10 million
calls to issubset().

execute() should only be processing task entries when that entry has
some kind of "progress" that can be made and there is "space" to
execute a new task. The millions of log lines suggest something is
being "processed" multiple times over with no progress. The issubset()
gives a pointer to which code block.

As you've already identified, that points back to the code block:

if nexttask in self.sqdata.sq_harddeps_rev and not self.sqdata.sq_harddeps_rev[nexttask].issubset(self.scenequeue_covered | self.scenequeue_notcovered):
    logger.debug2("Deferring %s due to hard dependencies" % nexttask)

but I mainly mention this to show how it shows up in the profile.

The key question is why does that block keep getting triggered and how
can we make it only run when it needs to.

The answer is perhaps the patch I sent to the bitbake list a few hours
ago, which runs it once, then skips it until it has progress than can
be made (the harddep dependencies have run).

That change in behaviour is able to change the profile to:

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.069    0.069   62.756   62.756 /media/build/poky/bitbake/lib/bb/server/process.py:421(idle_thread_internal)
    15222    0.013    0.000   57.848    0.004 /media/build/poky/bitbake/lib/bb/cooker.py:1474(buildTargetsIdle)
    15222    0.012    0.000   57.834    0.004 /media/build/poky/bitbake/lib/bb/runqueue.py:1624(execute_runqueue)
    15222    0.057    0.000   57.822    0.004 /media/build/poky/bitbake/lib/bb/runqueue.py:1523(_execute_runqueue)
    15222   15.182    0.001   39.881    0.003 /media/build/poky/bitbake/lib/bb/runqueue.py:2150(execute)
16970/15322   23.639    0.001   23.775    0.002 /media/build/poky/bitbake/lib/bb/runqueue.py:2686(scenequeue_updatecounters)
16739/15091    0.017    0.000   23.723    0.002 /media/build/poky/bitbake/lib/bb/runqueue.py:2756(sq_task_failoutright)
        1    0.022    0.022    8.504    8.504 /media/build/poky/bitbake/lib/bb/runqueue.py:1814(__init__)
        1    2.842    2.842    7.013    7.013 /media/build/poky/bitbake/lib/bb/runqueue.py:644(prepare)
    16970    0.044    0.000    4.550    0.000 /media/build/poky/bitbake/lib/bb/build.py:855(find_stale_stamps)
    33948    0.032    0.000    4.197    0.000 /usr/lib/python3.11/glob.py:13(glob)

so without profiling enabled, "bitbake world -n --setscene-only" takes
around 30s (60s with profiling) for the workload which previously was
taking 12 minutes.

execute() is 40s of that and of the 40s, 23s is spent in the
scenequeue_updatecounters() accounting function.

The other "performance" changes I sent help the task execution phase
which happens after setscene() so they improve "bitbake world -n" but
not the setscene piece specifically.

The patches fix low hanging issues but I suspect there is more we
could/should do in this code.

Cheers,

Richard

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

[Alexander Kanavin]

On Tue, 13 Feb 2024 at 09:57, Richard Purdie
<richard.purdie@linuxfoundation.org> wrote:

> The patches fix low hanging issues but I suspect there is more we
> could/should do in this code.

Thanks, I confirm that after replacing the previous 'return True ->
continue' patch with the latest one, the profile is similar to that
patch:

Tue Feb 13 10:29:59 2024    profile-mainloop.log

         171090640 function calls (170677396 primitive calls) in
1000.777 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    35784  301.390    0.008  509.820    0.014
/srv/work/alex/poky/bitbake/lib/bb/runqueue.py:225(next_buildable_task)
    34092  164.164    0.005  171.500    0.005
/srv/work/alex/poky/bitbake/lib/bb/runqueue.py:2438(build_taskdepdata)
    35787  120.062    0.003  120.062    0.003 {method 'difference' of
'set' objects}
    71572   55.117    0.001   55.117    0.001 {method
'difference_update' of 'set' objects}
17639/15964   49.593    0.003   49.869    0.003
/srv/work/alex/poky/bitbake/lib/bb/runqueue.py:2686(scenequeue_updatecounters)
    34096   44.287    0.001   44.287    0.001 {method 'write' of
'_io.BufferedWriter' objects}
   298936   43.070    0.000   43.070    0.000 {built-in method _pickle.dumps}
    52656   39.374    0.001  936.397    0.018
/srv/work/alex/poky/bitbake/lib/bb/runqueue.py:2150(execute)
    35787   21.456    0.001   21.456    0.001 {method
'intersection_update' of 'set' objects}
    35783   10.646    0.000   10.646    0.000 {method 'index' of 'list' objects}
   314739    7.954    0.000    8.176    0.000 {built-in method io.open}
 90090452    7.660    0.000    7.660    0.000 {method 'append' of
'list' objects}


There's only appending to list which is still done tens of millions of
times, not sure if that's a concern. The bulk of it is in
build_taskdepdata().

I first noticed the issue when working on python 3.12 upgrade by the
way: this version has a higher amount of breaking changes that has
been typical (this was noticeable already in plain oe-core builds), so
as a courtesy to those taking care of meta-oe I've decided to fix
everything there as well. Which meant adding all meta-oe layers, and
running bitbake -k world with that.

Alex

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

[Ross Burton]

What might be useful here is finding a host distro with Python 3.12 (or using our buildtools), as Python 3.12 has perf integration:

https://docs.python.org/3/howto/perf_profiling.html

Perf’s direct profiling might be more accessible and accurate than the profiling built into bitbake.

Ross

> On 12 Feb 2024, at 12:58, Alexander Kanavin via lists.openembedded.org <alex.kanavin=gmail.com@lists.openembedded.org> wrote:
> 
> On Sat, 10 Feb 2024 at 21:53, Richard Purdie
> <richard.purdie@linuxfoundation.org> wrote:
> 
>> Looking at the code, people have altered next_buildable_task() to add
>> per task thread limits and pressure regulation and they don't realise
>> how often that function can be called or how fast it really needs to
>> be. Note that the profile above doesn't include pressure regulation but
>> if it did, it would be much worse.
>> 
>> It can be reworked but it isn't trivial.
> 
> Thanks for working on this, over the weekend. I just re-run profiling
> with the fix for the mainloop, and here's what I see:
> 
> 1. There are three performance fixes in master-next. Without any of
> them, profile shows this (pressed ctrl-c while it was still not
> running any tasks):
> 
> Mon Feb 12 12:32:56 2024    profile-mainloop.log
> 
>         71983446 function calls (71606940 primitive calls) in 1546.118 seconds
> 
>   Ordered by: internal time
> 
>   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
>     9448 1461.507    0.155 1491.991    0.158
> /srv/work/alex/poky/bitbake/lib/bb/runqueue.py:2147(execute)
> 9510/9448   14.437    0.002   14.530    0.002
> /srv/work/alex/poky/bitbake/lib/bb/runqueue.py:2672(scenequeue_updatecounters)
>  5250612    7.414    0.000    7.414    0.000
> /srv/work/alex/poky/bitbake/lib/bb/__init__.py:63(bbdebug)
>  5219489    6.090    0.000   13.472    0.000
> /srv/work/alex/poky/bitbake/lib/bb/__init__.py:57(debug2)
>        1    5.906    5.906   18.979   18.979
> /srv/work/alex/poky/bitbake/lib/bb/runqueue.py:644(prepare)
> 43827/23463    1.662    0.000    4.198    0.000
> /usr/lib/python3.11/re/_parser.py:507(_parse)
> 
> So it is indeed the execute() loop itself which is slow. It's only
> logical then that with the first two performance fixes applied,
> nothing changes:
> 
> Mon Feb 12 13:03:42 2024    profile-mainloop.log
> 
>         67576990 function calls (67201484 primitive calls) in 1226.143 seconds
> 
>   Ordered by: internal time
> 
>   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
>     8711 1147.496    0.132 1173.321    0.135
> /srv/work/alex/poky/bitbake/lib/bb/runqueue.py:2149(execute)
> 8773/8711   12.261    0.001   12.347    0.001
> /srv/work/alex/poky/bitbake/lib/bb/runqueue.py:2683(scenequeue_updatecounters)
>  4498537    6.303    0.000    6.303    0.000
> /srv/work/alex/poky/bitbake/lib/bb/__init__.py:63(bbdebug)
>        1    6.238    6.238   16.135   16.135
> /srv/work/alex/poky/bitbake/lib/bb/runqueue.py:644(prepare)
>  4467414    5.149    0.000   11.418    0.000
> /srv/work/alex/poky/bitbake/lib/bb/__init__.py:57(debug2)
> 43827/23463    1.662    0.000    4.239    0.000
> /usr/lib/python3.11/re/_parser.py:507(_parse)
> 
> Do note the quadratic growth in tottime though: 9448/8711 = 1.08, but
> 1461/1148 = 1.27
> 
> 2. With the third fix (allow the loop to work through all items), I
> finally didn't have to press ctrl-c, and the dry world run completed,
> with the following picture:
> 
> Mon Feb 12 13:21:51 2024    profile-mainloop.log
> 
>         158073071 function calls (157658186 primitive calls) in 972.810 seconds
> 
>   Ordered by: internal time
> 
>   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
>    35784  307.013    0.009  513.933    0.014
> /srv/work/alex/poky/bitbake/lib/bb/runqueue.py:225(next_buildable_task)
>    34092  160.895    0.005  168.126    0.005
> /srv/work/alex/poky/bitbake/lib/bb/runqueue.py:2438(build_taskdepdata)
>    35807  118.265    0.003  118.265    0.003 {method 'difference' of
> 'set' objects}
>    71592   54.910    0.001   54.910    0.001 {method
> 'difference_update' of 'set' objects}
>    34096   50.010    0.001   50.010    0.001 {method 'write' of
> '_io.BufferedWriter' objects}
> 17639/15964   48.203    0.003   48.480    0.003
> /srv/work/alex/poky/bitbake/lib/bb/runqueue.py:2685(scenequeue_updatecounters)
>   298834   45.690    0.000   45.691    0.000 {built-in method _pickle.dumps}
>    35827   22.092    0.001   22.092    0.001 {method
> 'intersection_update' of 'set' objects}
>    35783   10.610    0.000   10.610    0.000 {method 'index' of 'list' objects}
>    35957    9.649    0.000  916.610    0.025
> /srv/work/alex/poky/bitbake/lib/bb/runqueue.py:2149(execute)
> 
> execute() moves to the 10th place, and the time starts to be dominated
> by other items
> 
> 3. I'm not seeing anything obviously inefficient in the execute() loop
> itself: it's mostly doing standard data structure lookups.
> So I'd say execute() should be allowed to handle all the items in a
> batch or otherwise make its own decisions about when to return. This
> results in fails elsewhere as you've commented, I didn't yet look into
> that.
> 
> Alex
> 
> -=-=-=-=-=-=-=-=-=-=-=-
> Links: You receive all messages sent to this group.
> View/Reply Online (#15880): https://lists.openembedded.org/g/bitbake-devel/message/15880
> Mute This Topic: https://lists.openembedded.org/mt/103680528/6875888
> Group Owner: bitbake-devel+owner@lists.openembedded.org
> Unsubscribe: https://lists.openembedded.org/g/bitbake-devel/unsub [ross.burton@arm.com]
> -=-=-=-=-=-=-=-=-=-=-=-
> 

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

[Richard Purdie]

On Tue, 2024-02-13 at 10:49 +0000, Ross Burton wrote:
> What might be useful here is finding a host distro with Python 
> 3.12 (or using our buildtools), as Python 3.12 has perf integration:
> 
> https://docs.python.org/3/howto/perf_profiling.html
> 
> Perf’s direct profiling might be more accessible and accurate than 
> the profiling built into bitbake.
> 

The profiling "built into bitbake" is using python's own internal
performance code using cprofile and pstats so those are deterministic
profiles with exact call counts.

perf is statistical profiler so it will show information differently as
averages.

Both have a time and a place and it could be interesting, just flagging
the difference (and that we're using python's own profiling tooling for
this).

Cheers,

Richard

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

[Richard Purdie]

On Tue, 2024-02-13 at 10:42 +0100, Alexander Kanavin wrote:
> On Tue, 13 Feb 2024 at 09:57, Richard Purdie
> <richard.purdie@linuxfoundation.org> wrote:
> 
> > The patches fix low hanging issues but I suspect there is more we
> > could/should do in this code.
> 
> Thanks, I confirm that after replacing the previous 'return True ->
> continue' patch with the latest one, the profile is similar to that
> patch:
> 
> Tue Feb 13 10:29:59 2024    profile-mainloop.log
> 
>          171090640 function calls (170677396 primitive calls) in
> 1000.777 seconds
> 
>    Ordered by: internal time
> 
>    ncalls  tottime  percall  cumtime  percall filename:lineno(function)
>     35784  301.390    0.008  509.820    0.014
> /srv/work/alex/poky/bitbake/lib/bb/runqueue.py:225(next_buildable_task)
>     34092  164.164    0.005  171.500    0.005
> /srv/work/alex/poky/bitbake/lib/bb/runqueue.py:2438(build_taskdepdata)
>     35787  120.062    0.003  120.062    0.003 {method 'difference' of
> 'set' objects}
>     71572   55.117    0.001   55.117    0.001 {method
> 'difference_update' of 'set' objects}
> 17639/15964   49.593    0.003   49.869    0.003
> /srv/work/alex/poky/bitbake/lib/bb/runqueue.py:2686(scenequeue_updatecounters)
>     34096   44.287    0.001   44.287    0.001 {method 'write' of
> '_io.BufferedWriter' objects}
>    298936   43.070    0.000   43.070    0.000 {built-in method _pickle.dumps}
>     52656   39.374    0.001  936.397    0.018
> /srv/work/alex/poky/bitbake/lib/bb/runqueue.py:2150(execute)
>     35787   21.456    0.001   21.456    0.001 {method
> 'intersection_update' of 'set' objects}
>     35783   10.646    0.000   10.646    0.000 {method 'index' of 'list' objects}
>    314739    7.954    0.000    8.176    0.000 {built-in method io.open}
>  90090452    7.660    0.000    7.660    0.000 {method 'append' of
> 'list' objects}
> 
> 
> There's only appending to list which is still done tens of millions of
> times, not sure if that's a concern. The bulk of it is in
> build_taskdepdata().

We can work out how it compares to what we'd expect. If you generate
task-depends.dot and count the number of dependencies between tasks,
I'd expect the number of appends in build_taskdepdata to be be
approximately:

No. Tasks * No. Dependencies * 0.5

The half is assuming that the number of dependencies a task as scales
linearly which it doesn't but should give a rough number. It certainly
shouldn't be more than tasks * dependencies as an upper bound.

> I first noticed the issue when working on python 3.12 upgrade by the
> way: this version has a higher amount of breaking changes that has
> been typical (this was noticeable already in plain oe-core builds), so
> as a courtesy to those taking care of meta-oe I've decided to fix
> everything there as well. Which meant adding all meta-oe layers, and
> running bitbake -k world with that.

Thanks for doing that, it is appreciated. I think it is also good to
flag the poor performance as there is something we can do about this
case.

Cheers,

Richard

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

[Alexander Kanavin]

On Tue, 13 Feb 2024 at 13:41, Richard Purdie
<richard.purdie@linuxfoundation.org> wrote:
> We can work out how it compares to what we'd expect. If you generate
> task-depends.dot and count the number of dependencies between tasks,
> I'd expect the number of appends in build_taskdepdata to be be
> approximately:
>
> No. Tasks * No. Dependencies * 0.5
>
> The half is assuming that the number of dependencies a task as scales
> linearly which it doesn't but should give a rough number. It certainly
> shouldn't be more than tasks * dependencies as an upper bound.

Here's what task-depends.dot contains:

alex@Zen2:/srv/storage/alex/yocto/build-metaoe$ grep label task-depends.dot |wc
  35783  107349 5655551
alex@Zen2:/srv/storage/alex/yocto/build-metaoe$ grep -v label
task-depends.dot |wc
 145771  437311 9299716

So 35000 tasks, and 145000 dependencies. If one is multiplied by the
other it becomes 5 billion, which is much higher than 90 million
appends. Not sure what to make of that.

Alex

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

[Richard Purdie]

On Wed, 2024-02-14 at 07:59 +0100, Alexander Kanavin wrote:
> On Tue, 13 Feb 2024 at 13:41, Richard Purdie
> <richard.purdie@linuxfoundation.org> wrote:
> > We can work out how it compares to what we'd expect. If you generate
> > task-depends.dot and count the number of dependencies between tasks,
> > I'd expect the number of appends in build_taskdepdata to be be
> > approximately:
> > 
> > No. Tasks * No. Dependencies * 0.5
> > 
> > The half is assuming that the number of dependencies a task as scales
> > linearly which it doesn't but should give a rough number. It certainly
> > shouldn't be more than tasks * dependencies as an upper bound.
> 
> Here's what task-depends.dot contains:
> 
> alex@Zen2:/srv/storage/alex/yocto/build-metaoe$ grep label task-depends.dot |wc
>   35783  107349 5655551
> alex@Zen2:/srv/storage/alex/yocto/build-metaoe$ grep -v label
> task-depends.dot |wc
>  145771  437311 9299716
> 
> So 35000 tasks, and 145000 dependencies. If one is multiplied by the
> other it becomes 5 billion, which is much higher than 90 million
> appends. Not sure what to make of that.

Looked at another way, the 90 million calls equates to about 2500
dependencies per task, which probably isn't unreasonable when you
consider how many a single command line tool has (bash, sed or
whatever).

That taskdep data is passed into the task in question so it is allowed
to "see" any dependencies but not anything of any other task as that
would not be deterministic. That is why the list is rebuilt each call.

Whether there is a better way to do what that code is doing, I'm not
sure but the number of calls isn't a red flag in this case.

The amount of time spent in the next_task function is a lot more
significant though.

Cheers,

Richard