Re: [PATCH 3/3] rm_work.bbclass: clean up sooner

[Martin Jansa <martin.jansa@gmail.com>]

[-- Attachment #1: Type: text/plain, Size: 15225 bytes --]

On Wed, Mar 01, 2017 at 05:44:53PM +0100, Patrick Ohly wrote:
> On Wed, 2017-03-01 at 16:52 +0100, Martin Jansa wrote:
> > On Thu, Feb 16, 2017 at 11:26:54AM +0100, Patrick Ohly wrote:
> > > On Wed, 2017-02-15 at 19:32 +0100, Martin Jansa wrote:
> > > > Are all changes necessary for this to work already in master?
> > > 
> > > Yes.
> > > 
> > > > Yesterday I've noticed that rm_work for some components which are
> > > > early in the dependency (like qtbase) are executed relatively late
> > > > (together with do_package_qa).
> > > 
> > > Could do_rm_work run before do_package_qa? rm_work.bbclass doesn't know
> > > that, and therefore schedules do_rm_work after do_package_qa.
> > > 
> > > If yes, then adding a list of tasks that can be ignored would be
> > > trivial. This can be a variable, so a recipe can even add their own
> > > ones, if necessary.
> > 
> > That's now what I've meant.
> > 
> > I believe that rm_work needs to be executed after do_package_qa, but I
> > don't understand the scheduler code enough (at least not yet) to say
> > that higher priority of rm_work task also makes all the tasks rm_work
> > depends on e.g. do_package_qa to be executed sooner.
> 
> I see. do_package_qa should have a high priority, but it's still blocked
> by its dependencies. Building those dependencies only gets an indirect
> boost from scheduling recipes that many other recipes depend on first (a
> feature of the normal scheduler).
> 
> I suspect the problem with do_package_qa is similar to the problem with
> do_build before: it depends on do_package_qa of everything a recipe
> depends on, and thus finishing the build of those other recipes also
> blocks finishing the current recipe. That creates very deep dependency
> chains and thus increases the number of recipes which are "in progress"
> at the same time.

Another (surprising for me) output from bitbake -D -D -D:

OE qemux86@ ~/build/oe-core $ head log.zlib.rm_work.debug3.prio.*
==> log.zlib.rm_work.debug3.prio.completion <==
DEBUG: completion priorities (most important first):
1. ID /OE/build/oe-core/openembedded-core/meta/recipes-core/zlib/zlib_1.2.8.bb:do_build
2. ID /OE/build/oe-core/openembedded-core/meta/recipes-core/zlib/zlib_1.2.8.bb:do_rm_work
3. ID /OE/build/oe-core/openembedded-core/meta/recipes-core/zlib/zlib_1.2.8.bb:do_package_write_ipk
4. ID /OE/build/oe-core/openembedded-core/meta/recipes-core/expat/expat_2.2.0.bb:do_package_write_ipk
5. ID /OE/build/oe-core/openembedded-core/meta/recipes-kernel/linux-libc-headers/linux-libc-headers_4.9.bb:do_package_write_ipk
6. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/libtool/libtool-cross_2.4.6.bb:do_package_write_ipk
7. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/make/make_4.2.1.bb:do_package_write_ipk
8. ID /OE/build/oe-core/openembedded-core/meta/recipes-core/gettext/gettext_0.19.8.1.bb:do_package_write_ipk
9. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/gcc/libgcc_6.3.bb:do_package_write_ipk

==> log.zlib.rm_work.debug3.prio.normal <==
DEBUG: original priorities (most important first):
1. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_fetch
2. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_unpack
3. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_prepare_recipe_sysroot
4. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_patch
5. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_configure
6. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_compile
7. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_install
8. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_populate_sysroot
9. ID /OE/build/oe-core/openembedded-core/meta/recipes-extended/texinfo-dummy-native/texinfo-dummy-native.bb:do_fetch

From these 2 I would expect the later one to be completion (to finish whole quilt-native before starting anything else
except when all quilt-native tasks are blocked waiting for dependencies and BB_NUMBER_THREADS allows to run
more task).

But I understand that this isn't the actual order of tasks as explained in bitbake comment:
        # Group tasks of the same kind before tasks of less important
        # kinds at the head of the queue (because earlier = lower
        # priority number = runs earlier), while preserving the
        # ordering by recipe. If recipe foo is more important than
        # bar, then the goal is to work on foo's do_populate_sysroot
        # before bar's do_populate_sysroot and on the more important
        # tasks of foo before any of the less important tasks in any
        # other recipe (if those other recipes are more important than
        # foo).
        #
        # All of this only applies when tasks are runable. Explicit
        # dependencies still override this ordering by priority.
        #
        # Here's an example why this priority re-ordering helps with
        # minimizing disk usage. Consider a recipe foo with a higher
        # priority than bar where foo DEPENDS on bar. Then the
        # implicit rule (from base.bbclass) is that foo's do_configure
        # depends on bar's do_populate_sysroot. This ensures that
        # bar's do_populate_sysroot gets done first. Normally the
        # tasks from foo would continue to run once that is done, and
        # bar only gets completed and cleaned up later. By ordering
        # bar's task that depend on bar's do_populate_sysroot before foo's
        # do_configure, that problem gets avoided.

and the later one still doesn't list rm_worl task for quilt-native which is the real
one I'm interested in.

When I do the same with last rm_work.bbclass change reverted I get this:
$ head -n 12 log.zlib.rm_work.revert.debug3.prio.*
==> log.zlib.rm_work.revert.debug3.prio.completion <==
DEBUG: completion priorities (most important first):
1. ID /OE/build/oe-core/openembedded-core/meta/recipes-core/zlib/zlib_1.2.8.bb:do_rm_work_all
2. ID /OE/build/oe-core/openembedded-core/meta/recipes-support/ptest-runner/ptest-runner_2.0.bb:do_rm_work
3. ID virtual:native:/OE/build/oe-core/openembedded-core/meta/recipes-support/libpcre/libpcre_8.40.bb:do_rm_work
4. ID virtual:native:/OE/build/oe-core/openembedded-core/meta/recipes-graphics/xorg-util/util-macros_1.19.0.bb:do_rm_work
5. ID virtual:native:/OE/build/oe-core/openembedded-core/meta/recipes-extended/gperf/gperf_3.0.4.bb:do_rm_work
6. ID virtual:native:/OE/build/oe-core/openembedded-core/meta/recipes-support/attr/attr_2.4.47.bb:do_rm_work
7. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/python/python-native_2.7.12.bb:do_rm_work
8. ID virtual:native:/OE/build/oe-core/openembedded-core/meta/recipes-core/zlib/zlib_1.2.8.bb:do_rm_work
9. ID /OE/build/oe-core/openembedded-core/meta/recipes-core/expat/expat_2.2.0.bb:do_rm_work
10. ID virtual:native:/OE/build/oe-core/openembedded-core/meta/recipes-devtools/gnu-config/gnu-config_git.bb:do_rm_work
11. ID virtual:native:/OE/build/oe-core/openembedded-core/meta/recipes-extended/pigz/pigz_2.3.4.bb:do_rm_work

==> log.zlib.rm_work.revert.debug3.prio.normal <==
DEBUG: original priorities (most important first):
1. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_fetch
2. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_unpack
3. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_patch
4. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_prepare_recipe_sysroot
5. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_configure
6. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_compile
7. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_install
8. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_populate_sysroot
9. ID /OE/build/oe-core/openembedded-core/meta/recipes-extended/texinfo-dummy-native/texinfo-dummy-native.bb:do_fetch
10. ID virtual:native:/OE/build/oe-core/openembedded-core/meta/recipes-devtools/gnu-config/gnu-config_git.bb:do_fetch
11. ID /OE/build/oe-core/openembedded-core/meta/recipes-extended/texinfo-dummy-native/texinfo-dummy-native.bb:do_unpack

Here it doesn't look so good for quilt-native:rm_work, it's included in zlib dependencies (thanks to the revert), but
with "speed" scheduler it's far, while "completion" puts it early:
log.zlib.rm_work.revert.debug3.prio.completion:40. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_rm_work
log.zlib.rm_work.revert.debug3.prio.completion:66. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_build
log.zlib.rm_work.revert.debug3.prio.completion:159. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_populate_lic
log.zlib.rm_work.revert.debug3.prio.completion:229. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_populate_sysroot
log.zlib.rm_work.revert.debug3.prio.completion:299. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_install
log.zlib.rm_work.revert.debug3.prio.completion:361. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_compile
log.zlib.rm_work.revert.debug3.prio.completion:423. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_configure
log.zlib.rm_work.revert.debug3.prio.completion:484. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_prepare_recipe_sysroot
log.zlib.rm_work.revert.debug3.prio.completion:546. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_patch
log.zlib.rm_work.revert.debug3.prio.completion:603. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_unpack
log.zlib.rm_work.revert.debug3.prio.completion:660. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_fetch

log.zlib.rm_work.revert.debug3.prio.normal:1. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_fetch
log.zlib.rm_work.revert.debug3.prio.normal:2. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_unpack
log.zlib.rm_work.revert.debug3.prio.normal:3. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_patch
log.zlib.rm_work.revert.debug3.prio.normal:4. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_prepare_recipe_sysroot
log.zlib.rm_work.revert.debug3.prio.normal:5. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_configure
log.zlib.rm_work.revert.debug3.prio.normal:6. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_compile
log.zlib.rm_work.revert.debug3.prio.normal:7. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_install
log.zlib.rm_work.revert.debug3.prio.normal:8. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_populate_sysroot
log.zlib.rm_work.revert.debug3.prio.normal:561. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_populate_lic
log.zlib.rm_work.revert.debug3.prio.normal:599. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_build
log.zlib.rm_work.revert.debug3.prio.normal:697. ID /OE/build/oe-core/openembedded-core/meta/recipes-devtools/quilt/quilt-native_0.65.bb:do_rm_work

From this it looks like setting the weight of do_rm_work above do_populate_sysroot
would work with "speed" scheduler the way I was hoping for.

I'll retry the same on even smaller build and with BB_NUMBER_THREADS = "1" so that
it's easier to grasp what the completion scheduler really tries to do and how it
influences the actual order of runqueue in the end.

> 
> > Another interesting test from today was to run:
> > # rm -rf tmp-glibc/*
> > # bitbake -n zlib | tee log.zlib.rm_work
> > # cd oe-core; git revert -1 936179754c8d0f98e1196ddc6796fdfd72c0c3b4; cd ..
> > # rm -rf tmp-glibc/*
> > # bitbake -n zlib | tee log.zlib.rm_work.revert
> > 
> > and it shows interesting difference that many rm_work tasks aren't
> > executed at all:
> > 
> > # grep rm_work log.zlib.rm_work* | grep zlib_
> > log.zlib.rm_work:NOTE: Running task 526 of 527 (/OE/build/oe-core/openembedded-core/meta/recipes-core/zlib/zlib_1.2.8.bb:do_rm_work)
> > log.zlib.rm_work.revert:NOTE: Running task 128 of 721 (virtual:native:/OE/build/oe-core/openembedded-core/meta/recipes-core/zlib/zlib_1.2.8.bb:do_rm_work)
> > log.zlib.rm_work.revert:NOTE: Running task 717 of 721 (/OE/build/oe-core/openembedded-core/meta/recipes-core/zlib/zlib_1.2.8.bb:do_rm_work)
> > log.zlib.rm_work.revert:NOTE: Running task 721 of 721 (/OE/build/oe-core/openembedded-core/meta/recipes-core/zlib/zlib_1.2.8.bb:do_rm_work_all)
> > 
> > # grep rm_work log.zlib.rm_work* | grep gcc
> > log.zlib.rm_work.revert:NOTE: Running task 2 of 721 (/OE/build/oe-core/openembedded-core/meta/recipes-devtools/gcc/gcc-source_6.3.bb:do_rm_work)
> > log.zlib.rm_work.revert:NOTE: Running task 240 of 721 (/OE/build/oe-core/openembedded-core/meta/recipes-devtools/gcc/gcc-cross-initial_6.3.bb:do_rm_work)
> > log.zlib.rm_work.revert:NOTE: Running task 250 of 721 (/OE/build/oe-core/openembedded-core/meta/recipes-devtools/gcc/libgcc-initial_6.3.bb:do_rm_work)
> > log.zlib.rm_work.revert:NOTE: Running task 634 of 721 (/OE/build/oe-core/openembedded-core/meta/recipes-devtools/gcc/gcc-cross_6.3.bb:do_rm_work)
> > log.zlib.rm_work.revert:NOTE: Running task 674 of 721 (/OE/build/oe-core/openembedded-core/meta/recipes-devtools/gcc/libgcc_6.3.bb:do_rm_work)
> > log.zlib.rm_work.revert:NOTE: Running task 678 of 721 (/OE/build/oe-core/openembedded-core/meta/recipes-devtools/gcc/gcc-runtime_6.3.bb:do_rm_work)
> > 
> > # grep -c rm_work log.zlib.rm_work*
> > log.zlib.rm_work:1
> > log.zlib.rm_work.revert:63
> > 
> > I'll check if it's something in my setup or if this happens everywhere now.
> 
> I'll try to double-check this myself, too.
> 
> -- 
> Best Regards, Patrick Ohly
> 
> The content of this message is my personal opinion only and although
> I am an employee of Intel, the statements I make here in no way
> represent Intel's position on the issue, nor am I authorized to speak
> on behalf of Intel on this matter.
> 
> 
> 

-- 
Martin 'JaMa' Jansa     jabber: Martin.Jansa@gmail.com

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 201 bytes --]