Bug 10369

Corrected title - this is the install time, not the build time.

If I rebase out pretty much all of the changes to the eSDK install process since c24b6512d73ca54fb0e053e55fc8e0a501d8df0e - the commit before the one that actually enabled the functionality, whereas f3b62c1c2e47968084342d1fe2a9af596a3ba93c provided it (they were effectively merged in the wrong order) I get 4m33s, vs 4m3s for master, so I'm fairly convinced it wasn't the changes to the eSDK itself.

I've pushed the branch with the commits removed to paule/esdk-revert (although I didn't actually use reverts, so I guess it's mis-named).

CCing Markus so he can take a look at your comment.

Actually I just installed the eSDK from krogoth, took 3m56s - then I re-ran the install of the one from master twice and it took 3m51s and 3m55s.

I re-ran my tests and still get the same data.

f3b62c1c2e47968084342d1fe2a9af596a3ba93c^:
   eSDK install time 3:39
f3b62c1c2e47968084342d1fe2a9af596a3ba93c:
   eSDK install time 7:19.37
   
The latter clearly is the "bad" commit in the sense that it causes a huge increase in the eSDK install time.

(In reply to comment #5)
> I re-ran my tests and still get the same data.
> 
> f3b62c1c2e47968084342d1fe2a9af596a3ba93c^:
>    eSDK install time 3:39
> f3b62c1c2e47968084342d1fe2a9af596a3ba93c:
>    eSDK install time 7:19.37
>    
> The latter clearly is the "bad" commit in the sense that it causes a huge
> increase in the eSDK install time.

Markus, What are the changes from the default configuration, i.e. machine etc. And what sdk image are you building?

Here are the times I got using default config with core-image-minimal ext sdk installer. The last entry is master as of today.

467.27s user 93.65s system 576% cpu 1:37.36 total - f3b62c1c2e47968084342d1fe2a9af596a3ba93c^

499.20s user 95.01s system 467% cpu 2:07.18 total - f3b62c1c2e47968084342d1fe2a9af596a3ba93c

503.21s user 59.24s system 497% cpu 1:52.99 total - 4189a1977e65f71ddb8fc0498bcef91754c673d8

Oh, that inform(In reply to comment #6)
> (In reply to comment #5)
> > I re-ran my tests and still get the same data.
> > 
> > f3b62c1c2e47968084342d1fe2a9af596a3ba93c^:
> >    eSDK install time 3:39
> > f3b62c1c2e47968084342d1fe2a9af596a3ba93c:
> >    eSDK install time 7:19.37
> >    
> > The latter clearly is the "bad" commit in the sense that it causes a huge
> > increase in the eSDK install time.
> 
> Markus, What are the changes from the default configuration, i.e. machine
> etc. And what sdk image are you building?

Oh, that information is missing. The "standard test" is core-image-sato with default settings, i.e. no changes to local.conf.

We did change quite a few things that would affect Sato in master, could that have had an effect? The question is was there a change in the sstate restore time for core-image-sato (since that's one of the things we're doing during install)?

Wanted to leave the krogoth timing here:

582.60s user 53.23s system 815% cpu 1:17.99 total

This is interesting to me because it seems krogoth was actually doing more work, but because of better parallezation, wall clock time was slower.

(In reply to comment #7)
> Here are the times I got using default config with core-image-minimal ext
> sdk installer. The last entry is master as of today.
> 
> 467.27s user 93.65s system 576% cpu 1:37.36 total -
> f3b62c1c2e47968084342d1fe2a9af596a3ba93c^
> 
> 499.20s user 95.01s system 467% cpu 2:07.18 total -
> f3b62c1c2e47968084342d1fe2a9af596a3ba93c
> 
> 503.21s user 59.24s system 497% cpu 1:52.99 total -
> 4189a1977e65f71ddb8fc0498bcef91754c673d8

Hi Randy,
I checked what you executed for f3b62c1c2e47968084342d1fe2a9af596a3ba93c. Here only are four test cases that were initially developed. The remaining test cases are missing here. So I consider we can't compare with the full execution.
Regards
Paco

The test case is pretty simple: build eSDK for core-image-sato and measure it's installation time.

I.e. (on poky) do something like:
$ . ./oe-init-build-env build-10369
$ bitbake core-image-sato -c populate_sdk_ext
$ sync
$ echo 3 | sudo /usr/bin/tee /proc/sys/vm/drop_caches
$ time ./tmp/deploy/sdk/poky*-toolchain-ext-*.sh -y -d esdk-deploy

So I ran a new test where I set BB_NUMBER_THREADS=1, BB_NUMBER_PARSE_THREADS=1, PARALLEL_MAKE=-j1 in sdk-extra.conf. I then used a container to install the sdk restricting it to 1 core and here are the results:

34.35s user 52.50s system 103% cpu 6:14.84 total - 4454d024485d671ded558e3c617900f6fad414a4a (master)

319.50s user 81.34s system 93% cpu 7:07.41 total - e93596fe74927e2e2f4dd7f671994ccb9744cff8 (krogoth)

It looks like master is actually faster than krogoth. So combined with the previous results I posted, it seems that we lost some parallezation on master compared to krogoth.

It's not an sstate problem it seems:

sstate-only                                                                      
bitbake core-image-minimal  341.54s user 45.25s system 546% cpu 1:10.76 total - 4454d024485d671ded558e3c617900f6fad414a4a (master)                                          

bitbake core-image-minimal  327.05s user 113.48s system 565% cpu 1:17.91 total - e93596fe74927e2e2f4dd7f671994ccb9744cff8 (krogoth)


So the next thing I tried was installing an sdk without BB_SETSCENE_ENFORCE and with it on again:

without BB_SETSCENE_ENFORCE

452.32s user 55.43s system 519% cpu 1:37.74 total - 4454d024485d671ded558e3c617900f6fad414a4a (master)                                                                      

with BB_SETSCENE_ENFORCE
492.57s user 57.73s system 435% cpu 2:06.50 total


So we can see there is a bit of overhead there. My theory is that even though krogoth was doing more work to enforce sstate, since it was basically doing a dry run it gained massive benefits from parallezation.

Whereas BB_SETSCENE_ENFORCE is on one core while it's generating the runqueue. I'm curious if there is some optimization that could be done to the enforce code.

Hopefully this isn't a red herring.

Created attachment 3465 [details]
profile_without_enforce

This is the python profile data with BB_SETSCENE_ENFORCE=0.

Created attachment 3466 [details]
profile_with_enforce

The above profile attachments were from an install using core-image-minimal and master as of 4454d024485d671ded558e3c617900f6fad414a4a.

So after looking at the profile data, you can see split_tid() is taking huge amount of time compared to the non-enforce run.

That's because of this code in execute() in runqueue.py:

for tid in self.rqdata.runtaskentries:
    if check_norun_task(tid):
        unexpected = True
        break

The first thing that check_norun_task() does is to call split_tid(), and execute() gets called for every task.

So essentially there is O(n^2) that is calling an expensive function.

I've briefly talked to Paul, and it sounds like it was intended for it to be O(n).

Submitted one change: http://lists.openembedded.org/pipermail/bitbake-devel/2016-October/008148.html

With that change applied on top of 4454d024485d671ded558e3c617900f6 the timing for core-image-minimal sdk install changed to:

447.20s user 54.39s system 475% cpu 1:45.52 total

Note that last nights build failed with bug 10420, which I'm suspecting was caused by this patch.

I evidently did the krogoth install with hot cache. With a drop_cache first,

./krogoth-sdk-no-profile.sh -d sdk -y  601.00s user 128.95s system 804% cpu 1:30.73 total

I just did some measurements with core-image-sato that are at the bottom of this comment. The tests were all done using a ramdisk for everything to eliminate time differences due to i/o fluctuations.

The extraction(no prepare) for master takes longer than krogoth by ~7 seconds. This is somewhat expected due to the larger esdk size(due to also pulling in the toolchain), as well as a larger buildtools due to python2 and python3 being included in buildtools.

The part that concerned me was the fact that the "prepare only" took ~40 seconds more on master than on krogoth. This made no sense because the "bitbake core-image-sato" for master was roughly the same time as on krogoth.

So what was actually happening is that krogoth esdk didn't actually build the sdk_target(core-image-sato), it was doing a --setscene-only. When I instead told krogoth to behave like master and build the sdk_target the time was

./krogoth-sato-sdk-no-profile-with-image-prepare.sh -d sdk -y  656.65s user 269.89s system 374% cpu 4:07.72 total. That is ~75 seconds slower than master.


full install of sdk
./krogoth-sato-sdk-no-profile.sh -d sdk -y  956.22s user 361.27s system 1095% cpu 2:00.22 total
./krogoth-sato-sdk-no-profile.sh -d sdk -y  956.97s user 363.18s system 1097% cpu 2:00.31 total
./krogoth-sato-sdk-no-profile.sh -d sdk -y  955.61s user 360.05s system 1099% cpu 1:59.71 total

./master-sato-sdk-no-profile.sh -d sdk -y  853.90s user 138.69s system 603% cpu 2:44.42 total
./master-sato-sdk-no-profile.sh -d sdk -y  848.13s user 131.90s system 597% cpu 2:44.00 total
./master-sato-sdk-no-profile.sh -d sdk -y  850.45s user 134.92s system 599% cpu 2:44.39 total


no prepare(extract sdk and buildtools prep only)
./krogoth-sato-sdk-no-profile.sh -n -d sdk -y  7.31s user 6.86s system 45% cpu 30.847 total
./krogoth-sato-sdk-no-profile.sh -n -d sdk -y  6.82s user 7.29s system 45% cpu 30.802 total
./krogoth-sato-sdk-no-profile.sh -n -d sdk -y  7.97s user 7.36s system 48% cpu 31.711 total

./master-sato-sdk-no-profile.sh -n -d sdk -y  11.47s user 8.76s system 52% cpu 38.311 total
./master-sato-sdk-no-profile.sh -n -d sdk -y  11.75s user 8.36s system 51% cpu 38.708 total
./master-sato-sdk-no-profile.sh -n -d sdk -y  11.96s user 8.41s system 51% cpu 39.277 total


prepare only
python ext-sdk-prepare.py core-image-sato  944.65s user 351.83s system 1476% cpu 1:27.83 total -krogoth
python ext-sdk-prepare.py core-image-sato  947.37s user 349.94s system 1425% cpu 1:31.00 total -krogoth
python ext-sdk-prepare.py core-image-sato  947.71s user 354.61s system 1481% cpu 1:27.93 total -krogoth

python ext-sdk-prepare.py mylog.log core-image-sato  838.70s user 124.04s system 751% cpu 2:08.09 total -master
python ext-sdk-prepare.py mylog.log core-image-sato  844.25s user 125.42s system 752% cpu 2:08.94 total -master
python ext-sdk-prepare.py mylog.log core-image-sato  836.20s user 120.40s system 756% cpu 2:06.45 total -master


regular build from sstate
bitbake core-image-sato  670.69s user 363.70s system 834% cpu 2:03.89 total -krogoth
bitbake core-image-sato  669.24s user 365.07s system 840% cpu 2:03.09 total -krogoth
bitbake core-image-sato  670.53s user 363.49s system 841% cpu 2:02.84 total -krogoth

bitbake core-image-sato  698.39s user 121.87s system 694% cpu 1:58.18 total -master
bitbake core-image-sato  711.01s user 125.27s system 696% cpu 2:00.12 total -master
bitbake core-image-sato  702.30s user 123.67s system 700% cpu 1:57.95 total -master

bitbake core-image-sato meta-extsdk-toolchain:do_populate_sysroot  636.27s user 125.21s system 634% cpu 1:59.92 total -master

Paul, based on the previous comment with the core-image-sato times, I'm curious why we started building the image as part of the sdk install where we didn't do that previously on krogoth.

Because at this point, to close this bug, I think we need to say whether or not we want to match the old behavior or stick with the new.

If someone can suggest a mechanism that isn't horrifically hacky to install without running do_rootfs et al, then I'm in favour. Right now I can't think of one.

Here are the times for full install, restricting BB_NUMBER_THREADS and BB_NUMBER_PARSE_THREADS to eight. This was done because that is more representative of typical hardware than 40 cores.

full install of sdk limited to 8 cores
./master-sato-8-thread-no-profile.sh -d sdk -y  536.49s user 94.08s system 319% cpu 3:17.18 total -master
./master-sato-8-thread-no-profile.sh -d sdk -y  533.63s user 90.00s system 318% cpu 3:15.77 total -master

./krogoth-sato-8-thread-no-profile.sh -d sdk -y  568.66s user 230.68s system 463% cpu 2:52.55 total -krogoth
./krogoth-sato-8-thread-no-profile.sh -d sdk -y  576.29s user 241.83s system 470% cpu 2:53.80 total -krogoth


So for a relatively large image on typical hardware, master is ~25 seconds slower.

To clarify the last comment, yes it is 25 seconds total, but ~8 seconds of that is attributed to extraction, and that cannot be lowered.

So, in conclusion the extra time spent during installation is a combination of:

1) The increase in size of buildtools, which is likely due to python 3 being added (with python 2 still also being present - we may be able to remove python 2 during 2.3 if we sort out the dependencies)

2) Building the image which was something we were not doing previously (something which I had forgotten, sorry about that.) 

To explain what we are trying to do with this process - we need to restore from sstate what we can, and also check that there's nothing that should have restored from sstate but didn't (because the sstate wasn't available / the signatures didn't match, or it failed to restore). In krogoth we did this by  running bitbake twice: first bitbake --setscene-only on the image to do the restore from sstate, followed by bitbake -n (dry-run) on the same to check if there were any tasks shown as being run that we didn't expect. In morty/master I changed this to a single execution and added functionality to bitbake and sstate.bbclass so that we have a mode to do both things at once (enabled by setting BB_SETSCENE_ENFORCE=1 and BB_SETSCENE_ENFORCE_WHITELIST to specify which real tasks we will accept running, which includes the image construction tasks). Unfortunately a side-effect was that the image construction tasks actually get run - something that I should have fixed.

In order to fix this properly we need to ensure that those tasks can dry-run instead of actually running, but doing so requires changes to the runqueue that I feel are too invasive this close to release.

Richard has suggested using the "up-to-but-not-including-task" feature with do_rootfs to work around this; however this will exclude the tasks needed to restore dependencies for the image tasks that come after do_rootfs (those that we split out during krogoth). This means that there's no guarantee that the user will be able to build the image after the SDK is installed, which is something we're trying to verify as part of this.

OK, I've sent a patch to the bitbake list to fix this - it turned out not to be too tricky, we just needed to "dry-run" the real tasks that are currently executing here.

Fix merged to master:

http://git.yoctoproject.org/cgit/cgit.cgi/poky/commit/?id=fe7e75075e2d55a45ad2b81c9e493068a156d1dc